thr3ads.net - openssh unix dev - chaining AUTH methods -- adding GoogleAuthenticator 2nd Factor to pubkey auth? can't get the GA prompt :-/ [Dec 2014]

If this information is useful, please help other people find it:
Share via:

Dmt Ops

2014-Dec-23 15:22 UTC

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

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]

Dmt Ops

2014-Dec-23 18:51 UTC

head link

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

testing goole-authenticator's standalone functionality, it

    > cd google-authenticator/libpam/
    > ./demo
        Verification code:  123456
        Login failed
        Invalid verification code
    >

fails with an INVALID code, and

    > ./demo
        Verification code:  XXXXXX
    >

succeeds with a VALID code.

turning up the sshd server debug level to DEBUG3, entering a similarly
VALID GA verification code, the code is declared "invalid",

    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_respond [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 108 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_respond: waiting
for MONITOR_ANS_PAM_RESPOND [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive_expect
entering: type 109 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
    Dec 23 10:37:24 server sshd[22322]: debug3: monitor_read: checking
request 108
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_answer_pam_respond
    Dec 23 10:37:24 server sshd[22322]: debug2: PAM: sshpam_respond
entering, 1 responses
    Dec 23 10:37:24 server sshd[22322]: debug3: ssh_msg_send: type 6
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 109>>>    Dec 23 10:37:24 server sshd(pam_google_authenticator)[22326]:Invalid verification code
    Dec 23 10:37:24 server sshd[22326]: debug3: ssh_msg_send: type 7
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_respond:
pam_respond returned 1 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_query [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
    Dec 23 10:37:24 server sshd[22322]: debug3: monitor_read: checking
request 106
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_answer_pam_query
    Dec 23 10:37:24 server sshd[22322]: debug3: PAM: sshpam_query entering
    Dec 23 10:37:24 server sshd[22322]: debug3: ssh_msg_recv entering
    Dec 23 10:37:24 server sshd[22322]: debug3: PAM: Authentication failure
    Dec 23 10:37:24 server sshd[22322]: error: PAM: Cannot make/remove an
entry for the specified session for root from 2001:xxx:xxxx:xxx::107
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 107
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_query: pam_query
returned -1 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug2: auth2_challenge_start:
devices <empty> [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_free_ctx [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 110 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_free_ctx: waiting
for MONITOR_ANS_PAM_FREE_CTX [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive_expect
entering: type 111 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
    Dec 23 10:37:24 server sshd[22322]: debug3: monitor_read: checking
request 110
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_answer_pam_free_ctx
    Dec 23 10:37:24 server sshd[22322]: debug3: PAM: sshpam_free_ctx
entering
    Dec 23 10:37:24 server sshd[22322]: debug3: PAM: sshpam_thread_cleanup
entering
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 111
    Dec 23 10:37:24 server sshd[22322]: debug2: monitor_read: 110 used
once, disabling now
    Dec 23 10:37:24 server sshd[22322]: Failed keyboard-interactive/pam for
root from 2001:xxx:xxxx:xxx::107 port 49831 ssh2
    Dec 23 10:37:24 server sshd[22322]: debug3: userauth_finish: failure
partial=0 next methods="keyboard-interactive" [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug1: userauth-request for user
root service ssh-connection method keyboard-interactive [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug1: attempt 3 failures 2
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug2: input_userauth_request: try
method keyboard-interactive [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug1: keyboard-interactive devs
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug1: auth2_challenge: user=root
devs= [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug1: kbdint_alloc: devices
'pam'
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug2: auth2_challenge_start:
devices pam [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug2: kbdint_next_device: devices
<empty> [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug1: auth2_challenge_start:
trying authentication method 'pam' [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_init_ctx [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 104 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_init_ctx: waiting
for MONITOR_ANS_PAM_INIT_CTX [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive_expect
entering: type 105 [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
    Dec 23 10:37:24 server sshd[22322]: debug3: monitor_read: checking
request 104
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_answer_pam_init_ctx
    Dec 23 10:37:24 server sshd[22322]: debug3: PAM: sshpam_init_ctx
entering
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 105
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_query [preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 106 [preauth]
    Dec 23 10:37:24 server sshd[22327]: debug3: PAM: sshpam_thread_conv
entering, 1 messages
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_query: waiting
for MONITOR_ANS_PAM_QUERY [preauth]
    Dec 23 10:37:24 server sshd[22327]: debug3: ssh_msg_send: type 1
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive_expect
entering: type 107 [preauth]
    Dec 23 10:37:24 server sshd[22327]: debug3: ssh_msg_recv entering
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
[preauth]
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_receive entering
    Dec 23 10:37:24 server sshd[22322]: debug3: monitor_read: checking
request 106
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_answer_pam_query
    Dec 23 10:37:24 server sshd[22322]: debug3: PAM: sshpam_query entering
    Dec 23 10:37:24 server sshd[22322]: debug3: ssh_msg_recv entering
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_request_send entering:
type 107
    Dec 23 10:37:24 server sshd[22322]: debug3: mm_sshpam_query: pam_query
returned 0 [preauth]
    Dec 23 10:37:24 server sshd[22322]: Postponed keyboard-interactive for
root from 2001:xxx:xxxx:xxx::107 port 49831 ssh2 [preauth]

Damien Miller

2014-Dec-23 20:40 UTC

head link

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

On Tue, 23 Dec 2014, Dmt Ops wrote:
> 
> @ client
> 
>         debug1: Authentications that can continue: publickey
Server offers the first mandatory authentication method
>         debug1: Trying private key: /usr/local/etc/ssh/ssh.CLIENT.ed25519
>         debug2: we sent a publickey packet, wait for reply
>         Authenticated with partial success.
Client successfully completes pubkey
>         debug1: Authentications that can continue: keyboard-interactive
>         debug1: Next authentication method: keyboard-interactive
Server offers the next mandatory authentication method
>         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:
Client is not successful at kdb-int authentication.
> @ server, level 'DEBUG2'
> 
> 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]
Server is configured with multiple authentication
> [preauth]
>     Dec 23 07:05:21 server sshd[23109]: debug2: input_userauth_request: try
> method publickey [preauth]
client attempts pubkey
>     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]
Client succeeds pubkey
>     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]
server sends the password and verification code prompts to the client
>     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
Client replies with credentials that are rejected by the PAM stack.

Have you got keyboard-interactive working on its own with Google
authenticator? It seems like a good first step...

Also, if you provide any further logs then please use debug3 (ssh -vvv /
sshd -ddd).

-d

Damien Miller

2014-Dec-23 20:48 UTC

head link

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

On Tue, 23 Dec 2014, Dmt Ops wrote:
> testing goole-authenticator's standalone functionality, it
> 
>     > cd google-authenticator/libpam/
>     > ./demo
>         Verification code:  123456
>         Login failed
>         Invalid verification code
>     >
> 
> fails with an INVALID code, and
> 
>     > ./demo
>         Verification code:  XXXXXX
>     >
> 
> succeeds with a VALID code.
> 
> turning up the sshd server debug level to DEBUG3, entering a similarly
> VALID GA verification code, the code is declared "invalid",
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...

-d

openssh unix dev - Dec 2014 - chaining AUTH methods -- adding GoogleAuthenticator 2nd Factor to pubkey auth? can't get the GA prompt :-/

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

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

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

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