diff --git a/src/forge/workflow/nodes/implementation.py b/src/forge/workflow/nodes/implementation.py index 6bf02cd6..1d005f0e 100644 --- a/src/forge/workflow/nodes/implementation.py +++ b/src/forge/workflow/nodes/implementation.py @@ -108,12 +108,25 @@ async def implement_task(state: WorkflowState) -> WorkflowState: settings = get_settings() jira = JiraClient(settings) + # Initialize placeholder for early failure logging (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,18 @@ async def implement_task(state: WorkflowState) -> WorkflowState: if result.success: logger.info(f"Container completed successfully for {current_task}") + # Emit structured log for successful implementation + logger.info( + f"Implementation completed for task {current_task}", + extra={ + "event": "implementation_completed", + "task_name": task_summary, + "feature_id": ticket_key, + "task_id": current_task, + "success": True, + }, + ) + # Post status comment at task implementation completion await post_status_comment( jira, @@ -186,6 +211,17 @@ async def implement_task(state: WorkflowState) -> WorkflowState: except Exception as e: logger.error(f"Implementation failed for {current_task}: {e}") + # Emit structured end log for failed implementation + logger.info( + f"Implementation ended for task {current_task or 'unknown'}", + extra={ + "event": "implementation_ended", + "task_name": task_summary, + "feature_id": ticket_key, + "task_id": current_task or "unknown", + "success": False, + }, + ) return { **state, "last_error": str(e), diff --git a/tests/unit/workflow/nodes/test_implementation.py b/tests/unit/workflow/nodes/test_implementation.py index 64aeac11..036e7cc0 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.""" @@ -270,3 +268,253 @@ 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: Start log has correct extra fields.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Add new API endpoint") + runner = _make_successful_runner() + + with ( + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + 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"), + ): + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) + + # Find the start log record + start_logs = [ + r for r in caplog.records if "implementation_started" in str(getattr(r, "event", "")) + ] + assert len(start_logs) == 1 + record = start_logs[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_started" + assert record.task_name == "Add new API endpoint" + 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: Success end log has success=True.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Fix login bug") + runner = _make_successful_runner() + + with ( + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + 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"), + ): + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) + + # Find the completion log record + end_logs = [ + r for r in caplog.records if "implementation_completed" in str(getattr(r, "event", "")) + ] + assert len(end_logs) == 1 + record = end_logs[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_completed" + assert record.task_name == "Fix login bug" + assert record.feature_id == "FEAT-100" + assert record.task_id == "TASK-200" + assert record.success is True + + @pytest.mark.asyncio + async def test_logs_implementation_ended_on_failure(self, caplog): + """TS-003: Failure end log has success=False.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Refactor database") + runner = MagicMock() + result = MagicMock() + result.success = False + result.error_message = "Container crashed" + runner.run = AsyncMock(return_value=result) + + with ( + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + 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"), + ): + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) + + # Find the end log record + end_logs = [ + r for r in caplog.records if "implementation_ended" in str(getattr(r, "event", "")) + ] + assert len(end_logs) == 1 + record = end_logs[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_ended" + assert record.task_name == "Refactor database" + assert record.feature_id == "FEAT-100" + assert record.task_id == "TASK-200" + assert record.success is False + + @pytest.mark.asyncio + async def test_logs_implementation_ended_on_exception(self, caplog): + """TS-004: Exception path emits end log with success=False.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="Add feature X") + runner = MagicMock() + runner.run = AsyncMock(side_effect=RuntimeError("Network timeout")) + + with ( + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + 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"), + ): + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) + + # Find the end log record + end_logs = [ + r for r in caplog.records if "implementation_ended" in str(getattr(r, "event", "")) + ] + assert len(end_logs) == 1 + record = end_logs[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_ended" + assert record.task_name == "Add feature X" + assert record.feature_id == "FEAT-100" + assert record.task_id == "TASK-200" + assert record.success is False + + @pytest.mark.asyncio + async def test_logs_unknown_task_name_when_jira_fails_early(self, caplog): + """TS-005: Placeholder handling when Jira fails before getting summary.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = AsyncMock() + mock_jira.get_issue = AsyncMock(side_effect=Exception("Jira unavailable")) + mock_jira.close = AsyncMock() + + with ( + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + patch( + "forge.workflow.nodes.implementation.JiraClient", + return_value=mock_jira, + ), + patch("forge.workflow.nodes.implementation.get_settings"), + ): + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) + + # Find the end log record + end_logs = [ + r for r in caplog.records if "implementation_ended" in str(getattr(r, "event", "")) + ] + assert len(end_logs) == 1 + record = end_logs[0] + + assert record.levelname == "INFO" + assert record.event == "implementation_ended" + assert record.task_name == "unknown" + assert record.feature_id == "FEAT-100" + assert record.task_id == "TASK-200" + assert record.success is False + + @pytest.mark.asyncio + async def test_logs_empty_task_summary_as_empty_string(self, caplog): + """TS-006: Empty summary handling.""" + from forge.workflow.nodes.implementation import implement_task + + mock_jira = _make_mock_jira(summary="") + runner = _make_successful_runner() + + with ( + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + 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"), + ): + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) + + # Find the start log record + start_logs = [ + r for r in caplog.records if "implementation_started" in str(getattr(r, "event", "")) + ] + assert len(start_logs) == 1 + record = start_logs[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: Special characters not escaped in task_name.""" + from forge.workflow.nodes.implementation import implement_task + + special_summary = 'Fix "quotes" & and newline\nhere' + mock_jira = _make_mock_jira(summary=special_summary) + runner = _make_successful_runner() + + with ( + caplog.at_level("INFO", logger="forge.workflow.nodes.implementation"), + 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"), + ): + await implement_task(_make_state(ticket_key="FEAT-100", current_task_key="TASK-200")) + + # Find the start log record + start_logs = [ + r for r in caplog.records if "implementation_started" in str(getattr(r, "event", "")) + ] + assert len(start_logs) == 1 + record = start_logs[0] + + # Special characters should be preserved exactly as-is + assert record.task_name == special_summary