Repository: DiamondLightSource/pythonSoftIOC (language: python)

Issue:
Possible deadlock when record.set called in on_update callback
We have had an issue where a python IOC would hang sometimes and have to be restarted. We narrowed it down to calling `my_record.set()` within the `on_update` callback for `my_record` and removing that has fixed the problem.

I have added a [branch](https://github.com/dls-controls/pythonSoftIOC/tree/recursive-set-bug/example) with a minimal example to reproduce the problem. The instructions in the README should be sufficient to run it. The traceback provoked by faulthandler consistently shows the IOC stuck in `db_put_field`:

```
Thread 0x00007f66f4cef700 (most recent call first):
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/cothread/cothread.py", line 984 in __call__
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/softioc/cothread_dispatcher.py", line 32 in __call__
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/softioc/device.py", line 221 in _process
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/softioc/device_core.py", line 165 in __call_instance_method
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/softioc/device_core.py", line 145 in <lambda>

Current thread 0x00007f6728ed8740 (most recent call first):
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/softioc/imports.py", line 24 in db_put_field
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/softioc/device.py", line 243 in set
  File "/scratch/development/pythonSoftIoc/example/cothread_ioc.py", line 10 in useless_callback
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/softioc/cothread_dispatcher.py", line 29 in wrapper
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/cothread/cothread.py", line 971 in callback_events
  File "/scratch/development/pythonSoftIoc/venv/lib/python3.7/site-packages/cothread/cothread.py", line 671 in __run
```

This was tested with base 7.0.7.0 and it does not seem to happen with 3.14.12.7.


Discussion / hints:
I think the following happens (@Araneidae correct me if I'm wrong):
- Class creation adds `_process` callback: https://github.com/dls-controls/pythonSoftIOC/blob/503453184184de701af101ab4271e15e3557258e/softioc/device_core.py#L117-L124
- Someone does a caput to an output record type
- EPICS updates the `VAL` and calls `_process` (on what thread?)
- This validates the result and calls the dispatcher to move it to the asyncio event loop thread (or cothread thread): https://github.com/dls-controls/pythonSoftIOC/blob/503453184184de701af101ab4271e15e3557258e/softioc/device.py#L143-L146
- This calls the user callback: https://github.com/dls-controls/pythonSoftIOC/blob/269faefd8e5d5db218c4b150899e13a1a9fc5136/example/aioca_ioc.py#L8-L10
- This calls `record.set()` which calls `db_put_field`: https://github.com/dls-controls/pythonSoftIOC/blob/503453184184de701af101ab4271e15e3557258e/softioc/device.py#L214-L215
- This calls the following function that sometimes deadlocks: https://github.com/dls-controls/pythonSoftIOC/blob/503453184184de701af101ab4271e15e3557258e/softioc/extension.c#L92-L109

@mdavidsaver this used to work in 3.14.12.7, but now fails in 7.0.7.0. Can you think what might be going wrong here?
I've investigated this a bit, and had a few more observations to add:

- Cothread seems much more susceptible to the problem than aioca. On my machine, the aioca example can run for a couple of minutes before hanging. For cothread the break is immediate upon the first `caput`. 
- It's also possible to have the same lock occur if you manually call `.set()` on the record, anytime after `iocInit()`. This effectively begins a recursive `.set()` chain (as the `on_update` calls `set()`), and ends up locking up at the same place.
- As discussed above, this appears to be an issue in EPICS's locking logic. The next step for investigation is most likely to be removing the Python and recreating the issue in pure C.
I don't think I can follow all of the details, but I see a call to `dbPutField()`.  This function must not be called from a device support callback, or from any other context in which any record lock is held.  For "virtual" access to fields within a device support callback, `dbPut()` is the way to go.

Also, it looks like your `db_put_field()` wrapper has the GIL locked when calling `dbPutField()`.  Unless you are zealous to avoid locking the GIL in a device support callback, this is constitutes a lock order violation.

The `dbPutField()` calls are in fact correct, because the `on_update` callback is called _after_ record processing has completed.

However, thank you very much for the GIL spot!  Yep, we need to drop the GIL around field access calls, and that makes a lot of sense.  Am pretty sure that's fixed things now.

Fix patch:
diff --git a/Pipfile.lock b/Pipfile.lock
index f5f07ac4..770702c5 100644
--- a/Pipfile.lock
+++ b/Pipfile.lock
@@ -23,9 +23,21 @@
         },
         "cothread": {
             "hashes": [
-                "sha256:4661ca129d4f83a7651764419c2302272d9e1da96d011f6cc9d59532505e2dca"
-            ],
-            "version": "==2.18.2"
+                "sha256:15825b3cca1e8b30d02b04aab26dfdf31c0bab5b3ef80a656aff79dc23573db9",
+                "sha256:2aa54274dfada9140e9ae2037dc64d90feafab6016d2f0ac8c980f34e31d9628",
+                "sha256:4fa7bfb3f9c528a9b51f97e127b3ee66610b3773dba7ca84ce7542727d49f1de",
+                "sha256:6da610401bc7981703e87a7efe93fcd87bd232d3a47c89b71bd7d4c530567a6e",
+                "sha256:749c03636e05f310fb8652a83328555a67bee6d83b2af030e4c39b77e9ed0ce1",
+                "sha256:7c9b6c735ad2f4f12672a5ba41e792e18931b9dcfee99c28a8bac5223cd65563",
+                "sha256:aac14a1248d4c55e86f460220586d3b87100876084cfb799af9b0eb41dacf3b5",
+                "sha256:be514d49dd63331aa0f8def607eff52424f0674647878b776d76d4a7769fc3ab",
+                "sha256:c62e6697814256d6f07d4bbdddcce9f89816fe30df8dd1bbb3cf5af1ad6330c1",
+                "sha256:caa0e37ae6d4f9adddf56addd76959103f2a388d0a6e1c1ddd833a87f0551d40",
+                "sha256:dc4a6fa654a6013ec95cbd5cfffb1bce53f74d9d470d2c5d1341e7073d686064",
+                "sha256:f0f57697eee1b87cf2bad4683e0deda5b3fe4505400084369274393999fcc3d0",
+                "sha256:fb12d99088ce073412fb0f84930d2b08a134ba4eeb441d3beac1fe62b2e5f9e5"
+            ],
+            "version": "==2.19.1"
         },
         "epicscorelibs": {
             "hashes": [
@@ -231,9 +243,21 @@
         },
         "cothread": {
             "hashes": [
-                "sha256:4661ca129d4f83a7651764419c2302272d9e1da96d011f6cc9d59532505e2dca"
-            ],
-            "version": "==2.18.2"
+                "sha256:15825b3cca1e8b30d02b04aab26dfdf31c0bab5b3ef80a656aff79dc23573db9",
+                "sha256:2aa54274dfada9140e9ae2037dc64d90feafab6016d2f0ac8c980f34e31d9628",
+                "sha256:4fa7bfb3f9c528a9b51f97e127b3ee66610b3773dba7ca84ce7542727d49f1de",
+                "sha256:6da610401bc7981703e87a7efe93fcd87bd232d3a47c89b71bd7d4c530567a6e",
+                "sha256:749c03636e05f310fb8652a83328555a67bee6d83b2af030e4c39b77e9ed0ce1",
+                "sha256:7c9b6c735ad2f4f12672a5ba41e792e18931b9dcfee99c28a8bac5223cd65563",
+                "sha256:aac14a1248d4c55e86f460220586d3b87100876084cfb799af9b0eb41dacf3b5",
+                "sha256:be514d49dd63331aa0f8def607eff52424f0674647878b776d76d4a7769fc3ab",
+                "sha256:c62e6697814256d6f07d4bbdddcce9f89816fe30df8dd1bbb3cf5af1ad6330c1",
+                "sha256:caa0e37ae6d4f9adddf56addd76959103f2a388d0a6e1c1ddd833a87f0551d40",
+                "sha256:dc4a6fa654a6013ec95cbd5cfffb1bce53f74d9d470d2c5d1341e7073d686064",
+                "sha256:f0f57697eee1b87cf2bad4683e0deda5b3fe4505400084369274393999fcc3d0",
+                "sha256:fb12d99088ce073412fb0f84930d2b08a134ba4eeb441d3beac1fe62b2e5f9e5"
+            ],
+            "version": "==2.19.1"
         },
         "coverage": {
             "extras": [
@@ -377,7 +401,7 @@
                 "sha256:8c501196e49fb9df5df43833bdb1e4328f64847763ec8a50703148b73784d581",
                 "sha256:d7eb1dea6d6a6086f8be21784cc9e3bcfa55872b52309bc5fad53a8ea444465d"
             ],
-            "markers": "python_version < '3.8' and python_version < '3.8'",
+            "markers": "python_version < '3.8'",
             "version": "==4.0.1"
         },
         "iniconfig": {
@@ -744,10 +768,10 @@
         },
         "urllib3": {
             "hashes": [
-                "sha256:3fa96cf423e6987997fc326ae8df396db2a8b7c667747d47ddd8ecba91f4a74e",
-                "sha256:b930dd878d5a8afb066a637fbb35144fe7901e3b209d1cd4f524bd0e9deee997"
+                "sha256:24d6a242c28d29af46c3fae832c36db3bbebcc533dd1bb549172cd739c82df21",
+                "sha256:94a757d178c9be92ef5539b8840d48dc9cf1b2709c9d6b588232a055c524458b"
             ],
-            "version": "==1.26.12"
+            "version": "==1.26.17"
         },
         "zipp": {
             "hashes": [
diff --git a/softioc/extension.c b/softioc/extension.c
index 6b21fb54..fd71687c 100644
--- a/softioc/extension.c
+++ b/softioc/extension.c
@@ -107,10 +107,26 @@ static PyObject *db_put_field(PyObject *self, PyObject *args)
     if (dbNameToAddr(name, &dbAddr))
         return PyErr_Format(
             PyExc_RuntimeError, "dbNameToAddr failed for %s", name);
-    if (dbPutField(&dbAddr, dbrType, pbuffer, length))
+
+    long put_result;
+    /* There are two important locks to consider at this point: The Global
+     * Interpreter Lock (GIL) and the EPICS record lock. A deadlock is possible if
+     * this thread holds the GIL and wants the record lock (which happens inside
+     * dbPutField), and there exists another EPICS thread that has the record lock
+     * and wants to call Python (which requires the GIL).
+     * This can occur if this code is called as part of an asynchronous on_update
+     * callback.
+     * Therefore, we must ensure we relinquish the GIL while we perform this
+     * EPICS call, to avoid potential deadlocks.
+     * See https://github.com/dls-controls/pythonSoftIOC/issues/119. */
+    Py_BEGIN_ALLOW_THREADS
+    put_result = dbPutField(&dbAddr, dbrType, pbuffer, length);
+    Py_END_ALLOW_THREADS
+    if (put_result)
         return PyErr_Format(
             PyExc_RuntimeError, "dbPutField failed for %s", name);
-    Py_RETURN_NONE;
+    else
+        Py_RETURN_NONE;
 }
 
 static PyObject *db_get_field(PyObject *self, PyObject *args)
@@ -127,11 +143,17 @@ static PyObject *db_get_field(PyObject *self, PyObject *args)
         return PyErr_Format(
             PyExc_RuntimeError, "dbNameToAddr failed for %s", name);
 
+    long get_result;
     long options = 0;
-    if (dbGetField(&dbAddr, dbrType, pbuffer, &options, &length, NULL))
+    /* See reasoning for Python macros in long comment in db_put_field. */
+    Py_BEGIN_ALLOW_THREADS
+    get_result = dbGetField(&dbAddr, dbrType, pbuffer, &options, &length, NULL);
+    Py_END_ALLOW_THREADS
+    if (get_result)
         return PyErr_Format(
             PyExc_RuntimeError, "dbGetField failed for %s", name);
-    Py_RETURN_NONE;
+    else
+        Py_RETURN_NONE;
 }
 
 /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */


