最近会社で聞かれて答えたことをまとめてみました。

関連会社が用意したSSHサーバーに公開鍵認証でログインできない、関連会社からログを送ってほしいと言われた、どの部分を送ればいいだろうかと聞かれました。

この場面で答えたことをまとめてみました。

質問された環境の背景

質問された環境の背景状況は以下のとおりです。

認証方式は公開鍵認証のみです。パスワード認証は許可されていません。
認証に必要な情報はすべて、関連会社が用意しています。ここでいう"認証に必要な情報"には、接続先サーバーのIPアドレス、ポート番号、ユーザー名、秘密鍵を含んでいます。
鍵の形式は"RSA-2048ビット"です。
SSHサーバーのログを参照する術はありません。
今回の接続は、本番接続ではありません。テスト接続です。そのため、SSHクライアントに指定はありません。
サーバーはLinux+OpenSSHサーバーです。

接続先サーバーを管理する組織が秘密鍵を作成するというのは適切ではない運用だと思います。しかし、技術的に最適な方法を必ずしも選択できるわけではないという、世間でよくある状況の一つだと思ってください。

SSHクライアントに指定はありません。本番環境に近い環境でテストすることが理想です。OSにはWindows 10を選択しました。SSHクライアントソフトウェアには、ログ機能の充実度合いを考慮し、Windows 10に標準付属されている"ssh.exe"を用いることにしています。

上記の質問状況と同じ環境でテストするための環境

今回は、以下のようなテスト環境でテストを行いました。

サーバー : OpenSSHサーバー on Linux(Debian) on Docker on Linux(CentOS:7.7)
クライアント : Windows 10 + OpenSSHクライアント

DockerホストにはSSHで接続している環境となっています。そして、DockerコンテナにはSSHトンネル越しに"localhost:10022"で接続できる環境になっています。

環境構築

ここからは、質問状況と同じ環境をテストするための環境構築方法を説明します。

今回は、以下のようなテスト環境を用いました。

サーバー : OpenSSHサーバー on Linux(Debian) on Docker on Linux(CentOS:7.7)
クライアント : Windows 10 + OpenSSHクライアント

手間を省くため、鍵生成はDockerホストで作成しています。

鍵ペアの作成

Dockerホスト上で以下のコマンドを実行します。ここで作成した鍵ペアは、このテストでのみ使用するものです。

[linuser@localhost ~]$PS1='[\u@localhost \W]\$'
[linuser@localhost ~]$cd ~/tmp
[linuser@localhost tmp]$ssh-keygen -t rsa -b 2048 -N ABCDEFG -C TestKey -f id_rsa_test
Generating public/private rsa key pair.
Your identification has been saved in id_rsa_test.
Your public key has been saved in id_rsa_test.pub.
The key fingerprint is:
SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds TestKey
The key's randomart image is:
+---[RSA 2048]----+
|           .o+o o|
|          .o=o.o |
|        . o=+o   |
|       + * o+o.  |
|      . S * +..  |
|       o * + =o.o|
|      . + . E+oo+|
|         o...oo+.|
|         .o..oo..|
+----[SHA256]-----+
[linuser@localhost tmp]$

サーバー環境の構築

先日作成した"cvs-server"を簡素化したものを"ssh-server"として実行します。

Dockerfileは以下のような感じです。今回はsshdを手動起動としてあります。設定変更を行った場合の動作を確認したいため、sshdの再起動を必要とする部分があるからです。

FROM debian
RUN apt-get update && \
    apt-get -y install openssh-server && \
    useradd -m linuser && \
    ( echo linuser:linuser | chpasswd )
RUN /bin/sed -i -e 's/^#PasswordAuthentication yes/PasswordAuthentication no/' /etc/ssh/sshd_config
RUN /etc/init.d/ssh start && /etc/init.d/ssh stop
CMD [ "tail", "-f", "/dev/null" ]

以下のコマンドでコンテナを起動し、公開鍵認証に必要なファイルの作成と、SSHサーバーの起動を行いました。

docker build -t my/ssh-server .
docker run -d --name ssh-server -p 10022:22 my/ssh-server
docker exec /etc/init.d/sshd start
docker exec -u linuser ssh-server mkdir /home/linuser/.ssh
docker exec -u linuser ssh-server chmod u=rwx,go= /home/linuser/.ssh
docker exec -u linuser ssh-server touch /home/linuser/.ssh/authorized_keys
docker exec -u linuser ssh-server chmod u=rw,go= /home/linuser/.ssh/authorized_keys
cat id_rsa_test.pub | docker exec -i -u linuser ssh-server sh -c 'cat >> /home/linuser/.ssh/authorized_keys'
docker exec ssh-server /etc/init.d/ssh start

