> 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