Refactor tests to avoid most race conditions

These tests have passed 10 consecutive runs on CI with no failures.

There were race conditions regarding processing of record callbacks, so
we swap to a model of using a "DONE" record that, when processed,
signals that the IOC process has finished all of its callbacks.

Logging also added to some tests that had weird failures on CI, so if
they appear again we'll have more information.

Author: AlexanderWells-diamond

tests/conftest.py

@@ -19,6 +19,9 @@
 # Length picked to match string record length, so we can re-use test strings.
 WAVEFORM_LENGTH = 40
 
+# Default timeout for many operations across testing
+TIMEOUT = 10  # Seconds
+
 def create_random_prefix():
     """Create 12-character random string, for generating unique Device Names"""
     return "".join(random.choice(string.ascii_uppercase) for _ in range(12))
@@ -99,3 +102,21 @@ def enable_code_coverage():
         pass
     else:
         cleanup_on_sigterm()
+
+def select_and_recv(conn, expected_char = None):
+    """Wait for the given Connection to have data to receive, and return it.
+    If a character is provided check its correct before returning it.
+    This function imports Cothread, and so must NOT be called before any
+    multiprocessing sub-processes are spawned."""
+    from cothread import select
+    rrdy, _, _ = select([conn], [], [], TIMEOUT)
+    if rrdy:
+        val = conn.recv()
+    else:
+        pytest.fail("Did not receive expected char before TIMEOUT expired")
+
+    if expected_char:
+        assert val == expected_char, \
+            "Expected character did not match"
+
+    return val

tests/test_record_values.py

@@ -6,7 +6,12 @@
 from enum import Enum
 from math import isnan, inf, nan
 
-from conftest import requires_cothread, WAVEFORM_LENGTH
+from conftest import (
+    requires_cothread,
+    WAVEFORM_LENGTH,
+    select_and_recv,
+    TIMEOUT
+)
 
 from softioc import asyncio_dispatcher, builder, softioc
 from softioc.pythonSoftIoc import RecordWrapper
@@ -16,7 +21,6 @@
 
 # Test parameters
 DEVICE_NAME = "RECORD-VALUE-TESTS"
-TIMEOUT = 5  # Seconds
 
 # The maximum length string for StringIn/Out records
 MAX_LEN_STR = "a 39 char string exactly maximum length"
@@ -329,7 +333,7 @@ def run_ioc(record_configurations: list, conn, set_enum, get_enum):
     dispatcher = asyncio_dispatcher.AsyncioDispatcher()
     builder.LoadDatabase()
     softioc.iocInit(dispatcher)
-    conn.send("IOC started")
+    conn.send("R")  # "Ready"
 
     # Record list and record config list should always be in line
     for record, configuration in zip(records, record_configurations):
@@ -351,18 +355,19 @@ def run_ioc(record_configurations: list, conn, set_enum, get_enum):
             if set_enum == SetValueEnum.CAPUT:
                 if conn.poll(TIMEOUT):
                     val = conn.recv()
-                    if val is not None:
+                    if val == "G":
                         conn.send(record.get())
+                    else:
+                        pytest.fail(f"Received unexpected character {val}")
 
     # Keep process alive while main thread works.
     # This is most applicable to CAGET tests.
     while (True):
         if conn.poll(TIMEOUT):
             val = conn.recv()
-            if val == "EXIT":
+            if val == "D":  # "Done"
                 break
 
-
 def run_test_function(
     record_configurations: list, set_enum: SetValueEnum, get_enum: GetValueEnum
 ):
@@ -379,19 +384,17 @@ def run_test_function(
 
     ioc_process.start()
 
+
     # Wait for message that IOC has started
-    if parent_conn.poll(TIMEOUT):
-        parent_conn.recv()
-    else:
-        pytest.fail("IOC process did not start before TIMEOUT expired")
+    select_and_recv(parent_conn, "R")
 
-    try:
-        # Cannot do these imports before the subprocess starts, as cothread
-        # isn't threadsafe (in the way we require)
-        from cothread import Yield
-        from cothread.catools import caget, caput, _channel_cache
-        from cothread.dbr import DBR_CHAR_STR
+    # Cannot do these imports before the subprocess starts, as the subprocess
+    # would inherit cothread's internal state which would break things!
+    from cothread import Yield
+    from cothread.catools import caget, caput, _channel_cache
+    from cothread.dbr import DBR_CHAR_STR
 
+    try:
         # cothread remembers connected IOCs. As we potentially restart the same
         # named IOC multiple times, we have to purge the cache else the
         # result from caget/caput cache would be a DisconnectError during the
@@ -424,10 +427,7 @@ def run_test_function(
 
             if set_enum == SetValueEnum.CAPUT:
                 if get_enum == GetValueEnum.GET:
-                    if parent_conn.poll(TIMEOUT):
-                        parent_conn.recv()
-                    else:
-                        pytest.fail("IOC did not provide initial record value")
+                    select_and_recv(parent_conn)
                 caput(
                     DEVICE_NAME + ":" + record_name,
                     initial_value,
@@ -437,18 +437,16 @@ def run_test_function(
                 )
 
                 if get_enum == GetValueEnum.GET:
-                    parent_conn.send("Do another get!")
+                    parent_conn.send("G")  # "Get"
+
                 # Ensure IOC process has time to execute.
                 # I saw failures on MacOS where it appeared the IOC had not
                 # processed the put'ted value as the caget returned the same
                 # value as was originally passed in.
                 Yield(timeout=TIMEOUT)
 
             if get_enum == GetValueEnum.GET:
-                if parent_conn.poll(TIMEOUT):
-                    rec_val = parent_conn.recv()
-                else:
-                    pytest.fail("IOC did not provide record value in queue")
+                rec_val = select_and_recv(parent_conn)
             else:
                 rec_val = caget(
                     DEVICE_NAME + ":" + record_name,
@@ -477,10 +475,8 @@ def run_test_function(
         # Purge cache to suppress spurious "IOC disconnected" exceptions
         _channel_cache.purge()
 
+        parent_conn.send("D")  # "Done"
 
-        parent_conn.send("EXIT")
-
-        # ioc_process.terminate()
         ioc_process.join(timeout=TIMEOUT)
         if ioc_process.exitcode is None:
             pytest.fail("Process did not terminate")
@@ -771,11 +767,16 @@ def none_value_test_func(self, record_func, queue):
         builder.LoadDatabase()
         softioc.iocInit()
 
+        print("CHILD: Soft IOC started, about to .set(None)")
+
         try:
             record.set(None)
+            print("CHILD: Uh-OH! No exception thrown when setting None!")
         except Exception as e:
             queue.put(e)
 
+        print("CHILD: We really should never get here...")
+
         queue.put(Exception("FAIL:Test did not raise exception during .set()"))
 
     @requires_cothread
@@ -791,13 +792,18 @@ def test_value_none_rejected_set_after_init(self, record_func_reject_none):
 
         process.start()
 
+        print("PARENT: Child process started, waiting for returned exception")
+
         try:
-            exception = queue.get(timeout=5)
+            exception = queue.get(timeout=TIMEOUT)
 
             assert isinstance(exception, self.expected_exceptions)
         finally:
+            print("PARENT: Issuing terminate to child process")
             process.terminate()
-            process.join(timeout=3)
+            process.join(timeout=TIMEOUT)
+            if process.exitcode is None:
+                pytest.fail("Process did not terminate")
 
 
 class TestInvalidValues: