TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ... (1071 Views)
Reply
Occasional Contributor
PeterPaul
Posts: 4
Registered: ‎06-20-2011
Message 1 of 6 (1,071 Views)

TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ...

Hello,

 

after installing many layerd products and patches at OpenVMS 8.3 Alpha I see now at TCPIP startup OPCOM failure messages for FTP,NTP and XDM. Before installing and configuring ACMS (VMS, LDAP, ACMEutil), Kerberos, CIFS and Legato Networker backup client the TCPIP daemons start with any problems.  Networker Client 7.3-4, CIFS Samba and SSH don't work, too now. The system security alarm and audits are enabled. When I start SSH interactive (@TCPIP$SYSTEM:TCPIP$SSH_RUN.COM) with debug option it failed when SSH switched to daemon. TCPIP is configured by tcpip$config and IPv6 is disabled.  I have no idea of how and when it its broken.
Any ideas or hints
 Peter
TCPIP Startup OPCOM Messages:
===========================
...
-TCPIP-I-SERVTOTAL, total of 0 proxy records read
%TCPIP-S-STARTDONE, TCPIP$PROXY startup completed
%%%%%%%%%%%  OPCOM  14-JUL-2012 15:51:48.05  %%%%%%%%%%%
Message from user INTERnet on RUMBA
INTERnet ACP Activate FTP Server 
%%%%%%%%%%%  OPCOM  14-JUL-2012 15:51:48.05  %%%%%%%%%%%
Message from user INTERnet on RUMBA
INTERnet ACP NOLISTEN Process creation success: Service - FTP
%%%%%%%%%%%  OPCOM  14-JUL-2012 15:51:48.05  %%%%%%%%%%%
Message from user INTERnet on RUMBA
INTERnet ACP Error during process startup, Nolisten Service Disabled - FTP Server 
%TCPIP-S-STARTDONE, TCPIP$FTP startup completed
%%%%%%%%%%%  OPCOM  14-JUL-2012 15:51:48.05  %%%%%%%%%%%
Message from user INTERnet on RUMBA
INTERnet ACP Deactivate FTP Server 
%TCPIP-S-STARTDONE, TCP/IP Services startup completed at 14-JUL-2012 15:51:49.30
...
System Securiity Settings
====================  
 
RUMBA::SYSTEM>show audit
System security alarms currently enabled for:
  ACL
  Authorization
  Audit:         illformed
  Breakin:       dialup,local,remote,network,detached,server
  Login:         batch,dialup,local,remote,network,subprocess,detached,server
  Logfailure:    batch,dialup,local,remote,network,subprocess,detached
System security audits currently enabled for:
  ACL
  Authorization
  Audit:         illformed
  Breakin:       dialup,local,remote,network,detached
  Login:         batch,dialup,local,remote,network,subprocess,detached,server
  Logfailure:    batch,dialup,local,remote,network,subprocess,detached
