NX authentication error

Mon Jun 29 00:08:34 UTC 2009

On Mon, Jun 29, 2009 at 10:03 AM, L<yuanlux at gmail.com> wrote:
> I I set up a nxserver at remote PC (F10 2.6.27.25-170.2.72.fc10.i686),
> followed all steps, shipped key from server to client. tried login
> from client to sever as
>
>
> ssh -i /usr/NX/share/keys/user.id_dsa.key nx at server
> ssh -l USER1 server
>
> all work.
>
> when I login via nxclient, after pass steps Connected, download
> session, it failed with errors:
>
>
> NX> 203 NXSSH running with pid: 11935
> NX> 285 Enabling check on switch command
> NX> 285 Enabling skip of SSH config files
> NX> 285 Setting the preferred NX options
> NX> 200 Connected to address: xx.xx.xx.xx. on port: 22
> NX> 202 Authenticating user: nx
> NX> 208 Using auth method: publickey
> HELLO NXSERVER - Version 3.3.0-22 - LFE
> NX> 105 Hello NXCLIENT - Version 3.3.0
> NX> 134 Accepted protocol: 3.3.0
> NX> 105 Set shell_mode: shell
> NX> 105 Set auth_mode: password
> NX> 105 Login
> NX> 101 User: USER1
> NX> 102 Password: **********
> NX> 103 Welcome to: localhost.localdomain user: USER1
> NX> 105 Listsession --user="USER1" --status="suspended\054running"
> --geometry="1280x1024x24+render" --type="unix-application"
> NX> 127 Available sessions:
>
> Display Type             Session ID                       Options
> Depth Screen         Status      Session Name
> ------- ---------------- -------------------------------- --------
> ----- -------------- ----------- ------------------------------
>
> NX> 148 Server capacity: not reached for user: USER1
> NX> 105 Start session with: --rootless="1" --virtualdesktop="0"
> --application="xterm" --link="adsl" --backingstore="1"
> --encryption="1" --cache="16M" --images="64M" --shmem="1" --shpix="1"
> --strict="0" --composite="1" --media="0" --session="neau"
> --type="unix-application" --client="linux" --keyboard="pc105\057us"
> --screeninfo="1280x1024x24+render"
> NX> 502 ERROR: Public key authentication failed
> NX> 502 ERROR: NX server was unable to login as user: USER1
> NX> 502 ERROR: Please check that the account is enabled to login,
> NX> 502 ERROR: the user's home directory, the directory ~/.ssh
> NX> 502 ERROR: and the file ~/.ssh/authorized_keys2 have correct
> NX> 502 ERROR: permissions setting according to the StrictModes
> NX> 502 ERROR: of your SSHD configuration.
> NX> 999 Bye.
> NX> 280 Exiting on signal: 15
>
> where is the problem?
>
> thanks
>
> Y

addition info
[localhost|08:04:43|~]sudo /usr/NX/bin/nxserver --userauth USER1
NX> 139 NX user DB is: off NX password DB is: off.
NX> 139 Authentication for user: USER1 is: system.
NX> 999 Bye.

[localhost|08:04:55|~]sudo /usr/NX/bin/nxserver --usercheck USER1
NX> 900 Verifying public key authentication for NX user: USER1.
NX> 900 Public key authentication succeeded.
NX> 999 Bye.

