Having an issue with NX 3.5.0 and SSH during user authentication phase (time out)

Question

SuSE SLES 11 SP3 Intel P4

I've installed NX 3.5.0 from NoMachines on my home server which has been working quite well until recently when I change the Domain Name for my server through my registrar which inadvertently broke authentication on the system by invalidating the SSL Cert for openLDAP. I have a openLDAP setup as my back-end for Linux authentications. I have disabled SSL both for openLDAP server and LDAP client libraries as all connections will be local and avoid the overhead. Now I authenticate quite well now. Although that resolve that particular problem, I continue to having an issue with NX Client authenticating, I keep getting this error:

NX> 500 ERROR: Operation timeout in communication with SSH server

On further investigation, server logs indicate:

Sep 14 05:07:43 home NXSERVER-3.5.0-11[27342]: ERROR: reached timeout of 20s while trying SSHd authentication for user '*************', to '127.0.0.1', port '22' 'NXNssUserManager::auth'

Steps taken attempting to resolve this issue. I went thought NoMachine documentation and I could not discover any information regarding how to increase the timeout value. Alternatively. I decided that I should try to shorten SSH login delay. This is basically were I am stuck for the past few days, during some test:

OpenSSH_6.2p2, OpenSSL 0.9.8j-fips 07 Jan 2009
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 20: Applying options for *
debug1: Connecting to localhost [::1] port 22.
debug1: Connection established.
debug1: identity file /home/***********/.ssh/id_rsa type -1
debug1: identity file /home/***********/.ssh/id_rsa-cert type -1
debug1: identity file /home/***********/.ssh/id_dsa type -1
debug1: identity file /home/***********/.ssh/id_dsa-cert type -1
debug1: identity file /home/***********/.ssh/id_ecdsa type -1
debug1: identity file /home/***********/.ssh/id_ecdsa-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.2
debug1: Remote protocol version 2.0, remote software version OpenSSH_6.2
debug1: match: OpenSSH_6.2 pat OpenSSH*
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr [e-mail] none
debug1: kex: client->server aes128-ctr [e-mail] none
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA 46:0f:51:88:c1:55:6f:c0:15:9e:5c:08:57:cc:5a:d9 [MD5]
debug1: Host 'localhost' is known and matches the ECDSA host key.
debug1: Found key in /home/lutchy.horace/.ssh/known_hosts:1
debug1: ssh_ecdsa_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,keyboard-interactive
debug1: Next authentication method: publickey
debug1: Trying private key: /home/***********/.ssh/id_rsa
debug1: Trying private key: /home/***********/.ssh/id_dsa
debug1: Trying private key: /home/***********/.ssh/id_ecdsa
debug1: Next authentication method: keyboard-interactive
....

There is a 20 second delay for the server to respond with a prompt. One the server side:

Sep 14 05:29:14 home sshd[27452]: debug1: userauth-request for user ******** service ssh-connection method keyboard-interactive [preauth]
Sep 14 05:29:14 home sshd[27452]: debug1: attempt 1 failures 0 [preauth]
Sep 14 05:29:14 home sshd[27452]: debug2: input_userauth_request: try method keyboard-interactive [preauth]
Sep 14 05:29:14 home sshd[27452]: debug1: keyboard-interactive devs  [preauth]
Sep 14 05:29:14 home sshd[27452]: debug1: auth2_challenge: user=******** devs= [preauth]
Sep 14 05:29:14 home sshd[27452]: debug1: kbdint_alloc: devices 'pam' [preauth]
Sep 14 05:29:14 home sshd[27452]: debug2: auth2_challenge_start: devices pam [preauth]
Sep 14 05:29:14 home sshd[27452]: debug2: kbdint_next_device: devices <empty> [preauth]
Sep 14 05:29:14 home sshd[27452]: debug1: auth2_challenge_start: trying authentication method 'pam' [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_sshpam_init_ctx [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_send entering: type 104 [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_sshpam_init_ctx: waiting for MONITOR_ANS_PAM_INIT_CTX [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_receive_expect entering: type 105 [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_receive entering [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_receive entering
Sep 14 05:29:14 home sshd[27452]: debug3: monitor_read: checking request 104
Sep 14 05:29:14 home sshd[27452]: debug3: mm_answer_pam_init_ctx
Sep 14 05:29:14 home sshd[27452]: debug3: PAM: sshpam_init_ctx entering
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_send entering: type 105
Sep 14 05:29:14 home sshd[27452]: debug3: mm_sshpam_query [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_send entering: type 106 [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_sshpam_query: waiting for MONITOR_ANS_PAM_QUERY [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_receive_expect entering: type 107 [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_receive entering [preauth]
Sep 14 05:29:14 home sshd[27452]: debug3: mm_request_receive entering
Sep 14 05:29:14 home sshd[27452]: debug3: monitor_read: checking request 106
Sep 14 05:29:14 home sshd[27452]: debug3: mm_answer_pam_query
Sep 14 05:29:14 home sshd[27452]: debug3: PAM: sshpam_query entering
Sep 14 05:29:14 home sshd[27452]: debug3: ssh_msg_recv entering
...

20 second delay:

Sep 14 05:29:34 home sshd[27454]: debug3: PAM: sshpam_thread_conv entering, 1 messages
Sep 14 05:29:34 home sshd[27454]: debug3: ssh_msg_send: type 1
Sep 14 05:29:34 home sshd[27454]: debug3: ssh_msg_recv entering
Sep 14 05:29:34 home sshd[27452]: debug3: mm_request_send entering: type 107
Sep 14 05:29:34 home sshd[27452]: debug3: mm_sshpam_query: pam_query returned 0 [preauth]
Sep 14 05:29:34 home sshd[27452]: Postponed keyboard-interactive for ********* from ::1 port 55653 ssh2 [preauth].

I've already followed common threads for SSH Login delays, none have provided any solutions to rectify the problem. I can only deduced that SSH is probably waiting for a response from PAM (PAM: sshpam_thread_conv)? NSCD is running and is caching passwd. For the life me, I can't tell well the delay might be in terms of PAM and pam_ldap.so. Any assistance would be helpful.

P.S. I don't have any complicated PAM setup, 'pam_unix then pam_ldap'

Answer 1

Luckily, after several hours of toying with this issues I was able to resolve this nasty problem. It appears that the hostname of the system is intertwined into everything you do in Linux and it appears prior to the ldap client libraries connecting to the server, it does a forward lookup on the server hostname.

I did some TCPDUMP and it looks like the DNS server was returning a Format error because the query string was invalid. It looks like Linux doesn't play nice with hostnames with several sub domains, ie home.s2.lhprojects.net, instead is was doing a forward lookup on home. lhprojects.net An odd behavior but I am sure there is a really good reason for that.

Simply adding 127.0.0.1 home.s2.lhprojects.net to /etc/hosts solved it. Thanks anyway all.