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 02:22:32 EST 2014 

On Sun, Dec 21, 2014 at 5:25 PM, Damien Miller <djm at mindrot.org> wrote:

> On Fri, 19 Dec 2014, Dmt Ops wrote:
>
> > I added an EXPLICIT
> >
> >     AuthenticationMethods  publickey,keyboard-interactive
> > +    UsePam yes
> >
> > to sshd_config.  Now, at connect attempt I get
> >
> > Password:
> > Verification code:
> > Password:
> > Verification code:
> > Password:
>
> figuring out what is happening is pretty hard without logs from the client
> and server.
>

@ client

    ssh server.MYDOMAIN.com -vv
        OpenSSH_6.7p1, OpenSSL 1.0.1j 15 Oct 2014
        debug1: Reading configuration data /usr/local/etc/ssh/ssh_config
        debug1: /usr/local/etc/ssh/ssh_config line 88: Applying options for
server.MYDOMAIN.com
        debug1: /usr/local/etc/ssh/ssh_config line 100: Applying options
for *.MYDOMAIN.com
        debug1: /usr/local/etc/ssh/ssh_config line 158: Applying options
for *
        debug2: ssh_connect: needpriv 0
        debug1: Connecting to server.MYDOMAIN.com [2001:xxx:xxxx:xxx::108]
port 22.
        debug2: fd 3 setting O_NONBLOCK
        debug1: fd 3 clearing O_NONBLOCK
        debug1: Connection established.
        debug1: permanently_set_uid: 0/0
        debug1: key_load_public: No such file or directory
        debug1: identity file /usr/local/etc/ssh/ssh.CLIENT.ed25519 type -1
        debug1: key_load_public: No such file or directory
        debug1: identity file /usr/local/etc/ssh/ssh.CLIENT.ed25519-cert
type -1
        debug1: key_load_public: No such file or directory
        debug1: identity file /usr/local/etc/ssh/ssh.CLIENT.ecdsa type -1
        debug1: key_load_public: No such file or directory
        debug1: identity file /usr/local/etc/ssh/ssh.CLIENT.ecdsa-cert type
-1
        debug1: identity file /usr/local/etc/ssh/ssh.CLIENT.rsa type 1
        debug1: key_load_public: No such file or directory
        debug1: identity file /usr/local/etc/ssh/ssh.CLIENT.rsa-cert type -1
        debug1: Enabling compatibility mode for protocol 2.0
        debug1: Local version string SSH-2.0-OpenSSH_6.7
        debug1: Remote protocol version 2.0, remote software version
OpenSSH_6.7
        debug1: match: OpenSSH_6.7 pat OpenSSH* compat 0x04000000
        debug2: fd 3 setting O_NONBLOCK
        debug1: SSH2_MSG_KEXINIT sent
        debug1: SSH2_MSG_KEXINIT received
        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
        debug2: kex_parse_kexinit:
ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,ssh-dss,ssh-rsa
        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
        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
        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
        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
        debug2: kex_parse_kexinit: none,zlib at openssh.com,zlib
        debug2: kex_parse_kexinit: none,zlib at openssh.com,zlib
        debug2: kex_parse_kexinit:
        debug2: kex_parse_kexinit:
        debug2: kex_parse_kexinit: first_kex_follows 0
        debug2: kex_parse_kexinit: reserved 0
        debug2: kex_parse_kexinit: curve25519-sha256 at libssh.org
,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256
        debug2: kex_parse_kexinit: ssh-ed25519,ecdsa-sha2-nistp521,ssh-rsa
        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
        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
        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
        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
        debug2: kex_parse_kexinit: none
        debug2: kex_parse_kexinit: none
        debug2: kex_parse_kexinit:
        debug2: kex_parse_kexinit:
        debug2: kex_parse_kexinit: first_kex_follows 0
        debug2: kex_parse_kexinit: reserved 0
        debug1: kex: server->client chacha20-poly1305 at openssh.com
<implicit> none
        debug1: kex: client->server chacha20-poly1305 at openssh.com
<implicit> none
        debug1: sending SSH2_MSG_KEX_ECDH_INIT
        debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
        debug1: Server host key: ED25519
xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx
        debug1: Host 'server.MYDOMAIN.com' is known and matches the ED25519
host key.
        debug1: Found key in /usr/local/etc/ssh/ssh_known_hosts:1
        debug2: kex_derive_keys
        debug2: set_newkeys: mode 1
        debug1: SSH2_MSG_NEWKEYS sent
        debug1: expecting SSH2_MSG_NEWKEYS
        debug2: set_newkeys: mode 0
        debug1: SSH2_MSG_NEWKEYS received
        debug1: SSH2_MSG_SERVICE_REQUEST sent
        debug2: service_accept: ssh-userauth
        debug1: SSH2_MSG_SERVICE_ACCEPT received
        debug2: key: /usr/local/etc/ssh/ssh.CLIENT.ed25519 ((nil)), explicit
        debug2: key: /usr/local/etc/ssh/ssh.CLIENT.ecdsa ((nil)), explicit
        debug2: key: /usr/local/etc/ssh/ssh.CLIENT.rsa (0x7ff343d79620),
