scp コマンドにまつわる不思議な挙動を追う

こんにちは、masm11 です。

scp で大きなファイルを転送すること、ありますよね。

私も時々やるのですが、今回、ログアウトすると scp が通信しなくなる、 という妙な症状に見舞われましたので、ご紹介します。

症状

状況としては、まず、3台のコンピュータがあります。

f:id:masm11:20200209235930p:plain

A から B に ssh でログインし、scp コマンドを使って C にあるファイルを B にコピーします。

A$ ssh B
B$ nohup scp C:bigfile.tar.gz . < /dev/null >& /dev/null &

こんな感じですね。zsh を使っているので >& を使っていますが、 bash だと2行目は、

B$ nohup scp C:bigfile.tar.gz . < /dev/null > /dev/null 2>&1 &

になるでしょう。

そして、B の bigfile.tar.gz が大きくなっていくのを以下のようにして 見ていました。

B$ watch -n 1 ls -l bigfile.tar.gz

こうすると、一秒おきに、画面をクリアして ls -l bigfile.tar.gz を実行してくれます。

さて、この後、ひょんなことから、A の端末が落ちてしまいました。

まぁそんなことはよくあることです。 気を取り直して、再び B に ssh して watch コマンドを実行してみたところ、 ファイルサイズが大きくなっていかなくなっていました。

nohup を付けていたのに、scp コマンドが終了してしまったのか? と思い、 ps auxww | grep scp してみたところ、プロセスは生きていました。 B でも C でも確認しました。

プロセスが残っているのに、データが転送されなくなっています。

コネクションが詰まってしまったのでしょうか? B で scp コマンドを kill で殺したところ、C でも scp プロセスがいなくなりました。 コネクションには問題なかったようです。

以上をもう一度試してみたところ、完全に再現しました。再現性はあるようです。

検証

いくつか気になる点がありますので、列挙してみます。

  • nohup はちゃんと仕事をしているのか?
  • SIGHUP を本当に受け取ったのか?
  • scp は独自の SIGHUP ハンドラを設定しているのか?
  • scp は SIGHUP を受けて何かするのか?
  • scp は止まった状態で何をしていたのか?
  • scp のマニュアルに記載はあるか?
  • この症状に zsh は関係するのか?

以下、これらを一つずつ調べていきます。

nohup はちゃんと仕事をしているのか?

nohup を付けると、以下のように出力されますよね。

luna:/tmp % nohup ls
nohup: 入力を無視し、出力を 'nohup.out' に追記します
luna:/tmp % 

標準入力は /dev/null になり、標準出力、標準エラー出力は nohup.out になります。

しかし、nohup の仕事はこれだけではありません。 SIGHUP という signal を無視するようにする、という重要な仕事があります。

これが行われているのかどうかを確認してみました。

C で以下のコードを書きます。

#include <stdio.h>
#include <signal.h>

static void handler(int signo)
{
}

int main(void)
{
    printf("%p\n", signal(SIGHUP, handler));
    return 0;
}

signal() 関数は、新しい signal ハンドラ を設定すると共に、 旧 signal ハンドラを返してくれますので、その値を出力します。

これを test.c というファイル名で保存し、コンパイル、実行してみます。

すると、以下のように出力されます。

luna:~ % ./test 
(nil)
luna:~ % 

では nohup を付けてみます。

luna:~ % nohup ./test 
nohup: 入力を無視し、出力を 'nohup.out' に追記します
luna:~ % cat nohup.out
0x1
luna:~ % 

0x1 ですね。これが何かと言うと、

luna:~ % grep SIG_IGN /usr/include/bits/signum-generic.h
#define    SIG_IGN  ((__sighandler_t)  1)  /* Ignore signal.  */
luna:~ % 

これです。signal を無視する設定 SIG_IGN の値は 1 なのです。 これが出力されたんですね。

このように、nohup は

  • 標準入力を /dev/null にする
  • 標準出力、標準エラー出力は nohup.out にする
  • SIGHUP を無視するようにする
  • これらを設定した上で、指定されたプログラムを実行する

という仕事をしているのです。

問題ないようですね。

SIGHUP を本当に受け取ったのか?

signal を受け取ったかどうかを確認するには、strace を使うのが手っ取り早いです。

B$ strace -f -o log nohup scp C:bigfile.tar.gz . < /dev/null >& /dev/null &
[1] 732184
B$

こうすると、strace の子孫プロセス全てにわたって (-f)、システムコールの状況が log ファイルに (-o log) 出力されます。また、signal を受け取った時はその signal 番号も出力してくれます。

出力から一部を抜き出すと、以下のようになっていました。

732460 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=732179, si_uid=1000} ---
732460 select(7, [3 4], [], NULL, NULL <unfinished ...>
732459 <... poll resumed>)              = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
732459 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=732179, si_uid=1000} ---
732459 kill(732460, SIGHUP)             = 0
732460 <... select resumed>)            = ? ERESTARTNOHAND (To be restarted if no handler)
732459 wait4(732460,  <unfinished ...>
732460 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=732459, si_uid=1000} ---

