SSHが重くなる・固まる原因を調査する（FreeBSD/pf）
はじめに
自宅のFreeBSDのFWサーバを踏み台にして、別のサーバなどで作業をしていると突然キー入力が反応しなくなったり、SSH接続が繋がりにくくなることが度々ありました。
家庭用回線だし仕方ないなんて思って作業をしていましたが、自宅で作業などをしているときは全く起きていないし、よくよく考えるとFreeBSD側を経由しているときに起きているなあ・・なんて思ったり
ある朝、8時17分頃に約45秒間フリーズし、再接続を余儀なくされたので、pfのログを読んで原因を調査することにしました。
pflogを読む
pflogはバイナリ形式のため、tcpdumpを使って内容を確認します。
sudo tcpdump -n -e -ttt -r /var/log/pflog
00:08:02.200354 rule 15/0(match): block in on ix0: 38.51.180.241.34770 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
# 00:08:02.200354→前のパケットからの経過時間
# rule 15/0(match)→マッチしたpfのルール番号
# block in→ブロックされた受信パケット
# on ix0→受信インターフェース
# 38.51.180.241.34770→送信元IP.ポート
# 192.168.2.1.22→宛先IP.ポート
# Flags [S]→SYNパケット（接続要求） 実際のPFログはこちら
38.51.180.241
00:08:02.200354 rule 15/0(match): block in on ix0: 38.51.180.241.34770 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.174537 rule 15/0(match): block in on ix0: 38.51.180.241.26768 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.143632 rule 15/0(match): block in on ix0: 38.51.180.241.64277 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.046780 rule 15/0(match): block in on ix0: 38.51.180.241.29766 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.236776 rule 15/0(match): block in on ix0: 38.51.180.241.21955 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.497211 rule 15/0(match): block in on ix0: 38.51.180.241.51907 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.174747 rule 15/0(match): block in on ix0: 38.51.180.241.52076 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.184100 rule 15/0(match): block in on ix0: 38.51.180.241.22839 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
00:00:00.388647 rule 15/0(match): block in on ix0: 38.51.180.241.10038 > 192.168.2.1.22: Flags [S], seq 0, win 53270, options [mss 536], length 0
130.12.181.252
00:09:48.357725 rule 15/0(match): block in on ix0: 130.12.181.252.44872 > 192.168.2.1.22: Flags [S], seq 2029899240, win 1024, options [mss 536], length 0
00:09:34.954240 rule 15/0(match): block in on ix0: 130.12.181.252.58011 > 192.168.2.1.22: Flags [S], seq 3487656457, win 1024, options [mss 536], length 0
00:29:17.554552 rule 15/0(match): block in on ix0: 130.12.181.252.53850 > 192.168.2.1.22: Flags [S], seq 1777814684, win 1024, options [mss 536], length 0
00:43:33.723970 rule 15/0(match): block in on ix0: 130.12.181.252.55984 > 192.168.2.1.22: Flags [S], seq 1023542708, win 1024, options [mss 536], length 0
98.35.26.193
00:08:40.311252 rule 15/0(match): block in on ix0: 98.35.26.193.48200 > 192.168.2.1.22: Flags [S], seq 1283197006, win 29200, options [mss 1452, [|tcp]
00:00:00.996837 rule 15/0(match): block in on ix0: 98.35.26.193.48200 > 192.168.2.1.22: Flags [S], seq 1283197006, win 29200, options [mss 1452, [|tcp]
00:00:01.998971 rule 15/0(match): block in on ix0: 98.35.26.193.48200 > 192.168.2.1.22: Flags [S], seq 1283197006, win 29200, options [mss 1452, [|tcp]
00:00:04.010787 rule 15/0(match): block in on ix0: 98.35.26.193.48200 > 192.168.2.1.22: Flags [S], seq 1283197006, win 29200, options [mss 1452, [|tcp]
00:00:08.019110 rule 15/0(match): block in on ix0: 98.35.26.193.48200 > 192.168.2.1.22: Flags [S], seq 1283197006, win 29200, options [mss 1452, [|tcp]
00:00:16.020592 rule 15/0(match): block in on ix0: 98.35.26.193.48200 > 192.168.2.1.22: Flags [S], seq 1283197006, win 29200, options [mss 1452, [|tcp]
00:00:32.082497 rule 15/0(match): block in on ix0: 98.35.26.193.48200 > 192.168.2.1.22: Flags [S], seq 1283197006, win 29200, options [mss 1452, [|tcp]
24.127.131.11
00:25:27.118302 rule 15/0(match): block in on ix0: 24.127.131.11.58144 > 192.168.2.1.22: Flags [S], seq 3953139854, win 29200, options [mss 1452, [|tcp]
00:00:00.992404 rule 15/0(match): block in on ix0: 24.127.131.11.58144 > 192.168.2.1.22: Flags [S], seq 3953139854, win 29200, options [mss 1452, [|tcp]
00:00:02.000324 rule 15/0(match): block in on ix0: 24.127.131.11.58144 > 192.168.2.1.22: Flags [S], seq 3953139854, win 29200, options [mss 1452, [|tcp]
00:00:04.009341 rule 15/0(match): block in on ix0: 24.127.131.11.58144 > 192.168.2.1.22: Flags [S], seq 3953139854, win 29200, options [mss 1452, [|tcp]
00:00:08.010311 rule 15/0(match): block in on ix0: 24.127.131.11.58144 > 192.168.2.1.22: Flags [S], seq 3953139854, win 29200, options [mss 1452, [|tcp]
00:00:10.818866 rule 15/0(match): block in on ix0: 24.127.131.11.58144 > 192.168.2.1.22: Flags [S], seq 3953139854, win 29200, options [mss 1452, [|tcp]
00:00:32.077143 rule 15/0(match): block in on ix0: 24.127.131.11.58144 > 192.168.2.1.22: Flags [S], seq 3953139854, win 29200, options [mss 1452, [|tcp]
45.227.254.170
00:03:00.653968 rule 15/0(match): block in on ix0: 45.227.254.170.9090 > 192.168.2.1.22: Flags [S], seq 30000, win 65535, options [mss 536], length 0
00:22:25.841202 rule 15/0(match): block in on ix0: 45.227.254.170.9090 > 192.168.2.1.22: Flags [S], seq 30000, win 65535, options [mss 536], length 0
00:20:07.932263 rule 15/0(match): block in on ix0: 45.227.254.170.9090 > 192.168.2.1.22: Flags [S], seq 30000, win 65535, options [mss 536], length 0
00:23:27.043587 rule 15/0(match): block in on ix0: 45.227.254.170.9090 > 192.168.2.1.22: Flags [S], seq 30000, win 65535, options [mss 536], length 0
00:02:02.462815 rule 15/0(match): block in on ix0: 45.227.254.170.9090 > 192.168.2.1.22: Flags [S], seq 30000, win 65535, options [mss 536], length 0以下pflogから推測される重くなる・固まる原因です。
重くなった原因
ログを読んだ結果、セキュリティ上の侵害などの問題はありませんでした。全パケットはpfのルールでブロックできています。
では何が原因だったのかですが、問題は pf.conf のこの1行です。
block in log quick on $ext_if proto tcp from ! <japan_ips> to any port 22log キーワードがついているため、ブロックしたパケットを全て /var/log/pflog に書き込んでいます。
38.51.180.241が9つのポートから約2秒以内に一斉にSYNを送りつけてきたとき、短時間にディスクI/Oが集中し、pflogdが詰まってSSHセッションの処理が約45秒間ブロックされました。
- 38.51.180.241から9パケットが約2秒以内に集中して到着
block in logによって全パケットが/var/log/pflogに書き込まれる- ディスクI/Oスパイク → pflogdが詰まる
- SSHセッションの処理が巻き込まれてフリーズ
守れてはいたけどログを取ることで自分が重くなっていた、というオチでした。
解決法
原因が block in log によるログI/Oスパイクとわかったので、pf.conf を1点修正します。
# 変更前
block log in quick on $ext_if proto tcp from ! <japan_ips> to any port 22
# 変更後
block in quick on $ext_if proto tcp from ! <japan_ips> to any port 22これだけで今回のフリーズは解消されると思っています。
ログが取れなくなるのは少し寂しいですが、そもそもブロック済みのパケットを全記録する必要性はあまり高くないため、割り切ることにしました。
この数日間、変更してから問題が起きていないです。他の原因などがわかれば追記していきたいと思います。
おわり