Re: chaining AUTH methods -- adding GoogleAuthenticator 2nd Factor to pubkey auth? can't get the GA prompt :-/

[Date Prev] [Date Next] [Thread Prev] [Thread Next] [Date Index] [Thread Index]

 



> This section of debug log is incomplete. Please try to get kbd-int auth
> working alone. I've used google authenticator via PAM before, so I know
> this works...

good to know.  lots of trouble with it for others I'm findig online.

setting up for GA keyboard-interactive only

cat /etc/pam.d/sshd
    #%PAM-1.0
    auth     required    pam_google_authenticator.so

cat /usr/local/etc/ssh/sshd_config
    ...
    AuthenticationMethods                keyboard-interactive
    ChallengeResponseAuthentication      yes
    PasswordAuthentication               no
    PubkeyAuthentication                 yes
    KbdInteractiveAuthentication         yes
    UsePAM                               yes
    ...

@ client

    > ssh server.MYDOMAIN.com
        Verification code:
        Verification code:
        Verification code:
        Permission denied (keyboard-interactive).
    >

@ server (DEBUG3)
    ...
    Dec 23 12:44:49 server sshd[29987]: debug3: fd 7 is not O_NONBLOCK
    Dec 23 12:44:49 server sshd[29987]: debug1: Forked child 29995.
    Dec 23 12:44:49 server sshd[29987]: debug3: send_rexec_state: entering
fd = 10 config len 2962
    Dec 23 12:44:49 server sshd[29987]: debug3: ssh_msg_send: type 0
    Dec 23 12:44:49 server sshd[29987]: debug3: send_rexec_state: done
    Dec 23 12:44:49 server sshd[29995]: debug3: oom_adjust_restore
    Dec 23 12:44:49 server sshd[29995]: Set /proc/self/oom_score_adj to 0
    Dec 23 12:44:49 server sshd[29995]: debug1: rexec start in 7 out 7
newsock 7 pipe 9 sock 10
    Dec 23 12:44:49 server sshd[29995]: debug1: inetd sockets after
dupping: 3, 3
    Dec 23 12:44:49 server sshd[29995]: Connection from
2001:xxx:xxxx:xxx::107 port 50338 on 2001:xxx:xxxx:xxx::108 port 22
    Dec 23 12:44:49 server sshd[29995]: debug1: Client protocol version
2.0; client software version OpenSSH_6.7
    Dec 23 12:44:49 server sshd[29995]: debug1: match: OpenSSH_6.7 pat
OpenSSH* compat 0x04000000
    Dec 23 12:44:49 server sshd[29995]: debug1: Enabling compatibility mode
for protocol 2.0
    Dec 23 12:44:49 server sshd[29995]: debug1: Local version string
SSH-2.0-OpenSSH_6.7
    Dec 23 12:44:49 server sshd[29995]: debug2: fd 3 setting O_NONBLOCK
    Dec 23 12:44:49 server sshd[29995]: debug2: Network child is on pid
29996
    Dec 23 12:44:49 server sshd[29995]: debug3: preauth child monitor