クライアント環境に秘密鍵ファイルをコピー

Dockerホストからクライアントに秘密鍵ファイルをコピーします。Dockerホストからscpする形でコピーすることにします。

C:\Tmp> scp linuser@***.***.***.***:~/tmp/id_rsa_test .
linuser@***.***.***.***'s password:
id_rsa_test                    100% 1766    27.0KB/s   00:00

C:\Tmp>

接続確認

クライアントからサーバーへの接続を確認します。

C:\Tmp> ssh -p 10022 -i id_rsa_test linuser@127.0.0.1 echo OK
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
@         WARNING: UNPROTECTED PRIVATE KEY FILE!          @
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
Permissions for 'id_rsa_test' are too open.
It is required that your private key files are NOT accessible by others.
This private key will be ignored.
Load key "id_rsa_test": bad permissions
linuser@127.0.0.1: Permission denied (publickey).

C:\Tmp>

このようになります。OpenSSHクライアントには、秘密鍵の権限が充分に制限されているかを確認する仕組みがあります。確認NGとなると、このようにエラーメッセージが表示されます。

権限を全削除して、利用者ユーザーだけが読み書きできるように権限を変更します。

C:\Tmp>icacls id_rsa_test /remove Administrators
    :
C:\Tmp>icacls id_rsa_test /remove SYSTEM
    :
C:\Tmp>icacls id_rsa_test /remove Users
    :
C:\Tmp>icacls id_rsa_test /remove "Authenticated Users"
    :
C:\Tmp>icacls id_rsa_test /grant WinUser:F
    :
C:\Tmp>

この状態で再度実行します。適切に接続できることが分かります。

C:\tmp>ssh -p 10022 -i id_rsa_test linuser@127.0.0.1 echo OK
Enter passphrase for key 'id_rsa_test':
OK
C:\tmp>

これで実験環境は整いました。

ログ確認結果

正常ログ

正常ログをデバッグレベル1で確認します。デバッグレベルは"-v"の数で決まります。

C:\tmp>ssh -p 10022 -i id_rsa_test -v linuser@127.0.0.1 echo OK
OpenSSH_for_Windows_7.7p1, LibreSSL 2.6.5
debug1: Reading configuration data C:\\Users\\WinUser/.ssh/config
debug1: Connecting to 127.0.0.1 [127.0.0.1] port 10022.
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established.
debug1: key_load_public: No such file or directory
debug1: identity file id_rsa_test type -1
debug1: key_load_public: No such file or directory
debug1: identity file id_rsa_test-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_for_Windows_7.7
debug1: Remote protocol version 2.0, remote software version OpenSSH_7.9p1 Debian-10+deb10u2
debug1: match: OpenSSH_7.9p1 Debian-10+deb10u2 pat OpenSSH* compat 0x04000000
debug1: Authenticating to 127.0.0.1:10022 as 'linuser'
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: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ecdsa-sha2-nistp256 SHA256:TMYajsSnGjt6+kR5Yb36PjciLhmNNebRgDQ+KxXRuZQ
debug1: Host '[127.0.0.1]:10022' is known and matches the ECDSA host key.
debug1: Found key in C:\\Users\\WinUser/.ssh/known_hosts:1
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=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521>
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey
debug1: Trying private key: id_rsa_test
debug1: read_passphrase: can't open /dev/tty: No such file or directory
Enter passphrase for key 'id_rsa_test':
debug1: Authentication succeeded (publickey).
Authenticated to 127.0.0.1 ([127.0.0.1]:10022).
debug1: channel 0: new [client-session]
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: pledge: network
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug1: Remote: /home/linuser/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Sending command: echo OK
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: client_input_channel_req: channel 0 rtype eow@openssh.com reply 0
OK
debug1: channel 0: free: client-session, nchannels 1♪◙Transferred: sent 2760, received 2464 bytes, in 0.1 seconds♪◙Bytes per second: sent 19570.3, received 17471.5♪◙s 0♪◙1: Exit statu
C:\tmp>

ログを読み解くと、大まかに以下の順に処理が行われていることが分かります。クライアント視点で書いています。