RUMBA::SYSTEM>
SSH Run with Debug Messages:
==========================
RUMBA::SYSTEM>@TCPIP$SYSTEM:TCPIP$SSH_RUN.COM
debug(14-JUL-2012 16:26:24.66): SshUnixUser/SSHUNIXUSER.C:833: ssh_user_initialize entered for user (NULL)
debug(14-JUL-2012 16:26:24.66): SshUnixUser/SSHUNIXUSER.C:1049: ssh_user_initialize_with_pw called for system, privileged = 0
debug(14-JUL-2012 16:26:24.66): SshUserFile/SSHUSERFILE.C:1359: ssh_userfile_init returning persona 2 for user system
debug(14-JUL-2012 16:26:24.66): SshUserFile/SSHUSERFILE.C:1371: ssh_userfile_uninit entered, ssh_userfile_initialized=1
debug(14-JUL-2012 16:26:24.73): SshHostKeyIO/SSHHOSTKEYIO.C:163: Reading private host key from ssh2/hostkey
debug(14-JUL-2012 16:26:24.73): SshUserFile/SSHUSERFILE.C:1359: ssh_userfile_init returning persona 2 for user system
debug(14-JUL-2012 16:26:25.06): SshUserFile/SSHUSERFILE.C:1359: ssh_userfile_init returning persona 2 for user system
debug(14-JUL-2012 16:26:25.06): SshUserFile/SSHUSERFILE.C:1371: ssh_userfile_uninit entered, ssh_userfile_initialized=1
debug(14-JUL-2012 16:26:25.06): SshUserFiles/SSHKEYBLOB2.C:584: key blob magic = 0x00000005
debug(14-JUL-2012 16:26:25.06): SshUserFile/SSHUSERFILE.C:1371: ssh_userfile_uninit entered, ssh_userfile_initialized=0
debug(14-JUL-2012 16:26:25.13): SshEncode/SSHENCODE.C:325: Format = 0x2
debug(14-JUL-2012 16:26:25.13): SshEncode/SSHENCODE.C:325: Format = 0x2
debug(14-JUL-2012 16:26:25.13): SshEncode/SSHENCODE.C:325: Format = 0x0
debug(14-JUL-2012 16:26:25.13): SshEncode/SSHENCODE.C:325: Format = 0xD0E0A0D
debug(14-JUL-2012 16:26:25.13): SshEncode/SSHENCODE.C:452: offset = 50
debug(14-JUL-2012 16:26:25.21): SshEncode/SSHENCODE.C:325: Format = 0x0
debug(14-JUL-2012 16:26:25.21): SshEncode/SSHENCODE.C:325: Format = 0x2
debug(14-JUL-2012 16:26:25.21): SshEncode/SSHENCODE.C:325: Format = 0xD0E0A0D
debug(14-JUL-2012 16:26:25.21): SshEncode/SSHENCODE.C:452: offset = 12
debug(14-JUL-2012 16:26:25.21): SshEncode/SSHENCODE.C:325: Format = 0x2
debug(14-JUL-2012 16:26:25.29): SshEncode/SSHENCODE.C:325: Format = 0xD0E0A0D
debug(14-JUL-2012 16:26:25.29): SshEncode/SSHENCODE.C:452: offset = 4
debug(14-JUL-2012 16:26:25.29): SshEncode/SSHENCODE.C:325: Format = 0x2
debug(14-JUL-2012 16:26:25.29): SshEncode/SSHENCODE.C:325: Format = 0xD0E0A0D
debug(14-JUL-2012 16:26:25.29): SshEncode/SSHENCODE.C:452: offset = 4
debug(14-JUL-2012 16:26:25.37): SshEncode/SSHENCODE.C:325: Format = 0x4
debug(14-JUL-2012 16:26:25.37): SshEncode/SSHENCODE.C:325: Format = 0x4
debug(14-JUL-2012 16:26:25.37): SshEncode/SSHENCODE.C:325: Format = 0x4
debug(14-JUL-2012 16:26:25.37): SshEncode/SSHENCODE.C:325: Format = 0xD0E0A0D
debug(14-JUL-2012 16:26:25.37): SshEncode/SSHENCODE.C:452: offset = 544
debug(14-JUL-2012 16:26:25.45): SshEncode/SSHENCODE.C:325: Format = 0x4
debug(14-JUL-2012 16:26:25.45): SshEncode/SSHENCODE.C:325: Format = 0x4
debug(14-JUL-2012 16:26:25.45): SshEncode/SSHENCODE.C:325: Format = 0xD0E0A0D
debug(14-JUL-2012 16:26:25.45): SshEncode/SSHENCODE.C:452: offset = 284
debug(14-JUL-2012 16:26:25.45): SshHostKeyIO/SSHHOSTKEYIO.C:174: Key comment: 2048-bit dsa, system@rumba.exp.bessy.de, Fri Jul 13 2012 15:18:39
debug(14-JUL-2012 16:26:25.53): SshHostKeyIO/SSHHOSTKEYIO.C:203: Reading public host key from ssh2/hostkey.pub
debug(14-JUL-2012 16:26:25.53): SshUserFile/SSHUSERFILE.C:1359: ssh_userfile_init returning persona 2 for user system
debug(14-JUL-2012 16:26:25.53): SshUserFile/SSHUSERFILE.C:1359: ssh_userfile_init returning persona 2 for user system
debug(14-JUL-2012 16:26:25.53): SshUserFile/SSHUSERFILE.C:1371: ssh_userfile_uninit entered, ssh_userfile_initialized=1
debug(14-JUL-2012 16:26:25.61): SshUserFiles/SSHKEYBLOB2.C:584: key blob magic = 0x00000005
debug(14-JUL-2012 16:26:25.61): SshUserFile/SSHUSERFILE.C:1371: ssh_userfile_uninit entered, ssh_userfile_initialized=0
debug(14-JUL-2012 16:26:25.61): SshEncode/SSHENCODE.C:325: Format = 0x0
debug(14-JUL-2012 16:26:25.61): SshEncode/SSHENCODE.C:325: Format = 0xD0E0A0D
debug(14-JUL-2012 16:26:25.69): SshEncode/SSHENCODE.C:452: offset = 11
debug(14-JUL-2012 16:26:25.69): SshHostKeyIO/SSHHOSTKEYIO.C:288: Host key algorithms (from disk): ssh-dss
debug(14-JUL-2012 16:26:25.69): SshUserFile/SSHUSERFILE.C:1359: ssh_userfile_init returning persona 2 for user system
debug(14-JUL-2012 16:26:25.69): GenRand/GENRAND.C:425: Starting to collect noise.
debug(14-JUL-2012 16:26:25.77): GenRand/GENRAND.C:266: Starting read from /dev/random.
debug(14-JUL-2012 16:26:25.77): GenRand/GENRAND.C:288: Opening /dev/random failed.
debug(14-JUL-2012 16:26:25.77): GenRand/GENRAND.C:420: Already acquiring noise.
debug(14-JUL-2012 16:26:25.77): GenRand/GENRAND.C:425: Starting to collect noise.
debug(14-JUL-2012 16:26:25.77): GenRand/GENRAND.C:266: Starting read from /dev/random.
debug(14-JUL-2012 16:26:25.85): GenRand/GENRAND.C:288: Opening /dev/random failed.
debug(14-JUL-2012 16:26:25.85): GenRand/GENRAND.C:420: Already acquiring noise.
debug(14-JUL-2012 16:26:25.85): SshUserFile/SSHUSERFILE.C:1359: ssh_userfile_init returning persona 2 for user system
debug(14-JUL-2012 16:26:26.04): SshUserFile/SSHUSERFILE.C:1371: ssh_userfile_uninit entered, ssh_userfile_initialized=1
debug(14-JUL-2012 16:26:26.19): GenRand/GENRAND.C:425: Starting to collect noise.
debug(14-JUL-2012 16:26:26.19): GenRand/GENRAND.C:266: Starting read from /dev/random.
debug(14-JUL-2012 16:26:26.19): GenRand/GENRAND.C:288: Opening /dev/random failed.
debug(14-JUL-2012 16:26:26.23): GenRand/GENRAND.C:420: Already acquiring noise.
debug(14-JUL-2012 16:26:26.23): GenRand/GENRAND.C:425: Starting to collect noise.
debug(14-JUL-2012 16:26:26.23): GenRand/GENRAND.C:266: Starting read from /dev/random.
debug(14-JUL-2012 16:26:26.23): GenRand/GENRAND.C:288: Opening /dev/random failed.
debug(14-JUL-2012 16:26:26.25): SshUserFile/SSHUSERFILE.C:1371: ssh_userfile_uninit entered, ssh_userfile_initialized=0
debug(14-JUL-2012 16:26:26.25): SshCertEdbOcsp/CMI-OCSP.C:1650: Initializing OCSP and creating a HTTP client.
debug(14-JUL-2012 16:26:26.25): SshADT/SSHADT.C:143: Registered hash callback @4c010.
debug(14-JUL-2012 16:26:26.25): SshADT/SSHADT.C:119: Registered compare callback @4bfe0.
debug(14-JUL-2012 16:26:26.33): SshADT/SSHADT.C:137: Registered destroy callback @4bfc0.
debug(14-JUL-2012 16:26:26.33): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.http
debug(14-JUL-2012 16:26:26.33): SshADT/SSHADT.C:143: Registered hash callback @4c010.
debug(14-JUL-2012 16:26:26.33): SshADT/SSHADT.C:119: Registered compare callback @4bfe0.
debug(14-JUL-2012 16:26:26.41): SshADT/SSHADT.C:137: Registered destroy callback @4bfc0.
debug(14-JUL-2012 16:26:26.41): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.http
debug(14-JUL-2012 16:26:26.41): SshCertEdb/CMI-EDB.C:277: EDB: Adding database: ssh.http
debug(14-JUL-2012 16:26:26.41): SshCertEdb/CMI-EDB.C:310: EDB: Removing database: ssh.ldap
debug(14-JUL-2012 16:26:26.49): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.ldap
debug(14-JUL-2012 16:26:26.49): SshCertEdbLdap/CMI-LDAP.C:989: EDB/LDAP: Adding new LDAP backend.
debug(14-JUL-2012 16:26:26.49): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.ldap
debug(14-JUL-2012 16:26:26.49): SshCertEdb/CMI-EDB.C:277: EDB: Adding database: ssh.ldap
debug(14-JUL-2012 16:26:26.57): SshCertEdb/CMI-EDB.C:310: EDB: Removing database: ssh.ldap
debug(14-JUL-2012 16:26:26.57): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.ldap
debug(14-JUL-2012 16:26:26.57): SshCertEdbLdap/CMI-LDAP.C:989: EDB/LDAP: Adding new LDAP backend.
debug(14-JUL-2012 16:26:26.57): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.ldap
debug(14-JUL-2012 16:26:26.65): SshCertEdb/CMI-EDB.C:277: EDB: Adding database: ssh.ldap
debug(14-JUL-2012 16:26:26.65): SshCertEdbOcsp/CMI-OCSP.C:1650: Initializing OCSP and creating a HTTP client.
debug(14-JUL-2012 16:26:26.65): SshADT/SSHADT.C:143: Registered hash callback @4c010.
debug(14-JUL-2012 16:26:26.65): SshADT/SSHADT.C:119: Registered compare callback @4bfe0.
debug(14-JUL-2012 16:26:26.73): SshADT/SSHADT.C:137: Registered destroy callback @4bfc0.
debug(14-JUL-2012 16:26:26.73): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.http
debug(14-JUL-2012 16:26:26.73): SshADT/SSHADT.C:143: Registered hash callback @4c010.
debug(14-JUL-2012 16:26:26.73): SshADT/SSHADT.C:119: Registered compare callback @4bfe0.
debug(14-JUL-2012 16:26:26.81): SshADT/SSHADT.C:137: Registered destroy callback @4bfc0.
debug(14-JUL-2012 16:26:26.81): SshCertEdb/CMI-EDB.C:243: EDB/DblookUp: Unknown database ssh.http
debug(14-JUL-2012 16:26:26.81): SshCertEdb/CMI-EDB.C:277: EDB: Adding database: ssh.http
debug(14-JUL-2012 16:26:26.81): Becoming server.
Sat 14 16:26:26 INFORMATIONAL: Starting image in auxiliary server mode.
Sat 14 16:26:26 ERROR: FATAL ERROR: Failed to create a socket. errno =  6
dsa200:[sys0.syscommon.][sysexe]tcpip$ssh_sshd2.exe[578815180]: FATAL: Failed to create a socket. errno =  6
%TCPIP-F-SSH_FATAL, non-specific fatal error condition

 
Honored Contributor
Steven Schweda
Posts: 9,089
Registered: ‎02-23-2005
Message 2 of 6 (1,061 Views)

