過去に何度か会社で聞かれて答えたことを思い起こし、共通部分を抜き出してまとめてみました。

もともと聞かれたことは「鍵認証でSSH接続できない」「Oracle接続できない」などです。これを題材に、問題の原因特定から解決までの道筋をまとめてみます。

ここに挙げた問題解決は、決まったゴールありきの狭い意味での問題解決です。代替手段を考えるとか、よりよい提案をするとか、本当の問題がそこにあるのか考えるとか、もっと広い意味での問題解決と呼べるものがいろいろあります。この記事ではそれらは対象外です。

SSHの鍵認証を題材に

鍵認証でSSH接続できないという場面を考えます。

まず、鍵認証でSSH接続するために必要な要素(ハードウェア、ソフトウェア、設定など)を思い描いてみます。
- SSHサーバーとSSHクライアント
- 途中のネットワーク機器(ルータやケーブル)
- 秘密鍵と公開鍵

今まで一度もやったことがないとしても、今から鍵認証をしようというなら、最低限これくらいのことを思い浮かべられるはずです。

次に、これらを使われる順に並べてみます。なお、かなり省略して書いています。そのため、図の順番は本当は正しくありません。

すべてがうまく動いていれば、鍵認証ログインできるはずです。うまく動いていない部分がどこかにあるから鍵認証ログインできないのです。例えば、SSHサーバーが鍵認証を使えるようにうまく設定できていない場合、以下のような図になります。

SSHサーバーの接続まではうまく動く、鍵認証の部分がうまく動かないという図です。

"鍵認証の部分が問題"ということを知らない状態で、問題がどこにあるかを特定する必要があります。SSHクライアントはOKのはずです。そして、鍵認証の部分はNGとなっているはずです。どこからか先がNGとなっているわけです。始まりと終わりのどちらかから順番に、あるいは途中のどこかを見て、OKとNGの境界となっている場所を追い詰めます。

どのような順番で調べるかはさておき、今回の場合は調べていく中で、SSHサーバーへの接続はうまく動くか、鍵認証がうまく動くか、この2つを調べることになります。

まずは、SSHサーバーに接続できるか調べるところを見ていきましょう。

良いシステムであれば問題調査のための仕組み、大抵はログ出力機能やデバッグ表示が設けられています。

SSHクライアントのログを見てみましょう。以下は、最近のWindowsに標準で付属しているsshクライアントです。"-v"オプションをつけているので、詳細なデバッグ表示が出力されています。SSHサーバーに接続できたこと、SSHサーバーが鍵認証だけを許可していること、鍵が受け付けられなかったことが確認できます。

PS > ssh -l linuser 192.168.56.102
PS > ssh -v -l linuser -i id_rsa 192.168.56.102
OpenSSH_for_Windows_7.7p1, LibreSSL 2.6.5
debug1: Connecting to 192.168.56.102 [192.168.56.102] port 22.
debug1: Connection established.
    : (略)
debug1: Authentications that can continue: publickey
debug1: Next authentication method: publickey
debug1: Offering public key: RSA SHA256:og/1Kz3RWqkClvYm1aKYznYhwngVCE1x070wouBurKQ id_rsa
debug1: Authentications that can continue: publickey
debug1: No more authentication methods to try.
linuser@192.168.56.102: Permission denied (publickey).
PS >

SSHサーバーに接続できたことは"Connection established."で分かります。SSHサーバーが鍵認証だけを許可していることは"(publickey)"で分かります。鍵が受け付けられなかったことを明示しているものはありません。但し結果的に認証に失敗したことが"Permission denied"で確認できます。

Puttyなら、コンテキストメニューの"Event Log"で確認できます。こちらも同様の情報を確認できます。以下は、Putty-GDIを使ったものです。

2019-04-03 20:06:35 Connecting to 192.168.56.102 port 22
2019-04-03 20:06:35 We claim version: SSH-2.0-PuTTY_Unidentified_Local_Build
2019-04-03 20:06:35 Server version: SSH-2.0-OpenSSH_7.7p1 Ubuntu-4
2019-04-03 20:06:35 Using SSH protocol version 2
    : (略)
2019-04-03 20:06:38 Disconnected: No supported authentication methods available (server sent: publickey)

SSHサーバーに接続できたことは"Server version"で分かります。SSHサーバーが鍵認証だけを許可していることは"(server sent: publickey)"で分かります。鍵が受け付けられなかったことを明示しているものはありません。但し結果的に認証に失敗したことが"No supported authentication methods available"で確認できます。

Windowsでよく使われる他のSSHクライアントにはTeraTermがあります。こちらのログの出し方はよくわかりません。メニューからは、上記のレベルのログ出力を制御することはできなそうです。

マニュアルによると、設定ファイルの"LogLevel"を変えればできそうです。しかし、試したところうまくできませんでした。多分やり方を間違っているのでしょう。たかが接続時の詳細ログを見たいだけなのに設定ファイルを書き換えないと見ることができないというのは、個人的には使い辛く思います。なおSSHサーバーに接続できたところまでの情報はTeraTermでも分かるようです。

