Repository: IDSIA/sacred
Pull request #740 (2020-05-31 22:53:42)

Handle tee_stdout.TimeoutExpired with warn() and terminate()
When I run Sacred jobs in parallel using Ray I run into an error where the experiment first prints that it finished complete successfully, and then crashes with a unhandled `subprocess.TimeoutExpired` while waiting for `tee_stdout` to finish.

I don't know why this happens, but it seems like a pretty harmless solution to handle the exception, warn the user, and then `terminate` the tee subproc forcibly.

Closing the `tee` forcibly here could lead to some of the captured stdout not making it into Observers, but this is still better than the current behavior for `TimeoutExpired`, which is to simply exit on error and not `terminate`.

If it is helpful, then I can try to come up a minimal reproducible example of this error.

shwang: The flake8 error is unrelated to these changes. Maybe it's a new error due to a flake8 upgrade, as if we ran flake8 on master right now we would get this error:

```
flake8 run-test: commands[0] | flake8 sacred
sacred/config/config_scope.py:189:48: E741 ambiguous variable name 'l'
sacred/config/config_scope.py:190:35: E741 ambiguous variable name 'l'
```

Anyways, I ended renaming `l` something longer in #737 to avoid this flake8 error.
AdamGleave: This seems related to https://github.com/IDSIA/sacred/issues/289

I'd rather get to the bottom of this but given the bug has been open for over a year a workaround like this is not crazy.
shwang: Interestingly in my case this is a deterministic fail
EspenHa: I also submitted a PR for this issue here: https://github.com/IDSIA/sacred/pull/718. Also related: https://github.com/IDSIA/sacred/issues/705
AdamGleave: @shwang I think you forgot to push the flake8 fix since that test is still failing?

@EspenHa thanks for the link! seems like a similar approach.
qxcv: Is there a more elegant way to fix this than just taking a shotgun to the `tee` children? I've run into this problem running `multiprocessing` with `forkserver`. It seems like the problem is that `forkserver` subprocess doesn't shut down until the parent process exits. Hence, `tee` keeps waiting on output from the `forkserver` (not the main process) indefinitely, and we get a timeout. There is a hack that will let you shut down the `forkserver` at the end of your script, thereby allowing Sacred to close the file descriptor used to capture stdout (in Python 3.7+):

```python
def stop_forkserver():
    from multiprocessing.forkserver import _forkserver as _fs
    if hasattr(_fs, '_stop'):
        _fs._stop()  # Python 3.8+
    else:
        # this next bit is copied from Python 3.8's ForkServer._stop()
        # (should work in 3.7, at least on Linux)
        if _fs._forkserver_pid is not None:
            os.close(_fs._forkserver_alive_fd)  # child now dies of its own accord
            os.waitpid(_fs._forkserver_pid, 0)  # reap the child
            os.unlink(_fs._forkserver_address)  # remove IPC channel
            _fs._forkserver_alive_fd = _fs._forkserver_pid = _fs._forkserver_address = None
```

Of course, the most elegant solution would be one that allows Sacred to stop _before_ all subprocesses exit. Unfortunately I'm not enough of a Unix wizard to say whether that exists. At the very least, I don't see a way to do it while still retaining the current method of redirecting output with `tee`.
shwang: Flake8 is fixed now. This should be passing soon.

Patch:
diff --git a/sacred/config/custom_containers.py b/sacred/config/custom_containers.py
index 40954a2..8f447bd 100644
--- a/sacred/config/custom_containers.py
+++ b/sacred/config/custom_containers.py
@@ -165,12 +165,14 @@ class DogmaticList(list):
 
 
 class ReadOnlyContainer:
-    def __init__(self, *args, message=None, **kwargs):
-        super().__init__(*args, **kwargs)
-        self.message = message or "This container is read-only!"
+    def __reduce__(self):
+        return self.__class__, (self.__copy__(),)
 
     def _readonly(self, *args, **kwargs):
-        raise SacredError(self.message, filter_traceback="always")
+        raise SacredError(
+            "The configuration is read-only in a captured function!",
+            filter_traceback="always",
+        )
 
 
 class ReadOnlyDict(ReadOnlyContainer, dict):
@@ -185,11 +187,6 @@ class ReadOnlyDict(ReadOnlyContainer, dict):
     __setitem__ = ReadOnlyContainer._readonly
     __delitem__ = ReadOnlyContainer._readonly
 
-    def __init__(self, *args, message=None, **kwargs):
-        if message is None:
-            message = "This ReadOnlyDict is read-only!"
-        super().__init__(*args, message=message, **kwargs)
-
     def __copy__(self):
         return {**self}
 
@@ -212,11 +209,6 @@ class ReadOnlyList(ReadOnlyContainer, list):
     __setitem__ = ReadOnlyContainer._readonly
     __delitem__ = ReadOnlyContainer._readonly
 
-    def __init__(self, *iterable, message=None, **kwargs):
-        if message is None:
-            message = "This ReadOnlyList is read-only!"
-        super().__init__(*iterable, message=message, **kwargs)
-
     def __copy__(self):
         return [*self]
 
@@ -225,7 +217,7 @@ class ReadOnlyList(ReadOnlyContainer, list):
         return copy.deepcopy(lst, memo=memo)
 
 
-def make_read_only(o, error_message=None):
+def make_read_only(o):
     """Makes objects read-only.
 
     Converts every `list` and `dict` into `ReadOnlyList` and `ReadOnlyDict` in
@@ -233,14 +225,9 @@ def make_read_only(o, error_message=None):
     but returns the converted structure.
     """
     if type(o) == dict:
