Fix Queue Timeout (#346)

- Fix an issue where the deadline of an enqueued workflow might be reset
during recovery.
- `SetWorkflowTimeout(None)` on a child workflow now properly unsets its
timeout.
- Timeout and deadline are now exposed in workflow status.

Author: kraftp

dbos/_context.py

@@ -392,6 +392,7 @@ def __init__(self, workflow_timeout_sec: Optional[float]) -> None:
             else None
         )
         self.saved_workflow_timeout: Optional[int] = None
+        self.saved_workflow_deadline_epoch_ms: Optional[int] = None
 
     def __enter__(self) -> SetWorkflowTimeout:
         # Code to create a basic context
@@ -402,6 +403,8 @@ def __enter__(self) -> SetWorkflowTimeout:
         ctx = assert_current_dbos_context()
         self.saved_workflow_timeout = ctx.workflow_timeout_ms
         ctx.workflow_timeout_ms = self.workflow_timeout_ms
+        self.saved_workflow_deadline_epoch_ms = ctx.workflow_deadline_epoch_ms
+        ctx.workflow_deadline_epoch_ms = None
         return self
 
     def __exit__(
@@ -411,6 +414,9 @@ def __exit__(
         traceback: Optional[TracebackType],
     ) -> Literal[False]:
         assert_current_dbos_context().workflow_timeout_ms = self.saved_workflow_timeout
+        assert_current_dbos_context().workflow_deadline_epoch_ms = (
+            self.saved_workflow_deadline_epoch_ms
+        )
         # Code to clean up the basic context if we created it
         if self.created_ctx:
             _clear_local_dbos_context()

dbos/_error.py

@@ -62,6 +62,7 @@ class DBOSErrorCode(Enum):
     WorkflowCancelled = 10
     UnexpectedStep = 11
     QueueDeduplicated = 12
+    AwaitedWorkflowCancelled = 13
     ConflictingRegistrationError = 25
 
 
@@ -206,6 +207,19 @@ def __reduce__(self) -> Any:
         )
 
 
+class DBOSAwaitedWorkflowCancelledError(DBOSException):
+    def __init__(self, workflow_id: str):
+        self.workflow_id = workflow_id
+        super().__init__(
+            f"Awaited workflow {workflow_id} was cancelled",
+            dbos_error_code=DBOSErrorCode.AwaitedWorkflowCancelled.value,
+        )
+
+    def __reduce__(self) -> Any:
+        # Tell jsonpickle how to reconstruct this object
+        return (self.__class__, (self.workflow_id,))
+
+
 #######################################
 ## BaseException
 #######################################

dbos/_sys_db.py