Re: TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ...

Occasional Contributor
PeterPaul
Posts: 4
Registered: ‎06-20-2011
Message 3 of 6 (1,027 Views)

Re: TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ...

Hello Steven,

 

interactive means for me testing with SSH without the TCPIP Auxillary Service (UNIX:inetd). When I start sshd at CLI it starts SSH only in non-auxillary mode, offer one connection and stop the ssh listener after closing the session from client. In auxiliary server mode SSH stop immedeatly. For me is SSH a good choose for testing.  I think, that my TCPIP Kernel, TCPIP Auxillary Process configuration or my login process is the problem. But I have no really good idea how to check it.

 

Peter

 

Testing SSH Daemon with CLI

========================

RUMBA::SYSTEM>tcpip disa serv ssh

RUMBA::SYSTEM>set def SYS$SYSDEVICE:[TCPIP$SSH]

RUMBA::SYSTEM>define tcpip$ssh_server_debug TRUE

 

RUMBA::SYSTEM>define tcpip$ssh_server_params "-i -d 1"
%DCL-I-SUPERSEDE, previous value of TCPIP$SSH_SERVER_PARAMS has been superseded
RUMBA::SYSTEM>@TCPIP$SYSTEM:TCPIP$SSH_RUN.COM
debug(15-JUL-2012 13:19:39.06): Becoming server.
Sun 15 13:19:39 INFORMATIONAL: Starting image in auxiliary server mode.
Sun 15 13:19:39 ERROR: FATAL ERROR: Failed to create a socket. errno = 6
dsa200:[sys0.syscommon.][sysexe]tcpip$ssh_sshd2.exe[578815296]: FATAL: Failed to create a socket. errno = 6
%TCPIP-F-SSH_FATAL, non-specific fatal error condition