-        return ReadOnlyDict(
-            {k: make_read_only(v, error_message) for k, v in o.items()},
-            message=error_message,
-        )
+        return ReadOnlyDict({k: make_read_only(v) for k, v in o.items()})
     elif type(o) == list:
-        return ReadOnlyList(
-            [make_read_only(v, error_message) for v in o], message=error_message
-        )
+        return ReadOnlyList([make_read_only(v) for v in o])
     elif type(o) == tuple:
         return tuple(map(make_read_only, o))
     else:
diff --git a/sacred/initialize.py b/sacred/initialize.py
index 12fd445..580b987 100755
--- a/sacred/initialize.py
+++ b/sacred/initialize.py
@@ -202,11 +202,7 @@ class Scaffold:
 
             # Make configuration read only if enabled in settings
             if SETTINGS.CONFIG.READ_ONLY_CONFIG:
-                cfunc.config = make_read_only(
-                    cfunc.config,
-                    error_message="The configuration is read-only in a "
-                    "captured function!",
-                )
+                cfunc.config = make_read_only(cfunc.config)
 
         if not run.force:
             self._warn_about_suspicious_changes()
diff --git a/sacred/stdout_capturing.py b/sacred/stdout_capturing.py
index c564304..2364b8a 100644
--- a/sacred/stdout_capturing.py
+++ b/sacred/stdout_capturing.py
@@ -4,6 +4,7 @@
 import os
 import sys
 import subprocess
+import warnings
 from io import StringIO
 from contextlib import contextmanager
 import wrapt
@@ -177,8 +178,17 @@ def tee_output_fd():
             os.dup2(saved_stdout_fd, original_stdout_fd)
             os.dup2(saved_stderr_fd, original_stderr_fd)
 
-            tee_stdout.wait(timeout=1)
-            tee_stderr.wait(timeout=1)
+            try:
+                tee_stdout.wait(timeout=1)
+            except subprocess.TimeoutExpired:
+                warnings.warn("tee_stdout.wait timeout. Forcibly terminating.")
+                tee_stdout.terminate()
+
+            try:
+                tee_stderr.wait(timeout=1)
+            except subprocess.TimeoutExpired:
+                warnings.warn("tee_stderr.wait timeout. Forcibly terminating.")
+                tee_stderr.terminate()
 
             os.close(saved_stdout_fd)
             os.close(saved_stderr_fd)


Test patch:
diff --git a/tests/test_config/test_readonly_containers.py b/tests/test_config/test_readonly_containers.py
index 24ae804..db8ed0c 100644
--- a/tests/test_config/test_readonly_containers.py
+++ b/tests/test_config/test_readonly_containers.py
@@ -1,3 +1,5 @@
+import json
+import pickle
 import pytest
 from copy import copy, deepcopy
 
@@ -5,10 +7,49 @@ from sacred.config.custom_containers import make_read_only, ReadOnlyList, ReadOn
 from sacred.utils import SacredError
 
 
+def _contains_tuple(json_compat_obj):
+    x = json_compat_obj
+    if isinstance(x, tuple):
+        return True
+    elif isinstance(x, list):
+        return any(map(_contains_tuple, x))
+    elif isinstance(x, dict):
+        # Don't check keys since we are assuming x is JSON-compatible.
+        # JSON-compatible keys are either number or string.
+        return any(map(_contains_tuple, x.values()))
+    else:
+        return False
+
+
+def _check_serializable(obj):
+    for format in [json, pickle]:
+        blob = format.dumps(obj)
+        obj_loaded = format.loads(blob)
+        if format is json and _contains_tuple(obj):
+            # JSON coerces () into []. So we won't expect equality.
+            # However, it's still nice to check if we can load and save.
+            continue
+        assert obj == obj_loaded, format.__name__ + " serialization failed"
+        assert obj_loaded == obj, format.__name__ + " serialization failed"
+
+
 def _check_read_only_dict(d):
     assert isinstance(d, ReadOnlyDict)
 
-    raises_dict = pytest.raises(SacredError, match="This ReadOnlyDict is read-only!")
+    # Check __eq__
+    assert d == d
+    assert d == ReadOnlyDict(d)
+
+    # Check __contains__ and __iter__
+    for k in d.keys():
+        assert k in d
+    for k in d:
+        assert k in d
+
+    # Check serialization
+    _check_serializable(d)
+
+    raises_dict = pytest.raises(SacredError, match="read-only")
 
     if len(d) > 0:
         # Test removal of entries and overwrite an already present entry
@@ -44,7 +85,18 @@ def _check_read_only_dict(d):
 def _check_read_only_list(lst):
     assert isinstance(lst, ReadOnlyList)
 
-    raises_list = pytest.raises(SacredError, match="This ReadOnlyList is read-only!")
+    # Check __eq__
+    assert lst == lst
+    assert lst == ReadOnlyList(lst)
+
+    # Check __contains__ and __iter__
+    for x in lst:
+        assert x in lst
+
+    # Check serialization
+    _check_serializable(lst)
+
+    raises_list = pytest.raises(SacredError, match="read-only")
 
     if len(lst):
         with raises_list:
@@ -224,6 +276,7 @@ def test_deepcopy_on_nested_readonly_list():
     lst = [1, [2, [3, [4]]]]
     lst = make_read_only(lst)
     copied_l = deepcopy(lst)
+    assert lst == copied_l
     for v, v_copied in zip(lst, copied_l):
         assert v == v_copied