[AISOS-2119] Josh-test - ignore

src/forge/workflow/nodes/implementation.py

@@ -108,12 +108,25 @@ 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)
         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,
@@ -155,6 +168,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,
@@ -186,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 or "",
+                "feature_id": ticket_key,
+                "task_id": task_id,
+                "success": False,
+            },
+        )
         return {
             **state,
             "last_error": str(e),

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."""
@@ -270,3 +268,238 @@ 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 <script>alert("xss")</script> & 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