@@ -32,6 +32,7 @@
 from . import _serialization
 from ._context import get_local_dbos_context
 from ._error import (
+    DBOSAwaitedWorkflowCancelledError,
     DBOSConflictingWorkflowError,
     DBOSDeadLetterQueueError,
     DBOSNonExistentWorkflowError,
@@ -96,6 +97,10 @@ class WorkflowStatus:
     executor_id: Optional[str]
     # The application version on which this workflow was started
     app_version: Optional[str]
+    # The start-to-close timeout of the workflow in ms
+    workflow_timeout_ms: Optional[int]
+    # The deadline of a workflow, computed by adding its timeout to its start time.
+    workflow_deadline_epoch_ms: Optional[int]
 
     # INTERNAL FIELDS
 
@@ -761,9 +766,9 @@ def await_workflow_result(self, workflow_id: str) -> Any:
                         error = row[2]
                         raise _serialization.deserialize_exception(error)
                     elif status == WorkflowStatusString.CANCELLED.value:
-                        # Raise a normal exception here, not the cancellation exception
+                        # Raise AwaitedWorkflowCancelledError here, not the cancellation exception
                         # because the awaiting workflow is not being cancelled.
-                        raise Exception(f"Awaited workflow {workflow_id} was cancelled")
+                        raise DBOSAwaitedWorkflowCancelledError(workflow_id)
                 else:
                     pass  # CB: I guess we're assuming the WF will show up eventually.
             time.sleep(1)
@@ -837,6 +842,8 @@ def get_workflows(self, input: GetWorkflowsInput) -> List[WorkflowStatus]:
             SystemSchema.workflow_inputs.c.inputs,
             SystemSchema.workflow_status.c.output,
             SystemSchema.workflow_status.c.error,
+            SystemSchema.workflow_status.c.workflow_deadline_epoch_ms,
+            SystemSchema.workflow_status.c.workflow_timeout_ms,
         ).join(
             SystemSchema.workflow_inputs,
             SystemSchema.workflow_status.c.workflow_uuid
@@ -918,6 +925,8 @@ def get_workflows(self, input: GetWorkflowsInput) -> List[WorkflowStatus]:
             info.input = inputs
             info.output = output
             info.error = exception
+            info.workflow_deadline_epoch_ms = row[18]
+            info.workflow_timeout_ms = row[19]
 
             infos.append(info)
         return infos
@@ -947,6 +956,8 @@ def get_queued_workflows(
             SystemSchema.workflow_inputs.c.inputs,
             SystemSchema.workflow_status.c.output,
             SystemSchema.workflow_status.c.error,
+            SystemSchema.workflow_status.c.workflow_deadline_epoch_ms,
+            SystemSchema.workflow_status.c.workflow_timeout_ms,
         ).select_from(
             SystemSchema.workflow_queue.join(
                 SystemSchema.workflow_status,
@@ -1024,6 +1035,8 @@ def get_queued_workflows(
             info.input = inputs
             info.output = output
             info.error = exception
+            info.workflow_deadline_epoch_ms = row[18]
+            info.workflow_timeout_ms = row[19]
 
             infos.append(info)
 
@@ -1827,8 +1840,13 @@ def start_queued_workflows(
                         # If a timeout is set, set the deadline on dequeue
                         workflow_deadline_epoch_ms=sa.case(
                             (
-                                SystemSchema.workflow_status.c.workflow_timeout_ms.isnot(
-                                    None
+                                sa.and_(
+                                    SystemSchema.workflow_status.c.workflow_timeout_ms.isnot(
+                                        None
+                                    ),
+                                    SystemSchema.workflow_status.c.workflow_deadline_epoch_ms.is_(
+                                        None
+                                    ),
                                 ),
                                 sa.func.extract("epoch", sa.func.now()) * 1000
                                 + SystemSchema.workflow_status.c.workflow_timeout_ms,

tests/test_dbos.py

@@ -24,6 +24,7 @@
 # Private API because this is a test
 from dbos._context import assert_current_dbos_context, get_local_dbos_context
 from dbos._error import (
+    DBOSAwaitedWorkflowCancelledError,
     DBOSConflictingRegistrationError,
     DBOSMaxStepRetriesExceeded,
     DBOSWorkflowCancelledError,
@@ -1507,7 +1508,14 @@ def blocked_workflow() -> None:
             with SetWorkflowID(wfid):
                 blocked_workflow()
         assert assert_current_dbos_context().workflow_deadline_epoch_ms is None
+        start_time = time.time() * 1000
         handle = DBOS.start_workflow(blocked_workflow)
+        status = handle.get_status()
+        assert status.workflow_timeout_ms == 100
+        assert (
+            status.workflow_deadline_epoch_ms is not None
+            and status.workflow_deadline_epoch_ms > start_time
+        )
         with pytest.raises(DBOSWorkflowCancelledError):
             handle.get_result()
 
@@ -1555,13 +1563,11 @@ def parent_workflow() -> None:
         with pytest.raises(DBOSWorkflowCancelledError):
             parent_workflow()
 
-    with pytest.raises(Exception) as exc_info:
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
         DBOS.retrieve_workflow(start_child).get_result()
-    assert "was cancelled" in str(exc_info.value)
 
-    with pytest.raises(Exception) as exc_info:
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
         DBOS.retrieve_workflow(direct_child).get_result()
-    assert "was cancelled" in str(exc_info.value)
 
     # Verify the context variables are set correctly
     with SetWorkflowTimeout(1.0):

tests/test_failures.py

@@ -9,6 +9,7 @@
 
 from dbos import DBOS, Queue, SetWorkflowID
 from dbos._error import (
+    DBOSAwaitedWorkflowCancelledError,
     DBOSDeadLetterQueueError,
     DBOSMaxStepRetriesExceeded,
     DBOSNotAuthorizedError,
@@ -461,6 +462,11 @@ def test_error_serialization() -> None:
     d = deserialize_exception(serialize_exception(e))
     assert isinstance(d, DBOSQueueDeduplicatedError)
     assert str(d) == str(e)
+    # AwaitedWorkflowCancelledError
+    e = DBOSAwaitedWorkflowCancelledError("id")
+    d = deserialize_exception(serialize_exception(e))
+    assert isinstance(d, DBOSAwaitedWorkflowCancelledError)
+    assert str(d) == str(e)
 
     # Test safe_deserialize
     class BadException(Exception):

tests/test_queue.py

@@ -26,6 +26,7 @@
 )
 from dbos._context import assert_current_dbos_context
 from dbos._dbos import WorkflowHandleAsync
+from dbos._error import DBOSAwaitedWorkflowCancelledError, DBOSWorkflowCancelledError
 from dbos._schemas.system_database import SystemSchema
 from dbos._sys_db import WorkflowStatusString
 from dbos._utils import GlobalParams
@@ -853,9 +854,8 @@ def regular_workflow() -> None:
 
     # Complete the blocked workflow
     blocking_event.set()
-    with pytest.raises(Exception) as exc_info:
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
         blocked_handle.get_result()
-    assert "was cancelled" in str(exc_info.value)
 
     # Verify all queue entries eventually get cleaned up.
     assert queue_entries_are_cleaned_up(dbos)
@@ -891,9 +891,8 @@ def normal_workflow() -> None:
 
     # Verify the blocked workflows are cancelled
     for handle in handles:
-        with pytest.raises(Exception) as exc_info:
+        with pytest.raises(DBOSAwaitedWorkflowCancelledError):
             handle.get_result()
-        assert "was cancelled" in str(exc_info.value)
 
     # Verify the normal workflow succeeds
     normal_handle.get_result()
@@ -911,17 +910,14 @@ def parent_workflow() -> None:
 
     with SetWorkflowTimeout(1.0):
         handle = queue.enqueue(parent_workflow)
-    with pytest.raises(Exception) as exc_info:
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
         handle.get_result()
-    assert "was cancelled" in str(exc_info.value)
 
-    with pytest.raises(Exception) as exc_info:
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
         DBOS.retrieve_workflow(child_id).get_result()
-    assert "was cancelled" in str(exc_info.value)
 
     # Verify if a parent called with a timeout enqueues a blocked child
     # then exits the deadline propagates and the child is cancelled.
-    child_id = str(uuid.uuid4())
     queue = Queue("regular_queue")
 
     @DBOS.workflow()
@@ -931,9 +927,41 @@ def exiting_parent_workflow() -> str:
 
     with SetWorkflowTimeout(1.0):
         child_id = exiting_parent_workflow()
-    with pytest.raises(Exception) as exc_info:
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
+        DBOS.retrieve_workflow(child_id).get_result()
+
+    # Verify if a parent called with a timeout enqueues a child that
+    # never starts because the queue is blocked, the deadline propagates
+    # and both parent and child are cancelled.
+    child_id = str(uuid.uuid4())
+    queue = Queue("stuck_queue", concurrency=1)
+
+    start_event = threading.Event()
+    blocking_event = threading.Event()
+
+    @DBOS.workflow()
+    def stuck_workflow() -> None:
+        start_event.set()
+        blocking_event.wait()
+
+    stuck_handle = queue.enqueue(stuck_workflow)
+    start_event.wait()
+
+    @DBOS.workflow()
+    def blocked_parent_workflow() -> None:
+        with SetWorkflowID(child_id):
+            queue.enqueue(blocking_workflow)
+        while True:
+            DBOS.sleep(0.1)
+
+    with SetWorkflowTimeout(1.0):
+        handle = DBOS.start_workflow(blocked_parent_workflow)
+    with pytest.raises(DBOSWorkflowCancelledError):
+        handle.get_result()
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
         DBOS.retrieve_workflow(child_id).get_result()
-    assert "was cancelled" in str(exc_info.value)
+    blocking_event.set()
+    stuck_handle.get_result()
 
     # Verify all queue entries eventually get cleaned up.
     assert queue_entries_are_cleaned_up(dbos)
@@ -1341,3 +1369,80 @@ def test_workflow() -> str:
     # Change the version, verify the other version complets
     GlobalParams.app_version = other_version
     assert other_version_handle.get_result()
+
+
+def test_timeout_queue_recovery(dbos: DBOS) -> None:
+    queue = Queue("test_queue")
+    evt = threading.Event()
+
+    @DBOS.workflow()
+    def blocking_workflow() -> None:
+        evt.set()
+        while True:
+            DBOS.sleep(0.1)
+
+    timeout = 3.0
+    enqueue_time = time.time()
+    with SetWorkflowTimeout(timeout):
+        original_handle = queue.enqueue(blocking_workflow)
+
+    # Verify the workflow's timeout is properly configured
+    evt.wait()
+    original_status = original_handle.get_status()
+    assert original_status.workflow_timeout_ms == timeout * 1000
+    assert (
+        original_status.workflow_deadline_epoch_ms is not None
+        and original_status.workflow_deadline_epoch_ms > enqueue_time * 1000
+    )
+
+    # Recover the workflow. Verify its deadline remains the same
+    evt.clear()
+    handles = DBOS._recover_pending_workflows()
+    assert len(handles) == 1
+    evt.wait()
+    recovered_handle = handles[0]
+    recovered_status = recovered_handle.get_status()
+    assert recovered_status.workflow_timeout_ms == timeout * 1000
+    assert (
+        recovered_status.workflow_deadline_epoch_ms
+        == original_status.workflow_deadline_epoch_ms
+    )
+
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
+        original_handle.get_result()
+
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
+        recovered_handle.get_result()
+
+
+def test_unsetting_timeout(dbos: DBOS) -> None:
+
+    queue = Queue("test_queue")
+
+    @DBOS.workflow()
+    def child() -> str:
+        for _ in range(5):
+            DBOS.sleep(1)
+        return DBOS.workflow_id
+
+    @DBOS.workflow()
+    def parent(child_one: str, child_two: str) -> None:
+        with SetWorkflowID(child_two):
+            with SetWorkflowTimeout(None):
+                queue.enqueue(child)
+
+        with SetWorkflowID(child_one):
+            queue.enqueue(child)
+
+    child_one, child_two = str(uuid.uuid4()), str(uuid.uuid4())
+    with SetWorkflowTimeout(1.0):
+        queue.enqueue(parent, child_one, child_two).get_result()
+
+    # Verify child one, which has a propagated timeout, is cancelled
+    handle: WorkflowHandle[str] = DBOS.retrieve_workflow(child_one)
+    with pytest.raises(DBOSAwaitedWorkflowCancelledError):
+        handle.get_result()
+
+    # Verify child two, which doesn't have a timeout, succeeds
+    handle = DBOS.retrieve_workflow(child_two)
+    assert handle.get_result() == child_two

tests/test_workflow_introspection.py

@@ -41,6 +41,8 @@ def simple_workflow(x: int) -> int:
     assert output.app_version == GlobalParams.app_version
     assert output.app_id == ""
     assert output.recovery_attempts == 1
+    assert output.workflow_timeout_ms is None
+    assert output.workflow_deadline_epoch_ms is None
 
     # Test searching by status
     outputs = DBOS.list_workflows(status="PENDING")
@@ -222,6 +224,8 @@ def blocking_step(i: int) -> int:
         assert workflow.created_at is not None and workflow.created_at > 0
         assert workflow.updated_at is not None and workflow.updated_at > 0
         assert workflow.recovery_attempts == 1
+        assert workflow.workflow_timeout_ms is None
+        assert workflow.workflow_deadline_epoch_ms is None
 
     # Test sort_desc inverts the order
     workflows = DBOS.list_queued_workflows(sort_desc=True)