title: Shell script hangs, but only when called into a variable or strace
body: <p><strong>General question:</strong> What could cause a script that works fine in itself, to hang if the script or shell (bash) command that calls it calls it into a variable? </p>
  
  <p>In other words, how could there be a script that works when called like this... <code>/path/to/script arg arg</code> ...fail and hang when called like this... <code>VAR=$(/path/to/script arg arg);</code>?</p>
  
  <hr>
  
  <p><em>(major edits after noticing that a software glitch caused much initial testing to give incorrect results)</em></p>
  
  <hr>
  
  <p><strong>My specific case:</strong> I've got a script that works fine (to start, stop or restart the java application Apache Solr, <a href="http://drupal.org/node/545368" rel="nofollow noreferrer">adapted from here</a>). Code is below, its command is <code>sbin/service solr [action]</code>, for example <code>sbin/service solr start</code>. </p>
  
  <p>When called from a script or directly from a console (<code>bash</code> in my case), like <code>sbin/service solr start</code>, it works fine and completes quickly. If, however, it's called into a variable, like <code>VAR=$(sbin/service solr start);</code>, it works, but hangs with a futext / clock_gettime loop (trace below). It also hangs if it's called not into a variable, but into <code>strace</code>.</p>
  
  <p>Curiously, other scripts called in the same way with the same syntax, e.g. <code>sbin/service httpd start</code>, work just fine when called into a variable. So it's clearly possible for there to be something about a script that makes it hang when the output is stored as a variable, but operate perfectly well when this isn't the case.</p>
  
  <hr>
  
  <p>Here's the results of testing what calls hang and what don't:</p>
  
  <p><strong>HANGS</strong>------------------------------------------------</p>
  
  <ul>
  <li><code>VAR=$(/sbin/service solr start);</code></li>
  <li><code>VAR=$(source /sbin/service solr start);</code></li>
  <li><code>VAR=$(nohup /sbin/service solr start &amp;);</code></li>
  </ul>
  
  <p>(so it doesn't matter which process it's called from) Also, editting the script file to start the service using <code>source</code> causes the service to not work.</p>
  
  <p><strong>DOESN'T HANG</strong>-------------------------------------</p>
  
  <ul>
  <li><code>VAR=$(/sbin/service solr start &gt;&gt; /dev/null);</code></li>
  </ul>
  
  <p><em>Outputting to <code>/dev/null</code> allows us to request the output without causing it to hang. However, it's not much use, as no actual output is received.</em> </p>
  
  <ul>
  <li><code>/sbin/service solr start</code></li>
  </ul>
  
  <p><em>Contrary to what I first thought. This outputs a simple update message which, ideally, we'd capture in a variable and log - but attempting to do so causes it to hang.</em></p>
  
  <ul>
  <li><code>VAR=$(/sbin/service httpd restart);</code></li>
  </ul>
  
  <p><em>The syntax that hangs works just fine on other <code>service</code> scripts, and the output of the script is passed to the variable without issue.</em></p>
  
  <hr>
  
  <p>Here's the full code of that script: (comments removed, naturally the $SOLR_DIR path is a real one in the real script)</p>
  
  <pre><code>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&gt; $LOG_FILE &amp;
          ;;
      stop)
          echo "Stopping Solr"
          cd $SOLR_DIR
          $JAVA $JAVA_OPTIONS --stop
          ;;
      restart)
          $0 stop
          sleep 1
          $0 start
          ;;
      *)
          echo "Usage: $0 {start|stop|restart}" &gt;&amp;2
          exit 1
          ;;
  esac
  </code></pre>
  
  <p>No errors or anything unusual in <code>var/log/solr.log</code> (log file named in script). Centos Linux server if that's relevant.</p>
  
  <hr>
  
  <p>In response to an earlier version of the question, @cdarke suggested I run <code>strace -f -o strace.out /path/to/script</code> on a script calling this script, and look in the (massive!) output file <code>strace.out</code>. It's nearly 3mbs, here's some observations:</p>
  
  <ol>
  <li><p>Starts with lots of activity that looks like the script functioning as intended.</p></li>
  <li><p>Then, the last 15% or so of the log file is this, repeated with different integers but seemingly the same hex codes:</p></li>
  </ol>
  
  <p>...</p>
  
  <pre><code>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
  </code></pre>
  
  <p>These PIDs  come up with nothing when put through <code>ps -p</code> <em>even if I do so while the script is still running, while the output file is still getting bigger and while these lines of code are still being written</em>. I'm not quite sure how that's possible.</p>
  
  <p>Here's the final bit out the output <em>before</em> it gets in the never-ending futex/clock_gettime loop, <em>after</em> the last part that is clearly the script executing correctly (<code>solr/solr.xml</code> is a Solr config file, which needs to be read to start the Solr process):</p>
  
  <pre><code>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&gt;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} &lt;unfinished ...&gt;
  25894 &lt;... futex resumed&gt; )             = 0
  25894 futex(0x2aaab0173028, FUTEX_WAIT_PRIVATE, 2, NULL &lt;unfinished ...&gt;
  25874 &lt;... futex resumed&gt; )             = 1
  25874 futex(0x2aaab0173028, FUTEX_WAKE_PRIVATE, 1 &lt;unfinished ...&gt;
  25894 &lt;... futex resumed&gt; )             = 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} &lt;unfinished ...&gt;
  25874 &lt;... futex resumed&gt; )             = 1
  25874 futex(0x2aaab0173054, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x2aaab0173050, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} &lt;unfinished ...&gt;
  25894 &lt;... futex resumed&gt; )             = 0
  25894 futex(0x2aaab0173028, FUTEX_WAIT_PRIVATE, 2, NULL &lt;unfinished ...&gt;
  25874 &lt;... futex resumed&gt; )             = 1
  25874 futex(0x2aaab0173028, FUTEX_WAKE_PRIVATE, 1 &lt;unfinished ...&gt;
  25894 &lt;... futex resumed&gt; )             = 0
  25894 futex(0x2aaab0173028, FUTEX_WAKE_PRIVATE, 1) = 0
  25894 poll([{fd=89, events=POLLIN|POLLERR}], 1, -1 &lt;unfinished ...&gt;
  25874 &lt;... futex resumed&gt; )             = 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 &lt;unfinished ...&gt;
  25882 &lt;... futex resumed&gt; )             = -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
  </code></pre>
  
  <p>So the last line before the death spiral is a <code>read()</code> on channel 12. Then it just loops futex and clock_gettime until it's manually killed. </p>
  
  <hr>
  
  <p>This last point may be irrelevant, but if, <a href="https://stackoverflow.com/questions/8122780/exiting-shell-script-with-background-processes">similar to in this question</a>, I run the script that calls this script using <code>nohup</code> and divert output to <code>/dev/null</code>, I get the following near the start ( about 100kb into the output file): a huge number of these: </p>
  
  <p><code>25664 close(67)                         = -1 EBADF (Bad file descriptor)</code></p>
  
  <p>They go from 67, increasing +1 each time, to:</p>
  
  <p><code>25664 close(1023)                       = -1 EBADF (Bad file descriptor)</code></p>
  
  <p>Then they're followed by </p>
  
  <p><code>25664 open("/dev/null", O_RDWR)         = 3</code></p>
  
  <p>Again, the PIDs are empty, so far as I can see. Not sure if this is relevant - I guess this opens the possibility that using nohup with output to /dev/null really is a general fix for problems like this but I'm doing it wrong somehow, causing these errors.</p>