確かに SIGHUP を受け取っているようです。 SIG_IGN に設定されていると、

732460 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=732179, si_uid=1000} ---

という出力はないはずだからです。

scp コマンドが独自の SIGHUP ハンドラを設定しているのでしょうか?

scp は独自の SIGHUP ハンドラを設定しているのか?

これについては、先程の strace のログをもう一度見てみましょう。ログの上の方に、

732459 rt_sigaction(SIGHUP, {sa_handler=0x556e9127d810, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f4df345cfb0},  <unfinished ...>

こんな行がありました。sa_handler= がいかにもプログラムの中っぽいアドレスになっています。

どうやら、自前のハンドラを設定しているようです。 これでは、nohup を付けても意味はないですね。

scp は SIGHUP を受けて何かするのか?

これについては、多少推測する程度しかできません。

先程の strace のログを再度引用すると、

732460 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=732179, si_uid=1000} ---
732460 select(7, [3 4], [], NULL, NULL <unfinished ...>
732459 <... poll resumed>)              = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
732459 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=732179, si_uid=1000} ---
732459 kill(732460, SIGHUP)             = 0
732460 <... select resumed>)            = ? ERESTARTNOHAND (To be restarted if no handler)
732459 wait4(732460,  <unfinished ...>
732460 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=732459, si_uid=1000} ---

おそらく scp は2つのプロセスで成り立っていて、732459 が親プロセス、732460 が子プロセスです。 そして、732459 が SIGHUP を受け取った後、kill(732460, SIGHUP) で 732460 に SIGHUP を送って います。

つまり、親プロセスが SIGHUP を受け取ったら、それを子プロセスにも送る、ということですね。 よくある構造です。

その他にも何かやっているかもしれませんが、これ以上は判りませんでした。

scp は止まった状態で何をしていたのか?

これもほとんど手がかりはないのですが、

B$ ss -n | grep :22 
tcp     ESTAB        0        0                         192.168.86.132:36134                       x.x.x.x:22
tcp     ESTAB        0        0                         192.168.86.132:22                         192.168.86.150:51614
B$

ソケットのバッファに何も溜まっていません。このことから、そもそも送信側 (C) が送ってなさそう、と考えられます。

scp のマニュアルに記載はあるか?

http://man7.org/linux/man-pages/man1/scp.1.html

ここにマニュアルがあります。このページから hupsignal でページ内検索してみましたが、引っかかりません。 記載はないようです。

https://linux.die.net/man/1/ssh

こちらに ssh のマニュアルがあります。scp は ssh を使っているので、もしや、と思いましたが、 こちらにも記載はありませんでした。

この症状に zsh は関係するのか?

man zshall して SIGHUP で検索してみたところ、記載がありました。 引用します。

       When  you  try  to leave the shell while jobs are running or suspended,
       you will be warned that `You have suspended (running) jobs'.   You  may
       use  the  jobs command to see what they are.  If you do this or immedi‐
       ately try to exit again, the shell will not warn you a second time; the
       suspended  jobs will be terminated, and the running jobs will be sent a
       SIGHUP signal, if the HUP option is set.

zsh を終了しようとした時、実行中のジョブには SIGHUP が送られるようです。 ただし、HUP オプションがセットされている場合。だそうです。

解決策 (回避策)

さて、ここまでいくつか検証してみた結果、

  • nohup は仕事をしているが、
  • scp が独自のハンドラを設定している。
  • zsh を抜ける時に SIGHUP が送られ、
  • SIGHUP を受け取った scp は
  • 独自のハンドラで何らかの処理を行い、
  • その結果、何故か転送が止まってしまう

ということがわかりました。

何故転送が止まってしまうかについては、マニュアルにも記載がなく、わかりませんでした。

しかし、ここまでわかれば回避はできます。

B で、zsh に

B$ unsetopt HUP

と設定すれば、zsh 終了時に SIGHUP が送られることはなくなります。

また、間に端末 (tty) を挟まなければ OK のはず、と思ったので、

A$ ssh B nohup scp C:bigfile.tar.gz . < /dev/null >& /dev/null &

これでも回避できました。ssh はコマンドラインに直接コマンドを書けば、 tty なしでコマンドを実行してくれます。

私が回避した時には、zsh が絡んでいるとは思っていなかったので、後者の方法で回避し、 以下のように問題なく最後まで転送できました。

B$ ls -l bigfile.tar.gz 
-rw-r--r-- 1 masm masm 2750186558  29 21:04 bigfile.tar.gz
B$

(たかが 3GB 弱です。ネットワーク遅いと萎えますよね…)

まとめ

結局、回避はできましたが、根本的に通信だけ止まっている原因は不明のまま残ってしまいました。 今後解決できるといいのですが…

ではまた!