環境
- Ubuntu 24.04
症状
SSHでログインしようとすると、認証が通ってからプロンプトが出るまでやたら待たされる。体感で20秒以上。
しかもSSHだけの話ではなく、ログイン後に sudo su - したときも同じくらい待たされる。
負荷が高いわけでもない。ロードアベレージは平常運転だし、いったんシェルが返ってきてしまえば他の作業は普通に動く。要するに「入り口だけ」が遅い。
この手の症状は経験則上DNSの名前解決が詰まっているケースが多いので真っ先に疑ったのだが、
$ nslookup google.com
は即返ってくる。逆引きも問題なし。つまりDNSは白だった。
調査
DNSが白なら何が問題なんだ、ということでAIに聞いたら「journalctlを見せろ」と言うので渡したところ、pam_systemd が怪しいと指摘された。
# journalctl -u ssh --since "30 min ago" -o short-precise | grep -i pam_systemd 8月 03 15:53:25.490898 sshd[22961]: pam_systemd(sshd:session): Failed to create session: Connection timed out 8月 03 15:54:23.513148 sshd[23028]: pam_systemd(sshd:session): Failed to create session: Connection timed out 8月 03 15:54:36.814603 sshd[23040]: pam_systemd(sshd:session): Failed to create session: Connection timed out 8月 03 15:56:38.677345 su[23170]: pam_systemd(su:session): Failed to create session: Connection timed out 8月 03 15:59:12.416183 sshd[23273]: pam_systemd(sshd:session): Failed to create session: Connection timed out 8月 03 16:00:22.013104 sshd[23300]: pam_systemd(sshd:session): Failed to create session: Connection timed out 8月 03 16:01:31.837444 su[23379]: pam_systemd(su:session): Failed to create session: Connection timed out 8月 03 16:02:43.493113 sshd[23470]: pam_systemd(sshd:session): Failed to create session: Connection timed out 8月 03 16:04:42.625850 sshd[23521]: pam_systemd(sshd:session): Failed to create session: Connection timed out
SSHとsuの両方で同じログが出ている。しかもタイムアウトしているだけで、最終的にログイン自体は成功している。体感の遅さと一致する。
次に、認証が通った瞬間とタイムアウトした瞬間の時刻を突き合わせてみる。
15:53:00.462 sshd: Accepted publickey ...（ログイン成功）
15:53:25.490 sshd: pam_systemd(sshd:session): Failed to create session: Connection timed out
↑ ちょうど 25.03 秒後
きれいに25秒。毎回この値なので、ネットワークの揺らぎのような不定な待ちではなく、どこかに設定された固定のタイムアウト値を待ち切っていることになる。
そこでsystemd-logindとdbus-daemon側のログを見ると、その25秒の出どころが出てきた。
systemd-logind: Failed to start user slice user-1000.slice, ignoring:
Connection timed out (org.freedesktop.DBus.Error.Timeout)
dbus-daemon: [system] Failed to activate service 'org.freedesktop.systemd1':
timed out (service_start_timeout=25000ms)
service_start_timeout=25000ms がまさに25秒で、観測された遅延と完全に一致する。
読み取れるのは、logindもdbus-daemon自体も正常に動いていて、その先にいるsystemd本体（PID1）がD-Bus越しの要求に応答していないということ。ログインのたびにPAMのsessionフェーズがそれを25秒待たされているわけだ。
となると次の疑問は「PID1が何か重い処理で詰まっているのか」だが、これは違った。
# systemctl list-jobs No jobs running. # systemctl --failed session-222422.scope failed session-234294.scope failed apparmor.service masked, failed # systemctl status State: degraded Jobs: 0 queued
ジョブキューは空。滞留しているユニットは無い。
failedになっている2つの session-*.scope は、過去のログインで同じ25秒タイムアウトが起きたときにセッションscopeの起動が失敗した残骸であって、原因ではなく結果のほう。
これで「特定のユニットがジョブキューをブロックしている」という線は消えた。残るのは、systemdマネージャのD-Busバス接続そのものが壊れている、つまり org.freedesktop.systemd1 というバス名の登録がおかしくなっている、という仮説になる。
このマシン、稼働開始から4年6ヶ月無停止だった。その間のどこかでPID1とdbus-daemonの間の接続状態が壊れ、PID1が org.freedesktop.systemd1 としてバスに応答できなくなっていたと考えるのが自然だろう。重い処理で詰まっているのではなく、通信経路そのものの不整合ということになる。
原因
systemd (PID1) が自分自身のD-Bus管理インターフェースである org.freedesktop.systemd1 への要求に応答しなくなっていた。
そのせいでログインのたびに pam_systemd のセッション作成要求が宙に浮き、D-Busの25秒という固定タイムアウトを待ち切るまで先に進めなくなる。ログインが失敗しないのは、pam_systemd がタイムアウトしてもエラーを無視して処理を続けるため。要するに「必ず25秒無駄に待ってから成功する」状態だった。
SSHログインも sudo su - も、PAMのsessionフェーズで systemd-logind にセッション登録を依頼するという同じ経路を通る。だから両方が揃って同じだけ遅くなる。
対応
壊れているのがPID1のD-Bus接続状態だけなら、systemd自身を再起動してバスに繋ぎ直させればいい。それをやってくれるのが daemon-reexec である。
sudo systemctl daemon-reexec
daemon-reload はユニットファイルを読み直すだけだが、daemon-reexec はsystemdのバイナリ自体を再実行する。稼働中のサービスやプロセスは維持したまま、マネージャの内部状態とD-Bus接続だけが作り直される。要するにOSを再起動せずにPID1だけ入れ直すやつ。
実行後、SSHもsudoも即座にプロンプトが返るようになった。
