QTZPOC-20

QTZPOC-20: Improve structured logging and reporting for all model import pipeline failures by introducing a dedicated activity and centralizing error classification. This ensures consistent observability, with all workflow failures now reported before cleanup. Also, adjusted import step timeouts and refined manual run script cleanup logic.

tests/laborious/activities/test_model_import_bundle.py

@@ -24,8 +24,8 @@ from pytest import fixture, mark, raises
 
 from laborious import metrics
 from laborious.activities.model_import import ModelImport
-from laborious.activities.model_import_errors import ImportGateRejectedError
 from laborious.utils.bundle.steps import ImportStep
+from laborious.utils.models.import_errors import ImportGateRejectedError
 from tests.helpers import bundle_factory as factory
 from tests.helpers.status_engine import FakeStatusEngine
 

tests/laborious/activities/test_model_import_status.py

@@ -32,12 +32,12 @@ from laborious.activities.model_import import (
     derive_run_name,
     map_state_to_status,
 )
-from laborious.activities.model_import_errors import (
+from laborious.utils.bundle.steps import ImportStep
+from laborious.utils.models.import_errors import (
     ImportErrorCode,
     ImportLogRowNotClaimableError,
     ImportStatusRejectedError,
 )
-from laborious.utils.bundle.steps import ImportStep
 from tests.helpers.status_engine import FakeStatusEngine
 
 STATUS_CONFIG = {
@@ -747,6 +747,78 @@ async def test_a_verdict_that_cannot_be_written_is_reported_with_the_verdict():
     assert 'connection refused' in logged
 
 
+@mark.asyncio
+async def test_the_failure_that_ended_the_import_is_reported_with_its_step_and_its_code():
+    """Before this activity existed, an MLflow that refused the connection reached the logs only as
+    whatever the Temporal SDK printed for the attempt: a traceback with no id, no step and no code."""
+    engine = FakeStatusEngine()
+    activity = build_activity(engine)
+
+    result = await activity.report_import_pipeline_failure(
+        {
+            **claim_input(),
+            'step': ImportStep.EXPERIMENT_CREATION.value,
+            'gate': None,
+            'detail': 'MlflowException: API request to http://mlflow:5080 failed: refused',
+            'error_type': 'MlflowException',
+        }
+    )
+
+    assert result == {'reported': True}
+    # The row is written by the terminal write, not by the reporting of a failure.
+    assert engine.statements == []
+    message, fields = activity.logger.custom_error.call_args_list[0].args
+    assert 'model import failed' in message
+    assert 'API request to http://mlflow:5080' in message
+    assert fields['import_step'] == ImportStep.EXPERIMENT_CREATION.value
+    assert fields['import_code'] == ImportErrorCode.STORAGE_PREPARATION_FAILED.value
+    assert fields['error_type'] == 'MlflowException'
+    assert fields['import_run_id'] == 77
+    assert fields['import_workflow_id'] == 'import_model-77-abc'
+    activity.emit_metric.assert_awaited_once()
+    assert (
+        activity.send_notification_async.await_args.kwargs['notification_id']
+        == ImportErrorCode.STORAGE_PREPARATION_FAILED.value
+    )
+
+
+@mark.asyncio
+async def test_a_gate_that_rejected_the_bundle_is_a_field_on_the_report():
+    engine = FakeStatusEngine()
+    activity = build_activity(engine)
+
+    await activity.report_import_pipeline_failure(
+        {
+            **claim_input(),
+            'step': ImportStep.DECRYPTION.value,
+            'gate': 3,
+            'detail': 'ImportGateRejectedError: gate 3 rejected the bundle',
+            'error_type': 'ImportGateRejectedError',
+        }
+    )
+
+    _, fields = activity.logger.custom_error.call_args_list[0].args
+    assert fields['import_gate'] == 3
+    assert fields['import_code'] == ImportErrorCode.BUNDLE_CANNOT_BE_OPENED.value
+
+
+@mark.asyncio
+async def test_a_step_this_module_does_not_know_is_reported_rather_than_raised():
+    """Reporting a failure is never a reason to fail: the raw step still reaches the log line."""
+    engine = FakeStatusEngine()
+    activity = build_activity(engine)
+
+    result = await activity.report_import_pipeline_failure(
+        {**claim_input(), 'step': 'provisioning', 'detail': 'RuntimeError: boom'}
+    )
+
+    assert result == {'reported': True}
+    _, fields = activity.logger.custom_error.call_args_list[0].args
+    assert fields['import_step'] == 'provisioning'
+    assert fields['import_code'] == ImportErrorCode.UNEXPECTED_ERROR.value
+    assert fields['error_type'] == 'unavailable'
+
+
 @mark.asyncio
 async def test_the_engine_is_disposed_on_shutdown(import_activity: ModelImport, engine):
     import_activity.close()

tests/laborious/test_import_absence.py

@@ -19,7 +19,7 @@ REPOSITORY_ROOT = Path(__file__).resolve().parents[2]
 
 WORKFLOW_MODULE = REPOSITORY_ROOT / 'laborious/workflows/import_model.py'
 ACTIVITIES_MODULE = REPOSITORY_ROOT / 'laborious/activities/model_import.py'
-ERRORS_MODULE = REPOSITORY_ROOT / 'laborious/activities/model_import_errors.py'
+ERRORS_MODULE = REPOSITORY_ROOT / 'laborious/utils/models/import_errors.py'
 READER_MODULE = REPOSITORY_ROOT / 'laborious/utils/bundle/reader.py'
 FORMAT_MODULE = REPOSITORY_ROOT / 'laborious/utils/bundle/format.py'
 

tests/laborious/utils/models/test_import_errors.py

@@ -16,9 +16,11 @@ from pathlib import Path
 from typing import Any
 
 from pytest import mark, raises
+from temporalio.exceptions import ApplicationError
 
 from laborious import metrics
-from laborious.activities.model_import_errors import (
+from laborious.utils.bundle.steps import GATE_TO_STEP, ImportStep
+from laborious.utils.models.import_errors import (
     IMPORT_FAILURE_CATALOG,
     STEPS_WITHOUT_A_USER_FACING_REASON,
     UNCLASSIFIED_FAILURE,
@@ -28,12 +30,13 @@ from laborious.activities.model_import_errors import (
     ImportLogRowNotClaimableError,
     ImportStatusRejectedError,
     classify_import_failure,
+    describe_failure_chain,
     failure_location,
     report_import_failure,
+    summarize_failure,
 )
-from laborious.utils.bundle.steps import GATE_TO_STEP, ImportStep
 
-REPOSITORY_ROOT = Path(__file__).resolve().parents[3]
+REPOSITORY_ROOT = Path(__file__).resolve().parents[4]
 
 # The modules that make up the import path. The channel lives in the third one; the other two may
 # not report a failure of their own.
@@ -359,6 +362,180 @@ async def test_an_explicit_code_keeps_the_step_s_sentence():
     assert sinks.notifications[0]['level'] == 'ERROR'
 
 
+# --------------------------------------------- the fields the two log lines carry
+#
+# The message text is for a person reading a log; these fields are for the query that finds it. Both
+# lines the channel produces — the technical one and the user-facing sentence the notification logs —
+# carry the same ones, which is what makes `import_run_id=30` return the pair.
+
+
+def _wrapped_activity_failure() -> BaseException:
+    """What an activity failure looks like by the time the channel sees it.
+
+    A `MlflowException` raised inside an activity reaches the workflow as an `ApplicationError` whose
+    `type` still names it, wrapped in the error Temporal raises for the failed activity. Built by hand
+    rather than through a real activity because what is under test is the unwrapping.
+    """
+    root = ApplicationError(
+        'API request to http://localhost:5080/api/2.0/mlflow/experiments/get-by-name failed with '
+        'exception HTTPConnectionPool(host=localhost, port=5080): Connection refused',
+        type='MlflowException',
+    )
+    wrapper = RuntimeError('Activity task failed')
+    wrapper.__cause__ = root
+    return wrapper
+
+
+@mark.asyncio
+async def test_the_log_line_carries_the_ids_the_step_and_the_code_as_fields():
+    sinks = FakeSinks()
+
+    await report_import_failure(
+        sinks,
+        ImportStep.EXPERIMENT_CREATION,
+        _wrapped_activity_failure(),
+        import_run_id=30,
+        workflow_id='manual-import-30',
+        metadata={'model_name': '-', 'model_id': '30'},
+    )
+
+    _, fields = sinks.logged[0]
+    assert fields['import_run_id'] == 30
+    assert fields['import_workflow_id'] == 'manual-import-30'
+    assert fields['import_step'] == ImportStep.EXPERIMENT_CREATION.value
+    assert fields['import_code'] == ImportErrorCode.STORAGE_PREPARATION_FAILED.value
+    # The workflow metadata every other line already carries is kept, not replaced.
+    assert fields['model_id'] == '30'
+
+
+@mark.asyncio
+async def test_the_fields_name_the_root_cause_not_the_wrapper():
+    """`error_type=ApplicationError` would be true of every activity failure there is."""
+    sinks = FakeSinks()
+
+    await report_import_failure(
+        sinks,
+        ImportStep.EXPERIMENT_CREATION,
+        _wrapped_activity_failure(),
+        import_run_id=30,
+        workflow_id='manual-import-30',
+    )
+
+    _, fields = sinks.logged[0]
+    assert fields['error_type'] == 'MlflowException'
+    assert 'Connection refused' in fields['error_summary']
+    assert '\n' not in fields['error_summary']
+
+
+@mark.asyncio
+async def test_the_user_facing_line_is_greppable_by_the_same_fields():
+    """The sentence a person reads said nothing technical, and nothing said where to look."""
+    sinks = FakeSinks()
+
+    await report_import_failure(
+        sinks,
+        None,
+        ImportLogRowNotClaimableError('row 29 is in status IMPORT_ERROR', import_run_id=29),
+        import_run_id=29,
+        workflow_id='manual-import-29',
+        code=ImportErrorCode.LOG_ROW_NOT_CLAIMABLE,
+        marker='not_claimable',
+    )
+
+    notified = sinks.notifications[0]
+    assert notified['message'] == UNCLASSIFIED_FAILURE[1]
+    assert notified['metadata']['import_code'] == ImportErrorCode.LOG_ROW_NOT_CLAIMABLE.value
+    assert notified['metadata']['import_step'] == 'not_claimable'
+    assert notified['metadata']['import_run_id'] == 29
+    assert notified['metadata']['error_type'] == 'ImportLogRowNotClaimableError'
+    assert notified['metadata'] == sinks.logged[0][1]
+
+
+@mark.asyncio
+async def test_the_gate_and_the_unrecorded_verdict_are_fields_when_there_are_any():
+    sinks = FakeSinks()
+
+    await report_import_failure(
+        sinks,
+        ImportStep.DECRYPTION,
+        ImportGateRejectedError('gate 3 rejected the bundle', step=ImportStep.DECRYPTION, gate=3),
+        import_run_id=77,
+        workflow_id='wf',
+        gate=3,
+        verdict='succeeded=False step=decryption gate=3',
+    )
+
+    _, fields = sinks.logged[0]
+    assert fields['import_gate'] == 3
+    assert fields['import_verdict_not_recorded'] == 'succeeded=False step=decryption gate=3'
+
+
+@mark.asyncio
+async def test_a_failure_with_neither_gate_nor_verdict_carries_neither_field():
+    """An empty field is noise in every line that has nothing to say in it."""
+    sinks = FakeSinks()
+
+    await report_import_failure(
+        sinks, ImportStep.DOWNLOAD, RuntimeError('boom'), import_run_id=77, workflow_id='wf'
+    )
+
+    _, fields = sinks.logged[0]
+    assert 'import_gate' not in fields
+    assert 'import_verdict_not_recorded' not in fields
+
+
+@mark.asyncio
+async def test_no_field_can_shadow_the_formatter_s_own_keys():
+    sinks = FakeSinks()
+
+    await report_import_failure(
+        sinks, ImportStep.DOWNLOAD, RuntimeError('boom'), import_run_id=77, workflow_id='wf'
+    )
+
+    _, fields = sinks.logged[0]
+    added = set(fields) - {'model_name', 'model_id', 'workflow_name', 'schedule_name'}
+    assert all(key.startswith(('import_', 'error_')) for key in added)
+    assert not {'at', 'msg', 'timestamp'} & set(fields)
+
+
+def test_the_chain_is_flattened_root_cause_first():
+    """Because the first line is what becomes `error_summary`, and it has to be the cause."""
+    kind, detail = describe_failure_chain(_wrapped_activity_failure())
+
+    assert kind == 'MlflowException'
+    assert detail.splitlines()[0].startswith('MlflowException: API request to')
+    assert detail.splitlines()[-1] == 'RuntimeError: Activity task failed'
+
+
+def test_a_cycle_in_the_chain_cannot_hang_the_reporting_of_a_failure():
+    first = RuntimeError('first')
+    second = RuntimeError('second')
+    first.__cause__ = second
+    second.__cause__ = first
+
+    _, detail = describe_failure_chain(first)
+
+    assert len(detail.splitlines()) <= 10
+
+
+def test_a_failure_that_arrives_as_text_keeps_the_type_that_travelled_with_it():
+    kind, summary = summarize_failure(
+        None,
+        'MlflowException: connection refused\nRuntimeError: Activity task failed',
+        'MlflowException',
+    )
+
+    assert kind == 'MlflowException'
+    assert summary == 'MlflowException: connection refused'
+
+
+def test_a_failure_that_arrives_as_nothing_says_so_rather_than_guessing():
+    kind, summary = summarize_failure(None, None, None)
+
+    assert kind == 'unavailable'
+    assert summary == ''
+
+
 # ------------------------------------------------- the channel is the only reporter
 
 
@@ -392,7 +569,7 @@ def test_no_import_module_reports_a_failure_of_its_own(module_path: Path):
 
 
 def test_the_channel_itself_is_where_the_reporting_lives():
-    channel = REPOSITORY_ROOT / 'laborious/activities/model_import_errors.py'
+    channel = REPOSITORY_ROOT / 'laborious/utils/models/import_errors.py'
 
     calls = _reporting_calls(channel)
 

tests/laborious/worker/test_runtime_task_queues.py

@@ -109,6 +109,6 @@ def test_the_import_worker_registers_only_the_import_activities():
             if isinstance(inner, ast.keyword) and inner.arg == 'other_workflows':
                 assert ast.unparse(inner.value) == '[]'
 
-    assert len(activities) == 13
+    assert len(activities) == 14
     assert all(name.startswith('activities.') for name in activities)
     assert all('import' in name for name in activities)

tests/laborious/workflows/test_import_model.py

@@ -15,18 +15,19 @@ from unittest.mock import MagicMock, patch
 
 from pytest import fixture, mark, raises
 from sientia_do.temporal.policies import retry_policy
+from temporalio.exceptions import ApplicationError
 
 from laborious.activities.activities import Activities
 from laborious.activities.model_import import (
     IMPORT_STATUS_HINT_RETRY_POLICY,
     IMPORT_STATUS_RETRY_POLICY,
 )
-from laborious.activities.model_import_errors import (
+from laborious.utils.bundle.steps import ImportStep
+from laborious.utils.models.import_errors import (
     ImportGateRejectedError,
     ImportInputError,
     ImportLogRowNotClaimableError,
 )
-from laborious.utils.bundle.steps import ImportStep
 from laborious.workflows.import_model import (
     REJECTED_INPUT_FIELDS,
     STATUS_WRITE_ENVELOPE,
@@ -224,6 +225,24 @@ async def test_the_names_are_recorded_before_mlflow_is_touched(
     assert names['run_name'] == 'import-factory_model-v2'
 
 
+@mark.asyncio
+async def test_the_model_is_named_from_the_bundles_model_name(
+    import_workflow: ImportModel, workflow_env
+):
+    """`metadata.model_name` names the model, verbatim, in both destinations.
+
+    The registered model and the model document take the bundle's own `model_name` and nothing else:
+    no other metadata field substitutes for it, and nothing is appended to it.
+    """
+    await import_workflow.run(valid_input())
+
+    registration = workflow_env.recorder.payload_of(Activities.register_import_model_version)
+    document = workflow_env.recorder.payload_of(Activities.write_import_model_document)
+    assert registration['model_name'] == BUNDLE_METADATA['model_name']
+    assert document['model_name'] == BUNDLE_METADATA['model_name']
+    assert document['model_name'] == registration['model_name']
+
+
 @mark.asyncio
 async def test_the_run_is_created_with_exactly_the_recorded_name(
     import_workflow: ImportModel, workflow_env
@@ -660,6 +679,168 @@ async def test_reporting_the_report_is_where_it_stops(import_workflow: ImportMod
     assert result['run_id'] == RUN_ID
 
 
+# --------------------------------------------------------------- the failure report
+
+
+def activity_failure(message: str, kind: str) -> BaseException:
+    """What a failed activity looks like from inside the workflow.
+
+    The activity's own exception type survives the boundary in `ApplicationError.type` and nowhere
+    else; the outer error is the one Temporal raises for the failed activity.
+    """
+    wrapper = RuntimeError('Activity task failed')
+    wrapper.__cause__ = ApplicationError(message, type=kind)
+    return wrapper
+
+
+@mark.asyncio
+async def test_the_failure_that_ends_an_import_is_reported_through_the_channel(
+    import_workflow: ImportModel,
+):
+    """The gap this closes: a failure at any pipeline step used to reach the structured logs as
+    nothing at all — only the SDK's own traceback for the attempt, with no id and no step."""
+    recorder = Recorder(
+        failures={
+            Activities.create_import_experiment: activity_failure(
+                'API request to http://localhost:5080/api/2.0/mlflow/experiments/get-by-name '
+                'failed with exception Connection refused',
+                'MlflowException',
+            )
+        }
+    )
+    patcher, _ = run_with(recorder)
+    try:
+        with raises(RuntimeError, match='Activity task failed'):
+            await import_workflow.run(valid_input())
+    finally:
+        patcher.stop()
+
+    reported = recorder.payload_of(Activities.report_import_pipeline_failure)
+    assert reported['step'] == ImportStep.EXPERIMENT_CREATION.value
+    assert reported['error_type'] == 'MlflowException'
+    assert reported['detail'].splitlines()[0].startswith('MlflowException: API request to')
+    assert reported['import_run_id'] == 77
+    assert reported['workflow_id'] == WORKFLOW_ID
+
+
+@mark.asyncio
+async def test_the_report_comes_before_the_cleanup_and_the_terminal_write(
+    import_workflow: ImportModel,
+):
+    """So the log reads in the order things happened, and the row's step matches the line's."""
+    recorder = Recorder(
+        failures={Activities.upload_import_artifacts: activity_failure('bucket gone', 'S3Error')}
+    )
+    patcher, _ = run_with(recorder)
+    try:
+        with raises(RuntimeError):
+            await import_workflow.run(valid_input())
+    finally:
+        patcher.stop()
+
+    order = recorder.order
+    assert (
+        order.index(Activities.report_import_pipeline_failure)
+        < order.index(Activities.cleanup_import_files)
+        < order.index(Activities.record_import_terminal_status)
+    )
+    reported = recorder.payload_of(Activities.report_import_pipeline_failure)
+    terminal = recorder.payload_of(Activities.record_import_terminal_status)
+    assert reported['step'] == terminal['step'] == ImportStep.ARTIFACT_UPLOAD.value
+
+
+@mark.asyncio
+async def test_the_gate_that_rejected_the_bundle_travels_into_the_report(
+    import_workflow: ImportModel,
+):
+    recorder = Recorder(
+        failures={
+            Activities.open_import_bundle: ImportGateRejectedError(
+                'gate 3 rejected the bundle', step=ImportStep.DECRYPTION, gate=3
+            )
+        }
+    )
+    patcher, _ = run_with(recorder)
+    try:
+        with raises(ImportGateRejectedError):
+            await import_workflow.run(valid_input())
+    finally:
+        patcher.stop()
+
+    reported = recorder.payload_of(Activities.report_import_pipeline_failure)
+    assert reported['step'] == ImportStep.DECRYPTION.value
+    assert reported['gate'] == 3
+
+
+@mark.asyncio
+async def test_a_claim_that_matches_nothing_is_not_reported_twice(import_workflow: ImportModel):
+    """The claim reports itself, and it runs outside the try — so the channel is hit once."""
+    recorder = Recorder(
+        failures={
+            Activities.claim_import_status: ImportLogRowNotClaimableError(
+                'row 29 could not be claimed', import_run_id=29
+            )
+        }
+    )
+    patcher, _ = run_with(recorder)
+    try:
+        with raises(ImportLogRowNotClaimableError):
+            await import_workflow.run(valid_input())
+    finally:
+        patcher.stop()
+
+    assert Activities.report_import_pipeline_failure not in recorder.order
+
+
+@mark.asyncio
+async def test_a_report_that_cannot_be_made_does_not_mask_the_failure(
+    import_workflow: ImportModel,
+):
+    recorder = Recorder(
+        failures={
+            Activities.write_import_model_document: activity_failure('mongo down', 'PyMongoError'),
+            Activities.report_import_pipeline_failure: RuntimeError('no channel'),
+        }
+    )
+    patcher, _ = run_with(recorder)
+    try:
+        with raises(RuntimeError, match='Activity task failed'):
+            await import_workflow.run(valid_input())
+    finally:
+        patcher.stop()
+
+    terminal = recorder.payload_of(Activities.record_import_terminal_status)
+    assert terminal['succeeded'] is False
+    assert terminal['step'] == ImportStep.MODEL_DOCUMENT.value
+
+
+@mark.asyncio
+async def test_a_successful_import_reports_no_failure(import_workflow: ImportModel, workflow_env):
+    await import_workflow.run(valid_input())
+
+    assert Activities.report_import_pipeline_failure not in workflow_env.recorder.order
+
+
+@mark.asyncio
+async def test_the_report_gives_up_inside_the_short_bound(import_workflow: ImportModel):
+    """A failure already happened; spending 151 seconds telling the log about it would be worse."""
+    recorder = Recorder(
+        failures={
+            Activities.create_import_experiment: activity_failure('refused', 'MlflowException')
+        }
+    )
+    patcher, _ = run_with(recorder)
+    try:
+        with raises(RuntimeError):
+            await import_workflow.run(valid_input())
+    finally:
+        patcher.stop()
+
+    call = recorder.calls_to(Activities.report_import_pipeline_failure)[0]
+    assert call.kwargs['retry_policy'] is IMPORT_STATUS_HINT_RETRY_POLICY
+    assert call.kwargs['start_to_close_timeout'] == STATUS_WRITE_TIMEOUT
+
+
 # ------------------------------------------------------------------- the retry split