デバッグ sshやscpで接続できないときに確認する内容(debug)

デバッグ sshやscpで接続できないときに確認する内容(debug)

この記事を読むのに必要な時間は約 22 分です。

クライアントからだと絶対にわからない

ssh接続が上手くいかないときの確認方法

たまにやる超個別記事です。

今回はサーバーからサーバーへsshとscpで接続した際に、鍵認証が上手く通らなかった場合の確認方法について説明したいと思います。

なお、今回私に発生していたトラブルはクライアントからだと絶対にわからない内容でした。

また、表記しているIPやサーバー、鍵情報は適宜適当な値に置き換えていると思ってください。

 

そもそも鍵認証とは

今度この部分はじっくり書きたいと思います。

( ;∀;)

クライアント側での確認

ssh -v デバッグモードで接続

まずはクライアントからデバッグモードで接続します。

デバッグモードのオプションは  -v です。

因みに -vv や -vvv で詳細レベルが上がっていきますが、大体は -vで十分だと思います。

デバッグモードで確認するとこのようなログがつらつら出ます。

 

[MotoServer@s123 ~]$ ssh -v -i ~/.ssh/id_rsa SetsuzokusakiID@20.20.20.20
OpenSSH_7.3p1, OpenSSL 1.0.2k-fips 26 Jan 2017
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 58: Applying options for *
debug1: Connecting to 20.20.20.20 [20.20.20.20] port 22.
debug1: Connection established.
debug1: key_load_public: No such file or directory
debug1: identity file /virtual/MotoServer/.ssh/id_rsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /virtual/MotoServer/.ssh/id_rsa-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_7.3
debug1: Remote protocol version 2.0, remote software version OpenSSH_7.3
debug1: match: OpenSSH_7.3 pat OpenSSH* compat 0x04000000
debug1: Authenticating to 20.20.20.20:22 as ‘SetsuzokusakiID’
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ecdsa-sha2-nistp256
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: curve25519-sha256 need=64 dh_need=64
debug1: kex: curve25519-sha256 need=64 dh_need=64
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ecdsa-sha2-nistp256 SHA256:mYToyPQoDRabp1232LbiNupKS8pasdfay03NQ
debug1: Host ‘20.20.20.20’ is known and matches the ECDSA host key.
debug1: Found key in /virtual/MotoServer/.ssh/known_hosts:2
debug1: rekey after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: rekey after 134217728 blocks
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<rsa-sha2-256,rsa-sha2-512>
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic
debug1: Next authentication method: gssapi-keyex
debug1: No valid Key exchange context
debug1: Next authentication method: gssapi-with-mic
debug1: Unspecified GSS failure. Minor code may provide more information
No Kerberos credentials available (default cache: KEYRING:persistent:10151)

debug1: Unspecified GSS failure. Minor code may provide more information
No Kerberos credentials available (default cache: KEYRING:persistent:10151)

debug1: Next authentication method: publickey
debug1: Trying private key: /virtual/MotoServer/.ssh/id_rsa
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic
debug1: No more authentication methods to try.
Permission denied (publickey,gssapi-keyex,gssapi-with-mic).

 

因みにこの状態でのサーバー側でのログは以下の通りです。

May 20 14:24:27 SakiServer sshd[3524]: Connection closed by 10.10.10.10 port 59668 [preauth]

たったのこれ一行だけです。

情報少なすぎでしょう・・・・

デバッグしていない状態だと殆ど情報が残りませんので原因の追究は正直難しいとです。

Unspecified GSS failure. Minor code may provide more information No Kerberos credentials available

因みに上記2個の文章ですが・・

めちゃくちゃそれっぽいですが、こんなの調べ続けて行っても原因にはたどり着けません!

sshのログモードをデバッグモードにしてみる。

CentOS7 の前提ですがクライアントではなくサーバー側のSSHの設定をいじってデバッグモードをオンにします。

いじくるファイルは/etc/ssh配下にあるsshd_configです。

このファイルの中のこのような記載があるのですが・・・

# Logging
#SyslogFacility AUTH
SyslogFacility AUTHPRIV
#LogLevel INFO

このように書き換えます。

# Logging
#SyslogFacility AUTH
SyslogFacility AUTHPRIV
#LogLevel INFO
LogLevel debug

ピンク色文字を追加しただけですね。

この状態でサーバーのプロセス再起動を行います。

以下コマンド一発です。

