[FreeNX-kNX] Authetication failure and nothing helped so far

Thomas Pfrommer pfrommer at phas.ubc.ca
Sat Apr 21 04:35:06 UTC 2007 

Hi again,
OK took me a while to figure it out but here it is the sshd log (its 
quite a bit ... is this normal?), while trying to log on with ssh 
nx at host and LogLevel DEBUG3 as suggested by Rick Stout:

Apr 20 22:19:30 localhost sshd[5406]: debug3: fd 4 is not O_NONBLOCK
Apr 20 22:19:30 localhost sshd[5406]: debug1: Forked child 5466.
Apr 20 22:19:30 localhost sshd[5406]: debug3: send_rexec_state: entering 
fd = 7 config len 623
Apr 20 22:19:30 localhost sshd[5406]: debug3: ssh_msg_send: type 0
Apr 20 22:19:30 localhost sshd[5406]: debug3: send_rexec_state: done
Apr 20 22:19:30 localhost sshd[5466]: debug1: rexec start in 4 out 4 
newsock 4 pipe 6 sock 7
Apr 20 22:19:30 localhost sshd[5466]: debug1: inetd sockets after 
dupping: 3, 3
Apr 20 22:19:30 localhost sshd[5466]: Connection from 154.20.41.180 port 
63242
Apr 20 22:19:30 localhost sshd[5466]: debug1: Client protocol version 
2.0; client software version OpenSSH_4.5
Apr 20 22:19:30 localhost sshd[5466]: debug1: match: OpenSSH_4.5 pat 
OpenSSH*
Apr 20 22:19:30 localhost sshd[5466]: debug1: Enabling compatibility 
mode for protocol 2.0
Apr 20 22:19:30 localhost sshd[5466]: debug1: Local version string 
SSH-2.0-OpenSSH_4.3
Apr 20 22:19:30 localhost sshd[5466]: debug2: fd 3 setting O_NONBLOCK
Apr 20 22:19:30 localhost sshd[5469]: debug3: privsep user:group 74:74
Apr 20 22:19:30 localhost sshd[5469]: debug1: permanently_set_uid: 74/74
Apr 20 22:19:30 localhost sshd[5469]: debug1: list_hostkey_types: 
ssh-rsa,ssh-dss
Apr 20 22:19:30 localhost sshd[5466]: debug2: Network child is on pid 5469
Apr 20 22:19:30 localhost sshd[5469]: debug1: SSH2_MSG_KEXINIT sent
Apr 20 22:19:30 localhost sshd[5466]: debug3: preauth child monitor started
Apr 20 22:19:30 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:30 localhost sshd[5469]: debug1: SSH2_MSG_KEXINIT received
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
ssh-rsa,ssh-dss
Apr 20 22:19:30 localhost sshd[5469]: 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
Apr 20 22:19:30 localhost sshd[5469]: 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
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
none,zlib at openssh.com
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
none,zlib at openssh.com
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit:
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit:
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
first_kex_follows 0
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: reserved 0
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
ssh-rsa,ssh-dss
Apr 20 22:19:30 localhost sshd[5469]: 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
Apr 20 22:19:30 localhost sshd[5469]: 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
Apr 20 22:19:30 localhost sshd[5469]: debug2: kex_parse_kexinit: 
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
Apr 20 22:19:31 localhost sshd[5469]: debug2: kex_parse_kexinit: 
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
Apr 20 22:19:31 localhost sshd[5469]: debug2: kex_parse_kexinit: 
none,zlib at openssh.com,zlib
Apr 20 22:19:31 localhost sshd[5469]: debug2: kex_parse_kexinit: 
none,zlib at openssh.com,zlib
Apr 20 22:19:31 localhost sshd[5469]: debug2: kex_parse_kexinit:
Apr 20 22:19:31 localhost sshd[5469]: debug2: kex_parse_kexinit:
Apr 20 22:19:31 localhost sshd[5469]: debug2: kex_parse_kexinit: 
first_kex_follows 0
Apr 20 22:19:31 localhost sshd[5469]: debug2: kex_parse_kexinit: reserved 0
Apr 20 22:19:31 localhost sshd[5469]: debug2: mac_init: found hmac-md5
Apr 20 22:19:31 localhost sshd[5469]: debug1: kex: client->server 
aes128-cbc hmac-md5 none
Apr 20 22:19:31 localhost sshd[5469]: debug2: mac_init: found hmac-md5
Apr 20 22:19:31 localhost sshd[5469]: debug1: kex: server->client 
aes128-cbc hmac-md5 none
Apr 20 22:19:31 localhost sshd[5469]: debug1: 
SSH2_MSG_KEX_DH_GEX_REQUEST received
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_request_send entering: 
type 0
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_choose_dh: waiting for 
MONITOR_ANS_MODULI
Apr 20 22:19:31 localhost sshd[5466]: debug3: monitor_read: checking 
request 0
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_request_receive_expect 
entering: type 1
Apr 20 22:19:31 localhost sshd[5466]: debug3: mm_answer_moduli: got 
parameters: 1024 1024 8192
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_request_receive entering
Apr 20 22:19:31 localhost sshd[5466]: debug3: mm_request_send entering: 
type 1
Apr 20 22:19:31 localhost sshd[5466]: debug2: monitor_read: 0 used once, 
disabling now
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_choose_dh: remaining 0
Apr 20 22:19:31 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:31 localhost sshd[5469]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
Apr 20 22:19:31 localhost sshd[5469]: debug2: dh_gen_key: priv key bits 
set: 138/256
Apr 20 22:19:31 localhost sshd[5469]: debug2: bits set: 500/1024
Apr 20 22:19:31 localhost sshd[5469]: debug1: expecting 
SSH2_MSG_KEX_DH_GEX_INIT
Apr 20 22:19:31 localhost sshd[5469]: debug2: bits set: 515/1024
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_key_sign entering
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_request_send entering: 
type 5
Apr 20 22:19:31 localhost sshd[5469]: debug3: mm_key_sign: waiting for 
MONITOR_ANS_SIGN
Apr 20 22:19:31 localhost sshd[5466]: debug3: monitor_read: checking 
request 5
Apr 20 22:19:32 localhost sshd[5469]: debug3: mm_request_receive_expect 
entering: type 6
Apr 20 22:19:32 localhost sshd[5466]: debug3: mm_answer_sign
Apr 20 22:19:32 localhost sshd[5469]: debug3: mm_request_receive entering
Apr 20 22:19:32 localhost sshd[5466]: debug3: mm_answer_sign: signature 
0x806450d8(271)
Apr 20 22:19:32 localhost sshd[5466]: debug3: mm_request_send entering: 
type 6
Apr 20 22:19:32 localhost sshd[5466]: debug2: monitor_read: 5 used once, 
disabling now
Apr 20 22:19:32 localhost sshd[5469]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
Apr 20 22:19:32 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:32 localhost sshd[5469]: debug2: kex_derive_keys
Apr 20 22:19:32 localhost sshd[5469]: debug2: set_newkeys: mode 1
Apr 20 22:19:32 localhost sshd[5469]: debug1: SSH2_MSG_NEWKEYS sent
Apr 20 22:19:32 localhost sshd[5469]: debug1: expecting SSH2_MSG_NEWKEYS
Apr 20 22:19:32 localhost sshd[5469]: debug2: set_newkeys: mode 0
Apr 20 22:19:32 localhost sshd[5469]: debug1: SSH2_MSG_NEWKEYS received
Apr 20 22:19:32 localhost sshd[5469]: debug1: KEX done
Apr 20 22:19:32 localhost sshd[5469]: debug1: userauth-request for user 
nx service ssh-connection method none
Apr 20 22:19:32 localhost sshd[5469]: debug1: attempt 0 failures 0
Apr 20 22:19:32 localhost sshd[5469]: debug3: mm_getpwnamallow entering
Apr 20 22:19:32 localhost sshd[5469]: debug3: mm_request_send entering: 
type 7
Apr 20 22:19:32 localhost sshd[5469]: debug3: mm_getpwnamallow: waiting 
for MONITOR_ANS_PWNAM
Apr 20 22:19:32 localhost sshd[5466]: debug3: monitor_read: checking 
request 7
Apr 20 22:19:32 localhost sshd[5469]: debug3: mm_request_receive_expect 
entering: type 8
Apr 20 22:19:32 localhost sshd[5466]: debug3: mm_answer_pwnamallow
Apr 20 22:19:32 localhost sshd[5469]: debug3: mm_request_receive entering
Apr 20 22:19:32 localhost sshd[5466]: debug3: mm_answer_pwnamallow: 
sending MONITOR_ANS_PWNAM: 1
Apr 20 22:19:32 localhost sshd[5466]: debug3: mm_request_send entering: 
type 8
Apr 20 22:19:32 localhost sshd[5466]: debug2: monitor_read: 7 used once, 
disabling now
Apr 20 22:19:32 localhost sshd[5469]: debug2: input_userauth_request: 
setting up authctxt for nx
Apr 20 22:19:33 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_start_pam entering
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_request_send entering: 
type 46
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_inform_authserv entering
Apr 20 22:19:33 localhost sshd[5466]: debug3: monitor_read: checking 
request 46
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_request_send entering: 
type 3
Apr 20 22:19:33 localhost sshd[5466]: debug1: PAM: initializing for "nx"
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_inform_authrole entering
Apr 20 22:19:33 localhost sshd[5466]: debug3: Trying to reverse map 
address 154.20.41.180.
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_request_send entering: 
type 4
Apr 20 22:19:33 localhost sshd[5469]: debug2: input_userauth_request: 
try method none
Apr 20 22:19:33 localhost sshd[5469]: debug1: userauth-request for user 
nx service ssh-connection method publickey
Apr 20 22:19:33 localhost sshd[5469]: debug1: attempt 1 failures 1
Apr 20 22:19:33 localhost sshd[5469]: debug2: input_userauth_request: 
try method publickey
Apr 20 22:19:33 localhost sshd[5469]: debug1: test whether pkalg/pkblob 
are acceptable
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_key_allowed entering
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_request_send entering: 
type 21
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_key_allowed: waiting 
for MONITOR_ANS_KEYALLOWED
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_request_receive_expect 
entering: type 22
Apr 20 22:19:33 localhost sshd[5469]: debug3: mm_request_receive entering
Apr 20 22:19:43 localhost sshd[5466]: debug1: PAM: setting PAM_RHOST to 
"d154-20-41-180.bchsia.telus.net"
Apr 20 22:19:43 localhost sshd[5466]: debug1: PAM: setting PAM_TTY to "ssh"
Apr 20 22:19:43 localhost sshd[5466]: debug2: monitor_read: 46 used 
once, disabling now
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:43 localhost sshd[5466]: debug3: monitor_read: checking 
request 3
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_answer_authserv: 
service=ssh-connection, style=
Apr 20 22:19:43 localhost sshd[5466]: debug2: monitor_read: 3 used once, 
disabling now
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:43 localhost sshd[5466]: debug3: monitor_read: checking 
request 4
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_answer_authrole: role=
Apr 20 22:19:43 localhost sshd[5466]: debug2: monitor_read: 4 used once, 
disabling now
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:43 localhost sshd[5466]: debug3: monitor_read: checking 
request 21
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_answer_keyallowed entering
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_answer_keyallowed: 
key_from_blob: 0x8064b2b8
Apr 20 22:19:43 localhost sshd[5466]: debug1: temporarily_use_uid: 
501/501 (e=0/0)
Apr 20 22:19:43 localhost sshd[5466]: debug1: trying public key file 
/usr/NX/home/nx/home/lobs/.ssh/authorized_keys2
Apr 20 22:19:43 localhost sshd[5466]: debug1: restore_uid: 0/0
Apr 20 22:19:43 localhost sshd[5466]: debug1: temporarily_use_uid: 
501/501 (e=0/0)
Apr 20 22:19:43 localhost sshd[5466]: debug1: trying public key file 
/usr/NX/home/nx/home/lobs/.ssh/authorized_keys2
Apr 20 22:19:43 localhost sshd[5466]: debug1: restore_uid: 0/0
Apr 20 22:19:43 localhost sshd[5466]: Failed publickey for nx from 
154.20.41.180 port 63242 ssh2
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_answer_keyallowed: key 
0x8064b2b8 is disallowed
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_request_send entering: 
type 22
Apr 20 22:19:43 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:43 localhost sshd[5469]: debug2: userauth_pubkey: 
authenticated 0 pkalg ssh-rsa
Apr 20 22:19:43 localhost sshd[5469]: debug1: userauth-request for user 
nx service ssh-connection method publickey
Apr 20 22:19:43 localhost sshd[5469]: debug1: attempt 2 failures 2
Apr 20 22:19:43 localhost sshd[5469]: debug2: input_userauth_request: 
try method publickey
Apr 20 22:19:43 localhost sshd[5469]: debug3: mm_key_allowed entering
Apr 20 22:19:43 localhost sshd[5469]: debug3: mm_request_send entering: 
type 21
Apr 20 22:19:44 localhost sshd[5469]: debug3: mm_key_allowed: waiting 
for MONITOR_ANS_KEYALLOWED
Apr 20 22:19:44 localhost sshd[5466]: debug3: monitor_read: checking 
request 21
Apr 20 22:19:44 localhost sshd[5469]: debug3: mm_request_receive_expect 
entering: type 22
Apr 20 22:19:44 localhost sshd[5466]: debug3: mm_answer_keyallowed entering
Apr 20 22:19:44 localhost sshd[5469]: debug3: mm_request_receive entering
Apr 20 22:19:44 localhost sshd[5466]: debug3: mm_answer_keyallowed: 
key_from_blob: 0x8064b5c8
Apr 20 22:19:44 localhost sshd[5466]: debug1: temporarily_use_uid: 
501/501 (e=0/0)
Apr 20 22:19:44 localhost sshd[5466]: debug1: trying public key file 
/usr/NX/home/nx/home/lobs/.ssh/authorized_keys2
Apr 20 22:19:44 localhost sshd[5466]: debug1: restore_uid: 0/0
Apr 20 22:19:44 localhost sshd[5466]: debug1: temporarily_use_uid: 
501/501 (e=0/0)
Apr 20 22:19:44 localhost sshd[5466]: debug1: trying public key file 
/usr/NX/home/nx/home/lobs/.ssh/authorized_keys2
Apr 20 22:19:44 localhost sshd[5466]: debug1: restore_uid: 0/0
Apr 20 22:19:44 localhost sshd[5466]: Failed publickey for nx from 
154.20.41.180 port 63242 ssh2
Apr 20 22:19:44 localhost sshd[5466]: debug3: mm_answer_keyallowed: key 
0x8064b5c8 is disallowed
Apr 20 22:19:44 localhost sshd[5466]: debug3: mm_request_send entering: 
type 22
Apr 20 22:19:44 localhost sshd[5466]: debug3: mm_request_receive entering
Apr 20 22:19:44 localhost sshd[5469]: debug2: userauth_pubkey: 
authenticated 0 pkalg ssh-dss