>
> below is sshd message ai DEBUG2 level
> Jun 29 07:44:37 localhost sshd[25855]: Accepted publickey for nx from
> xx.xx.xx.xx port 51390 ssh2
> Jun 29 07:44:37 localhost sshd[25855]: debug1: monitor_child_preauth:
> nx has been authenticated by privileged process
> Jun 29 07:44:37 localhost sshd[25855]: debug2: mac_setup: found hmac-md5
> Jun 29 07:44:37 localhost sshd[25855]: debug2: mac_setup: found hmac-md5
> Jun 29 07:44:37 localhost sshd[25855]: debug1: temporarily_use_uid:
> 489/483 (e=0/0)
> Jun 29 07:44:37 localhost sshd[25855]: debug1: ssh_gssapi_storecreds:
> Not a GSSAPI mechanism
> Jun 29 07:44:37 localhost sshd[25855]: debug1: restore_uid: 0/0
> Jun 29 07:44:37 localhost sshd[25855]: debug1: SELinux support disabled
> Jun 29 07:44:37 localhost sshd[25855]: debug1: PAM: establishing credentials
> Jun 29 07:44:37 localhost sshd[25855]: pam_unix(sshd:session): session
> opened for user nx by (uid=0)
> Jun 29 07:44:37 localhost sshd[25858]: debug1: PAM: establishing credentials
> Jun 29 07:44:37 localhost sshd[25855]: User child is on pid 25858
> Jun 29 07:44:38 localhost sshd[25858]: debug1: permanently_set_uid: 489/483
> Jun 29 07:44:38 localhost sshd[25858]: debug2: set_newkeys: mode 0
> Jun 29 07:44:38 localhost sshd[25858]: debug2: set_newkeys: mode 1
> Jun 29 07:44:38 localhost sshd[25858]: debug1: Entering interactive
> session for SSH2.
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 4 setting O_NONBLOCK
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 6 setting O_NONBLOCK
> Jun 29 07:44:38 localhost sshd[25858]: debug1: server_init_dispatch_20
> Jun 29 07:44:38 localhost sshd[25858]: debug1:
> server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
> Jun 29 07:44:38 localhost sshd[25858]: debug1: input_session_request
> Jun 29 07:44:38 localhost sshd[25858]: debug1: channel 0: new [server-session]
> Jun 29 07:44:38 localhost sshd[25858]: debug2: session_new: allocate
> (allocated 0 max 10)
> Jun 29 07:44:38 localhost sshd[25858]: debug1: session_new: session 0
> Jun 29 07:44:38 localhost sshd[25858]: debug1: session_open: channel 0
> Jun 29 07:44:38 localhost sshd[25858]: debug1: session_open: session
> 0: link with channel 0
> Jun 29 07:44:38 localhost sshd[25858]: debug1:
> server_input_channel_open: confirm session
> Jun 29 07:44:38 localhost sshd[25858]: debug1:
> server_input_channel_req: channel 0 request x11-req reply 0
> Jun 29 07:44:38 localhost sshd[25858]: debug1: session_by_channel:
> session 0 channel 0
> Jun 29 07:44:38 localhost sshd[25858]: debug1:
> session_input_channel_req: session 0 req x11-req
> Jun 29 07:44:38 localhost sshd[25858]: debug2: bind port 6010: Address
> already in use
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 7 setting O_NONBLOCK
> Jun 29 07:44:38 localhost sshd[25858]: debug1: channel 1: new [X11
> inet listener]
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 8 setting O_NONBLOCK
> Jun 29 07:44:38 localhost sshd[25858]: debug1: channel 2: new [X11
> inet listener]
> Jun 29 07:44:38 localhost sshd[25858]: debug1:
> server_input_channel_req: channel 0 request shell reply 0
> Jun 29 07:44:38 localhost sshd[25858]: debug1: session_by_channel:
> session 0 channel 0
> Jun 29 07:44:38 localhost sshd[25858]: debug1:
> session_input_channel_req: session 0 req shell
> Jun 29 07:44:38 localhost sshd[25858]: debug1: Forced command (key
> option) '/usr/NX/bin/nxserver --login'
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 3 setting TCP_NODELAY
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 11 setting O_NONBLOCK
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 10 setting O_NONBLOCK
> Jun 29 07:44:38 localhost sshd[25858]: debug2: fd 13 setting O_NONBLOCK
> Jun 29 07:44:39 localhost sshd[25901]: debug1: rexec start in 5 out 5
> newsock 5 pipe 7 sock 8
> Jun 29 07:44:39 localhost sshd[25852]: debug1: Forked child 25901.
> Jun 29 07:44:39 localhost sshd[25901]: debug1: inetd sockets after dupping: 3, 3
> Jun 29 07:44:39 localhost sshd[25901]: Connection from 127.0.0.1 port 60512
> Jun 29 07:44:39 localhost sshd[25901]: debug1: Client protocol version
> 2.0; client software version OpenSSH_4.7
> Jun 29 07:44:39 localhost sshd[25901]: debug1: match: OpenSSH_4.7 pat OpenSSH_4*
> Jun 29 07:44:39 localhost sshd[25901]: debug1: Enabling compatibility
> mode for protocol 2.0
> Jun 29 07:44:39 localhost sshd[25901]: debug1: Local version string
> SSH-2.0-OpenSSH_5.1
> Jun 29 07:44:39 localhost sshd[25901]: debug2: fd 3 setting O_NONBLOCK
> Jun 29 07:44:39 localhost sshd[25901]: debug2: Network child is on pid 25902
> Jun 29 07:44:39 localhost sshd[25902]: debug1: permanently_set_uid: 74/74
> Jun 29 07:44:39 localhost sshd[25902]: debug1: list_hostkey_types:
> ssh-rsa,ssh-dss
> Jun 29 07:44:39 localhost sshd[25902]: debug1: SSH2_MSG_KEXINIT sent
> Jun 29 07:44:39 localhost sshd[25902]: debug1: SSH2_MSG_KEXINIT received
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> ssh-rsa,ssh-dss
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> none,zlib at openssh.com
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> none,zlib at openssh.com
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> first_kex_follows 0
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit: reserved 0
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> ssh-rsa,ssh-dss
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> hmac-md5,hmac-sha1,umac-64 at openssh.com,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> none,zlib at openssh.com,zlib
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> none,zlib at openssh.com,zlib
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit:
> first_kex_follows 0
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_parse_kexinit: reserved 0
> Jun 29 07:44:39 localhost sshd[25902]: debug2: mac_setup: found hmac-md5
> Jun 29 07:44:39 localhost sshd[25902]: debug1: kex: client->server
> aes128-cbc hmac-md5 none
> Jun 29 07:44:39 localhost sshd[25902]: debug2: mac_setup: found hmac-md5
> Jun 29 07:44:39 localhost sshd[25902]: debug1: kex: server->client
> aes128-cbc hmac-md5 none
> Jun 29 07:44:39 localhost sshd[25902]: debug1:
> SSH2_MSG_KEX_DH_GEX_REQUEST received
> Jun 29 07:44:39 localhost sshd[25902]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
> Jun 29 07:44:39 localhost sshd[25902]: debug2: dh_gen_key: priv key
> bits set: 119/256
> Jun 29 07:44:39 localhost sshd[25902]: debug2: bits set: 501/1024
> Jun 29 07:44:39 localhost sshd[25902]: debug1: expecting
> SSH2_MSG_KEX_DH_GEX_INIT
> Jun 29 07:44:39 localhost sshd[25901]: debug2: monitor_read: 0 used
> once, disabling now
> Jun 29 07:44:39 localhost sshd[25902]: debug2: bits set: 511/1024
> Jun 29 07:44:39 localhost sshd[25902]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
> Jun 29 07:44:39 localhost sshd[25901]: debug2: monitor_read: 5 used
> once, disabling now
> Jun 29 07:44:39 localhost sshd[25902]: debug2: kex_derive_keys
> Jun 29 07:44:39 localhost sshd[25902]: debug2: set_newkeys: mode 1
> Jun 29 07:44:39 localhost sshd[25902]: debug1: SSH2_MSG_NEWKEYS sent
> Jun 29 07:44:39 localhost sshd[25902]: debug1: expecting SSH2_MSG_NEWKEYS
> Jun 29 07:44:39 localhost sshd[25902]: debug2: set_newkeys: mode 0
> Jun 29 07:44:39 localhost sshd[25902]: debug1: SSH2_MSG_NEWKEYS received
> Jun 29 07:44:39 localhost sshd[25902]: debug1: KEX done
> Jun 29 07:44:39 localhost sshd[25902]: debug1: userauth-request for
> user USER1 service ssh-connection method none
> Jun 29 07:44:39 localhost sshd[25902]: debug1: attempt 0 failures 0
> Jun 29 07:44:39 localhost sshd[25901]: debug2: parse_server_config:
> config reprocess config len 696
> Jun 29 07:44:39 localhost sshd[25901]: debug2: monitor_read: 7 used
> once, disabling now
> Jun 29 07:44:39 localhost sshd[25902]: debug2: input_userauth_request:
> setting up authctxt for USER1
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: initializing for "USER1"
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: setting PAM_RHOST
> to "localhost.localdomain"
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: setting PAM_TTY to "ssh"
> Jun 29 07:44:39 localhost sshd[25901]: debug2: monitor_read: 46 used
> once, disabling now
> Jun 29 07:44:39 localhost sshd[25902]: debug2: input_userauth_request:
> try method none
> Jun 29 07:44:39 localhost sshd[25901]: debug2: monitor_read: 3 used
> once, disabling now
> Jun 29 07:44:39 localhost sshd[25901]: debug2: monitor_read: 4 used
> once, disabling now
> Jun 29 07:44:39 localhost sshd[25902]: debug1: userauth-request for
> user USER1 service ssh-connection method password
> Jun 29 07:44:39 localhost sshd[25902]: debug1: attempt 1 failures 0
> Jun 29 07:44:39 localhost sshd[25902]: debug2: input_userauth_request:
> try method password
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: password
> authentication accepted for USER1
> Jun 29 07:44:39 localhost sshd[25901]: debug1: do_pam_account: called
> Jun 29 07:44:39 localhost sshd[25901]: Accepted password for USER1
> from 127.0.0.1 port 60512 ssh2
> Jun 29 07:44:39 localhost sshd[25901]: debug1: monitor_child_preauth:
> USER1 has been authenticated by privileged process
> Jun 29 07:44:39 localhost sshd[25901]: debug2: mac_setup: found hmac-md5
> Jun 29 07:44:39 localhost sshd[25901]: debug2: mac_setup: found hmac-md5
> Jun 29 07:44:39 localhost sshd[25901]: debug1: temporarily_use_uid:
> 503/504 (e=0/0)
> Jun 29 07:44:39 localhost sshd[25901]: debug1: ssh_gssapi_storecreds:
> Not a GSSAPI mechanism
> Jun 29 07:44:39 localhost sshd[25901]: debug1: restore_uid: 0/0
> Jun 29 07:44:39 localhost sshd[25901]: debug1: SELinux support disabled
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: establishing credentials
> Jun 29 07:44:39 localhost sshd[25901]: pam_unix(sshd:session): session
> opened for user USER1 by (uid=0)
> Jun 29 07:44:39 localhost sshd[25901]: User child is on pid 25903
> Jun 29 07:44:39 localhost sshd[25903]: debug1: PAM: establishing credentials
> Jun 29 07:44:39 localhost sshd[25903]: debug1: permanently_set_uid: 503/504
> Jun 29 07:44:39 localhost sshd[25903]: debug2: set_newkeys: mode 0
> Jun 29 07:44:39 localhost sshd[25903]: debug2: set_newkeys: mode 1
> Jun 29 07:44:39 localhost sshd[25903]: debug1: Entering interactive
> session for SSH2.
> Jun 29 07:44:39 localhost sshd[25903]: debug2: fd 4 setting O_NONBLOCK
> Jun 29 07:44:39 localhost sshd[25903]: debug2: fd 6 setting O_NONBLOCK
> Jun 29 07:44:39 localhost sshd[25903]: debug1: server_init_dispatch_20
> Jun 29 07:44:39 localhost sshd[25903]: Connection closed by 127.0.0.1
> Jun 29 07:44:39 localhost sshd[25903]: debug1: do_cleanup
> Jun 29 07:44:39 localhost sshd[25903]: Transferred: sent 1768,
> received 1184 bytes
> Jun 29 07:44:39 localhost sshd[25903]: Closing connection to 127.0.0.1
> port 60512
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: cleanup
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: deleting credentials
> Jun 29 07:44:39 localhost sshd[25901]: debug1: PAM: closing session
> Jun 29 07:44:39 localhost sshd[25901]: pam_unix(sshd:session): session
> closed for user USER1
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: read<=0 rfd 11 len 0
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: read failed
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: close_read
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: input open -> drain
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: ibuf_empty
> delayed efd 13/(0)
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: read 0 from efd 13
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: closing read-efd 13
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: ibuf empty
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: send eof
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: input drain -> closed
> Jun 29 07:44:41 localhost sshd[25858]: debug1: Received SIGCHLD.
> Jun 29 07:44:41 localhost sshd[25858]: debug1: session_by_pid: pid 25859
> Jun 29 07:44:41 localhost sshd[25858]: debug1: session_exit_message:
> session 0 channel 0 pid 25859
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: request
> exit-status confirm 0
> Jun 29 07:44:41 localhost sshd[25858]: debug1: session_exit_message:
> release channel 0
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: write failed
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: close_write
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: send eow
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: output open -> closed
> Jun 29 07:44:41 localhost sshd[25858]: debug2: channel 0: send close
> Jun 29 07:44:41 localhost sshd[25858]: debug2: notify_done: reading
> Jun 29 07:44:41 localhost sshd[25858]: Connection closed by xx.xx.xx.xx
> Jun 29 07:44:41 localhost sshd[25858]: debug1: channel 0: free:
> server-session, nchannels 3
> Jun 29 07:44:41 localhost sshd[25858]: debug1: channel 1: free: X11
> inet listener, nchannels 2
> Jun 29 07:44:41 localhost sshd[25858]: debug1: channel 2: free: X11
> inet listener, nchannels 1
> Jun 29 07:44:41 localhost sshd[25858]: debug1: session_close: session 0 pid 0
> Jun 29 07:44:41 localhost sshd[25858]: debug1: do_cleanup
> Jun 29 07:44:41 localhost sshd[25858]: Transferred: sent 3832,
> received 2496 bytes
> Jun 29 07:44:41 localhost sshd[25858]: Closing connection to
> xx.xx.xx.xx port 51390
> Jun 29 07:44:41 localhost sshd[25855]: debug1: PAM: cleanup
> Jun 29 07:44:41 localhost sshd[25855]: debug1: PAM: deleting credentials
> Jun 29 07:44:42 localhost sshd[25855]: debug1: PAM: closing session
> Jun 29 07:44:42 localhost sshd[25855]: pam_unix(sshd:session): session
> closed for user nx
>