2026年4月26日日曜日

SSHログイン後にプロンプトが返ってくるまで2分かかる問題を解決した話

はじめに

ある日、自宅のLinuxサーバ（ホスト名 macmini）にSSHでログインしようとしたところ、 パスワードを入力した後、プロンプトが返ってくるまで 毎回きっちり2分 待たされる現象が発生しました。 さらに、ログイン後に sudo を実行してパスワードを入力した後も同じように遅延が発生します。

切り分けと調査の結果、原因は systemd-logind の応答不能 でした。 本記事ではその調査手順と解決方法を備忘録として残しておきます。

目次
  • 発生していた症状
  • 調査ステップ1: SSHの詳細ログを取る
  • 調査ステップ2: サーバ側の認証ログを確認
  • 原因の特定
  • 解決方法
  • なぜ sudo も遅かったのか
  • まとめ

発生していた症状

  • SSHでパスワードを入力後、プロンプトが返るまで約2分かかる
  • ログイン後の sudo でも、パスワード入力後に同じく長時間待たされる
  • パスワード認証自体は成功している

調査ステップ1: SSHの詳細ログを取る

まずクライアント側から -vvv オプションで詳細ログを出して、どこで止まっているのかを確認しました。 

ssh -vvv user@192.168.0.2xx

すると、以下の箇所で長時間停止していることが分かりました。 

Authenticated to 192.168.0.2xx ([192.168.0.2xx]:22) using "password".
debug1: channel 0: new session [client-session] (inactive timeout: 0)
debug3: ssh_session2_open: channel_new: 0 (tty)
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Requesting no-more-sessions@openssh.com
debug3: send packet: type 80
debug1: Entering interactive session.
認証は完了しており、セッションチャンネルを開く段階で止まっている。 つまり、サーバ側のセッション初期化処理（PAMセッション）に問題があると判断できます。

調査ステップ2: サーバ側の認証ログを確認

サーバ側で journalctl または /var/log/auth.log を確認します。 

sudo journalctl -u ssh -n 100 --no-pager

すると、決定的な手がかりが出てきました。 

Apr 26 22:10:24 macmini sshd-session[1947102]: Accepted password for xxxxxx from 192.168.0.2xx port 49762 ssh2
Apr 26 22:12:24 macmini sshd-session[1947102]: pam_systemd(sshd:session): Failed to create session: Connection timed out
Apr 26 22:12:24 macmini sshd-session[1947102]: pam_unix(sshd:session): session opened for user xxxxxx(uid=1000) by xxxxxx(uid=0)

ポイントは以下の2点です。

  • 認証成功（22:10:24）から ちょうど2分後（22:12:24）にタイムアウト
  • pam_systemd が「Failed to create session: Connection timed out」を出している

原因の特定

このログから、以下の処理フローで遅延が発生していたと特定できました。

  1. SSHで認証が成功する
  2. PAMセッションを開く際、pam_systemd.so が D-Bus経由で systemd-logind にセッション作成を依頼
  3. systemd-logind が応答不能になっており、応答が返ってこない
  4. D-Busのデフォルトタイムアウトである 120秒（=2分） 待たされる
  5. タイムアウト後、pam_systemd はセッション作成を諦め、SSHログインは継続される

ぴったり2分で進むあたりが、いかにもタイムアウトという挙動です。

解決方法

systemd-logind を再起動するだけで復旧しました。 

sudo systemctl restart systemd-logind

再起動後、SSHログインも sudo も即座にプロンプトが返るようになり、待ち時間ゼロで快適に戻りました。

もし再起動でも改善しない場合は、dbus サービスの再起動や、最終手段としてOS自体の再起動（sudo reboot）を検討します。

事前に状態を確認するなら

systemctl status systemd-logind
sudo journalctl -u systemd-logind -n 50 --no-pager
loginctl list-sessions

loginctl 系のコマンドが応答しなかったりハングする場合は、systemd-logind が壊れているサインです。

なぜ sudo も遅かったのか

sudo も内部的にPAMを使っており、PAMスタックの中で pam_systemd.so が呼ばれます。 そのため、SSHログイン時と全く同じ理由で systemd-logind へのD-Bus通信を待たされ、120秒のタイムアウトが発生していました。

「SSHログイン後にプロンプトが遅い」かつ「sudo のパスワード入力後も遅い」という2つが同時に起きている時点で、 共通項である PAM + systemd-logind を疑うのが近道です。

切り分けの観点まとめ

遅延箇所疑うべき原因確認方法
パスワード入力前に遅い DNS逆引き（UseDNS）、GSSAPI ssh -vvv で接続冒頭を確認
認証後〜プロンプト直前で遅い pam_systemd / systemd-logind、pam_lastlog、motd サーバの auth.log / journalctl
プロンプト表示後に重い .bashrc、シェル起動スクリプト bash -x -l でトレース

まとめ

  • SSHログイン後の遅延は、ssh -vvv でどこで止まるかを観察するのが第一歩
  • 「認証成功後にちょうど2分」止まる場合は、pam_systemd と systemd-logind の通信タイムアウトをまず疑う
  • サーバ側の認証ログ（journalctl -u ssh や /var/log/auth.log）に決定的なエラーが残っていることが多い
  • 多くの場合 sudo systemctl restart systemd-logind で復旧する
  • sudo も同時に遅い場合は、PAMの共通モジュールが原因と考えると当たりをつけやすい

同じ症状で困っている方の助けになれば幸いです。

時刻: 0 件のコメント:
登録: コメント (Atom)