I must admit I do not understand a lot but what i noticed is that when 
first entering as nx and searching for the public key, the public key 
i.e. authorized_keys2 is not in the directory it is looking for. it 
looks in the directory for nx, which is actually empty and then adds 
right away the actual directory where the key is. Hm Could somebody 
please advice how to fix this? Also if there is some other problem ... 
Thanks a lot for your help!
Thomas

Fabian Franz wrote:
>> Thanks for the fast response,
>> I did stop sshd with /etc/init.d/sshd stop, started it with 
>> /etc/init.d/sshd start -v -v -v 
>>     
>
> Uhm, no:
>
> Just:
>
> /usr/sbin/sshd -v -v -v
>
> Then login and see what log messages it gives.
>
> An alternative is to set the log level higher in sshd.log and do a:
>
> tail -f /var/log/*.log
>
> Then login again and see what messages it gives.
>
> cu
>
> Fabian
> ________________________________________________________________
>      Were you helped on this list with your FreeNX problem?
>     Then please write up the solution in the FreeNX Wiki/FAQ:
>   http://openfacts.berlios.de/index-en.phtml?title=FreeNX_FAQ
>          Don't forget to check the NX Knowledge Base:
>                  http://www.nomachine.com/kb/ 
>
> ________________________________________________________________
>        FreeNX-kNX mailing list --- FreeNX-kNX at kde.org
>       https://mail.kde.org/mailman/listinfo/freenx-knx
> ________________________________________________________________
>

More information about the FreeNX-kNX mailing list