systemctl restart sshd.service

因みにほとんどが sudo su でルートになった状態でないとコマンドが通らないです。

ここまでの設定をしてみたら、改めて接続を試してみたいと思います。

ログの変化

以下、うまくいかない状態でデバッグログを有効にしてみた結果です。

May 20 14:36:38 SakiServer sshd[3726]: debug1: Forked child 3731.
May 20 14:36:38 SakiServer sshd[3731]: debug1: Set /proc/self/oom_score_adj to 0
May 20 14:36:38 SakiServer sshd[3731]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
May 20 14:36:38 SakiServer sshd[3731]: debug1: inetd sockets after dupping: 3, 3
May 20 14:36:38 SakiServer sshd[3731]: Connection from 10.10.10.10 port 35118 on 30.30.30.30 port 22
May 20 14:36:38 SakiServer sshd[3731]: debug1: Client protocol version 2.0; client software version OpenSSH_7.3
May 20 14:36:38 SakiServer sshd[3731]: debug1: match: OpenSSH_7.3 pat OpenSSH* compat 0x04000000
May 20 14:36:38 SakiServer sshd[3731]: debug1: Local version string SSH-2.0-OpenSSH_7.3
May 20 14:36:38 SakiServer sshd[3731]: debug1: Enabling compatibility mode for protocol 2.0
May 20 14:36:38 SakiServer sshd[3731]: debug1: SELinux support enabled [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: permanently_set_uid: 74/74 [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: SSH2_MSG_KEXINIT sent [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: SSH2_MSG_KEXINIT received [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: kex: algorithm: curve25519-sha256 [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: rekey after 134217728 blocks [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: SSH2_MSG_NEWKEYS received [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: rekey after 134217728 blocks [preauth]
May 20 14:36:38 SakiServer sshd[3731]: debug1: KEX done [preauth]
May 20 14:36:39 SakiServer sshd[3731]: debug1: userauth-request for user SetsuzokusakiID service ssh-connection method none [preauth]
May 20 14:36:39 SakiServer sshd[3731]: debug1: attempt 0 failures 0 [preauth]
May 20 14:36:39 SakiServer sshd[3731]: debug1: PAM: initializing for “SetsuzokusakiID”
May 20 14:36:39 SakiServer sshd[3731]: debug1: PAM: setting PAM_RHOST to “FromNoServer”
May 20 14:36:39 SakiServer sshd[3731]: debug1: PAM: setting PAM_TTY to “ssh”
May 20 14:36:39 SakiServer sshd[3731]: debug1: userauth-request for user SetsuzokusakiID service ssh-connection method publickey [preauth]
May 20 14:36:39 SakiServer sshd[3731]: debug1: attempt 1 failures 0 [preauth]
May 20 14:36:39 SakiServer sshd[3731]: debug1: temporarily_use_uid: 1000/1001 (e=0/0)
May 20 14:36:39 SakiServer sshd[3731]: debug1: trying public key file /home/SetsuzokusakiID/.ssh/authorized_keys
May 20 14:36:39 SakiServer sshd[3731]: debug1:Could not open authorized keys ‘/home/SetsuzokusakiID/.ssh/authorized_keys’: No such file or directory
May 20 14:36:39 SakiServer sshd[3731]: debug1: restore_uid: 0/0
May 20 14:36:39 SakiServer sshd[3731]: Failed publickey for SetsuzokusakiID from 10.10.10.10 port 35118 ssh2: RSA SHA256:2CcO8pGRspOL2cjgi1123gXFYyJsAhBOqJhs
May 20 14:36:39 SakiServer sshd[3731]: Connection closed by 10.10.10.10 port 35118 [preauth]
May 20 14:36:39 SakiServer sshd[3731]: debug1: do_cleanup [preauth]
May 20 14:36:39 SakiServer sshd[3731]: debug1: monitor_read_log: child log fd closed
May 20 14:36:39 SakiServer sshd[3731]: debug1: do_cleanup
May 20 14:36:39 SakiServer sshd[3731]: debug1: PAM: cleanup
May 20 14:36:39 SakiServer sshd[3731]: debug1: Killing privsep child 3732

どうですか?デバッグをオンにしていないときがたったの1行なのに対して、

これだけの分量でログを出力してくれます。また、エラーがばっちり出ていますがわかりますか?

それでは次のページで、わからない人向けの解説をしてみたいと思います。

タイトルとURLをコピーしました