Shell 脚本挂起，但仅在调用变量或 strace 时答案

【问题标题】：Shell script hangs, but only when called into a variable or straceShell 脚本挂起，但仅在调用变量或 strace 时
【发布时间】：2012-12-09 20:51:42
【问题描述】：

一般性问题：如果调用它的脚本或 shell (bash) 命令将其调用到变量中，什么会导致本身运行良好的脚本挂起？

换句话说，怎么会有这样的脚本在这样调用时工作.../path/to/script arg arg ...失败并在这样调用时挂起...VAR=$(/path/to/script arg arg);？

（在注意到软件故障导致大量初始测试给出错误结果后进行重大修改）

我的具体情况：我有一个运行良好的脚本（启动、停止或重新启动 java 应用程序 Apache Solr，adapted from here）。代码如下，其命令为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 脚本上工作得很好，并且脚本的输出可以毫无问题地传递给变量。

这是该脚本的完整代码：（cmets 被移除，$SOLR_DIR 路径自然是真实脚本中的真实路径）

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，以下是一些观察结果：

从大量活动开始，看起来脚本按预期运行。
那么，日志文件的最后 15% 左右是这样的，用不同的整数重复但看似相同的十六进制代码：

...

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

当通过ps -p 输入这些 PID 时，这些 PID 什么也没有出现。时间>。我不太确定这怎么可能。

这是输出的最后一点之前它进入永无止境的 futex/clock_gettime 循环，之后最后一部分显然是正确执行的脚本（@ 987654347@是一个Solr配置文件，需要读取它才能启动Solr进程）：

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

所以死亡螺旋前的最后一行是通道 12 上的 read()。然后它只是循环 futex 和 clock_gettime 直到它被手动杀死。

最后一点可能无关紧要，但是如果similar to in this question，我使用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 是空的。不确定这是否相关 - 我想这可能会导致使用 nohup 输出到 /dev/null 确实是解决此类问题的一般方法，但我做错了，导致这些错误。

【问题讨论】：

哪个外壳？例如，ksh93 将使用exec 执行脚本中的最终命令，因此您不一定会看到两个进程。我们需要知道“挂起”是否在等待某个信号，例如信号。尝试运行strace -f -o strace.out ScriptB。然后查看 strace.out（它会很大）。这应该跟踪内核调用并显示它是否正在等待任何东西。
@cdarke 感谢您的帖子。回覆。哪个外壳：ps -p $$ -o comm,args 给了我bash 和 args -bash。回覆。 strace - 你是对的，它接近 3mbs！我要将该文件中的观察结果编辑到问题中。
@cdarke 我已经编辑了所有看起来相关的输出，以及通过查找这些进程的 PID 可以获得的非常有限的信息。非常感谢您的帮助，请询问我是否应该在输出中查找任何特定内容。
1.不知道你为什么使用nohup $( /sbin/service .. ) > /dev/null。那只会使事情复杂化（我认为）。尝试一个简单的nohup /sbin/service ... > /dev/null（但你可能已经尝试过这个，考虑到你投入的时间）。 2.从您的标题中，我想到了“阻塞终端读取”，这意味着只是等待输入的普通shell read 命令，但我在您发布的代码中没有看到它，但它在您的跟踪中......只是进一步探索的想法。 3. 作为替代方案，您可以取出 nohups 并从 crontab 条目中运行这一切吗？祝你好运
原来是软件故障导致我的大部分初始测试出错。剧本仍然有一个无法解释的（对我来说）问题，但它并不像以前那样疯狂。对于错误信息，我很抱歉 - 我已经重新调整了问题的范围，现在似乎不再那么令人生畏地违反直觉，而且症状也不那么严重了。

标签： linux bash shell

【解决方案1】：

我很确定问题在于 shell 正在捕获 /sbin/service 脚本的输出和它启动的 solr 服务，因此将等待服务退出（或在在继续之前至少关闭其标准输出）。这是一个简单的演示：

$ 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]

【讨论】：

听起来很可能。关于如何以不捕获嵌套脚本的输出并挂起的方式启动 solr 服务的任何想法？我想调用启动脚本来捕获启动脚本本身的输出，并从启动脚本启动的进程中输出到日志文件并被调用它的父级忽略
启动脚本当前将服务器的stderr重定向到日志；只需修改它以在那里重定向标准输出：$JAVA $JAVA_OPTIONS &> $LOG_FILE &
酷。根据您的评论，我使用$JAVA $JAVA_OPTIONS 1> /dev/null 2> $LOG_FILE & 丢弃标准输出并记录标准错误，这更接近于之前的设置（记录错误但不记录标准输出）。同样的原理，完美运行！谢谢:)
如果您不需要标准输入，我建议添加 /null.