explicit
        debug1: Authentications that can continue: publickey
        debug1: Next authentication method: publickey
        debug1: Trying private key: /usr/local/etc/ssh/ssh.CLIENT.ed25519
        debug2: we sent a publickey packet, wait for reply
        Authenticated with partial success.
        debug2: key: /usr/local/etc/ssh/ssh.CLIENT.ed25519 ((nil)), explicit
        debug2: key: /usr/local/etc/ssh/ssh.CLIENT.ecdsa ((nil)), explicit
        debug2: key: /usr/local/etc/ssh/ssh.CLIENT.rsa ((nil)), explicit
        debug1: Authentications that can continue: keyboard-interactive
        debug1: Next authentication method: keyboard-interactive
        debug2: userauth_kbdint
        debug2: we sent a keyboard-interactive packet, wait for reply
        debug2: input_userauth_info_req
        debug2: input_userauth_info_req: num_prompts 1
        Password:
        debug2: input_userauth_info_req
        debug2: input_userauth_info_req: num_prompts 1
        Verification code:
        debug1: Authentications that can continue: keyboard-interactive
        debug2: userauth_kbdint
        debug2: we sent a keyboard-interactive packet, wait for reply
        debug2: input_userauth_info_req
        debug2: input_userauth_info_req: num_prompts 1
        Password:

@ server, level 'DEBUG2'

    Dec 23 07:05:21 server sshd[23102]: debug1: Forked child 23109.
    Dec 23 07:05:21 server sshd[23109]: Set /proc/self/oom_score_adj to 0
    Dec 23 07:05:21 server sshd[23109]: debug1: rexec start in 7 out 7
newsock 7 pipe 9 sock 10
    Dec 23 07:05:21 server sshd[23109]: debug1: inetd sockets after
dupping: 3, 3
    Dec 23 07:05:21 server sshd[23109]: Connection from
2001:xxx:xxxx:xxx::107 port 48866 on 2001:xxx:xxxx:xxx::108 port 22
    Dec 23 07:05:21 server sshd[23109]: debug1: Client protocol version
2.0; client software version OpenSSH_6.7
    Dec 23 07:05:21 server sshd[23109]: debug1: match: OpenSSH_6.7 pat
OpenSSH* compat 0x04000000
    Dec 23 07:05:21 server sshd[23109]: debug1: Enabling compatibility mode
for protocol 2.0
    Dec 23 07:05:21 server sshd[23109]: debug1: Local version string
SSH-2.0-OpenSSH_6.7
    Dec 23 07:05:21 server sshd[23109]: debug2: fd 3 setting O_NONBLOCK
    Dec 23 07:05:21 server sshd[23109]: debug2: Network child is on pid
23110
    Dec 23 07:05:21 server sshd[23109]: debug1: permanently_set_uid:
