Repository: pavdmyt/yaspin

Issue:
Race condition between spinner thread and write()
When I use `write()` a lot on a spinner it often happens to me that the written text is displayed after the spinner message, like this:

```
[...]
noot noot
⠋ spinning...noot noot
noot noot
[...]
```
I used the script below to recreate the problem. It takes some time (400-800 writes) with it, but happens to me far more often with real world applications.
```python
import random
import time

import yaspin

with yaspin.yaspin() as sp:
    sp.text = 'spinning...'
    while True:
        sp.write('noot noot')
        time.sleep(0.051 + random.randint(0, 10) / 100)
```
I think this happens because of concurrent access to `sys.stdout.write()` by the spinning thread and the spinners `write()`. This should be solvable by using a `threading.Lock()` and guarding access to sys.stdout.write() with it. In a quick local hack-fix-test it worked for me by doing this in `write()` and `_spin()`, but there are a lot more functions that would need guarding, if done right.


Discussion:
coveralls: 
[![Coverage Status](https://coveralls.io/builds/22896148/badge)](https://coveralls.io/builds/22896148)

Coverage increased (+0.1%) to 94.822% when pulling **d724596c7a4e6bacd9ca4172361981c984ca0978 on sebageek:fix-write-spin-race-condition** into **62902dec938957120d7bec72cd974a75be0f187e on pavdmyt:master**.

pavdmyt: @sebageek thanks for fixing this!

What about unittests? Can we reproduce this somehow via tests?
sebageek: I don't think this PR will fix the underlying issue if the locks are atomic, as their function is to protect parts of the code that should happen without being interrupted. Take the following example of `_spin()` vs `write()`:
```
_spin():  sys.stdout.write(out)
_write(): sys.stdout.write("{0}\n".format(_text))
_spin():  self._clear_line()
```
This case would lead to the message written with `write()` being truncated by `_spin()` and to prevent that the lock needs to make sure that in `_spin()` the text plus clear line text is written at the same time without anyone writing to `sys.stdout` in that time.

For this I see two options:
 * protect the whole section where `sys.stdout` is accessed with one lock
 * compose the complete message beforehand and just have one `sys.stdout.write()` call and rely on `sys.stdout.write()` being somewhat thread safe (I'd believe it would write things at one go)

If the goal is on the other hand to also protect access to `_hide_cursor`, `_show_cursor` and `_clear_line` for future development we could exchange the `Lock()` with an `RLock()` and add an additional `with self._stdout_lock` around these functions.
pavdmyt: I'm going to vacation next week. Will proceed with this PR a bit later.
sebageek: I took another look at this after writing the already to this PR commited test. I think `sys.stdout.write()` is handled as an atomic operation. Therefore converging all writes of a function into a single `sys.stdout.write()` call would also solve the problem. A simple proof of concept looked something like this:
```python
def write():
    [...]
    sys.stdout.write("\r{0}{1}\n".format(self._get_clear_line(), _text))

def _spin():
    [...]
    sys.stdout.write(out + self._get_clear_line())
    sys.stdout.flush()

def _get_clear_line():
    return "\033[K"
```
This resulted also in the racecondition test being green. I haven't look at the other `write()` calls though.

Patch:
diff --git a/HISTORY.rst b/HISTORY.rst
index e42a4e8..f811286 100644
--- a/HISTORY.rst
+++ b/HISTORY.rst
@@ -1,6 +1,12 @@
 Release History
 ===============
 
+0.14.3 / 2019-05-12
+-------------------
+
+* fix(#29): race condition between spinner thread and ``write()``
+
+
 0.14.2 / 2019-04-27
 -------------------
 
diff --git a/setup.cfg b/setup.cfg
index 414ae9c..710350c 100644
--- a/setup.cfg
+++ b/setup.cfg
@@ -1,5 +1,5 @@
 [bumpversion]
-current_version = 0.14.2
+current_version = 0.14.3
 
 [metadata]
 description-file = README.rst
diff --git a/yaspin/__version__.py b/yaspin/__version__.py
index 745162e..23f0070 100644
--- a/yaspin/__version__.py
+++ b/yaspin/__version__.py
@@ -1,1 +1,1 @@
-__version__ = "0.14.2"
+__version__ = "0.14.3"
diff --git a/yaspin/core.py b/yaspin/core.py
index f61bdc0..803daf7 100644
--- a/yaspin/core.py
+++ b/yaspin/core.py
@@ -76,6 +76,7 @@ class Yaspin(object):
         self._hide_spin = None
         self._spin_thread = None
         self._last_frame = None
+        self._stdout_lock = threading.Lock()
 
         # Signals
 
@@ -247,43 +248,47 @@ class Yaspin(object):
         thr_is_alive = self._spin_thread and self._spin_thread.is_alive()
 
         if thr_is_alive and not self._hide_spin.is_set():
-            # set the hidden spinner flag
-            self._hide_spin.set()
+            with self._stdout_lock:
+                # set the hidden spinner flag
+                self._hide_spin.set()
 
-            # clear the current line
-            sys.stdout.write("\r")
-            self._clear_line()
+                # clear the current line
+                sys.stdout.write("\r")
+                self._clear_line()
 
-            # flush the stdout buffer so the current line can be rewritten to
-            sys.stdout.flush()
+                # flush the stdout buffer so the current line
+                # can be rewritten to
+                sys.stdout.flush()
 
     def show(self):
         """Show the hidden spinner."""
         thr_is_alive = self._spin_thread and self._spin_thread.is_alive()
 
         if thr_is_alive and self._hide_spin.is_set():
-            # clear the hidden spinner flag
-            self._hide_spin.clear()
+            with self._stdout_lock:
+                # clear the hidden spinner flag
+                self._hide_spin.clear()
 
-            # clear the current line so the spinner is not appended to it
-            sys.stdout.write("\r")
-            self._clear_line()
+                # clear the current line so the spinner is not appended to it
+                sys.stdout.write("\r")
+                self._clear_line()
 
     def write(self, text):
         """Write text in the terminal without breaking the spinner."""
         # similar to tqdm.write()
         # https://pypi.python.org/pypi/tqdm#writing-messages
-        sys.stdout.write("\r")
-        self._clear_line()
+        with self._stdout_lock:
+            sys.stdout.write("\r")
+            self._clear_line()
 
-        _text = to_unicode(text)
-        if PY2:
-            _text = _text.encode(ENCODING)
+            _text = to_unicode(text)
+            if PY2:
+                _text = _text.encode(ENCODING)
 
-        # Ensure output is bytes for Py2 and Unicode for Py3
-        assert isinstance(_text, builtin_str)
+            # Ensure output is bytes for Py2 and Unicode for Py3
+            assert isinstance(_text, builtin_str)
 
-        sys.stdout.write("{0}\n".format(_text))
+            sys.stdout.write("{0}\n".format(_text))
 
     def ok(self, text="OK"):
         """Set Ok (success) finalizer to a spinner."""
@@ -306,7 +311,8 @@ class Yaspin(object):
         # Should be stopped here, otherwise prints after
         # self._freeze call will mess up the spinner
         self.stop()
-        sys.stdout.write(self._last_frame)
+        with self._stdout_lock:
+            sys.stdout.write(self._last_frame)
 
     def _spin(self):
         while not self._stop_spin.is_set():
@@ -321,9 +327,10 @@ class Yaspin(object):
             out = self._compose_out(spin_phase)
 
             # Write
-            sys.stdout.write(out)
-            self._clear_line()
-            sys.stdout.flush()
+            with self._stdout_lock:
+                sys.stdout.write(out)
+                self._clear_line()
+                sys.stdout.flush()
 
             # Wait
             time.sleep(self._interval)


Test patch:
diff --git a/tests/test_in_out.py b/tests/test_in_out.py
index 180b642..0fe6e49 100644
--- a/tests/test_in_out.py
+++ b/tests/test_in_out.py
@@ -8,7 +8,9 @@ Checks that all input data is converted to unicode.
 And all output data is converted to builtin str type.
 """
 
+import re
 import sys
+import time
 
 import pytest
 
@@ -159,3 +161,22 @@ def test_hide_show(capsys, text, request):
 
     # ensure that text was cleared before resuming the spinner
     assert out[:4] == "\r\033[K"
+
+
+def test_spinner_write_race_condition(capsys):
+    # test that spinner text does not overwrite write() contents
+    # this generally happens when the spinner thread writes
+    # between write()'s \r and the text it actually wants to write
+
+    sp = yaspin(text="aaaa")
+    sp.start()
+    sp._interval = 0.0
+    start_time = time.time()
+    while time.time() - start_time < 3.0:
+        sp.write("bbbb")
+    sp.stop()
+
+    out, _ = capsys.readouterr()
+    assert "aaaa" in out  # spinner text is present
+    assert "bbbb" in out  # write() text is present
+    assert not re.search(r"aaaa[^\rb]*bbbb", out)