さて、SSHサーバー側のログはどうなっているでしょうか。

root@osboxes:~# tail -n 100 /var/log/auth.log
    : (略)
Apr  3 20:06:38 osboxes sshd[4215]: Authentication refused: bad ownership or modes for file /home/linuser/.ssh/authorized_keys
Apr  3 20:06:38 osboxes sshd[4215]: Connection reset by authenticating user linuser 192.168.56.1 port 52227 [preauth]
    : (略)

クライアントから接続されていることが分かります。さらには、なぜ認証に失敗しているかという理由も書かれています。"/home/linuser/.ssh/authorized_keys"のオーナーあるいは権限が悪い、と書かれています。

SSHサーバーへの接続を調べていた最中に、鍵認証の確認もできてしまいました。これは幸運です。しかし、鍵認証の確認をSSHサーバーへの接続可否確認と独立して行っていたとしても、同じように原因に辿り着けたでしょう。

では、オーナーや権限を確認してみます。

root@osboxes:~# ls -l /home/linuser/.ssh/authorized_keys
-rwxrwxrwx 1 linuser linuser 389 Apr  3 10:40 /home/linuser/.ssh/authorized_keys
root@osboxes:~#

"authorized_keys"がa=rwxになっています。これだと誰しもが書き換えできてしまいます。つまり、攻撃者にとって都合の良いエントリをauthorized_keysに追加することができてしまいます。そのような危険なファイルはダメというわけです。

原因が分かったので修正しましょう。

root@osboxes:~# ls -l /home/linuser/.ssh/authorized_keys
-rwxrwxrwx 1 linuser linuser 389 Apr  3 10:40 /home/linuser/.ssh/authorized_keys
root@osboxes:~# chmod go= /home/linuser/.ssh/authorized_keys
root@osboxes:~# ls -l /home/linuser/.ssh/authorized_keys
-rwx------ 1 linuser linuser 389 Apr  3 10:40 /home/linuser/.ssh/authorized_keys
root@osboxes:~#

もう一度ログインを試してみましょう("-v"は省略)。

PS > ssh -l linuser -i id_rsa 192.168.56.102
linuser@192.168.56.102: Permission denied (publickey).
PS >

ダメですね。もう一度サーバーのログを見てみましょう。

root@osboxes:~# tail -n 100 /var/log/auth.log
    : (略)
Apr  3 20:12:38 osboxes sshd[4276]: Authentication refused: bad ownership or modes for directory /home/linuser/.ssh
Apr  3 20:12:20 osboxes sshd[4276]: Connection reset by authenticating user linuser 192.168.56.1 port 52247 [preauth]
    : (略)

変えたはずなのに。と思ってよく見ると、メッセージが変わっています。".ssh"のオーナーか権限が悪いようです。

root@osboxes:~# ls -ld /home/linuser/.ssh/
drwxrwxrwx 2 linuser linuser 4096 Apr  3 10:40 /home/linuser/.ssh/
root@osboxes:~#

".ssh"がa=rwxになっています。これだと".ssh/authorized_keys"を別の内容に差し替えできてしまいます。以前書いた通り、.sshの書き込み権限がある人は、その下にぶら下がるファイルの移動や新規ファイル作成を自由に行えます。つまり、攻撃者は今あるauthorized_keysの名前を変えて、攻撃者にとって都合の良いauthorized_keysを新規作成できてしまいます。そのような危険なディレクトリはダメというわけです。

原因が分かったので再度修正しましょう。

drwxrwxrwx 2 linuser linuser 4096 Apr 3 10:40 /home/linuser/.ssh/
root@osboxes:~# chmod go= /home/linuser/.ssh/
root@osboxes:~# ls -ld /home/linuser/.ssh/
drwx------ 2 linuser linuser 4096 Apr 3 10:40 /home/linuser/.ssh/
root@osboxes:~#

もう一度ログインを試してみましょう("-v"は省略)。

PS > ssh -l linuser -i id_rsa 192.168.56.102
Welcome to Ubuntu 18.10 (GNU/Linux 4.18.0-10-generic x86_64)
    : (略)
$

無事ログインできました。

問題解決のためにやっていること

ここまでやっていることを簡単にまとめると、以下のようなステップです。

問題に関わる要素を思い浮かべる
それぞれの要素を、使っている順番に思い浮かべる
どの要素がうまく動いているか、うまく動かないかを確認して、境界となっている部分を見極める(問題の切り分け)
境界となっている部分が問題と考えて、問題部分の状況を確認する
問題部分の原因が分かれば、直してみる
問題部分の原因が分からないなら、より細分化して1から繰り返す

今回はステップ6にあたるものはありませんでした。例えば、SSHサーバーに繋がらなかったという場合なら、途中のネットワーク機器のどこまでうまくいっているかを確認する必要があります。その場合、"途中のネットワーク機器"という大きな単位ではなく、個々のルータやケーブルといった単位に細分化して、どの機器がうまく動いていないのかを特定する必要があります。