RUMBA::SYSTEM>

 

RUMBA::SYSTEM>define tcpip$ssh_server_params "-d 1"
%DCL-I-SUPERSEDE, previous value of TCPIP$SSH_SERVER_PARAMS has been superseded
RUMBA::SYSTEM>@TCPIP$SYSTEM:TCPIP$SSH_RUN.COM
dsa200:[sys0.syscommon.][sysexe]tcpip$ssh_sshd2.exe: SSH Secure Shell OpenVMS (V5.5) 3.2.0 on AlphaServer DS25 - VMS V8.3
debug(15-JUL-2012 13:19:49.68): Becoming server.
Sun 15 13:19:49 WARNING: Starting image in non-auxiliary server mode.
debug(15-JUL-2012 13:19:49.68): Creating listener
Sun 15 13:19:49 WARNING: ssh_tcp_make_ip4_listener: bind failed: address already in use , errno: 48, vaxc$errno: 148
debug(15-JUL-2012 13:19:49.68): Listener created
debug(15-JUL-2012 13:19:49.74): no udp listener created.
Sun 15 13:19:49 WARNING: Listener created on port 22.
debug(15-JUL-2012 13:19:49.74): Running event loop

 

waiting here for connection from SSH client

 

CTRL-C

 

RUMBA::SYSTEM>tcpip ena serv ssh

 