設定ファイルの読み込み (C:\Users\WinUser.ssh\config)
SSHサーバーへの接続確立
ログイン認証のための秘密鍵ファイルの存在確認 (id_rsa)
サーバーとのネゴシエーション
ホスト鍵の受信、ホスト鍵の確認 (known_hosts)
使用可能な認証方式の受信 (Authentications that can continue: publickey)
公開鍵認証の開始 (Authentications that can continue: publickey)(Trying private key: id_rsa_test)
公開鍵認証の正否受信 (Authentication succeeded (publickey))
サーバー機能の受信 (key options: agent-forwarding port-forwarding pty user-rc x11-forwarding)
コマンド送信 (Sending command: echo OK)
結果受領
SSHサーバーから接続切断

今回の質問は、公開鍵認証の認証NG時のログを送るには何を送ればよいか、でした。その観点でログを抜粋すると、必要なものは"使用可能な認証方式の受信"～"公開鍵認証の正否受信"です。逆に"設定ファイルの読み込み"などの情報は、協力会社に提出する必要がない、場合によっては送るにふさわしくない情報が含まれている可能性すらあります。

さて、"使用可能な認証方式の受信"～"公開鍵認証の正否受信"にあたるログを抜粋すると、以下になります。

C:\tmp>ssh -p 10022 -i id_rsa_test -v linuser@127.0.0.1 echo OK
    :
debug1: Authentications that can continue: publickey
debug1: Trying private key: id_rsa_test
debug1: read_passphrase: can't open /dev/tty: No such file or directory
Enter passphrase for key 'id_rsa_test':
debug1: Authentication succeeded (publickey).
    :
C:\tmp>

デバッグレベルを3に上げると、以下のようになります。デバッグレベルを上げても、それほど情報量は増えません。送信する公開鍵を確認できるようになるくらいです。

C:\tmp>ssh -p 10022 -i id_rsa_test -v -v -v linuser@127.0.0.1 echo OK
    :
debug1: Authentications that can continue: publickey
debug1: Trying private key: id_rsa_test
debug3: failed to open file:C:/dev/tty error:3
debug1: read_passphrase: can't open /dev/tty: No such file or directory
Enter passphrase for key 'id_rsa_test':
debug3: sign_and_send_pubkey: RSA SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 52
debug1: Authentication succeeded (publickey).
    :
C:\tmp>

送信している公開鍵のハッシュ値は、"ssh-keygen -lf id_rsa_test"で確認できます。

C:\Tmp>ssh-keygen -lf id_rsa_test
Enter PEM pass phrase:
2048 SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds no comment (RSA)

C:\Tmp>

異常ログ：公開鍵認証失敗

SSHサーバーの"authorized_keys"をなくしてみます。今回の場合、Dockerホストで以下のコマンドを実行することで、環境を作り出すことができます。

docker exec -u linuser ssh-server mv /home/linuser/.ssh/authorized_keys /home/linuser/.ssh/authorized_keys_backup

クライアントログは以下のようになります。

C:\tmp>ssh -p 10022 -i id_rsa_test -v -v -v linuser@127.0.0.1 echo OK
    :
debug1: Authentications that can continue: publickey
debug1: Trying private key: id_rsa_test
debug3: failed to open file:C:/dev/tty error:3
debug1: read_passphrase: can't open /dev/tty: No such file or directory
Enter passphrase for key 'id_rsa_test':
debug3: sign_and_send_pubkey: RSA SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey
debug2: we did not send a packet, disable method
debug1: No more authentication methods to try.
linuser@127.0.0.1: Permission denied (publickey).
    :
C:\tmp>

ログを比較すると、以下のことが分かります。

送信した鍵が受け付けられると、サーバーから"debug3: receive packet: type 52"が返される。
送信した鍵が受け付けられないと、サーバーから"debug3: receive packet: type 51"が返される。
鍵が受け付けられない場合、次の鍵に移る。全ての鍵が受け付けられないことが分かると、公開鍵認証失敗となる。

会社では、この"debug3: receive packet: type 51"の部分を説明することができませんでした。このあたりの動きをより詳しく知るには、OpenSSHのソースコードの"SSH2_MSG_USERAUTH_FAILURE"部分を調べるといいと思います。

異常ログ：公開鍵認証失敗、パスワード認証成功

パスワード認証を許可してみます。今回の場合、Dockerホストで以下のコマンドを実行することで、環境を作り出すことができます。

