読者です 読者をやめる 読者になる 読者になる

Thanks Driven Life

日々是感謝

ServersMan@VPS で「shell request failed on channel 0」と出てログインできなくなる悲しみを知った私は

泣いた。嘘です。

ServersMan@VPS に限った話ではないかもしれませんが、私が今使ってる他の VPS (さくらとか)では起きなかったのでこういうタイトルで。

経緯

実はいろいろあって ServersMan@VPS を一度解約しています(さくらで十分だったから)が、
Jenkins サーバを別で欲しかったので、無料期間が2ヶ月あっていろいろ調整しやすいので
再び ServersMan を借りることにしました。前回は Cent で今回は Ubuntu です。(11.04 に upgrade 済み)

で、なんか調子が変。夜までは普通に触れるんですが、朝起きて ssh すると

shell request failed on channel 0

と出て拒否られる。パスワード入力した直後ですね。おそらく認証は通っているんでしょう。
しかし意味がわからない。とりあえずぐぐってみると

みたいな情報が得られる。しかし私の環境では

  • ajaxterm は契約してログインできるようになって10秒後に削除した
  • screen は今のところサーバ上にて使っていない
  • cat /proc/user_beancounters も見ているが、就寝直前までは 1 をキープしていた

みたいな感じなので、上記リンクの内容が原因ではあるんだろうけど、きっかけがわからない。

「朝起きたら満杯になっている」ということなので、夜中に何かが起きている。まさか不正ログイン?

調査

不正ログインだったらどこだろう。/var/log 以下の auth.log や syslog だろうか。
まずは auth.log を見てみた

$ sudo less /var/log/auth.log

(省略)
Nov 14 22:06:01 ci CRON[32503]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 14 23:06:01 ci CRON[38571]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 14 23:06:01 ci CRON[38571]: pam_unix(cron:session): session closed for user root
Nov 15 00:06:01 ci CRON[40606]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 00:06:01 ci CRON[40606]: pam_unix(cron:session): session closed for user root
Nov 15 00:20:01 ci CRON[30303]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 00:20:01 ci CRON[30303]: pam_unix(cron:session): session closed for user root
Nov 15 01:06:01 ci CRON[36473]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 02:06:01 ci CRON[35994]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 03:06:01 ci CRON[48965]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 04:06:01 ci CRON[29724]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 05:06:01 ci CRON[30199]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 05:06:01 ci CRON[30199]: pam_unix(cron:session): session closed for user root
Nov 15 06:06:01 ci CRON[33902]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 15 07:06:01 ci CRON[27957]: pam_unix(cron:session): session opened for user root by (uid=0)
(省略)

cron で一時間ごとに何かが実行されてる。おそらく cron.hourly だろう。
それはともかく、何かがおかしい。途中途中に closed が無いぞ。

syslog も見てみる

$ sudo less /var/log/syslog

(省略)

Nov 15 02:06:01 ci CRON[35995]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Nov 15 02:06:01 ci CRON[35994]: (CRON) error (grandchild #35995 failed with exit status 2)
Nov 15 02:06:01 ci postfix/sendmail[35997]: fatal: open /etc/postfix/main.cf: No such file or directory
Nov 15 02:17:43 ci -- MARK --
Nov 15 02:37:43 ci -- MARK --
Nov 15 02:57:43 ci -- MARK --
Nov 15 03:06:01 ci CRON[48970]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Nov 15 03:06:01 ci CRON[48965]: (CRON) error (grandchild #48970 failed with exit status 2)
Nov 15 03:06:01 ci postfix/sendmail[48975]: fatal: open /etc/postfix/main.cf: No such file or directory
Nov 15 03:17:43 ci -- MARK --
Nov 15 03:37:43 ci -- MARK --
Nov 15 03:57:43 ci -- MARK --
Nov 15 04:06:01 ci CRON[29730]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Nov 15 04:06:01 ci CRON[29724]: (CRON) error (grandchild #29730 failed with exit status 2)
Nov 15 04:06:01 ci postfix/sendmail[29735]: fatal: open /etc/postfix/main.cf: No such file or directory
Nov 15 04:17:43 ci -- MARK --
Nov 15 04:37:43 ci -- MARK --
Nov 15 04:57:43 ci -- MARK --
Nov 15 05:06:01 ci CRON[30215]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Nov 15 05:06:01 ci CRON[30199]: (CRON) error (grandchild #30215 failed with exit status 2)
Nov 15 05:06:01 ci postfix/sendmail[30220]: fatal: open /etc/postfix/main.cf: No such file or directory
Nov 15 05:06:01 ci CRON[30199]: (root) MAIL (mailed 1 byte of output; but got status 0x004b,  )
Nov 15 05:17:44 ci -- MARK --
Nov 15 05:37:44 ci -- MARK --
Nov 15 05:57:44 ci -- MARK --
Nov 15 06:06:01 ci CRON[33914]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Nov 15 06:06:01 ci CRON[33902]: (CRON) error (grandchild #33914 failed with exit status 2)
Nov 15 06:06:01 ci postfix/sendmail[33917]: fatal: open /etc/postfix/main.cf: No such file or directory
(省略)

詳しいことはわかんないけど

  1. cron.hourly で何かが実行されてる
  2. 正常終了か異常終了かはわからないが、何かが終了したのでそのメールを送ろうとしている
  3. 「fatal: open /etc/postfix/main.cf: No such file or directory」で死んでる
  4. exit 2 したせいで cron の session が close されてない
  5. close されてないので貯まりに貯まって、上記リンクで書かれてるように最大8セッションの制限に引っかかった
  6. 朝起きた俺が ssh して泣く

おそらくこういう流れだろう

ちなみによく見てみると、5時6分のところが

「 MAIL (mailed 1 byte of output; but got status 0x004b,  )」

も付いてきており、この場合はちゃんと session closed なのだ。わけわからん。まじわけわからん。

解決へ

postfix 関連ってのはわかった。しかし俺はこいつをよくわからない。

逃げるように、まずは cron.hourly を調べてみる。

$ ls /etc/cron.hourly/
$

何もないってことは cron.hourly そのものを止めればいいんだよね

--- /etc/crontab.orig	2011-10-31 19:46:21.000000000 +0900
+++ /etc/crontab	2011-11-15 18:09:06.000000000 +0900
@@ -8,7 +8,7 @@
 PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
 
 # m h dom mon dow user	command
-6 * * * * root    cd / && run-parts --report /etc/cron.hourly
+#6 * * * * root    cd / && run-parts --report /etc/cron.hourly
 20 0 * * * root test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )
 30 4 * * 7 root test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.weekly )
 19 4 25 * * root test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.monthly )

世界に平和が戻りました。

ちなみに hourly 以外は anacron でガードされてるので問題ない。きっと run-parts からメールが飛ぶときにほげほげなんだろう。

解決へ(追記)

cron.hourly そのものが動かないのもやっぱあれなので、メール送信をやめるために

--- /etc/crontab.orig	2011-10-31 19:46:21.000000000 +0900
+++ /etc/crontab	2011-11-15 22:33:43.000000000 +0900
@@ -6,9 +6,10 @@
 
 SHELL=/bin/sh
 PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
+MAILTO=""
 
 # m h dom mon dow user	command
 6 * * * * root    cd / && run-parts --report /etc/cron.hourl

こうしました。こっちの方が健全だよねきっと。

まとめ

結果を見ずしてこの記事書いてますけど、きっと明日の朝は泣かなくて済むと思います。
もし朝8時くらいにこの記事が更新されてたら、泣いてると思ってください。