SSH -vvv localhost (TCPIP enabled service ssh)

=====================================

RUMBA::SYSTEM>ssh -vvv localhost

debug(15-JUL-2012 13:05:02.87): Connecting to localhost, port 22... (SOCKS not used)
debug(15-JUL-2012 13:05:02.87): Ssh2/SSH2.C:2881: Entering event loop.
debug(15-JUL-2012 13:05:03.00): Ssh2Client/SSHCLIENT.C:1609: Creating transport protocol.
debug(15-JUL-2012 13:05:03.00): SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "publickey" to usable methods.
debug(15-JUL-2012 13:05:03.00): SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "password" to usable methods.
debug(15-JUL-2012 13:05:03.00): Ssh2Client/SSHCLIENT.C:1650: Creating userauth protocol.
debug(15-JUL-2012 13:05:03.04): client supports 2 auth methods: 'publickey,password'
debug(15-JUL-2012 13:05:03.04): SshUnixTcp/SSHUNIXTCP.C:1750: using local hostname rumba.exp.bessy.de
debug(15-JUL-2012 13:05:03.04): Ssh2Common/SSHCOMMON.C:541: local ip = 127.0.0.1, local port = 49159
debug(15-JUL-2012 13:05:03.04): Ssh2Common/SSHCOMMON.C:543: remote ip = 127.0.0.1, remote port = 22
debug(15-JUL-2012 13:05:03.08): SshConnection/SSHCONN.C:2435: Wrapping...
debug(15-JUL-2012 13:05:03.08): SshReadLine/SSHREADLINE.C:3662: Initializing ReadLine...
debug(15-JUL-2012 13:05:03.08): Ssh2Common/SSHCOMMON.C:180: DISCONNECT received: Connection closed by remote host.
debug(15-JUL-2012 13:05:03.08): SshReadLine/SSHREADLINE.C:3728: Uninitializing ReadLine...
warning: Authentication failed.
debug(15-JUL-2012 13:05:03.16): Ssh2/SSH2.C:327: locally_generated = TRUE
Disconnected; connection lost (Connection closed by remote host.).

