2

AuthorizedKeysCommand paramter present in the file /etc/ssh/sshd_config. The bash script which i called using this command is getting called twice.

The config file is as follows

#RSAAuthentication yes
#PubkeyAuthentication yes
AuthorizedKeysFile      %h/.ssh/authorized_keys
AuthorizedKeysCommand /opt/a.sh
AuthorizedKeysCommandRunAs nobody

And the bash script which is being called is as follows:

#!/bin/bash
logger "have fun"
if [ $# -eq 1 ];
then
python /opt/validate_user.py $1
exit $?
fi

When i see the logs at /var/log/messages, i see follwing

May 19 20:07:32 username vagrant: have fun
May 19 20:07:32 username vagrant: have fun

I am running Centos 6.7 and ssh version of the server is OpenSSH_5.3p1, OpenSSL 1.0.1e-fips 11 Feb 2013 and of the client is OpenSSH_6.2p2, OSSLShim 0.9.8r 8 Dec 2011 and the command which i am using is ssh -v vagrant@127.0.0.1 -p 2222 Also when i do vagrant ssh then the script is called only once

Edit: When i use the following command ssh vagrant@127.0.0.1 -p 2200 -o IdentitiesOnly=yes -i /Users/Vivek/new_file_1/.vagrant/machines/default/virtualbox/private_key then the script is getting called once only ssh log found using ssh -vv

OpenSSH_6.2p2, OSSLShim 0.9.8r 8 Dec 2011
debug1: Reading configuration data /etc/ssh_config
debug1: /etc/ssh_config line 20: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to 127.0.0.1 [127.0.0.1] port 2200.
debug1: Connection established.
debug3: Incorrect RSA1 identifier
debug3: Could not load "/Users/Vivek/.ssh/id_rsa" as a RSA1 public key
debug1: identity file /Users/Vivek/.ssh/id_rsa type 1
debug1: identity file /Users/Vivek/.ssh/id_rsa-cert type -1
debug1: identity file /Users/Vivek/.ssh/id_dsa type -1
debug1: identity file /Users/Vivek/.ssh/id_dsa-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.2
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.3
debug1: match: OpenSSH_5.3 pat OpenSSH_5*
debug2: fd 3 setting O_NONBLOCK
debug3: put_host_port: [127.0.0.1]:2200
debug3: load_hostkeys: loading entries for host "[127.0.0.1]:2200" from file "/Users/Vivek/.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /Users/Vivek/.ssh/known_hosts:3
debug3: load_hostkeys: loaded 1 keys
debug3: order_hostkeyalgs: prefer hostkeyalgs: ssh-rsa-cert-v01@openssh.com,ssh-rsa-cert-v00@openssh.com,ssh-rsa
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa-cert-v01@openssh.com,ssh-rsa-cert-v00@openssh.com,ssh-rsa,ssh-dss-cert-v01@openssh.com,ssh-dss-cert-v00@openssh.com,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib@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: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug2: dh_gen_key: priv key bits set: 125/256
debug2: bits set: 526/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: RSA d2:10:e9:2e:60:59:8e:52:cd:f9:14:c3:45:fa:71:9d
debug3: put_host_port: [127.0.0.1]:2200
debug3: put_host_port: [127.0.0.1]:2200
debug3: load_hostkeys: loading entries for host "[127.0.0.1]:2200" from file "/Users/Vivek/.ssh/known_hosts"
debug3: load_hostkeys: found key type RSA in file /Users/Vivek/.ssh/known_hosts:3
debug3: load_hostkeys: loaded 1 keys
debug1: Host '[127.0.0.1]:2200' is known and matches the RSA host key.
debug1: Found key in /Users/Vivek/.ssh/known_hosts:3
debug2: bits set: 529/1024
debug1: ssh_rsa_verify: signature correct
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: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /Users/Vivek/.ssh/id_rsa (0x7fc920700000),
debug2: key: .vagrant/machines/default/virtualbox/private_key (0x7fc920416de0),
debug2: key: /Users/Vivek/.ssh/id_dsa (0x0),
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-keyex,gssapi-with-mic,password
debug3: preferred publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /Users/Vivek/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 535
debug2: input_userauth_pk_ok: fp 
debug3: sign_and_send_pubkey: RSA 
debug1: Authentication succeeded (publickey).
Authenticated to 127.0.0.1 ([127.0.0.1]:2200).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: packet_set_tos: set IP_TOS 0x10
debug2: client_session2_setup: id 0
debug2: channel 0: request pty-req confirm 1
debug1: Sending environment.
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env Apple_PubSub_Socket_Render
debug3: Ignored env COLORFGBG
debug3: Ignored env ITERM_PROFILE
debug3: Ignored env XPC_FLAGS
debug3: Ignored env PWD
debug3: Ignored env SHELL
debug3: Ignored env SECURITYSESSIONID
debug1: Sending env LC_CTYPE = UTF-8
debug2: channel 0: request env confirm 0
debug3: Ignored env TERM_PROGRAM
debug3: Ignored env PATH
debug3: Ignored env COMMAND_MODE
debug3: Ignored env TERM
debug3: Ignored env HOME
debug3: Ignored env TMPDIR
debug3: Ignored env USER
debug3: Ignored env XPC_SERVICE_NAME
debug3: Ignored env LOGNAME
debug3: Ignored env ITERM_SESSION_ID
debug3: Ignored env __CF_USER_TEXT_ENCODING
debug3: Ignored env SHLVL
debug3: Ignored env OLDPWD
debug3: Ignored env ZSH
debug3: Ignored env PAGER
debug3: Ignored env LESS
debug3: Ignored env LSCOLORS
debug3: Ignored env _
debug2: channel 0: request shell confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel_input_status_confirm: type 99 id 0
debug2: PTY allocation request accepted on channel 0
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: shell request accepted on channel 0
Last login: Fri May 20 16:19:12 2016 from 10.0.2.2
-bash: warning: setlocale: LC_CTYPE: cannot change locale (UTF-8): No such file or directory

Log of /var/log/secure http://pastebin.com/BSk2j2Qf

  • 1) Server debug log will give you more clue when it is called. 2) Provide the log (ssh -vvv host), where you see it is called twice. I suspect you offer two different keys. – Jakuje May 20 '16 at 10:50
  • @Jakuje Added server debug log pastebin link – user2823667 May 20 '16 at 11:06