docker exec ssh-server sed -i -e 's/^PasswordAuthentication no/PasswordAuthentication yes/' /etc/ssh/sshd_config
docker exec ssh-server /etc/init.d/ssh stop
docker exec ssh-server /etc/init.d/ssh start

クライアントログは以下のようになります。

C:\tmp>ssh -p 10022 -i id_rsa_test -v -v -v linuser@127.0.0.1 echo OK
    :
debug1: Authentications that can continue: publickey,password
debug1: Trying private key: id_rsa_test
debug3: failed to open file:C:/dev/tty error:3
debug1: read_passphrase: can't open /dev/tty: No such file or directory
Enter passphrase for key 'id_rsa_test':
debug3: sign_and_send_pubkey: RSA SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey,password
debug2: we did not send a packet, disable method
debug3: authmethod_lookup password
debug3: remaining preferred: ,password
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
debug3: failed to open file:C:/dev/tty error:3
debug1: read_passphrase: can't open /dev/tty: No such file or directory
linuser@127.0.0.1's password:
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 52
debug1: Authentication succeeded (password).
    :
C:\tmp>

ログを比較すると、以下のことが分かります。

パスワード認証が許可されていると、"debug1: Authentications that can continue: publickey,password"と表示される。許可されていないと、末尾部分には"publickey"とだけ表示される。
送信した鍵が受け付けられないため、サーバーから"debug3: receive packet: type 51"が返される
全ての鍵が受け付けられないことが分かり、公開鍵認証失敗となる。
公開鍵認証は失敗となったがパスワード認証が残っているので、"Next authentication method: password"と表示される。

ログのこのあたりを見ることで、サーバーがパスワード認証を許しているか否かが分かります。

まとめ

今回の質問は、"公開鍵認証の認証NG時のログを送るには何を送ればよいか"でした。クライアントから接続する際に必要な設定情報が正しいものであること、それでもなお異常動作となっていること、それをログで示すということが重要なポイントでした。

クライアントから接続する際に、クライアント側から制御できる情報は以下のようなものです。

接続先：IPアドレスおよびポート番号
ユーザー名
鍵情報

これらの情報と、それでもなお接続NGであること、それらをログで示すことができればよいわけです。

公開鍵認証NG時のログを再掲してみます。デバッグレベル3のログです。加えて、接続先情報の部分も抜粋しています。

C:\tmp>ssh -p 10022 -i id_rsa_test -v -v -v linuser@127.0.0.1 echo OK
    :
debug1: Connecting to 127.0.0.1 [127.0.0.1] port 10022.
    :
debug1: Authentications that can continue: publickey
debug1: Trying private key: id_rsa_test
debug3: failed to open file:C:/dev/tty error:3
debug1: read_passphrase: can't open /dev/tty: No such file or directory
Enter passphrase for key 'id_rsa_test':
debug3: sign_and_send_pubkey: RSA SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey
debug2: we did not send a packet, disable method
debug1: No more authentication methods to try.
linuser@127.0.0.1: Permission denied (publickey).
    :
C:\tmp>

ここから読み解けるものは、以下のとおりです。

接続先のIPアドレスおよびポート番号が"127.0.0.1:10022"であること
- debug1: Connecting to 127.0.0.1 [127.0.0.1] port 10022
サーバーが公開鍵認証のみを許していること
- debug1: Authentications that can continue: publickey
クライアントが使用している秘密鍵は"id_rsa_test"であること
- debug1: Trying private key: id_rsa_test
クライアントが使用している秘密鍵は、ハッシュ値が"RSA SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds"であること
- debug3: sign_and_send_pubkey: RSA SHA256:4dPGF1yXMEp70guF7f7TpCtl7tWgrWEBLozb+eMQtds
クライアントからの認証要求"SSH2_MSG_USERAUTH_REQUEST(50)"に対して、認証NG応答"SSH2_MSG_USERAUTH_FAILURE(51)"を受信したということ
- debug3: receive packet: type 51
認証に使用したユーザー名が"linuser"であること
- linuser＠127.0.0.1: Permission denied (publickey)
上記の接続設定を用いて、最終的に認証NGとなったこと
- linuser＠127.0.0.1: Permission denied (publickey)

このログがあれば十分だということが分かると思います。

なお、今回の話は、過去の記事"問題の解決方法 SSHの鍵認証接続を題材に"に挙げた、以下の要素にリンクする話でもあると思います。

問題の要素が使われる順番を正しく理解するように心がける
現象や調査結果から多くの情報を得ようとする

OpenSSHの公開鍵認証時の正常異常ログ比較