5

一般的な質問:スクリプトを呼び出すスクリプトまたはシェル (bash) コマンドがスクリプトを変数に呼び出した場合、それ自体は問題なく動作するスクリプトがハングする原因は何ですか?

つまり、このように呼び出されたときに機能するスクリプトがどのように存在する可能性があります... /path/to/script arg arg...このように呼び出されたときに失敗してハングする... VAR=$(/path/to/script arg arg);?

(ソフトウェアの不具合により、多くの初期テストで誤った結果が得られたことに気付いた後の大幅な編集)

私の具体的なケース:私は正常に動作するスクリプトを持っています (Java アプリケーション Apache Solr を開始、停止、または再起動するため、ここから適応)。コードは以下のとおりです。コマンドはsbin/service solr [action]、たとえばsbin/service solr startです。

のように、スクリプトから、またはコンソール (bash私の場合)から直接呼び出すと、sbin/service solr start正常に動作し、すぐに完了します。ただし、のように変数に呼び出された場合、VAR=$(sbin/service solr start);機能しますが、futext / clock_gettime ループでハングします (以下のトレース)。変数ではなく に呼び出された場合にもハングしstraceます。

興味深いことに、同じ構文で同じ方法で呼び出された他のスクリプト (たとえばsbin/service httpd start、変数に呼び出された場合は問題なく動作します)。したがって、出力が変数として格納されている場合にスクリプトがハングする可能性はありますが、そうでない場合は完全に正常に動作します。

ハングするコールとハングしないコールをテストした結果を次に示します。

ハング------------------------------------------------

  • VAR=$(/sbin/service solr start);
  • VAR=$(source /sbin/service solr start);
  • VAR=$(nohup /sbin/service solr start &);

(そのため、どのプロセスから呼び出されてもかまいません) また、スクリプト ファイルを編集してサービスを開始するsourceと、サービスが動作しなくなります。

ハングしない-------------------------------------

  • VAR=$(/sbin/service solr start >> /dev/null);

に出力する/dev/nullと、ハングすることなく出力を要求できます。ただし、実際の出力は受信されないため、あまり役に立ちません。

  • /sbin/service solr start

最初に思ったのとは逆。これは単純な更新メッセージを出力します。理想的には、変数とログにキャプチャしますが、そうしようとするとハングします。

  • VAR=$(/sbin/service httpd restart);

ハングする構文は他のserviceスクリプトでも問題なく機能し、スクリプトの出力は問題なく変数に渡されます。

そのスクリプトの完全なコードは次のとおりです。

SOLR_DIR="[path/to/application]"
JAVA_OPTIONS="-Xms64m -Xmx64m -DSTOP.PORT=8079 -DSTOP.KEY=mustard -jar start.jar"
LOG_FILE="/var/log/solr.log"
JAVA="/usr/bin/java"

case $1 in
    start)
        echo "Starting Solr"
        cd $SOLR_DIR
        $JAVA $JAVA_OPTIONS 2> $LOG_FILE &
        ;;
    stop)
        echo "Stopping Solr"
        cd $SOLR_DIR
        $JAVA $JAVA_OPTIONS --stop
        ;;
    restart)
        $0 stop
        sleep 1
        $0 start
        ;;
    *)
        echo "Usage: $0 {start|stop|restart}" >&2
        exit 1
        ;;
esac

var/log/solr.log(スクリプトで指定されたログ ファイル)にエラーや異常はありません。関連する場合はCentos Linuxサーバー。

質問の以前のバージョンに応えて、@cdarke は、strace -f -o strace.out /path/to/scriptこのスクリプトを呼び出すスクリプトで実行し、(大規模な!) 出力ファイルを調べることを提案しましたstrace.out。それはほぼ3mbsです、ここにいくつかの観察があります：

  1. スクリプトが意図したとおりに機能しているように見える多くのアクティビティから始まります。

  2. 次に、ログ ファイルの最後の 15% 程度が次のようになります。異なる整数で繰り返されていますが、一見同じ 16 進コードです。

...

25687 futex(0x688d454, FUTEX_WAIT_PRIVATE, 1, {0, 49980000}) = -1 ETIMEDOUT (Connection timed out)
25687 futex(0x688d428, FUTEX_WAKE_PRIVATE, 1) = 0
25687 clock_gettime(CLOCK_MONOTONIC, {39074112, 932735888}) = 0
25687 clock_gettime(CLOCK_REALTIME, {1355007234, 333458000}) = 0

これらの PIDps -p は、スクリプトがまだ実行されている間、出力ファイルがまだ大きくなっている間、およびこれらのコード行がまだ書き込まれている間に実行しても、何も表示されません。それがどのように可能かはよくわかりません。

これは、終わりのない futex/clock_gettime ループに入る前の出力の最後のビットです。スクリプトが正しく実行されていることは明らかな最後の部分 ( Solr プロセスを開始するために読み取る必要がある Solr 構成ファイル) の後の部分です。solr/solr.xml

