From 24c48da8dfac806182147fa7297c5ce83cefc237 Mon Sep 17 00:00:00 2001 From: Forge Date: Thu, 16 Jul 2026 11:55:07 +0000 Subject: [PATCH 1/5] [AISOS-2201] Add structured start log to implement_task function Added INFO-level structured log after Jira issue fetch in implement_task: - Log message: 'Implementation started for task {current_task}' - Includes structured extra fields: event, task_name, feature_id, task_id - Handles empty task summary with fallback to empty string - Special characters in task summary logged as-is (no escaping) Closes: AISOS-2201 --- src/forge/workflow/nodes/implementation.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/src/forge/workflow/nodes/implementation.py b/src/forge/workflow/nodes/implementation.py index 6bf02cd6..9dd3765c 100644 --- a/src/forge/workflow/nodes/implementation.py +++ b/src/forge/workflow/nodes/implementation.py @@ -114,6 +114,16 @@ async def implement_task(state: WorkflowState) -> WorkflowState: task_description = task_issue.description or "" task_summary = task_issue.summary + logger.info( + f"Implementation started for task {current_task}", + extra={ + "event": "implementation_started", + "task_name": task_summary or "", + "feature_id": ticket_key, + "task_id": current_task, + }, + ) + # Post status comment at task implementation start await post_status_comment( jira, From a0fc363cf8ea419d0ea7f031a2db3a5361cee8cb Mon Sep 17 00:00:00 2001 From: Forge Date: Thu, 16 Jul 2026 11:57:35 +0000 Subject: [PATCH 2/5] [AISOS-2202] Add structured end log on successful implementation Added INFO-level structured log when implementation completes successfully: - Log message: 'Implementation completed for task {current_task}' - Extra fields: event='implementation_completed', task_name, feature_id, task_id, success=True - Placed after container success log and before status comment posting Closes: AISOS-2202 --- src/forge/workflow/nodes/implementation.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/src/forge/workflow/nodes/implementation.py b/src/forge/workflow/nodes/implementation.py index 9dd3765c..bc46e622 100644 --- a/src/forge/workflow/nodes/implementation.py +++ b/src/forge/workflow/nodes/implementation.py @@ -165,6 +165,17 @@ async def implement_task(state: WorkflowState) -> WorkflowState: if result.success: logger.info(f"Container completed successfully for {current_task}") + logger.info( + f"Implementation completed for task {current_task}", + extra={ + "event": "implementation_completed", + "task_name": task_summary or "", + "feature_id": ticket_key, + "task_id": current_task, + "success": True, + }, + ) + # Post status comment at task implementation completion await post_status_comment( jira, From 716f467e7be18a7a36e7a39241a84b57e6359e51 Mon Sep 17 00:00:00 2001 From: Forge Date: Thu, 16 Jul 2026 11:59:55 +0000 Subject: [PATCH 3/5] [AISOS-2203] Add structured end log on failed implementation - Initialize task_summary='unknown' before Jira fetch to handle early failures - Add INFO-level structured log in exception handler with event='implementation_ended' - Include task_name, feature_id, task_id, success=False in extra dict - Handle missing task_id with 'unknown' placeholder per BR-003 - Log emitted before return for timing accuracy Closes: AISOS-2203 --- src/forge/workflow/nodes/implementation.py | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/src/forge/workflow/nodes/implementation.py b/src/forge/workflow/nodes/implementation.py index bc46e622..6ac3badd 100644 --- a/src/forge/workflow/nodes/implementation.py +++ b/src/forge/workflow/nodes/implementation.py @@ -108,6 +108,9 @@ async def implement_task(state: WorkflowState) -> WorkflowState: settings = get_settings() jira = JiraClient(settings) + # Initialize task_summary before Jira fetch to handle early failures (BR-003) + task_summary = "unknown" + try: # Get Task details from Jira task_issue = await jira.get_issue(current_task) @@ -207,6 +210,18 @@ async def implement_task(state: WorkflowState) -> WorkflowState: except Exception as e: logger.error(f"Implementation failed for {current_task}: {e}") + # Emit structured end log before notify_error for timing accuracy + task_id = current_task if current_task else "unknown" + logger.info( + f"Implementation ended for task {task_id}", + extra={ + "event": "implementation_ended", + "task_name": task_summary, + "feature_id": ticket_key, + "task_id": task_id, + "success": False, + }, + ) return { **state, "last_error": str(e), From ca7e5787899204d8726f64a764a24fd3ed1aa642 Mon Sep 17 00:00:00 2001 From: Forge Date: Thu, 16 Jul 2026 12:04:56 +0000 Subject: [PATCH 4/5] [AISOS-2204] Add unit tests for structured logging in implement_task Added TestImplementTaskStructuredLogging class with 7 test methods covering: - TS-001: test_logs_implementation_started_with_structured_fields - TS-002: test_logs_implementation_completed_on_success - TS-003: test_logs_implementation_ended_on_failure - TS-004: test_logs_implementation_ended_on_exception - TS-005: test_logs_unknown_task_name_when_jira_fails_early - TS-006: test_logs_empty_task_summary_as_empty_string - TS-007: test_logs_special_characters_in_task_summary Tests use caplog fixture, verify INFO log level, and check presence of event, task_name, feature_id, task_id fields. End logs also verify success field. Closes: AISOS-2204 --- .../workflow/nodes/test_implementation.py | 263 ++++++++++++++++++ 1 file changed, 263 insertions(+) diff --git a/tests/unit/workflow/nodes/test_implementation.py b/tests/unit/workflow/nodes/test_implementation.py index 64aeac11..d328be82 100644 --- a/tests/unit/workflow/nodes/test_implementation.py +++ b/tests/unit/workflow/nodes/test_implementation.py @@ -270,3 +270,266 @@ async def test_bug_container_failure_keeps_bug_implementation_node(self): assert result["current_node"] == "implement_bug_fix" assert result["last_error"] == "container failed" assert result["retry_count"] == 1 + + +class TestImplementTaskStructuredLogging: + """Tests for structured logging in implement_task (TS-001 through TS-007).""" + + @pytest.mark.asyncio + async def test_logs_implementation_started_with_structured_fields(self, caplog): + """TS-001: Verify start log has correct extra fields.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Add caching layer") + runner = _make_successful_runner() + + with ( + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch( + "forge.workflow.nodes.implementation.ContainerRunner", + return_value=runner, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + ): + await implement_task( + _make_state(ticket_key="FEAT-100", current_task_key="TASK-200") + ) + + # Find the start log record + start_records = [ + r for r in caplog.records if "implementation_started" in str(r.__dict__) + ] + assert len(start_records) == 1 + record = start_records[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_started" + assert record.task_name == "Add caching layer" + assert record.feature_id == "FEAT-100" + assert record.task_id == "TASK-200" + + @pytest.mark.asyncio + async def test_logs_implementation_completed_on_success(self, caplog): + """TS-002: Verify success end log has success=True.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Refactor DB queries") + runner = _make_successful_runner() + + with ( + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch( + "forge.workflow.nodes.implementation.ContainerRunner", + return_value=runner, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + ): + await implement_task( + _make_state(ticket_key="FEAT-101", current_task_key="TASK-201") + ) + + # Find the completion log record + end_records = [ + r for r in caplog.records if "implementation_completed" in str(r.__dict__) + ] + assert len(end_records) == 1 + record = end_records[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_completed" + assert record.task_name == "Refactor DB queries" + assert record.feature_id == "FEAT-101" + assert record.task_id == "TASK-201" + assert record.success is True + + @pytest.mark.asyncio + async def test_logs_implementation_ended_on_failure(self, caplog): + """TS-003: Verify failure end log has success=False.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Fix memory leak") + runner = MagicMock() + container_result = MagicMock() + container_result.success = False + container_result.error_message = "container failed" + runner.run = AsyncMock(return_value=container_result) + + with ( + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch( + "forge.workflow.nodes.implementation.ContainerRunner", + return_value=runner, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + ): + await implement_task( + _make_state(ticket_key="FEAT-102", current_task_key="TASK-202") + ) + + # Find the failure log record + end_records = [ + r for r in caplog.records if "implementation_ended" in str(r.__dict__) + ] + assert len(end_records) == 1 + record = end_records[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_ended" + assert record.task_name == "Fix memory leak" + assert record.feature_id == "FEAT-102" + assert record.task_id == "TASK-202" + assert record.success is False + + @pytest.mark.asyncio + async def test_logs_implementation_ended_on_exception(self, caplog): + """TS-004: Verify exception path emits end log.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Add retry logic") + runner = MagicMock() + runner.run = AsyncMock(side_effect=RuntimeError("Connection timeout")) + + with ( + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch( + "forge.workflow.nodes.implementation.ContainerRunner", + return_value=runner, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + ): + await implement_task( + _make_state(ticket_key="FEAT-103", current_task_key="TASK-203") + ) + + # Find the failure log record + end_records = [ + r for r in caplog.records if "implementation_ended" in str(r.__dict__) + ] + assert len(end_records) == 1 + record = end_records[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_ended" + assert record.feature_id == "FEAT-103" + assert record.task_id == "TASK-203" + assert record.success is False + + @pytest.mark.asyncio + async def test_logs_unknown_task_name_when_jira_fails_early(self, caplog): + """TS-005: Verify placeholder handling when Jira fetch fails.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = AsyncMock() + mock_jira.get_issue = AsyncMock(side_effect=Exception("Jira API timeout")) + mock_jira.close = AsyncMock() + + with ( + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + ): + await implement_task( + _make_state(ticket_key="FEAT-104", current_task_key="TASK-204") + ) + + # Find the failure log record + end_records = [ + r for r in caplog.records if "implementation_ended" in str(r.__dict__) + ] + assert len(end_records) == 1 + record = end_records[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_ended" + assert record.task_name == "unknown" + assert record.feature_id == "FEAT-104" + assert record.task_id == "TASK-204" + assert record.success is False + + @pytest.mark.asyncio + async def test_logs_empty_task_summary_as_empty_string(self, caplog): + """TS-006: Verify empty summary handling.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="") + runner = _make_successful_runner() + + with ( + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch( + "forge.workflow.nodes.implementation.ContainerRunner", + return_value=runner, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + ): + await implement_task( + _make_state(ticket_key="FEAT-105", current_task_key="TASK-205") + ) + + # Find the start log record + start_records = [ + r for r in caplog.records if "implementation_started" in str(r.__dict__) + ] + assert len(start_records) == 1 + record = start_records[0] + + assert record.levelname == "INFO" + assert record.task_name == "" + + @pytest.mark.asyncio + async def test_logs_special_characters_in_task_summary(self, caplog): + """TS-007: Verify special chars not escaped.""" + from forge.workflow.nodes.implementation import implement_task + + special_summary = 'Fix & handle "quotes"' + mock_jira = _make_mock_jira(summary=special_summary) + runner = _make_successful_runner() + + with ( + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch( + "forge.workflow.nodes.implementation.ContainerRunner", + return_value=runner, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + ): + await implement_task( + _make_state(ticket_key="FEAT-106", current_task_key="TASK-206") + ) + + # Find the start log record + start_records = [ + r for r in caplog.records if "implementation_started" in str(r.__dict__) + ] + assert len(start_records) == 1 + record = start_records[0] + + assert record.levelname == "INFO" + assert record.task_name == special_summary From d24f1328a5b2618dc0c38da350f41f2e2e234369 Mon Sep 17 00:00:00 2001 From: Forge Date: Thu, 16 Jul 2026 12:08:51 +0000 Subject: [PATCH 5/5] [AISOS-2119-review] Fix inconsistent task_name handling in failure log - Changed task_name from 'task_summary' to 'task_summary or ""' in exception handler (line 219) to match behavior of start and success logs - Ran ruff format on test file to fix formatting issues The spec requires empty task summaries to be logged as empty strings, but the failure path was missing the 'or ""' fallback, which could cause inconsistent behavior when task_summary is empty or None. Closes: AISOS-2119-review --- src/forge/workflow/nodes/implementation.py | 2 +- .../workflow/nodes/test_implementation.py | 58 +++++-------------- 2 files changed, 15 insertions(+), 45 deletions(-) diff --git a/src/forge/workflow/nodes/implementation.py b/src/forge/workflow/nodes/implementation.py index 6ac3badd..c1c8451f 100644 --- a/src/forge/workflow/nodes/implementation.py +++ b/src/forge/workflow/nodes/implementation.py @@ -216,7 +216,7 @@ async def implement_task(state: WorkflowState) -> WorkflowState: f"Implementation ended for task {task_id}", extra={ "event": "implementation_ended", - "task_name": task_summary, + "task_name": task_summary or "", "feature_id": ticket_key, "task_id": task_id, "success": False, diff --git a/tests/unit/workflow/nodes/test_implementation.py b/tests/unit/workflow/nodes/test_implementation.py index d328be82..0d5d3457 100644 --- a/tests/unit/workflow/nodes/test_implementation.py +++ b/tests/unit/workflow/nodes/test_implementation.py @@ -56,7 +56,6 @@ def _make_successful_runner(): class TestImplementTaskStartedComment: - @pytest.mark.asyncio async def test_posts_comment_on_task_ticket_before_container(self): """A comment is posted on the task ticket (not parent) when implementation starts.""" @@ -184,7 +183,6 @@ async def test_passes_trace_context_to_container_runner(self): class TestImplementationNodeRouting: - @pytest.mark.asyncio async def test_feature_missing_workspace_uses_feature_implementation_node(self): """Feature implementation failures must resume at implement_task.""" @@ -295,14 +293,10 @@ async def test_logs_implementation_started_with_structured_fields(self, caplog): patch("forge.workflow.nodes.implementation.get_settings"), caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), ): - await implement_task( - _make_state(ticket_key="FEAT-100", current_task_key="TASK-200") - ) + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) # Find the start log record - start_records = [ - r for r in caplog.records if "implementation_started" in str(r.__dict__) - ] + start_records = [r for r in caplog.records if "implementation_started" in str(r.__dict__)] assert len(start_records) == 1 record = start_records[0] @@ -332,14 +326,10 @@ async def test_logs_implementation_completed_on_success(self, caplog): patch("forge.workflow.nodes.implementation.get_settings"), caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), ): - await implement_task( - _make_state(ticket_key="FEAT-101", current_task_key="TASK-201") - ) + await implement_task(_make_state(ticket_key="FEAT-101", current_task_key="TASK-201")) # Find the completion log record - end_records = [ - r for r in caplog.records if "implementation_completed" in str(r.__dict__) - ] + end_records = [r for r in caplog.records if "implementation_completed" in str(r.__dict__)] assert len(end_records) == 1 record = end_records[0] @@ -374,14 +364,10 @@ async def test_logs_implementation_ended_on_failure(self, caplog): patch("forge.workflow.nodes.implementation.get_settings"), caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), ): - await implement_task( - _make_state(ticket_key="FEAT-102", current_task_key="TASK-202") - ) + await implement_task(_make_state(ticket_key="FEAT-102", current_task_key="TASK-202")) # Find the failure log record - end_records = [ - r for r in caplog.records if "implementation_ended" in str(r.__dict__) - ] + end_records = [r for r in caplog.records if "implementation_ended" in str(r.__dict__)] assert len(end_records) == 1 record = end_records[0] @@ -413,14 +399,10 @@ async def test_logs_implementation_ended_on_exception(self, caplog): patch("forge.workflow.nodes.implementation.get_settings"), caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), ): - await implement_task( - _make_state(ticket_key="FEAT-103", current_task_key="TASK-203") - ) + await implement_task(_make_state(ticket_key="FEAT-103", current_task_key="TASK-203")) # Find the failure log record - end_records = [ - r for r in caplog.records if "implementation_ended" in str(r.__dict__) - ] + end_records = [r for r in caplog.records if "implementation_ended" in str(r.__dict__)] assert len(end_records) == 1 record = end_records[0] @@ -447,14 +429,10 @@ async def test_logs_unknown_task_name_when_jira_fails_early(self, caplog): patch("forge.workflow.nodes.implementation.get_settings"), caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), ): - await implement_task( - _make_state(ticket_key="FEAT-104", current_task_key="TASK-204") - ) + await implement_task(_make_state(ticket_key="FEAT-104", current_task_key="TASK-204")) # Find the failure log record - end_records = [ - r for r in caplog.records if "implementation_ended" in str(r.__dict__) - ] + end_records = [r for r in caplog.records if "implementation_ended" in str(r.__dict__)] assert len(end_records) == 1 record = end_records[0] @@ -485,14 +463,10 @@ async def test_logs_empty_task_summary_as_empty_string(self, caplog): patch("forge.workflow.nodes.implementation.get_settings"), caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), ): - await implement_task( - _make_state(ticket_key="FEAT-105", current_task_key="TASK-205") - ) + await implement_task(_make_state(ticket_key="FEAT-105", current_task_key="TASK-205")) # Find the start log record - start_records = [ - r for r in caplog.records if "implementation_started" in str(r.__dict__) - ] + start_records = [r for r in caplog.records if "implementation_started" in str(r.__dict__)] assert len(start_records) == 1 record = start_records[0] @@ -520,14 +494,10 @@ async def test_logs_special_characters_in_task_summary(self, caplog): patch("forge.workflow.nodes.implementation.get_settings"), caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), ): - await implement_task( - _make_state(ticket_key="FEAT-106", current_task_key="TASK-206") - ) + await implement_task(_make_state(ticket_key="FEAT-106", current_task_key="TASK-206")) # Find the start log record - start_records = [ - r for r in caplog.records if "implementation_started" in str(r.__dict__) - ] + start_records = [r for r in caplog.records if "implementation_started" in str(r.__dict__)] assert len(start_records) == 1 record = start_records[0]