泣いた。嘘です。
ServersMan@VPS に限った話ではないかもしれませんが、私が今使ってる他の VPS (さくらとか)では起きなかったのでこういうタイトルで。
経緯
実はいろいろあって ServersMan@VPS を一度解約しています(さくらで十分だったから)が、
Jenkins サーバを別で欲しかったので、無料期間が2ヶ月あっていろいろ調整しやすいので
再び ServersMan を借りることにしました。前回は Cent で今回は Ubuntu です。(11.04 に upgrade 済み)
で、なんか調子が変。夜までは普通に触れるんですが、朝起きて ssh すると
shell request failed on channel 0
と出て拒否られる。パスワード入力した直後ですね。おそらく認証は通っているんでしょう。
しかし意味がわからない。とりあえずぐぐってみると
- PTY allocation request failed on channel 0 - yokochiの開発メモ
- screenの「No more PTY」 - 「君、給料いくらもらってるの？」「俺は人間国宝だから二億もらえる」
みたいな情報が得られる。しかし私の環境では
- 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 (省略)
詳しいことはわかんないけど
- cron.hourly で何かが実行されてる
- 正常終了か異常終了かはわからないが、何かが終了したのでそのメールを送ろうとしている
- 「fatal: open /etc/postfix/main.cf: No such file or directory」で死んでる
- exit 2 したせいで cron の session が close されてない
- close されてないので貯まりに貯まって、上記リンクで書かれてるように最大8セッションの制限に引っかかった
- 朝起きた俺が 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時くらいにこの記事が更新されてたら、泣いてると思ってください。