started
    Dec 23 12:44:49 server sshd[29995]: debug3: privsep user:group 100:101
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: permanently_set_uid:
100/101 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: list_hostkey_types:
ssh-ed25519,ecdsa-sha2-nistp521,ssh-rsa [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: SSH2_MSG_KEXINIT sent
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: SSH2_MSG_KEXINIT received
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
curve25519-sha256@xxxxxxxxxx,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
ssh-ed25519,ecdsa-sha2-nistp521,ssh-rsa [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
chacha20-poly1305@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx,aes128-gcm@xxxxxxxxxxx,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
chacha20-poly1305@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx,aes128-gcm@xxxxxxxxxxx,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm@xxxxxxxxxxx,hmac-sha2-256-etm@xxxxxxxxxxx,
umac-128-etm@xxxxxxxxxxx,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64@xxxxxxxxxxx [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm@xxxxxxxxxxx,hmac-sha2-256-etm@xxxxxxxxxxx,
umac-128-etm@xxxxxxxxxxx,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64@xxxxxxxxxxx [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: none
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: none
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
first_kex_follows 0  [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: reserved
0  [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
curve25519-sha256@xxxxxxxxxx,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,ssh-dss,ssh-rsa
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
chacha20-poly1305@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx,aes128-gcm@xxxxxxxxxxx,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
chacha20-poly1305@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx,aes128-gcm@xxxxxxxxxxx,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm@xxxxxxxxxxx,hmac-sha2-256-etm@xxxxxxxxxxx,
umac-128-etm@xxxxxxxxxxx,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64@xxxxxxxxxxx [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm@xxxxxxxxxxx,hmac-sha2-256-etm@xxxxxxxxxxx,
umac-128-etm@xxxxxxxxxxx,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64@xxxxxxxxxxx [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: none,
zlib@xxxxxxxxxxx,zlib [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: none,
zlib@xxxxxxxxxxx,zlib [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
first_kex_follows 0  [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: reserved
0  [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: kex: client->server
chacha20-poly1305@xxxxxxxxxxx <implicit> none [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: kex: server->client
chacha20-poly1305@xxxxxxxxxxx <implicit> none [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: expecting
SSH2_MSG_KEX_ECDH_INIT [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_key_sign entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 6 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_key_sign: waiting for
MONITOR_ANS_SIGN [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 7 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:49 server sshd[29995]: debug3: monitor_read: checking
request 6
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_answer_sign
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_answer_sign: signature
0x7fe81db0e600(83)
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 7
    Dec 23 12:44:49 server sshd[29995]: debug2: monitor_read: 6 used once,
disabling now
    Dec 23 12:44:49 server sshd[29995]: debug2: kex_derive_keys [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: set_newkeys: mode 1
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: SSH2_MSG_NEWKEYS sent
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: expecting SSH2_MSG_NEWKEYS
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: set_newkeys: mode 0
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: SSH2_MSG_NEWKEYS received
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: KEX done [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: userauth-request for user
root service ssh-connection method none [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: attempt 0 failures 0
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_getpwnamallow entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 8 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_getpwnamallow: waiting
for MONITOR_ANS_PWNAM [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 9 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:49 server sshd[29995]: debug3: monitor_read: checking
request 8
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_answer_pwnamallow
    Dec 23 12:44:49 server sshd[29995]: debug2: parse_server_config: config
reprocess config len 2962
    Dec 23 12:44:49 server sshd[29995]: debug3: checking match for
'group                          sftp-chroot' user root host
2001:xxx:xxxx:xxx::107 addr 2001:xxx:xxxx:xxx::107 laddr
2001:xxx:xxxx:xxx::108 lport 22
    Dec 23 12:44:49 server sshd[29995]: debug1: user root does not match
group list sftp-chroot at line 92
    Dec 23 12:44:49 server sshd[29995]: debug3: match not found
    Dec 23 12:44:49 server sshd[29995]: debug3: auth2_setup_methods_lists:
checking methods
    Dec 23 12:44:49 server sshd[29995]: debug1: authentication methods list
0: keyboard-interactive
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_answer_pwnamallow:
sending MONITOR_ANS_PWNAM: 1
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 9
    Dec 23 12:44:49 server sshd[29995]: debug2: monitor_read: 8 used once,
disabling now
    Dec 23 12:44:49 server sshd[29995]: debug2: input_userauth_request:
setting up authctxt for root [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_start_pam entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 100 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_inform_authserv entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 4 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: auth2_setup_methods_lists:
checking methods [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: authentication methods list
0: keyboard-interactive [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: Unrecognized authentication
method name: none [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: userauth_finish: failure
partial=0 next methods="keyboard-interactive" [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: userauth-request for user
root service ssh-connection method keyboard-interactive [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: attempt 1 failures 0
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: input_userauth_request: try
method keyboard-interactive [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: keyboard-interactive devs
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: auth2_challenge: user=root
devs= [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: kbdint_alloc: devices 'pam'
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: auth2_challenge_start:
devices pam [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug2: kbdint_next_device: devices
<empty> [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug1: auth2_challenge_start:
trying authentication method 'pam' [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_sshpam_init_ctx [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 104 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_sshpam_init_ctx: waiting
for MONITOR_ANS_PAM_INIT_CTX [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 105 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:49 server sshd[29995]: debug3: monitor_read: checking
request 100
    Dec 23 12:44:49 server sshd[29995]: debug1: PAM: initializing for "root"
    Dec 23 12:44:49 server sshd[29995]: debug1: PAM: setting PAM_RHOST to
"2001:xxx:xxxx:xxx::107"
    Dec 23 12:44:49 server sshd[29995]: debug1: PAM: setting PAM_TTY to
"ssh"
    Dec 23 12:44:49 server sshd[29995]: debug2: monitor_read: 100 used
once, disabling now
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:49 server sshd[29995]: debug3: monitor_read: checking
request 4
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_answer_authserv:
service=ssh-connection, style=
    Dec 23 12:44:49 server sshd[29995]: debug2: monitor_read: 4 used once,
disabling now
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:49 server sshd[29995]: debug3: monitor_read: checking
request 104
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_answer_pam_init_ctx
    Dec 23 12:44:49 server sshd[29995]: debug3: PAM: sshpam_init_ctx
entering
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 105
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_sshpam_query [preauth]
    Dec 23 12:44:49 server sshd[29997]: debug3: PAM: sshpam_thread_conv
entering, 1 messages
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 12:44:49 server sshd[29997]: debug3: ssh_msg_send: type 1
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 12:44:49 server sshd[29997]: debug3: ssh_msg_recv entering
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:49 server sshd[29995]: debug3: monitor_read: checking
request 106
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_answer_pam_query
    Dec 23 12:44:49 server sshd[29995]: debug3: PAM: sshpam_query entering
    Dec 23 12:44:49 server sshd[29995]: debug3: ssh_msg_recv entering
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_request_send entering:
type 107
    Dec 23 12:44:49 server sshd[29995]: debug3: mm_sshpam_query: pam_query
returned 0 [preauth]
    Dec 23 12:44:49 server sshd[29995]: Postponed keyboard-interactive for
root from 2001:xxx:xxxx:xxx::107 port 50338 ssh2 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_respond [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 108 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_respond: waiting
for MONITOR_ANS_PAM_RESPOND [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 109 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:54 server sshd[29995]: debug3: monitor_read: checking
request 108
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_answer_pam_respond
    Dec 23 12:44:54 server sshd[29995]: debug2: PAM: sshpam_respond
entering, 1 responses
    Dec 23 12:44:54 server sshd[29995]: debug3: ssh_msg_send: type 6
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 109
    Dec 23 12:44:54 server sshd(pam_google_authenticator)[29997]: Invalid
verification code
    Dec 23 12:44:54 server sshd[29997]: debug3: ssh_msg_send: type 7
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_respond:
pam_respond returned 1 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_query [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:54 server sshd[29995]: debug3: monitor_read: checking
request 106
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_answer_pam_query
    Dec 23 12:44:54 server sshd[29995]: debug3: PAM: sshpam_query entering
    Dec 23 12:44:54 server sshd[29995]: debug3: ssh_msg_recv entering
    Dec 23 12:44:54 server sshd[29995]: debug3: PAM: Authentication failure
    Dec 23 12:44:54 server sshd[29995]: error: PAM: Cannot make/remove an
entry for the specified session for root from 2001:xxx:xxxx:xxx::107
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 107
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_query: pam_query
returned -1 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug2: auth2_challenge_start:
devices <empty> [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_free_ctx [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 110 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_free_ctx: waiting
for MONITOR_ANS_PAM_FREE_CTX [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 111 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:54 server sshd[29995]: debug3: monitor_read: checking
request 110
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_answer_pam_free_ctx
    Dec 23 12:44:54 server sshd[29995]: debug3: PAM: sshpam_free_ctx
entering
    Dec 23 12:44:54 server sshd[29995]: debug3: PAM: sshpam_thread_cleanup
entering
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 111
    Dec 23 12:44:54 server sshd[29995]: debug2: monitor_read: 110 used
once, disabling now
    Dec 23 12:44:54 server sshd[29995]: Failed keyboard-interactive/pam for
root from 2001:xxx:xxxx:xxx::107 port 50338 ssh2
    Dec 23 12:44:54 server sshd[29995]: debug3: userauth_finish: failure
partial=0 next methods="keyboard-interactive" [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug1: userauth-request for user
root service ssh-connection method keyboard-interactive [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug1: attempt 2 failures 1
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug2: input_userauth_request: try
method keyboard-interactive [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug1: keyboard-interactive devs
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug1: auth2_challenge: user=root
devs= [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug1: kbdint_alloc: devices 'pam'
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug2: auth2_challenge_start:
devices pam [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug2: kbdint_next_device: devices
<empty> [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug1: auth2_challenge_start:
trying authentication method 'pam' [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_init_ctx [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 104 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_init_ctx: waiting
for MONITOR_ANS_PAM_INIT_CTX [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 105 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:54 server sshd[29995]: debug3: monitor_read: checking
request 104
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_answer_pam_init_ctx
    Dec 23 12:44:54 server sshd[29995]: debug3: PAM: sshpam_init_ctx
entering
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 105
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_query [preauth]
    Dec 23 12:44:54 server sshd[29998]: debug3: PAM: sshpam_thread_conv
entering, 1 messages
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 12:44:54 server sshd[29998]: debug3: ssh_msg_send: type 1
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 12:44:54 server sshd[29998]: debug3: ssh_msg_recv entering
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:54 server sshd[29995]: debug3: monitor_read: checking
request 106
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_answer_pam_query
    Dec 23 12:44:54 server sshd[29995]: debug3: PAM: sshpam_query entering
    Dec 23 12:44:54 server sshd[29995]: debug3: ssh_msg_recv entering
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_request_send entering:
type 107
    Dec 23 12:44:54 server sshd[29995]: debug3: mm_sshpam_query: pam_query
returned 0 [preauth]
    Dec 23 12:44:54 server sshd[29995]: Postponed keyboard-interactive for
root from 2001:xxx:xxxx:xxx::107 port 50338 ssh2 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_respond [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 108 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_respond: waiting
for MONITOR_ANS_PAM_RESPOND [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 109 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:58 server sshd[29995]: debug3: monitor_read: checking
request 108
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_answer_pam_respond
    Dec 23 12:44:58 server sshd[29995]: debug2: PAM: sshpam_respond
entering, 1 responses
    Dec 23 12:44:58 server sshd[29995]: debug3: ssh_msg_send: type 6
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 109
    Dec 23 12:44:58 server sshd(pam_google_authenticator)[29998]: Invalid
verification code
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_respond:
pam_respond returned 1 [preauth]
    Dec 23 12:44:58 server sshd[29998]: debug3: ssh_msg_send: type 7
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_query [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:58 server sshd[29995]: debug3: monitor_read: checking
request 106
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_answer_pam_query
    Dec 23 12:44:58 server sshd[29995]: debug3: PAM: sshpam_query entering
    Dec 23 12:44:58 server sshd[29995]: debug3: ssh_msg_recv entering
    Dec 23 12:44:58 server sshd[29995]: debug3: PAM: Authentication failure
    Dec 23 12:44:58 server sshd[29995]: error: PAM: Cannot make/remove an
entry for the specified session for root from 2001:xxx:xxxx:xxx::107
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 107
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_query: pam_query
returned -1 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug2: auth2_challenge_start:
devices <empty> [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_free_ctx [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 110 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_free_ctx: waiting
for MONITOR_ANS_PAM_FREE_CTX [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 111 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:58 server sshd[29995]: debug3: monitor_read: checking
request 110
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_answer_pam_free_ctx
    Dec 23 12:44:58 server sshd[29995]: debug3: PAM: sshpam_free_ctx
entering
    Dec 23 12:44:58 server sshd[29995]: debug3: PAM: sshpam_thread_cleanup
entering
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 111
    Dec 23 12:44:58 server sshd[29995]: debug2: monitor_read: 110 used
once, disabling now
    Dec 23 12:44:58 server sshd[29995]: Failed keyboard-interactive/pam for
root from 2001:xxx:xxxx:xxx::107 port 50338 ssh2
    Dec 23 12:44:58 server sshd[29995]: debug3: userauth_finish: failure
partial=0 next methods="keyboard-interactive" [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug1: userauth-request for user
root service ssh-connection method keyboard-interactive [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug1: attempt 3 failures 2
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug2: input_userauth_request: try
method keyboard-interactive [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug1: keyboard-interactive devs
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug1: auth2_challenge: user=root
devs= [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug1: kbdint_alloc: devices 'pam'
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug2: auth2_challenge_start:
devices pam [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug2: kbdint_next_device: devices
<empty> [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug1: auth2_challenge_start:
trying authentication method 'pam' [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_init_ctx [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 104 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_init_ctx: waiting
for MONITOR_ANS_PAM_INIT_CTX [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 105 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:58 server sshd[29995]: debug3: monitor_read: checking
request 104
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_answer_pam_init_ctx
    Dec 23 12:44:58 server sshd[29995]: debug3: PAM: sshpam_init_ctx
entering
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 105
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_query [preauth]
    Dec 23 12:44:58 server sshd[29999]: debug3: PAM: sshpam_thread_conv
entering, 1 messages
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 12:44:58 server sshd[29999]: debug3: ssh_msg_send: type 1
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 12:44:58 server sshd[29999]: debug3: ssh_msg_recv entering
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:44:58 server sshd[29995]: debug3: monitor_read: checking
request 106
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_answer_pam_query
    Dec 23 12:44:58 server sshd[29995]: debug3: PAM: sshpam_query entering
    Dec 23 12:44:58 server sshd[29995]: debug3: ssh_msg_recv entering
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_request_send entering:
type 107
    Dec 23 12:44:58 server sshd[29995]: debug3: mm_sshpam_query: pam_query
returned 0 [preauth]
    Dec 23 12:44:58 server sshd[29995]: Postponed keyboard-interactive for
root from 2001:xxx:xxxx:xxx::107 port 50338 ssh2 [preauth]
    Dec 23 12:45:01 server cron[30000]: pam_unix(crond:session): session
opened for user root by (uid=0)
    Dec 23 12:45:01 server cron[30001]: pam_unix(crond:session): session
opened for user root by (uid=0)
    Dec 23 12:45:01 server CRON[30001]: pam_unix(crond:session): session
closed for user root
    Dec 23 12:45:01 server CRON[30000]: pam_unix(crond:session): session
closed for user root
    Dec 23 12:45:01 server sshd[21866]: debug1:
server_input_global_request: rtype keepalive@xxxxxxxxxxx want_reply 1
    Dec 23 12:45:07 server sshd[21736]: debug1:
server_input_global_request: rtype keepalive@xxxxxxxxxxx want_reply 1
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_respond [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_send entering:
type 108 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_respond: waiting
for MONITOR_ANS_PAM_RESPOND [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 109 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:45:08 server sshd[29995]: debug3: monitor_read: checking
request 108
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_answer_pam_respond
    Dec 23 12:45:08 server sshd[29995]: debug2: PAM: sshpam_respond
entering, 1 responses
    Dec 23 12:45:08 server sshd[29995]: debug3: ssh_msg_send: type 6
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_send entering:
type 109
    Dec 23 12:45:08 server sshd(pam_google_authenticator)[29999]: Invalid
verification code
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_respond:
pam_respond returned 1 [preauth]
    Dec 23 12:45:08 server sshd[29999]: debug3: ssh_msg_send: type 7
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_query [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:45:08 server sshd[29995]: debug3: monitor_read: checking
request 106
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_answer_pam_query
    Dec 23 12:45:08 server sshd[29995]: debug3: PAM: sshpam_query entering
    Dec 23 12:45:08 server sshd[29995]: debug3: ssh_msg_recv entering
    Dec 23 12:45:08 server sshd[29995]: debug3: PAM: Authentication failure
    Dec 23 12:45:08 server sshd[29995]: error: PAM: Cannot make/remove an
entry for the specified session for root from 2001:xxx:xxxx:xxx::107
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_send entering:
type 107
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_query: pam_query
returned -1 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug2: auth2_challenge_start:
devices <empty> [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_free_ctx [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_send entering:
type 110 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_sshpam_free_ctx: waiting
for MONITOR_ANS_PAM_FREE_CTX [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive_expect
entering: type 111 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive entering
[preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:45:08 server sshd[29995]: debug3: monitor_read: checking
request 110
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_answer_pam_free_ctx
    Dec 23 12:45:08 server sshd[29995]: debug3: PAM: sshpam_free_ctx
entering
    Dec 23 12:45:08 server sshd[29995]: debug3: PAM: sshpam_thread_cleanup
entering
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_send entering:
type 111
    Dec 23 12:45:08 server sshd[29995]: debug2: monitor_read: 110 used
once, disabling now
    Dec 23 12:45:08 server sshd[29995]: Failed keyboard-interactive/pam for
root from 2001:xxx:xxxx:xxx::107 port 50338 ssh2
    Dec 23 12:45:08 server sshd[29995]: debug3: userauth_finish: failure
partial=0 next methods="keyboard-interactive" [preauth]
    Dec 23 12:45:08 server sshd[29995]: Connection closed by
2001:xxx:xxxx:xxx::107 [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug1: do_cleanup [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug3: PAM: sshpam_thread_cleanup
entering [preauth]
    Dec 23 12:45:08 server sshd[29995]: debug1: monitor_read_log: child log
fd closed
    Dec 23 12:45:08 server sshd[29995]: debug3: mm_request_receive entering
    Dec 23 12:45:08 server sshd[29995]: debug1: do_cleanup
    Dec 23 12:45:08 server sshd[29995]: debug1: PAM: cleanup
    Dec 23 12:45:08 server sshd[29995]: debug3: PAM: sshpam_thread_cleanup
entering
    Dec 23 12:45:08 server sshd[29995]: debug1: Killing privsep child 29996
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@xxxxxxxxxxx
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev



[Date Prev] [Date Next] [Thread Prev] [Thread Next] [Date Index] [Thread Index]

[Index of Archives]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Security]     [Bugtraq]     [Linux]     [Linux OMAP]     [Linux MIPS]     [ECOS]     [Asterisk Internet PBX]     [Linux API]

  Powered by Linux