100/101 [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: list_hostkey_types:
ssh-ed25519,ecdsa-sha2-nistp521,ssh-rsa [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: SSH2_MSG_KEXINIT sent
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: SSH2_MSG_KEXINIT received
[preauth]
    Dec 23 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
ssh-ed25519,ecdsa-sha2-nistp521,ssh-rsa [preauth]
    Dec 23 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit: none
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit: none
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
first_kex_follows 0  [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit: reserved
0  [preauth]
    Dec 23 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,ssh-dss,ssh-rsa
[preauth]
    Dec 23 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: 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 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit: none,
zlib at openssh.com,zlib [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit: none,
zlib at openssh.com,zlib [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit:
first_kex_follows 0  [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_parse_kexinit: reserved
0  [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: kex: client->server
chacha20-poly1305 at openssh.com <implicit> none [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: kex: server->client
chacha20-poly1305 at openssh.com <implicit> none [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: expecting
SSH2_MSG_KEX_ECDH_INIT [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: monitor_read: 6 used once,
disabling now
    Dec 23 07:05:21 server sshd[23109]: debug2: kex_derive_keys [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: set_newkeys: mode 1
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: SSH2_MSG_NEWKEYS sent
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: expecting SSH2_MSG_NEWKEYS
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: set_newkeys: mode 0
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: SSH2_MSG_NEWKEYS received
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: KEX done [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: userauth-request for user
root service ssh-connection method none [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: attempt 0 failures 0
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: parse_server_config: config
reprocess config len 2927
    Dec 23 07:05:21 server sshd[23109]: debug1: user root does not match
group list sftp-chroot at line 83
    Dec 23 07:05:21 server sshd[23109]: debug1: authentication methods list
0: publickey,keyboard-interactive:pam
    Dec 23 07:05:21 server sshd[23109]: debug2: monitor_read: 8 used once,
disabling now
    Dec 23 07:05:21 server sshd[23109]: debug2: input_userauth_request:
setting up authctxt for root [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: authentication methods list
0: publickey,keyboard-interactive:pam [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: Unrecognized authentication
method name: none [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: PAM: initializing for "root"
    Dec 23 07:05:21 server sshd[23109]: debug1: PAM: setting PAM_RHOST to
"2001:xxx:xxxx:xxx::107"
    Dec 23 07:05:21 server sshd[23109]: debug1: PAM: setting PAM_TTY to
"ssh"
    Dec 23 07:05:21 server sshd[23109]: debug2: monitor_read: 100 used
once, disabling now
    Dec 23 07:05:21 server sshd[23109]: debug1: userauth-request for user
root service ssh-connection method publickey [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: attempt 1 failures 0
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: input_userauth_request: try
method publickey [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: monitor_read: 4 used once,
disabling now
    Dec 23 07:05:21 server sshd[23109]: debug1: temporarily_use_uid: 0/0
(e=0/0)
    Dec 23 07:05:21 server sshd[23109]: debug1: trying public key file
/usr/local/etc/ssh/authorized_keys2
    Dec 23 07:05:21 server sshd[23109]: debug1: fd 4 clearing O_NONBLOCK
    Dec 23 07:05:21 server sshd[23109]: debug1: matching key found: file
/usr/local/etc/ssh/authorized_keys2, line 2 ED25519
yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy
    Dec 23 07:05:21 server sshd[23109]: debug1: restore_uid: 0/0
    Dec 23 07:05:21 server sshd[23109]: Partial publickey for root from
2001:xxx:xxxx:xxx::107 port 48866 ssh2: ED25519
yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy
    Dec 23 07:05:21 server sshd[23109]: debug2: userauth_pubkey:
authenticated 1 pkalg ssh-ed25519 [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: userauth-request for user
root service ssh-connection method keyboard-interactive [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: attempt 2 failures 1
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: input_userauth_request: try
method keyboard-interactive [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: keyboard-interactive devs
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: auth2_challenge: user=root
devs= [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: kbdint_alloc: devices 'pam'
[preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: auth2_challenge_start:
devices pam [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug2: kbdint_next_device: devices
<empty> [preauth]
    Dec 23 07:05:21 server sshd[23109]: debug1: auth2_challenge_start:
trying authentication method 'pam' [preauth]
    Dec 23 07:05:21 server sshd[23109]: Postponed keyboard-interactive for
root from 2001:xxx:xxxx:xxx::107 port 48866 ssh2: ED25519
yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy:yy [preauth]
    Dec 23 07:05:27 server sshd[23109]: debug2: PAM: sshpam_respond
entering, 1 responses
    Dec 23 07:05:27 server sshd[23109]: Postponed keyboard-interactive/pam
for root from 2001:xxx:xxxx:xxx::107 port 48866 ssh2 [preauth]
    Dec 23 07:05:34 server sshd[23109]: debug2: PAM: sshpam_respond
entering, 1 responses
    Dec 23 07:05:34 server sshd(pam_google_authenticator)[23111]: Invalid
verification code
    Dec 23 07:05:34 server sshd[23109]: error: PAM: Authentication failure
for root from 2001:xxx:xxxx:xxx::107
    Dec 23 07:05:34 server sshd[23109]: debug2: auth2_challenge_start:
devices <empty> [preauth]
    Dec 23 07:05:34 server sshd[23109]: debug2: monitor_read: 110 used
once, disabling now
    Dec 23 07:05:34 server sshd[23109]: Failed keyboard-interactive/pam for
root from 2001:xxx:xxxx:xxx::107 port 48866 ssh2
    Dec 23 07:05:34 server sshd[23109]: debug1: userauth-request for user
root service ssh-connection method keyboard-interactive [preauth]
    Dec 23 07:05:34 server sshd[23109]: debug1: attempt 3 failures 2
[preauth]
    Dec 23 07:05:34 server sshd[23109]: debug2: input_userauth_request: try
method keyboard-interactive [preauth]
    Dec 23 07:05:34 server sshd[23109]: debug1: keyboard-interactive devs
[preauth]
    Dec 23 07:05:34 server sshd[23109]: debug1: auth2_challenge: user=root
devs= [preauth]
    Dec 23 07:05:34 server sshd[23109]: debug1: kbdint_alloc: devices 'pam'
[preauth]
    Dec 23 07:05:34 server sshd[23109]: debug2: auth2_challenge_start:
devices pam [preauth]
    Dec 23 07:05:34 server sshd[23109]: debug2: kbdint_next_device: devices
<empty> [preauth]
    Dec 23 07:05:34 server sshd[23109]: debug1: auth2_challenge_start:
trying authentication method 'pam' [preauth]
    Dec 23 07:05:34 server sshd[23109]: Postponed keyboard-interactive for
root from 2001:xxx:xxxx:xxx::107 port 48866 ssh2 [preauth]

More information about the openssh-unix-dev mailing list