SSHログインで「shell-init: error retrieving current directory」となるのを調べたら意外に時間がかかったという話
サーバにログインしたとき、こんなメッセージに出会うことがある。
$ ssh server.example.jp shell-init: error retrieving current directory: getcwd: cannot access parent directories: そのようなファイルやディレクトリはありません
たまに目にするのだけど、実害がないので放っておく。そうしてふと気付いたときには発生しなくなっている。でも今回はちょっと気になったのでもう少し調べてみた。(以下はその少し長いログである。)
見わたしたところで手がかりがない。だから手始めに検索から始めた。何はともあれ検索だろう。
エラーメッセージそのものを条件として検索を実行するととそれなりの数が出てくる。そのうち上位にあるいくつかではサービスの起動や停止の際に見掛けることがあるという内容だった。OS環境によって方法は異なるがservice httpd startとか、invoke-rc.d apache2 startとか、/etc/init.d/mysql startとか、を実行した際に表示されるという事例である。
このケースへの回答は「一度cdしてから実行してみよ」といったものが目立つ。これはつまり、コマンド実行時に位置しているディレクトリが失われているのが原因だからである。
$ mkdir /tmp/test $ cd /tmp/test $ rmdir /tmp/test $ /etc/init.d/bind9 status shell-init: error retrieving current directory: getcwd: cannot access parent directories: そのようなファイルやディレクトリはありません bind9 is running. $ cd $ /etc/init.d/bind9 status bind9 is running.
うん、それはそうだろう。けども今はSSHログインしたときに表示されるものが問題なんだ。
実際、これらの事例の中にはネットワークに関わるものは見当たらない。すべてが一つのホストの環境の中に閉じている。これらの問題とは前提が異なるはずである。と、そのように考えた。それに対し、検索結果には同様の事例が出てくるばかり。情報は多いもののキリがなく、この検索結果からはこれというヒントが見付かりそうにない。検索に絞り込みをかけるにしても、もう少し突っ込んだ情報が必要となるだろう。
何がこのメッセージを出しているのかを特定できないだろうか。
やはりこれという手がかりはないままだが、簡単にできることは端からやってみよう。まずは現象が起きているサーバでsuを実行してみる。この問題はサーバへのログイン処理の中の何かに起因するはずであるから、その周辺の様子を見ていかなければならない。ネットワークを使わずに問題を再現できれば追跡が楽になるし、ログイン処理に関わる設定やプログラムに手を加えなくてすむ。これでメッセージを出力させられれば一息に解析が進むはず、と期待した。だが、残念ながらそううまくはいかない。
実際、このメッセージが表示されながらもログインはできている。もちろんホームディレクトリが失われているなんてことはないし、他に目立つ何かが起きているわけでもない。だからこそ「放っておく」ということをしてきたわけだ。
ともあれ、ログイン処理そのものではないとしよう。であるならばログイン処理に至るまでの間に何かが起きているのだろうか。ここでちょっとしたひらめきがあった。
もしかしてsshdのカレントワーキングディレクトリが失われているのか?
SSHでログインするとSSHサーバの実体であるsshdからいくつかのプログラムを経てシェルが起動されるに至る。その際、大本のカレントワーキングディレクトリが失われていれば、あるいはそういったことも…… などと想像したわけだが、むろんそんなことは起きていない。一般にdaemonのカレントワーキングディレクトリは「/」である。sshdもそうだ。それが失われているはずは(少なくもこの状況では)ない。
念のためにlsofで調べて、と。やはり外れている、な、と。
外れを確認できたのも一つの前進ではある。せっかくなので失われたディレクトリを参照しているプロセスがないかと同じくlsofで調べたが特別なものはなさそうだった。
落ち着いてみればすぐに分かることなのに。少し頭を冷やさないと。
気持ちを切り換え、そして改めて条件を見直してみる。SSHでのログインの際に出力されたものであるから関係していそうなのはSSHサーバ、ログインシェル、ホームディレクトリ、だろう。このうちの二つはすでに見てきたから残るはログインシェル。このときサーバ上で利用しているたのはzshであったので、zshがメッセージを出力している可能性を調べてみよう。apt-getでソースを取得し、ack(ack-grep)でざっと検索してみる。念のため-aオプションを付けての検索もしておく。
んん、それららしいメッセージを出力しているところはなさそうだ。
では、ログインシェルそのものではなく、シェルの初期化中に何かが起きているのだろうか。
まずは~/.zprofileを退避しておいて読み込まれないようにしてみよう。
~/.zprofileがなくなったところでどうということはないはずだ。だが、ログインできなくなると面倒ではある。安全のため、現行セッションを維持したままにしておきたい。
別ウィンドウからログイン、っと。
すると、問題のメッセージが表示されない。もしや、と思い、今度は~/.zprofileを復帰させてからもう一度試してみることにする。これでメッセージが表示されれば当たりだ。すると……
あれ、やっぱりメッセージが表示されない。うわ、やっちゃった?!
見込み違いだったのはしょうがないし問題ない。問題ないのは、これをもって、せっかく捕まえていた現象を逃がしてしまった(再現できなくなってしまった)ということだ。 あぁーと(心の中で)叫び、頭をかかえ——はしなかったが、つかの間ぼーっとし、そしてがっくりきた。
しょうがない、あきらめるほかないかね。念のため、サーバにおかしなことが起きていないかだけ確認しておこう。
ログインできなくなっているとコトなので、ログインからやり直す。別ウィンドウからのログインを数回行った上で、最初のウィンドウからのログインも確認しておく。すると、なんと問題のメッセージが再び表示されいる。ここにきて「やった!」というよろこびよりも「おや?」と違和感を覚えた。
SSHログインに際してメッセージが表示されるものだから、つい、ログイン先で問題が起きていると考えた。その前提で問題を追い込んできたつもりだった。だが、どうもそうではないのかもしれない。
このメッセージを出力しているのはいったい何なのだ?
最初からやり直してみよう。検索条件を絞り込むことを考えたが逆にもう少し一般化して範囲を広げてみよう。「shell-init」をキーに検索してみる。
するとこんなやり取りが見付かる。その先のリンクをたどっていくと、問題のこのメッセージはbashが出しているといったことが書いてある。実際にソースにあたってみると、たしかにそのためのコードを見付けることができた。なるほどbashか。
では、誰がbashを呼び出しているのだろう?
すでに触れた通り、ログイン先のシェルはzshであってbashではない。(ついでにいうならログイン元もzshである。)初期化スクリプトにはオプション設定を書いている程度で、その内部でbashを使ってはいない。それに、これまでの調査の中で~/.zprofileをなくした状態でもメッセージが表示されるのを確認もした。ホームディレクトリはちゃんとある。sshdでもなければログインシェル(zsh)でもない。こうなると残るのはSSH
——のまだ疑っていないほうの片割れ、sshだろうか。
端末ログインの動きからsshを追跡するのは少しめんどうになりそうだ。端末を開かないリモートコマンド実行で現象を再現できないだろうか。そう考えて試してみる。
$ ssh server.example.jp /bin/true shell-init: error retrieving current directory: getcwd: cannot access parent directories: そのようなファイルやディレクトリはありません
よし、問題ない。再現できる。これならばstraceをかけるだけで済みそうだ。
31177 execve("/usr/bin/ssh", ["ssh", "server.example.jp", "/bin/true"], [/* 159 vars */]) = 0
[...]
31177 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb73da748) = 31179
[...]
31179 execve("/bin/sh", ["sh", "-c", "/usr/bin/xauth list :0.0 2>/dev"...], [/* 159 vars */]
[...]
31179 write(2, "shell-init: error retrieving cur"..., 157) = 157
[...] -fオプションを付け忘れたりもしつつ何度か実行し、そうして上の結果を得ることができた。sshが内部でxauthを実行しており、その際に/bin/shを使っているのを見てとれる。そして/bin/shの実体は、このホストではbashである。
問題のメッセージを出力しているbashが起動されているのはこの箇所であり、つまり、リモートホスト上ではなくローカルホスト上でメッセージが出力されている、と考えられる。このことを検索するにはsshに-xオプションを指定してxauthが起動されないようにすればよい。
いざ、実験。
ssh -xでコマンド実行、それからログインをしてみる。問題のメッセージは表示されない。
もう一度。今度は-xオプションなしでコマンド実行、それからログイン。問題のメッセージが表示された!
まとめ
さて、すでに答は出ているわけであるが、まとめておく。
そもそもの発端であった「SSHでログインした際にshel-init: error retrieving current directory...というメッセージが表示される」という問題の原因は、sshを実行したローカルホスト側にあった。sshの内部的な動作において/bin/shが起動され、その実体がbashであり、そしてssh実行時のカレントワーキングディレクトリが削除されているために現象が発生していた。だから、この問題の解決方法も「一度cdしてから実行してみよ」である。
今回の反省
明らかに最初から視野が狭まっていた。
リモートログイン時の問題だからリモートで何かが起きていると考えてしまったのだろうと思う。メッセージが表示された際、同じ環境で別ホストにログインしてみれば、そこでも再現することを確認できたはずだ。また、サービス起動時の同様のメッセージについても、前提が異なると思い込まずに実験してみていれば実は同じ現象だと分かったはずだ。
細かく言えば、いつの間にか起きるようになり、いつの間にか起きなくなる現象という印象があったため、環境を変えるようなことをできるだけしたくないと考えていた部分もあるのではないかと思う。そのことと、上の思い込みとが合わさった結果として予想だけで判断してしまった。
行き詰まったときに検索条件を緩めるという程度のことではあるものの、結果的に、視野を少し広げられたのがよかった。それにしてもあっちにぶつかり、こっちにぶつかりしながらの追跡でなんともぶきっちょなことであったが。