客先の火消し案件中にsshの鍵ファイル認証でハデにハマり
限りある時間を必要以上に使ってしまったので
この悲しい記憶を記録とします。
以下の様な環境で、同一の秘密鍵を利用しているのに
【Linux1】<->【Server】の接続は問題ないのだが
【Linux2】<->【Server】の接続は失敗する現象に出くわしました。
ssh ssh
+--------+ +--------+ +--------+
| Linux1 |<---->| Server |<---->| Linux2 |
+--------+ +--------+ +--------+
OK NG
【Server】
os：CentOS release 5.6
sshd：openssh-server 4.3p2-72
【Linux1,Linux2】
openssh-clients 4.3p2-41
まずは【Server】の設定ファイル『/etc/ssh/sshd_config』を以下のとおり変更し
デバッグメッセージを『/var/log/secure』へ出力するようにします。
SyslogFacility AUTHPRIV
LogLevel DEBUG3
んで【Linux2】から【Server】へssh接続を実行すると
[piyo@linux2 ~]$ ssh hoge@example.com
【Server】側にて、以下のログが出力されました。
Jul 28 12:12:48 svn sshd[27401]: debug3: fd 4 is not O_NONBLOCK
Jul 28 12:12:48 svn sshd[27494]: debug1: rexec start in 4 out 4 newsock 4 pipe 6 sock 7
Jul 28 12:12:48 svn sshd[27401]: debug1: Forked child 27494.
Jul 28 12:12:48 svn sshd[27401]: debug3: send_rexec_state: entering fd = 7 config len 701
Jul 28 12:12:48 svn sshd[27401]: debug3: ssh_msg_send: type 0
Jul 28 12:12:48 svn sshd[27401]: debug3: send_rexec_state: done
Jul 28 12:12:48 svn sshd[27494]: debug1: inetd sockets after dupping: 3, 3
Jul 28 12:12:48 svn sshd[27494]: debug3: Normalising mapped IPv4 in IPv6 address
Jul 28 12:12:48 svn sshd[27494]: Connection from xxx.xxx.xxx.xxx port 42178
Jul 28 12:12:48 svn sshd[27494]: debug1: Client protocol version 2.0; client software version OpenSSH_4.3
Jul 28 12:12:48 svn sshd[27494]: debug1: match: OpenSSH_4.3 pat OpenSSH*
Jul 28 12:12:48 svn sshd[27494]: debug1: Enabling compatibility mode for protocol 2.0
Jul 28 12:12:48 svn sshd[27494]: debug1: Local version string SSH-2.0-OpenSSH_4.3
Jul 28 12:12:48 svn sshd[27494]: debug2: fd 3 setting O_NONBLOCK
Jul 28 12:12:48 svn sshd[27495]: debug3: privsep user:group 74:74
Jul 28 12:12:48 svn sshd[27494]: debug2: Network child is on pid 27495
Jul 28 12:12:48 svn sshd[27495]: debug1: permanently_set_uid: 74/74
Jul 28 12:12:48 svn sshd[27494]: debug3: preauth child monitor started
Jul 28 12:12:48 svn sshd[27495]: debug1: list_hostkey_types: ssh-rsa,ssh-dss
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27495]: debug1: SSH2_MSG_KEXINIT sent
Jul 28 12:12:48 svn sshd[27495]: debug1: SSH2_MSG_KEXINIT received
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
Jul 28 12:12:48 svn sshd[27495]: 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
Jul 28 12:12:48 svn sshd[27495]: 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
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: none,zlib@openssh.com
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: none,zlib@openssh.com
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit:
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit:
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: first_kex_follows 0
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: reserved 0
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit:
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit:
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: first_kex_follows 0
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_parse_kexinit: reserved 0
Jul 28 12:12:48 svn sshd[27495]: debug2: mac_init: found hmac-md5
Jul 28 12:12:48 svn sshd[27495]: debug1: kex: client->server aes128-cbc hmac-md5 none
Jul 28 12:12:48 svn sshd[27495]: debug3: Normalising mapped IPv4 in IPv6 address
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_send entering: type 2
Jul 28 12:12:48 svn sshd[27494]: debug3: monitor_read: checking request 2
Jul 28 12:12:48 svn sshd[27494]: debug3: Normalising mapped IPv4 in IPv6 address
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_send entering: type 3
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive_expect entering: type 3
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27495]: debug2: mac_init: found hmac-md5
Jul 28 12:12:48 svn sshd[27495]: debug1: kex: server->client aes128-cbc hmac-md5 none
Jul 28 12:12:48 svn sshd[27495]: debug3: Normalising mapped IPv4 in IPv6 address
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_send entering: type 2
Jul 28 12:12:48 svn sshd[27494]: debug3: monitor_read: checking request 2
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive_expect entering: type 3
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_send entering: type 3
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27495]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_send entering: type 17
Jul 28 12:12:48 svn sshd[27494]: debug3: monitor_read: checking request 17
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_answer_moduli: got parameters: 1024 1024 8192
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive_expect entering: type 18
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_send entering: type 18
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27494]: debug2: monitor_read: 17 used once, disabling now
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_choose_dh: remaining 0
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27495]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
Jul 28 12:12:48 svn sshd[27495]: debug2: dh_gen_key: priv key bits set: 137/256
Jul 28 12:12:48 svn sshd[27495]: debug2: bits set: 536/1024
Jul 28 12:12:48 svn sshd[27495]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
Jul 28 12:12:48 svn sshd[27495]: debug2: bits set: 499/1024
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_key_sign entering
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_send entering: type 22
Jul 28 12:12:48 svn sshd[27494]: debug3: monitor_read: checking request 22
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive_expect entering: type 23
Jul 28 12:12:48 svn sshd[27495]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_answer_sign
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_answer_sign: signature 0x9c1c7a0(271)
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_send entering: type 23
Jul 28 12:12:48 svn sshd[27494]: debug2: monitor_read: 22 used once, disabling now
Jul 28 12:12:48 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:48 svn sshd[27495]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
Jul 28 12:12:48 svn sshd[27495]: debug2: kex_derive_keys
Jul 28 12:12:48 svn sshd[27495]: debug2: set_newkeys: mode 1
Jul 28 12:12:48 svn sshd[27495]: debug1: SSH2_MSG_NEWKEYS sent
Jul 28 12:12:48 svn sshd[27495]: debug1: expecting SSH2_MSG_NEWKEYS
Jul 28 12:12:48 svn sshd[27495]: debug2: set_newkeys: mode 0
Jul 28 12:12:48 svn sshd[27495]: debug1: SSH2_MSG_NEWKEYS received
Jul 28 12:12:48 svn sshd[27495]: debug1: KEX done
Jul 28 12:12:49 svn sshd[27495]: debug1: userauth-request for user kachina service ssh-connection method none
Jul 28 12:12:49 svn sshd[27495]: debug1: attempt 0 failures 0
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_getpwnamallow entering
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_send entering: type 24
Jul 28 12:12:49 svn sshd[27494]: debug3: monitor_read: checking request 24
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_answer_pwnamallow
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_request_send entering: type 25
Jul 28 12:12:49 svn sshd[27494]: debug2: monitor_read: 24 used once, disabling now
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_receive_expect entering: type 25
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_receive entering
Jul 28 12:12:49 svn sshd[27495]: debug2: input_userauth_request: setting up authctxt for kachina
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_start_pam entering
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_send entering: type 6
Jul 28 12:12:49 svn sshd[27494]: debug3: monitor_read: checking request 6
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_inform_authserv entering
Jul 28 12:12:49 svn sshd[27494]: debug1: PAM: initializing for "kachina"
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_send entering: type 20
Jul 28 12:12:49 svn sshd[27494]: debug3: Normalising mapped IPv4 in IPv6 address
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_inform_authrole entering
Jul 28 12:12:49 svn sshd[27494]: debug3: Trying to reverse map address xxx.xxx.xxx.xxx.
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_send entering: type 21
Jul 28 12:12:49 svn sshd[27495]: debug2: input_userauth_request: try method none
Jul 28 12:12:49 svn sshd[27495]: debug1: userauth-request for user kachina service ssh-connection method publickey
Jul 28 12:12:49 svn sshd[27495]: debug1: attempt 1 failures 1
Jul 28 12:12:49 svn sshd[27495]: debug2: input_userauth_request: try method publickey
Jul 28 12:12:49 svn sshd[27495]: debug1: test whether pkalg/pkblob are acceptable
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_key_allowed entering
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_send entering: type 38
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_receive_expect entering: type 39
Jul 28 12:12:49 svn sshd[27495]: debug3: mm_request_receive entering
Jul 28 12:12:49 svn sshd[27494]: debug1: PAM: setting PAM_RHOST to "example.com"
Jul 28 12:12:49 svn sshd[27494]: debug1: PAM: setting PAM_TTY to "ssh"
Jul 28 12:12:49 svn sshd[27494]: debug2: monitor_read: 6 used once, disabling now
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:49 svn sshd[27494]: debug3: monitor_read: checking request 20
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_answer_authserv: service=ssh-connection, style=
Jul 28 12:12:49 svn sshd[27494]: debug2: monitor_read: 20 used once, disabling now
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:49 svn sshd[27494]: debug3: monitor_read: checking request 21
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_answer_authrole: role=
Jul 28 12:12:49 svn sshd[27494]: debug2: monitor_read: 21 used once, disabling now
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:49 svn sshd[27494]: debug3: monitor_read: checking request 38
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_answer_keyallowed entering
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_answer_keyallowed: key_from_blob: 0x9c21770
Jul 28 12:12:49 svn sshd[27494]: debug1: temporarily_use_uid: 503/503 (e=0/0)
Jul 28 12:12:49 svn sshd[27494]: debug1: trying public key file /home/hoge/.ssh/authorized_keys
Jul 28 12:12:49 svn sshd[27494]: debug3: secure_filename: checking '/home/hoge/.ssh'
Jul 28 12:12:49 svn sshd[27494]: debug3: secure_filename: checking '/home/hoge'
Jul 28 12:12:49 svn sshd[27494]: debug3: secure_filename: terminating check at '/home/hoge'
Jul 28 12:12:49 svn sshd[27494]: debug1: restore_uid: 0/0
Jul 28 12:12:49 svn sshd[27494]: debug2: key not found
Jul 28 12:12:49 svn sshd[27494]: debug1: temporarily_use_uid: 503/503 (e=0/0)
Jul 28 12:12:49 svn sshd[27494]: debug1: trying public key file /home/hoge/.ssh/authorized_keys
Jul 28 12:12:49 svn sshd[27494]: debug3: secure_filename: checking '/home/hoge/.ssh'
Jul 28 12:12:49 svn sshd[27494]: debug3: secure_filename: checking '/home/hoge'
Jul 28 12:12:49 svn sshd[27494]: debug3: secure_filename: terminating check at '/home/hoge'
Jul 28 12:12:49 svn sshd[27494]: debug1: restore_uid: 0/0
Jul 28 12:12:49 svn sshd[27494]: debug2: key not found
Jul 28 12:12:49 svn sshd[27494]: Failed publickey for kachina from xxx.xxx.xxx.xxx port 42178 ssh2
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_answer_keyallowed: key 0x9c21770 is disallowed
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_request_send entering: type 39
Jul 28 12:12:49 svn sshd[27494]: debug3: mm_request_receive entering
Jul 28 12:12:49 svn sshd[27495]: debug2: userauth_pubkey: authenticated 0 pkalg ssh-rsa
Jul 28 12:12:49 svn sshd[27495]: debug3: Normalising mapped IPv4 in IPv6 address
Jul 28 12:12:49 svn sshd[27495]: Connection closed by xxx.xxx.xxx.xxx
Jul 28 12:12:49 svn sshd[27495]: debug1: do_cleanup
Jul 28 12:12:49 svn sshd[27495]: debug3: PAM: sshpam_thread_cleanup entering
Jul 28 12:12:49 svn sshd[27494]: debug1: do_cleanup
Jul 28 12:12:49 svn sshd[27494]: debug1: PAM: cleanup
Jul 28 12:12:49 svn sshd[27494]: debug3: PAM: sshpam_thread_cleanup entering
この手の内容でググると【Server】側のパーミッションの問題ってのがヒットするのだけど
その場合は【Linux1】<->【Server】も失敗するハズなので無関係と判断します。
さて、パーミッション以外の情報が全然ないの。。。
【Linux1】と【Linux2】の『~/.ssh』以下を比較してみると
【Linux1】の『id_rsa』と『id_rsa.pub』が対(キーペア)であることに対して
【Linux2】の『id_rsa』と『id_rsa.pub』は対(キーペア)ではありませんでした。
ってことで、【Linux2】の『id_rsa.pub』をリネームして再接続してみると成功！
要約すると、sshクライアントが自動認識する
秘密鍵ファイル『~/.ssh/id_rsa』と、公開鍵ファイル『~/.ssh/id_rsa.pub』が存在する場合に
この2ファイルは対(キーペア)である必要がある。
秘密鍵なんて、何個も作るもんじゃないね。。。