25874 stat("solr/solr.xml", {st_mode=S_IFREG|0777, st_size=1320, ...}) = 0
25874 write(2, "Dec 8, 2012 5:12:05 PM org.apach"..., 106) = 106
25874 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 89
25874 fcntl(89, F_GETFL)                = 0x2 (flags O_RDWR)
25874 fcntl(89, F_SETFL, O_RDWR|O_NONBLOCK) = 0
25874 setsockopt(89, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
25874 bind(89, {sa_family=AF_INET, sin_port=htons(8983), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
25874 listen(89, 50)                    = 0
25874 setsockopt(89, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
25874 lseek(12, 57747, SEEK_SET)        = 57747
25874 read(12, "PK\3\4\n\0\0\0\10\0\221Vi>F\347\254\364\325\4\0\0002\t\0\0002\0\0\0", 30) = 30
25874 lseek(12, 57827, SEEK_SET)        = 57827
25874 read(12, "\225V\377oSU\24\377\334\273\256\257_\36l\216m\254\262\351\224\241]\273\255\200\314/\5\246c\200"..., 1237) = 1237
25874 futex(0x2aaab0173054, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x2aaab0173050, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
25894 <... futex resumed> )             = 0
25894 futex(0x2aaab0173028, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
25874 <... futex resumed> )             = 1
25874 futex(0x2aaab0173028, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
25894 <... futex resumed> )             = 0
25894 futex(0x2aaab0173028, FUTEX_WAKE_PRIVATE, 1) = 0
25894 clock_gettime(CLOCK_REALTIME, {1355008325, 376033000}) = 0
25894 futex(0x2aaab0173054, FUTEX_WAIT_PRIVATE, 3, {0, 983000} <unfinished ...>
25874 <... futex resumed> )             = 1
25874 futex(0x2aaab0173054, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x2aaab0173050, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
25894 <... futex resumed> )             = 0
25894 futex(0x2aaab0173028, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
25874 <... futex resumed> )             = 1
25874 futex(0x2aaab0173028, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
25894 <... futex resumed> )             = 0
25894 futex(0x2aaab0173028, FUTEX_WAKE_PRIVATE, 1) = 0
25894 poll([{fd=89, events=POLLIN|POLLERR}], 1, -1 <unfinished ...>
25874 <... futex resumed> )             = 1
25874 write(2, "2012-12-08 17:12:05.376:INFO::St"..., 66) = 66
25874 write(2, "\n", 1)                 = 1
25874 mmap(0x41348000, 12288, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x41348000
25874 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
25874 sched_getaffinity(25874, 32,  { ffff, 0, 0, 0 }) = 32
25874 sched_getaffinity(25874, 32,  { ffff, 0, 0, 0 }) = 32
25874 gettid()                          = 25874
25874 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
25874 rt_sigprocmask(SIG_UNBLOCK, [HUP ILL BUS FPE SEGV USR2 TERM], NULL, 8) = 0
25874 rt_sigprocmask(SIG_BLOCK, [QUIT], NULL, 8) = 0
25874 mmap(0x41348000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x41348000
25874 mprotect(0x41348000, 12288, PROT_NONE) = 0
25874 futex(0x10632d54, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
25882 <... futex resumed> )             = -1 ETIMEDOUT (Connection timed out)
25882 futex(0x106cc428, FUTEX_WAKE_PRIVATE, 1) = 0
25882 clock_gettime(CLOCK_MONOTONIC, {39075204, 21489888}) = 0
25882 clock_gettime(CLOCK_REALTIME, {1355008325, 422198000}) = 0
25882 futex(0x106cc454, FUTEX_WAIT_PRIVATE, 1, {0, 49984000}) = -1 ETIMEDOUT (Connection timed out)
25882 futex(0x106cc428, FUTEX_WAKE_PRIVATE, 1) = 0
25882 clock_gettime(CLOCK_MONOTONIC, {39075204, 72479888}) = 0
25882 clock_gettime(CLOCK_REALTIME, {1355008325, 473185000}) = 0
25882 futex(0x106cc454, FUTEX_WAIT_PRIVATE, 1, {0, 49987000}) = -1 ETIMEDOUT (Connection timed out)
25882 futex(0x106cc428, FUTEX_WAKE_PRIVATE, 1) = 0

したがって、デス スパイラルの前の最後の行はread()チャネル 12 にあります。その後、手動で強制終了されるまで futex と clock_gettime をループします。

この最後のポイントは無関係かもしれませんが、この質問と同様に、このスクリプトを呼び出すスクリプトを実行し、nohup出力を/dev/nullに転送すると、開始近くで次のようになります (出力ファイルに約 100kb):これらは：

25664 close(67) = -1 EBADF (Bad file descriptor)

それらは 67 から、毎回 +1 ずつ増えていきます。

25664 close(1023) = -1 EBADF (Bad file descriptor)

その後、

25664 open("/dev/null", O_RDWR) = 3

繰り返しますが、私が見る限り、PID は空です。これが関連しているかどうかはわかりません-/ dev/nullへの出力でnohupを使用することは、このような問題の一般的な修正である可能性があると思いますが、どういうわけか間違っているため、これらのエラーが発生します。

4

1 に答える 1

2

問題は、シェルが /sbin/service スクリプトとそれが開始する solr サービスからの出力をキャプチャしているため、続行する前にサービスが終了する (または少なくとも stdout を閉じる) のを待つことだと確信しています。簡単なデモを次に示します。

$ bg_service() { while true; do sleep 10; done; }
$ start_bg_service() { echo "starting"; bg_service& echo "running"; }
$ start_bg_service 
starting
[1] 8656
running
$ var=$(start_bg_service)
[It hangs at this point... until I open another shell and kill the background process]
于 2012-12-09T02:33:46.003 に答える