topic TCPIP Startup OPCOM Messages: Error during process startup, Nolisten Service ... in Operating System - OpenVMS

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

PeterPaul — Sat, 14 Jul 2012 20:59:06 GMT

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

Logfailure: batch,dialup,local,remote,network,subprocess,detached

System security audits currently enabled for:

ACL

Authorization

Audit: illformed

Breakin: dialup,local,remote,network,detached

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 = 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 = 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 = 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: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

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

Steven Schweda — Sun, 15 Jul 2012 01:13:47 GMT

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

PeterPaul — Sun, 15 Jul 2012 11:33:50 GMT

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>

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

Steven Schweda — Sun, 15 Jul 2012 12:20:49 GMT

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

Jeremy Begg — Wed, 18 Jul 2012 02:41:32 GMT

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

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

PeterPaul — Wed, 18 Jul 2012 08:01:21 GMT

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