Repository: amoffat/sh (python)

Issue:
_done callback consistent deadlock when accessing RunningCommand arg passed to callback
This consistently deadlocks:

```python
from sh import sleep

def done(cmd, success, exit_code):
    print(cmd, success, exit_code)

sleep('1', _done=done)
```

This is possibly related to #413 and #518.  This is on version 1.14.1 and Python 3.7 (but I doubt that matters).

Now I suppose one might say "Well, don't do that with cmd and the done callback" ... However, if the argument is passed to the callback it should be safe to use, IMO.  And none of the test cases cover accessing done callback arg 0 at all.

The reason it deadlocks is because of a double wait on `_wait_lock`: `_wait_lock` is already held whenever `self._process_just_ended()` is called (either via `self.is_alive()` or `self.wait()`), `self._process_just_ended()` is what calls the done callback, and then the printing of `cmd` tries to coerce it to a string using its stdout value, which then also calls `self.wait()`, which tries to acquire `_wait_lock` again and deadlocks.

You can see this in the stack trace:

```
^CTraceback (most recent call last):
  File "y.py", line 6, in <module>
    sleep('1', _done=done)
  File ".../site-packages/sh.py", line 1520, in __call__
    return RunningCommand(cmd, call_args, stdin, stdout, stderr)
  File ".../site-packages/sh.py", line 784, in __init__
    self.wait()
  File ".../site-packages/sh.py", line 831, in wait
    exit_code = self.process.wait()
  File ".../site-packages/sh.py", line 2491, in wait
    self._process_just_ended()
  File ".../site-packages/sh.py", line 2442, in _process_just_ended
    done_callback(success, self.exit_code)
  File "y.py", line 4, in done
    print(cmd, success, exit_code)
  File ".../site-packages/sh.py", line 930, in __str__
    return self.__unicode__()
  File ".../site-packages/sh.py", line 937, in __unicode__
    if self.process and self.stdout:
  File ".../site-packages/sh.py", line 869, in stdout
    self.wait()
  File ".../site-packages/sh.py", line 831, in wait
    exit_code = self.process.wait()
  File ".../site-packages/sh.py", line 2457, in wait
    with self._wait_lock:
KeyboardInterrupt 
```

I believe this can be fixed simply by changing `_wait_lock` to a `threading.RLock()` instead of `threading.Lock()`.  (I tried it, and it seemed to work just fine.)

However, I do think a fresh look is needed at what `_wait_lock` is protecting.  The comments suggest it is _only_ for `self.exit_code` race prevention, but the lock is being held for much more than that.  I think the acquisition of this lock can be more fine-grained: only when `self.exit_code` is being _written_, and since `self.exit_code` never changes once written you don't need to hold the lock while reading it once you know it's not None.

You can do something like this, I think:

```python
def _do_stuff_when_exit_code_is_already_set():
    pass

if self.exit_code is not None:
    _do_stuff_when_exit_code_is_already_set()
    return

#  it appears that wait lock is None, but now we acquire the lock to be sure
while True:
    with self._wait_lock:
        if self.exit_code is not None:
            break
        # do stuff that will set exit_code
        break
_do_stuff_when_exit_code_is_already_set()
```

(Also, thanks for this library; I like the interface.)

Pull request:
Allow done callback to access RunningCommand
This avoids a deadlock by only locking the assignment of self.exit_code

Fixes #564

Patch:
diff --git a/sh.py b/sh.py
index 5fc9c2c..8929d2b 100644
--- a/sh.py
+++ b/sh.py
@@ -2412,6 +2412,7 @@ class OProc(object):
                 return False, self.exit_code
             return True, self.exit_code
 
+        witnessed_end = False
         try:
             # WNOHANG is just that...we're calling waitpid without hanging...
             # essentially polling the process.  the return result is (0, 0) if
@@ -2420,7 +2421,7 @@ class OProc(object):
             pid, exit_code = no_interrupt(os.waitpid, self.pid, os.WNOHANG)
             if pid == self.pid:
                 self.exit_code = handle_process_exit_code(exit_code)
-                self._process_just_ended()
+                witnessed_end = True
 
                 return False, self.exit_code
 
@@ -2431,6 +2432,8 @@ class OProc(object):
             return True, self.exit_code
         finally:
             self._wait_lock.release()
+            if witnessed_end:
+                self._process_just_ended()
 
     def _process_just_ended(self):
         if self._timeout_timer:
@@ -2466,31 +2469,32 @@ class OProc(object):
 
             else:
                 self.log.debug("exit code already set (%d), no need to wait", self.exit_code)
+        self._process_exit_cleanup(witnessed_end=witnessed_end)
+        return self.exit_code
 
-            self._quit_threads.set()
+    def _process_exit_cleanup(self, witnessed_end):
+        self._quit_threads.set()
 
-            # we may not have a thread for stdin, if the pipe has been connected
-            # via _piped="direct"
-            if self._input_thread:
-                self._input_thread.join()
+        # we may not have a thread for stdin, if the pipe has been connected
+        # via _piped="direct"
+        if self._input_thread:
+            self._input_thread.join()
 
-            # wait, then signal to our output thread that the child process is
-            # done, and we should have finished reading all the stdout/stderr
-            # data that we can by now
-            timer = threading.Timer(2.0, self._stop_output_event.set)
-            timer.start()
+        # wait, then signal to our output thread that the child process is
+        # done, and we should have finished reading all the stdout/stderr
+        # data that we can by now
+        timer = threading.Timer(2.0, self._stop_output_event.set)
+        timer.start()
 
-            # wait for our stdout and stderr streamreaders to finish reading and
-            # aggregating the process output
-            self._output_thread.join()
-            timer.cancel()
+        # wait for our stdout and stderr streamreaders to finish reading and
+        # aggregating the process output
+        self._output_thread.join()
+        timer.cancel()
 
-            self._background_thread.join()
-
-            if witnessed_end:
-                self._process_just_ended()
+        self._background_thread.join()
 
-            return self.exit_code
+        if witnessed_end:
+            self._process_just_ended()
 
 
 def input_thread(log, stdin, is_alive, quit_thread, close_before_term):


Test patch:
diff --git a/test.py b/test.py
index 0e4b206..d2c7bb4 100644
--- a/test.py
+++ b/test.py
@@ -2330,6 +2330,29 @@ print(time())
         self.assertEqual(callback.exit_code, 0)
         self.assertTrue(callback.success)
 
+    # https://github.com/amoffat/sh/issues/564
+    def test_done_callback_no_deadlock(self):
+        import time
+
+        py = create_tmp_test("""
+from sh import sleep
+
+def done(cmd, success, exit_code):
+    print(cmd, success, exit_code)
+
+sleep('1', _done=done)
+""")
+
+        p = python(py.name, _bg=True, _timeout=2)
+
+        # do a little setup to prove that a command with a _done callback is run
+        # in the background
+        wait_start = time.time()
+        p.wait()
+        wait_elapsed = time.time() - wait_start
+
+        self.assertLess(abs(wait_elapsed - 1.0), 1.0)
+
     def test_fork_exc(self):
         from sh import ForkException