Test patch:
diff --git a/tests/test_records.py b/tests/test_records.py
index 8ce13f49..1786b01e 100644
--- a/tests/test_records.py
+++ b/tests/test_records.py
@@ -1,5 +1,6 @@
 import asyncio
-import multiprocessing
+import subprocess
+import sys
 import numpy
 import os
 import pytest
@@ -347,7 +348,6 @@ def test_record_wrapper_str():
     # If we never receive R it probably means an assert failed
     select_and_recv(parent_conn, "R")
 
-
 def validate_fixture_names(params):
     """Provide nice names for the out_records fixture in TestValidate class"""
     return params[0].__name__
@@ -1104,3 +1104,114 @@ async def test_set_too_long_value(self):
             log(f"PARENT: Join completed with exitcode {process.exitcode}")
             if process.exitcode is None:
                 pytest.fail("Process did not terminate")
+
+
+class TestRecursiveSet:
+    """Tests related to recursive set() calls. See original issue here:
+    https://github.com/dls-controls/pythonSoftIOC/issues/119"""
+
+    recursive_record_name = "RecursiveLongOut"
+
+    def recursive_set_func(self, device_name, conn):
+        from cothread import Event
+
+        def useless_callback(value):
+            log("CHILD: In callback ", value)
+            useless_pv.set(0)
+            log("CHILD: Exiting callback")
+
+        def go_away(*args):
+            log("CHILD: received exit signal ", args)
+            event.Signal()
+
+        builder.SetDeviceName(device_name)
+
+
+        useless_pv = builder.aOut(
+            self.recursive_record_name,
+            initial_value=0,
+            on_update=useless_callback
+        )
+        event = Event()
+        builder.Action("GO_AWAY", on_update = go_away)
+
+        builder.LoadDatabase()
+        softioc.iocInit()
+
+        conn.send("R")  # "Ready"
+        log("CHILD: Sent R over Connection to Parent")
+
+        log("CHILD: About to wait")
+        event.Wait()
+        log("CHILD: Exiting")
+
+    @requires_cothread
+    @pytest.mark.asyncio
+    async def test_recursive_set(self):
+        """Test that recursive sets do not cause a deadlock"""
+        ctx = get_multiprocessing_context()
+        parent_conn, child_conn = ctx.Pipe()
+
+        device_name = create_random_prefix()
+
+        process = ctx.Process(
+            target=self.recursive_set_func,
+            args=(device_name, child_conn),
+        )
+
+        process.start()
+
+        log("PARENT: Child started, waiting for R command")
+
+        from aioca import caput, camonitor
+
+        try:
+            # Wait for message that IOC has started
+            select_and_recv(parent_conn, "R")
+            log("PARENT: received R command")
+
+            record = device_name + ":" + self.recursive_record_name
+
+            log(f"PARENT: monitoring {record}")
+            queue = asyncio.Queue()
+            monitor = camonitor(record, queue.put, all_updates=True)
+
+            log("PARENT: Beginning first wait")
+
+            # Expected initial state
+            new_val = await asyncio.wait_for(queue.get(), TIMEOUT)
+            log(f"PARENT: initial new_val: {new_val}")
+            assert new_val == 0
+
+            # Try a series of caput calls, to maximise chance to trigger
+            # the deadlock
+            i = 1
+            while i < 500:
+                log(f"PARENT: begin loop with i={i}")
+                await caput(record, i)
+                new_val = await asyncio.wait_for(queue.get(), 1)
+                assert new_val == i
+                new_val = await asyncio.wait_for(queue.get(), 1)
+                assert new_val == 0  # .set() should reset value
+                i += 1
+
+            # Signal the IOC to cleanly shut down
+            await caput(device_name + ":" + "GO_AWAY", 1)
+
+        except asyncio.TimeoutError as e:
+            raise asyncio.TimeoutError(
+                f"IOC did not send data back - loop froze on iteration {i} "
+                "- it has probably hung/deadlocked."
+            ) from e
+
+        finally:
+            monitor.close()
+            # Clear the cache before stopping the IOC stops
+            # "channel disconnected" error messages
+            aioca_cleanup()
+
+            process.join(timeout=TIMEOUT)
+            log(f"PARENT: Join completed with exitcode {process.exitcode}")
+            if process.exitcode is None:
+                process.terminate()
+                pytest.fail("Process did not finish cleanly, terminating")