問題解決のために気にしていること

適切な粒度を考える

初期段階では、途中のネットワーク機器をひとまとめに書きました。初期段階で"這わせてあるケーブルが断線していないか"といったことまで意識する必要はないと思います。初期段階では大きな範囲で確認し、問題個所が分かってきたら範囲をより絞る、と進めるようにしています。

漏れを補完する

上のケースで、SSHサーバーに接続すらできない状況だとします。上の図では、SSHサーバーの手前は途中のネットワーク機器です。そうすると、途中のネットワーク機器のどこかに原因があるということになるのでしょうか。

図に書いていない要素を挙げてみます。
- SSHサーバーのファイヤウォール設定
- SSHサーバーそのものが起動しているか

途中のネットワーク機器がOKでも、ファイヤウォールに阻まれたりSSHサーバーが起動していない場合には繋がらないことになります。

粒度が荒い状態から、問題個所が絞り込まれてより粒度の細かい段階に移るとき、細かくなった粒度で漏れを起こさないように気を付けています。

漏れに気付くことができれば、じゃあSSHサーバーが起動していることを確認しよう、となります。

問題の要素が使われる順番を正しく理解するように心がける

途中のネットワークやSSHサーバーが適切に設定されているにもかかわらず、鍵認証できない場合があります。例えば指定した秘密鍵の形式が間違っている、PPK形式かopenssh形式かが違う場合などです。

例えばパスフレーズ付きの秘密鍵なら、鍵を使うまでにパスフレーズを聞いてくるはずです。パスフレーズを聞いてこないときにおかしいと気付けるか、フェールバックしてパスワード認証になっていることに気付けるか。処理が行われる順番を正しく理解できていれば、気付ける可能性は高まると思います。

調査方法そのものを知る

例えばSSHサーバーそのものが起動しているかどうかを確認する方法にも色々あります。
- "service sshd status"的な方法
- "ps | grep"的な方法
- "netstat -lntp"的な方法
- "ssh localhost"的な方法

確認している内容はそれぞれ微妙に違います。しかし、おおよそSSHサーバーが起動していることの確認になっています。どの方法でもいいので知っていないと、SSHサーバーが起動しているかどうかを確認できません。

多くの方法を知っているなら、その場で最も簡単な方法を選ぶことができます。

現象や調査結果から多くの情報を得ようとする

ログやエラーメッセージをよく読むということに通じる部分です。

冒頭に挙げた「Oracle接続できない」ような場合、エラーメッセージが以下のように色々とあり得ます。

ORA-12170: TNS: 接続タイムアウトが発生しました。
ORA-12514: TNS: リスナーは接続記述子で要求されたサービスを現在認識していません。
ORA-01017: ユーザー名/パスワードが無効です。

そして、エラーメッセージが違えば、見るべき場所、見るべき設定も変わります。

これは、どの順番で処理が行われているか正しく知っているかという部分ともリンクします。上に挙げたエラーはおおよそ、上から順に判断が行われます。エラーがORA-01017ならリスナーまでの動きはおおよそ正しいだろうと期待できます(接続先を間違っているケースもあるので必ずしも正しいわけではありません)。

原因が一つだけとは限らない

SSHサーバーの例では2か所に問題がありました。順番に直せばよいケースでした。しかしそのような単純なケースばかりとは限りません。

Aを直すとより悪くなる。Bを直してもより悪くなる。AとBの両方を一度に直せばちゃんと直る。そんなこともあります。

原因が複数ある場合も想定に入れるようにしています。

調査に行き詰ったら、複数の視点で確認する、動きと設定の両面から確認する

調査結果の見間違いや見落としによって、真の原因に結びつかないこともあります。

調査に行き詰まったら、一度確認したことを、別の方法で確認しなおすようにしています。例えばSSHサーバーが起動していることを確認する方法をいくつか挙げました。大抵の場合はどれも同じ結果となるでしょう。しかし、一部だけ異なる結果となるかもしれません。

"service sshd status"的な方法や"ps | grep"的な方法では想定どおり動いているとします。しかし、"netstat -lntp"的な方法で確認したら想定とは異なるポートが開いているかもしれません。

調査に行き詰ったら、環境が変化していないかを確認する

調査環境が変化していると勘違いしやすくなります。

SSHサーバーに繋がらない、途中のネットワークがおかしいと考えているとします。どのネットワーク機器がおかしいか、順番に確認していきます。A-B-C-D-Eと順番に見ていき、AからCまでOK、Dの時にNGとします。Dがおかしそうだと調べていきます。しかし、繋がったり繋がらなかったりといった動きをしているとします。

この場合、Bがときどきおかしい場合もあり得ます。Dを調べるとき、AからCの環境が変化しないと思い込んでしまいがちです。しかしその前提が成り立たない場合もあるということです。

最後に

どれも当たり前のことだろうと思います。しかし、焦ると当たり前のことができなくなります。問題を前にしても冷静で居続けることもポイントかもしれません。

問題の解決方法 SSHの鍵認証接続を題材に