Custom PAM module not working correctly

Diogo Vieira dfv at eurotux.com
Fri Oct 21 06:19:16 AEDT 2016 

Hello,

I've developed a custom PAM module which only allows a user to 
authenticate to the server only if another user of the same machine 
also authenticates succesfully. It's currently a simple module which 
also works as a PAM aware application since it authenticates each user 
with PAM itself. Both the pamtester utility and su can use this module 
correctly. However, when I try to use it with my openssh server the 
authentication fails after the first prompt.

To give you an example of a session I've attached below both the logs 
server-side[0] and client-side[1]. A correct authentication flow should 
be like this example from pamtester:

[root at 035f4248e494 pam.d]# pamtester sshd root authenticate
Your username: dfv
Password:
Please ask for someone to grant you access.
Grantee's username: other
Password:
pamtester: successfully authenticated

I also attached my sshd_config[2] (maybe something's wrong with it).

Can someone help me understand the problem? I'm sorry if I'm missing 
something obvious but I'm new to PAM modules and didn't find anything 
relevant in the docs for openssh or the linux-pam project.

If it's relevant, the OS I'm using for development and testing is 
CentOS 7 (with OpenSSH_6.6.1p1, OpenSSL 1.0.1e-fips 11 Feb 2013).

Thank you very much,
Diogo Vieira


Logs:

 * [0]:

[root at 035f4248e494 pam.d]# /usr/sbin/sshd -D -dd
debug2: load_server_config: filename /etc/ssh/sshd_config
debug2: load_server_config: done config len = 653
debug2: parse_server_config: config /etc/ssh/sshd_config len 653
debug1: sshd version OpenSSH_6.6.1, OpenSSL 1.0.1e-fips 11 Feb 2013
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type RSA
debug1: private host key: #0 type 1 RSA
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type ECDSA
debug1: private host key: #1 type 3 ECDSA
debug1: private host key: #2 type 4 ED25519
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-D'
debug1: rexec_argv[2]='-dd'
Set /proc/self/oom_score_adj from 0 to -1000
debug2: fd 3 setting O_NONBLOCK
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 port 22.
debug2: fd 4 setting O_NONBLOCK
debug1: Bind to port 22 on ::.
Server listening on :: port 22.
debug1: Server will not fork when running in debugging mode.
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from 172.17.0.1 port 35432 on 172.17.0.2 port 22
debug1: Client protocol version 2.0; client software version OpenSSH_7.2
debug1: match: OpenSSH_7.2 pat OpenSSH* compat 0x04000000
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1
debug2: fd 3 setting O_NONBLOCK
debug2: Network child is on pid 98
debug1: SELinux support disabled [preauth]
debug1: permanently_set_uid: 74/74 [preauth]
debug1: list_hostkey_types: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 
[preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug2: kex_parse_kexinit: 
curve25519-sha256 at libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 
[preauth]
debug2: kex_parse_kexinit: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 
[preauth]
debug2: kex_parse_kexinit: 
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se 
[preauth]
debug2: kex_parse_kexinit: 
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se 
[preauth]
debug2: kex_parse_kexinit: 
hmac-md5-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,hmac-md5-96-etm at openssh.com,hmac-md5,hmac-sha1,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96 
[preauth]
debug2: kex_parse_kexinit: 
hmac-md5-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,hmac-md5-96-etm at openssh.com,hmac-md5,hmac-sha1,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96 
[preauth]
debug2: kex_parse_kexinit: none,zlib at openssh.com [preauth]
debug2: kex_parse_kexinit: none,zlib at openssh.com [preauth]
debug2: kex_parse_kexinit:  [preauth]
debug2: kex_parse_kexinit:  [preauth]
debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
debug2: kex_parse_kexinit: reserved 0  [preauth]
debug2: kex_parse_kexinit: 
curve25519-sha256 at libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,ext-info-c 
[preauth]
debug2: kex_parse_kexinit: 
ecdsa-sha2-nistp256-cert-v01 at openssh.com,ecdsa-sha2-nistp384-cert-v01 at openssh.com,ecdsa-sha2-nistp521-cert-v01 at openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519-cert-v01 at openssh.com,ssh-rsa-cert-v01 at openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa 
[preauth]
debug2: kex_parse_kexinit: 
chacha20-poly1305 at openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm at openssh.com,aes256-gcm at openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc 
[preauth]
debug2: kex_parse_kexinit: 
chacha20-poly1305 at openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm at openssh.com,aes256-gcm at openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc 
[preauth]
debug2: kex_parse_kexinit: 
umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 
[preauth]
debug2: kex_parse_kexinit: 
umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 
[preauth]
debug2: kex_parse_kexinit: zlib at openssh.com,zlib,none [preauth]
debug2: kex_parse_kexinit: zlib at openssh.com,zlib,none [preauth]
debug2: kex_parse_kexinit:  [preauth]
debug2: kex_parse_kexinit:  [preauth]
debug2: kex_parse_kexinit: first_kex_follows 0  [preauth]
debug2: kex_parse_kexinit: reserved 0  [preauth]
debug1: kex: client->server chacha20-poly1305 at openssh.com <implicit> 
zlib at openssh.com [preauth]
debug1: kex: server->client chacha20-poly1305 at openssh.com <implicit> 
zlib at openssh.com [preauth]
debug1: kex: curve25519-sha256 at libssh.org need=64 dh_need=64 [preauth]
debug1: kex: curve25519-sha256 at libssh.org need=64 dh_need=64 [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug2: monitor_read: 6 used once, disabling now
debug2: kex_derive_keys [preauth]
debug2: set_newkeys: mode 1 [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user root service ssh-connection method 
none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug2: parse_server_config: config reprocess config len 653
debug1: authentication methods list 0: keyboard-interactive
debug2: monitor_read: 8 used once, disabling now
debug2: input_userauth_request: setting up authctxt for root [preauth]
debug1: authentication methods list 0: keyboard-interactive [preauth]
debug2: Unrecognized authentication method name: none [preauth]
debug1: PAM: initializing for "root"
debug1: PAM: setting PAM_RHOST to "gateway"
debug1: PAM: setting PAM_TTY to "ssh"
debug2: monitor_read: 100 used once, disabling now
debug1: userauth-request for user root service ssh-connection method 
keyboard-interactive [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method keyboard-interactive 
[preauth]
debug1: keyboard-interactive devs  [preauth]
debug1: auth2_challenge: user=root devs= [preauth]
debug1: kbdint_alloc: devices 'pam' [preauth]
debug2: auth2_challenge_start: devices pam [preauth]
debug2: kbdint_next_device: devices <empty> [preauth]
debug1: auth2_challenge_start: trying authentication method 'pam' 
[preauth]
debug2: monitor_read: 4 used once, disabling now
debug2: monitor_read: 80 used once, disabling now
Postponed keyboard-interactive for root from 172.17.0.1 port 35432 ssh2 
[preauth]
debug2: PAM: sshpam_respond entering, 1 responses
Password: PAM: Authentication failure for root from gateway
debug2: auth2_challenge_start: devices <empty> [preauth]
debug2: monitor_read: 110 used once, disabling now
Failed keyboard-interactive/pam for root from 172.17.0.1 port 35432 ssh2
debug1: userauth-request for user root service ssh-connection method 
keyboard-interactive [preauth]
debug1: attempt 2 failures 1 [preauth]
debug2: input_userauth_request: try method keyboard-interactive 
[preauth]
debug1: keyboard-interactive devs  [preauth]
debug1: auth2_challenge: user=root devs= [preauth]
debug1: kbdint_alloc: devices 'pam' [preauth]
debug2: auth2_challenge_start: devices pam [preauth]
debug2: kbdint_next_device: devices <empty> [preauth]
debug1: auth2_challenge_start: trying authentication method 'pam' 
[preauth]
Postponed keyboard-interactive for root from 172.17.0.1 port 35432 ssh2 
[preauth]


  * [1]:

ssh root at 172.17.0.2 -vv                                                 
                                                                        
                                                                        
      ⏎
OpenSSH_7.2p2, OpenSSL 1.0.2j-fips  26 Sep 2016
debug1: Reading configuration data /home/dfv/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 58: Applying options for *
debug2: resolving "172.17.0.2" port 22
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to 172.17.0.2 [172.17.0.2] port 22.
debug1: Connection established.
debug1: identity file /home/dfv/.ssh/id_rsa type 1
debug1: key_load_public: No such file or directory
debug1: identity file /home/dfv/.ssh/id_rsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/dfv/.ssh/id_dsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/dfv/.ssh/id_dsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/dfv/.ssh/id_ecdsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/dfv/.ssh/id_ecdsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/dfv/.ssh/id_ed25519 type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/dfv/.ssh/id_ed25519-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_7.2
debug1: Remote protocol version 2.0, remote software version 
OpenSSH_6.6.1
debug1: match: OpenSSH_6.6.1 pat OpenSSH_6.6.1* compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to 172.17.0.2:22 as 'root'
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: 
curve25519-sha256 at libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,ext-info-c
debug2: host key algorithms: 
ecdsa-sha2-nistp256-cert-v01 at openssh.com,ecdsa-sha2-nistp384-cert-v01 at openssh.com,ecdsa-sha2-nistp521-cert-v01 at openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519-cert-v01 at openssh.com,ssh-rsa-cert-v01 at openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: 
chacha20-poly1305 at openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm at openssh.com,aes256-gcm at openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: ciphers stoc: 
chacha20-poly1305 at openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm at openssh.com,aes256-gcm at openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: MACs ctos: 
umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: 
umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: zlib at openssh.com,zlib,none
debug2: compression stoc: zlib at openssh.com,zlib,none
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: 
curve25519-sha256 at libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: host key algorithms: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519
debug2: ciphers ctos: 
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se
debug2: ciphers stoc: 
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc at lysator.liu.se
debug2: MACs ctos: 
hmac-md5-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,hmac-md5-96-etm at openssh.com,hmac-md5,hmac-sha1,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: MACs stoc: 
hmac-md5-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,hmac-md5-96-etm at openssh.com,hmac-md5,hmac-sha1,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: compression ctos: none,zlib at openssh.com
debug2: compression stoc: none,zlib at openssh.com
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug1: kex: algorithm: curve25519-sha256 at libssh.org
debug1: kex: host key algorithm: ecdsa-sha2-nistp256
debug1: kex: server->client cipher: chacha20-poly1305 at openssh.com MAC: 
<implicit> compression: zlib at openssh.com
debug1: kex: client->server cipher: chacha20-poly1305 at openssh.com MAC: 
<implicit> compression: zlib at openssh.com
debug1: kex: curve25519-sha256 at libssh.org need=64 dh_need=64
debug1: kex: curve25519-sha256 at libssh.org need=64 dh_need=64
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ecdsa-sha2-nistp256 
SHA256:Er0MNm+5rNC5ras2Lc04cAvtgYfkgTH85Eg8GMtznjg
debug1: Host '172.17.0.2' is known and matches the ECDSA host key.
debug1: Found key in /home/dfv/.ssh/known_hosts:90
debug2: set_newkeys: mode 1
debug1: rekey after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug2: set_newkeys: mode 0
debug1: rekey after 134217728 blocks
debug2: key: /home/dfv/.ssh/id_rsa (0x55bd50ecf980), agent
debug2: key: desafio-sei (0x55bd50ed4ae0), agent
debug2: key: /home/dfv/.ssh/id_dsa ((nil))
debug2: key: /home/dfv/.ssh/id_ecdsa ((nil))
debug2: key: /home/dfv/.ssh/id_ed25519 ((nil))
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
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
Your username: dfv
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
Your username:

  * [2]:

HostKey /etc/ssh/ssh_host_rsa_key
HostKey /etc/ssh/ssh_host_ecdsa_key
HostKey /etc/ssh/ssh_host_ed25519_key
SyslogFacility AUTHPRIV
AuthorizedKeysFile	.ssh/authorized_keys
UsePrivilegeSeparation sandbox		# Default for new installations.
AcceptEnv LANG LC_CTYPE LC_NUMERIC LC_TIME LC_COLLATE LC_MONETARY 
LC_MESSAGES
AcceptEnv LC_PAPER LC_NAME LC_ADDRESS LC_TELEPHONE LC_MEASUREMENT
AcceptEnv LC_IDENTIFICATION LC_ALL LANGUAGE
AcceptEnv XMODIFIERS
Subsystem	sftp	/usr/libexec/openssh/sftp-server

PasswordAuthentication no
ChallengeResponseAuthentication yes
GSSAPIAuthentication no
GSSAPICleanupCredentials no
UsePAM yes
PermitRootLogin yes

AuthenticationMethods keyboard-interactive

More information about the openssh-unix-dev mailing list