SSHログインの失敗が大量に記録されているとSSHログインが極端に遅くなる

Development Division/Platform Team/Sys-Infra Unitの伊豆です。Sys-Infra Unitはインフラエンジニア・SRE 的な役割を担っています。

今回は、ある日突然SSHログインが遅くなったときに調査した内容を共有します。

SSHログインに数分かかる

ある日、AWS EC2上で動いている開発環境のSSH ゲートウェイにSSHログインすると30秒以上かかると報告がありました。-vvvオプションを指定してSSHログインしてみるとpledge: filesystemというログが出力された後、数十秒から数分程度かかってSSHログインが成功する状況でした。

pledge: filesystemやssh slowなどで検索してみると、主に以下のような対処法が挙げられていましたがどれを試しても状況は改善されませんでした。

systemd-logindを再起動する
UseDNSをnoにする
GSSAPIAuthenticationをnoする

ダメ元でsshdプロセスを再起動する、EC2インスタンスのstop & startするなども試してましたが状況は変わりませんでした。

SSHログインの失敗が大量に記録されたログと巨大な`/var/log/btmp`ファイルが見つかる

何かおかしいことがログに記録されていないか調査していると、/var/log/secureにSSHログインの失敗が大量に記録されていました。

Oct 31 08:26:10 repro-ssh-gateway-dev-staging-i-xxxxxxxxxxxxxxxxx sshd[19036]: Invalid user xxxxxxxxxxxxxx from xx.xx.xx.xx port 1436

これ自体はとあるサービスの設定ミスが原因で、このサービスが存在しないユーザによるSSHログインを試行し続けていたため、SSHログインの失敗が大量に記録されていました。他におかしいことを見つけられなかったため、SSHログインが大量に失敗している状況と関連したものがないか調査をしました。すると、下記の投稿で/var/log/btmpファイルをクリアしたら問題を解決したという回答を見つけました。

ssh connection takes forever to initiate, stuck at "pledge: network"

/var/log/btmpファイルには失敗したSSHログインが記録されていて、まさに今回の問題が発生した状況と関連しているため、このファイルが原因かどうかを詳しく調べることにしました。

sshdプロセスに対してstraceを実行し調査した結果、下記のように/var/log/btmpファイルの読み込みが大量に記録されていることが確認できました。

$ sudo strace -fttTvyy -p <the pid of sshd> -o out.txt

26363 02:45:14.330135 openat(AT_FDCWD, "/var/log/btmp", O_RDONLY) = 6</var/log/btmp> <0.000023>
26363 02:45:14.330208 read(6</var/log/btmp>, "\6\0\0\0\24x\0\0ssh:notty\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000020>
26363 02:45:14.330267 read(6</var/log/btmp>, "\6\0\0\0\26x\0\0ssh:notty\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000018>
26363 02:45:14.330323 read(6</var/log/btmp>, "\6\0\0\0\30x\0\0ssh:notty\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000019>
26363 02:45:14.330379 read(6</var/log/btmp>, "\6\0\0\0\32x\0\0ssh:notty\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000017>
26363 02:45:14.330443 read(6</var/log/btmp>, "\6\0\0\0\34x\0\0ssh:notty\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000017>
26363 02:45:14.330496 read(6</var/log/btmp>, "\6\0\0\0\36x\0\0ssh:notty\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000017>
~~

/var/log/btmpファイルは調査時点で約1.5GBほどあり、このファイルをtruncateしたところ、SSHログインがすぐに完了するようになりました。

$ sudo du -sh /var/log/btmp
1.5G   /var/log/btmp

SSHログインが遅くなった原因はssh connection takes forever to initiate, stuck at "pledge: network"と同じで、肥大化した/var/log/btmpファイルだと判明しました。

なぜ`/var/log/btmp`ファイルが読み込まれるのか

この問題は前から報告されているようでssh slow btmpと検索すると、いくつか同様の問題を報告している記事がヒットします。

pam_lastlog.soでshowfailedオプションが有効になっていると、失敗したSSHログインの試行が何回あったか表示するために/var/log/btmpファイルが読み込まれるようです。

man pam_lastlog

showfailed
    Display number of failed login attempts and the date of the last failed attempt from btmp. The date is not displayed when nodate is specified.

弊社で使っているAmazon Linux 2ではこのオプションはデフォルトで有効になっていました。

$ cat /etc/pam.d/postlogin
#%PAM-1.0
# This file is auto-generated.
# User changes will be destroyed the next time authconfig is run.


session     [success=1 default=ignore] pam_succeed_if.so service !~ gdm* service !~ su* quiet
session     [default=1]   pam_lastlog.so nowtmp showfailed
session     optional      pam_lastlog.so silent noupdate showfailed

Amazon Linux 2ではデフォルトで/var/log/btmpファイルにローテートの設定がされているもののmonthlyとなっていました。そのため、短期間で失敗するSSHログインが何回も試行され、失敗したSSHログインが記録され続けると/var/log/btmpファイルが肥大化しSSHログインに時間がかかるようになります。

対策

このような問題を防ぐには主に以下のような対策が必要でした。

/var/log/btmpファイルをローテートする
SSHログインに一定回数失敗したらアカウントをロックする

`/var/log/btmp`ファイルをローテートする

logrotateなどで一定期間で、または一定サイズになったらファイルをローテートすることで、/var/log/btmpファイルが無制限に大きくなることを防げます。弊社で使っているAmazon Linux 2ではローテートの設定がされているもののmonthlyとなっていたため、weeklyなどの短い期間を指定したりサイズによるローテートを指定したりする必要がありました。

SSHログインに一定回数失敗したらアカウントをロックする

そもそもSSHログインの失敗を何回も許容し続けることはセキュリティ上好ましくないので、SSHログインに一定回数失敗したらそのユーザのアカウントを一定時間ロックするような対策が必要でした。これによってSSHログインの試行回数が制限されるので、短期間で/var/log/btmpファイルが肥大するのを防ぐこともできます。特にインターネットからアクセス可能なホストの場合、攻撃者がSSHログインを何回も試みることでこの問題を(時間はかかりますが)簡単に引き起こすことができるので、特に気をつける必要があります。