chaining AUTH methods -- adding GoogleAuthenticator 2nd Factor to pubkey auth? can't get the GA prompt :-/
Dmt Ops
opsdmt at gmail.com
Wed Dec 24 07:51:20 EST 2014
> 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 at libssh.org,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 at openssh.com,aes256-gcm at openssh.com,aes128-gcm at openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
chacha20-poly1305 at openssh.com,aes256-gcm at openssh.com,aes128-gcm at openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm at openssh.com,hmac-sha2-256-etm at openssh.com,
umac-128-etm at openssh.com,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64 at openssh.com [preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm at openssh.com,hmac-sha2-256-etm at openssh.com,
umac-128-etm at openssh.com,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64 at openssh.com [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 at libssh.org,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 at openssh.com,aes256-gcm at openssh.com,aes128-gcm at openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
chacha20-poly1305 at openssh.com,aes256-gcm at openssh.com,aes128-gcm at openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,arcfour
[preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm at openssh.com,hmac-sha2-256-etm at openssh.com,
umac-128-etm at openssh.com,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64 at openssh.com [preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit:
hmac-sha2-512-etm at openssh.com,hmac-sha2-256-etm at openssh.com,
umac-128-etm at openssh.com,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160,
umac-64 at openssh.com [preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: none,
zlib at openssh.com,zlib [preauth]
Dec 23 12:44:49 server sshd[29995]: debug2: kex_parse_kexinit: none,
zlib at openssh.com,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 at openssh.com <implicit> none [preauth]
Dec 23 12:44:49 server sshd[29995]: debug1: kex: server->client
chacha20-poly1305 at openssh.com <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 at openssh.com want_reply 1
Dec 23 12:45:07 server sshd[21736]: debug1:
server_input_global_request: rtype keepalive at openssh.com 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
More information about the openssh-unix-dev
mailing list