debug(15-JUL-2012 13:05:03.16): Ssh2Client/SSHCLIENT.C:1685: Destroying client.
debug(15-JUL-2012 13:05:03.16): SshConfig/SSHCONFIG.C:2862: Freeing pki. (host_pki != NULL, user_pki = NULL)
debug(15-JUL-2012 13:05:03.24): SshConnection/SSHCONN.C:2487: Destroying SshConn object.
debug(15-JUL-2012 13:05:03.24): Ssh2Client/SSHCLIENT.C:1753: Destroying client completed.
debug(15-JUL-2012 13:05:03.24): SshAuthMethodClient/SSHAUTHMETHODC.C:109: Destroying authentication method array.
debug(15-JUL-2012 13:05:03.49): SshAppCommon/SSHAPPCOMMON.C:326: Freeing global SshRegex context.
debug(15-JUL-2012 13:05:03.49): SshConfig/SSHCONFIG.C:2862: Freeing pki. (host_pki = NULL, user_pki = NULL)

RUMBA::SYSTEM>

Honored Contributor
Steven Schweda
Posts: 9,089
Registered: ‎02-23-2005
Message 4 of 6 (1,017 Views)

Re: TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ...

Trusted Contributor
Jeremy Begg
Posts: 383
Registered: ‎01-20-2005
Message 5 of 6 (907 Views)

Re: TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ...

Hi PP,

 

I ran into a very similar issue recently, and found that it was caused by the system-wide SYLOGIN procedure not being W:RE.

 

Your security alarms don't pick up file access failures.  Try

$ set audit/alarm/enable=file=fail=all

then attempt to restart (say) FTP.  If SYLOGIN protection is the problem, you will see a security audit OPCOM broadcast.

 

I have also found that quite a few of the directories for the TCP/IP auxilliary services are not always owned by their respective usernames.  For example, SYS$SYSDEVICE:[TCPIP$FTP] was not owned by TCPIP$FTP.  This seems to happen when systems with separate system disks are merged into a single cluster.  It would appear the TCP/IP Services installation hasn't always been consistent about using the same UICs for the same usernames :-(

 

Regards,

Jeremy Begg

Occasional Contributor
PeterPaul
Posts: 4
Registered: ‎06-20-2011
Message 6 of 6 (896 Views)

Re: TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ...

Hi Jeremy,

 

at OpenVMS system the loginout.exe image needs the W:RE file protection. After setting the right protection at my OpenVMS system TCPIP starts without any failure messages and Networker, CIFS and SSH  runs without any problems.

 

Regards,

 

 Peter

The opinions expressed above are the personal opinions of the authors, not of HP. By using this site, you accept the Terms of Use and Rules of Participation.