1

The authentication to ssh server goes in two steps. The first one is validation if your public key is in the authorized_keys file (or output of the appropriate command), the second one checks if the signature provided by the appropriate private part is the same. In the server log, you can see:

sshd[9951]: debug1: test whether pkalg/pkblob are acceptable
sshd[9950]: debug1: matching key found: file /opt/a.sh, line 1
sshd[9950]: Found matching RSA key: 8b:3c:20:c5:03:c4:c0:03:74:83:0a:8f:2d:d8:48:a2
sshd[9951]: Postponed publickey for vagrant from 10.0.2.2 port 54361 ssh2

referring to the first occurrence (test whether pkalg/pkblob are acceptable). And later one

sshd[9950]: debug1: matching key found: file /opt/a.sh, line 1
sshd[9950]: Found matching RSA key: 8b:3c:20:c5:03:c4:c0:03:74:83:0a:8f:2d:d8:48:a2
sshd[9950]: Accepted publickey for vagrant from 10.0.2.2 port 54361 ssh2
sshd[9950]: debug3: mm_answer_keyverify: key 0x7f54ce6ac570 signature verified

is checking the real signature made by the private part of the key.

And why does it behave different if you specify the key on command line? If openssh see only one identity, that is enforced by IdentitiesOnly option, it skips the first part and does only the second (if there are no more possibilities, what is the point of trying the first check?).

| improve this answer | |
  • Does this happen in the case of AuthorizedKeysFile also ? – user2823667 May 20 '16 at 12:24
  • Yes. This is how the SSH authentication works. You can verify it again by checking server debug log. – Jakuje May 20 '16 at 12:42

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.