From f97f98919c81d759052442b82dcdee18c391c9e0 Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 12:49:51 +0200 Subject: [PATCH 01/15] fix(log-viewer): improve workflow timeline modal error handling and data format Improve error handling in the frontend to show specific messages for different HTTP status codes (404, 400, 500+) instead of generic errors. Add _transform_json_entry_to_timeline() method to convert JSON log data into the format expected by the frontend (step_count, total_duration_ms, steps array with proper fields). Update tests to verify the new response format structure. --- webhook_server/tests/test_log_viewer.py | 103 ++++++++++++------- webhook_server/web/log_viewer.py | 112 ++++++++++++++++++--- webhook_server/web/static/js/log_viewer.js | 30 +++++- 3 files changed, 191 insertions(+), 54 deletions(-) diff --git a/webhook_server/tests/test_log_viewer.py b/webhook_server/tests/test_log_viewer.py index 98688c38..1cb9283a 100644 --- a/webhook_server/tests/test_log_viewer.py +++ b/webhook_server/tests/test_log_viewer.py @@ -101,8 +101,16 @@ def sample_json_webhook_data(self) -> dict: "duration_ms": 5000, }, "workflow_steps": { - "step1": {"status": "completed", "duration_ms": 1000}, - "step2": {"status": "completed", "duration_ms": 2000}, + "step1": { + "timestamp": "2025-01-05T10:00:01.000000Z", + "status": "completed", + "duration_ms": 1000, + }, + "step2": { + "timestamp": "2025-01-05T10:00:03.000000Z", + "status": "completed", + "duration_ms": 2000, + }, }, "token_spend": 35, "success": True, @@ -267,7 +275,7 @@ async def test_stream_json_log_entries_newest_first_ordering(self, controller, t assert entries[1]["hook_id"] == "old-hook" async def test_get_workflow_steps_json_returns_workflow_data(self, controller, tmp_path, sample_json_webhook_data): - """Test get_workflow_steps_json returns workflow steps for valid hook_id.""" + """Test get_workflow_steps_json returns workflow steps in frontend-expected format.""" log_dir = tmp_path / "logs" log_dir.mkdir() @@ -277,17 +285,33 @@ async def test_get_workflow_steps_json_returns_workflow_data(self, controller, t # Get workflow steps result = await controller.get_workflow_steps_json("test-hook-123") - # Should return structured workflow data + # Should return data in the format expected by the frontend (renderFlowModal) assert result["hook_id"] == "test-hook-123" - assert result["event_type"] == "pull_request" - assert result["action"] == "opened" - assert result["repository"] == "org/test-repo" - assert result["sender"] == "test-user" - assert result["pr"]["number"] == 456 - assert result["timing"]["duration_ms"] == 5000 - assert result["steps"] == sample_json_webhook_data["workflow_steps"] + assert result["start_time"] == "2025-01-05T10:00:00.000000Z" + assert result["total_duration_ms"] == 5000 + assert result["step_count"] == 2 assert result["token_spend"] == 35 - assert result["success"] is True + + # Steps should be an array, not a dict + assert isinstance(result["steps"], list) + assert len(result["steps"]) == 2 + + # Each step should have the expected fields + step_names = {step["step_name"] for step in result["steps"]} + assert step_names == {"step1", "step2"} + + for step in result["steps"]: + assert "message" in step + assert "level" in step + assert "repository" in step + assert step["repository"] == "org/test-repo" + assert "event_type" in step + assert step["event_type"] == "pull_request" + assert "pr_number" in step + assert step["pr_number"] == 456 + assert "task_status" in step + assert step["task_status"] == "completed" + assert "relative_time_ms" in step async def test_get_workflow_steps_json_returns_none_for_unknown_hook_id( self, controller, tmp_path, sample_json_webhook_data @@ -320,23 +344,31 @@ async def test_get_workflow_steps_json_no_log_files(self, controller, tmp_path): assert exc.value.status_code == 404 async def test_get_workflow_steps_json_with_error_in_log(self, controller, tmp_path, sample_json_webhook_data): - """Test get_workflow_steps_json with webhook that has error.""" + """Test get_workflow_steps_json with webhook that has error step.""" log_dir = tmp_path / "logs" log_dir.mkdir() - # Create JSON log entry with error - error_data = sample_json_webhook_data.copy() - error_data["success"] = False - error_data["error"] = "Test error occurred" + # Create JSON log entry with failed step + error_data = copy.deepcopy(sample_json_webhook_data) + error_data["workflow_steps"]["failed_step"] = { + "timestamp": "2025-01-05T10:00:04.000000Z", + "status": "failed", + "duration_ms": 500, + "error": {"type": "ValueError", "message": "Test error occurred"}, + } self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [error_data]) # Get workflow steps result = await controller.get_workflow_steps_json("test-hook-123") - # Should include error information - assert result["success"] is False - assert result["error"] == "Test error occurred" + # Should include the failed step with error information + assert result["hook_id"] == "test-hook-123" + assert result["step_count"] == 3 + failed_steps = [s for s in result["steps"] if s["task_status"] == "failed"] + assert len(failed_steps) == 1 + assert failed_steps[0]["error"]["message"] == "Test error occurred" + assert failed_steps[0]["level"] == "ERROR" async def test_get_workflow_steps_uses_json_when_available(self, controller, tmp_path, sample_json_webhook_data): """Test get_workflow_steps uses JSON logs when available.""" @@ -349,10 +381,12 @@ async def test_get_workflow_steps_uses_json_when_available(self, controller, tmp # Get workflow steps (should use JSON, not fall back to text) result = await controller.get_workflow_steps("test-hook-123") - # Should return JSON-based data + # Should return data in frontend-expected format assert result["hook_id"] == "test-hook-123" - assert result["event_type"] == "pull_request" - assert "steps" in result + assert result["start_time"] == "2025-01-05T10:00:00.000000Z" + assert result["total_duration_ms"] == 5000 + assert result["step_count"] == 2 + assert isinstance(result["steps"], list) assert result["token_spend"] == 35 async def test_get_workflow_steps_falls_back_to_text_logs(self, controller, tmp_path): @@ -419,7 +453,7 @@ async def test_get_workflow_steps_json_handles_missing_optional_fields(self, con # Create minimal JSON log entry minimal_data = { "hook_id": "minimal-hook", - # Missing: event_type, action, sender, pr, workflow_steps, token_spend, success, error + # Missing: event_type, action, sender, pr, workflow_steps, token_spend, timing } self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [minimal_data]) @@ -427,18 +461,13 @@ async def test_get_workflow_steps_json_handles_missing_optional_fields(self, con # Get workflow steps result = await controller.get_workflow_steps_json("minimal-hook") - # Should handle missing fields with None + # Should handle missing fields with defaults in frontend-expected format assert result["hook_id"] == "minimal-hook" - assert result["event_type"] is None - assert result["action"] is None - assert result["repository"] is None - assert result["sender"] is None - assert result["pr"] is None - assert result["timing"] is None - assert result["steps"] == {} # Default to empty dict + assert result["start_time"] is None # No timing info + assert result["total_duration_ms"] == 0 # Default to 0 + assert result["step_count"] == 0 # No workflow_steps + assert result["steps"] == [] # Empty array (not dict) assert result["token_spend"] is None - assert result["success"] is None - assert result["error"] is None async def test_stream_json_log_entries_handles_file_read_errors( self, controller, tmp_path, sample_json_webhook_data @@ -493,9 +522,11 @@ async def test_get_workflow_steps_json_with_multiple_entries_same_file( # Search for middle entry result = await controller.get_workflow_steps_json("target-hook") - # Should find correct entry + # Should find correct entry and transform to frontend format assert result["hook_id"] == "target-hook" - assert result["pr"]["number"] == 200 + # Verify correct entry was found by checking pr_number in steps + for step in result["steps"]: + assert step["pr_number"] == 200 async def test_stream_json_log_entries_pretty_printed_format(self, controller, tmp_path): """Test _stream_json_log_entries with JSONL format (one JSON object per line).""" diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 4d0d0bff..712db97b 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -554,7 +554,13 @@ async def get_workflow_steps_json(self, hook_id: str) -> dict[str, Any]: hook_id: The hook ID to get workflow steps for Returns: - Dictionary with workflow steps from JSON log + Dictionary with workflow steps in the format expected by the frontend: + - hook_id: The hook ID + - start_time: ISO timestamp of when processing started + - total_duration_ms: Total processing duration in milliseconds + - step_count: Number of workflow steps + - steps: Array of step objects with timestamp, message, level, etc. + - token_spend: Optional token consumption count Raises: HTTPException: 404 if hook ID not found @@ -563,26 +569,102 @@ async def get_workflow_steps_json(self, hook_id: str) -> dict[str, Any]: # Search JSON logs for this hook_id async for entry in self._stream_json_log_entries(max_files=25, max_entries=50000): if entry.get("hook_id") == hook_id: - # Found the entry - return structured workflow data - return { - "hook_id": hook_id, - "event_type": entry.get("event_type"), - "action": entry.get("action"), - "repository": entry.get("repository"), - "sender": entry.get("sender"), - "pr": entry.get("pr"), - "timing": entry.get("timing"), - "steps": entry.get("workflow_steps") or {}, - "token_spend": entry.get("token_spend"), - "success": entry.get("success"), - "error": entry.get("error"), - } + # Found the entry - transform to frontend-expected format + return self._transform_json_entry_to_timeline(entry, hook_id) raise ValueError(f"No JSON log entry found for hook ID: {hook_id}") except ValueError as e: raise HTTPException(status_code=404, detail=str(e)) from e + def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) -> dict[str, Any]: + """Transform JSON log entry to the timeline format expected by the frontend. + + Converts the workflow_steps dict format from JSON logs into the array format + that matches the output of _build_workflow_timeline(). + + Args: + entry: JSON log entry with workflow_steps dict + hook_id: The hook ID for this entry + + Returns: + Dictionary in the format expected by renderFlowModal(): + - hook_id, start_time, total_duration_ms, step_count, steps, token_spend + """ + timing = entry.get("timing") or {} + workflow_steps = entry.get("workflow_steps") or {} + repository = entry.get("repository") + event_type = entry.get("event_type") + pr_info = entry.get("pr") or {} + pr_number = pr_info.get("number") if pr_info else None + + # Extract timing info + start_time = timing.get("started_at") + total_duration_ms = timing.get("duration_ms") or 0 + + # Transform workflow_steps dict to array format + # Sort by timestamp to maintain execution order + steps_list = [] + for step_name, step_data in workflow_steps.items(): + step_timestamp = step_data.get("timestamp") + step_status = step_data.get("status", "unknown") + step_duration_ms = step_data.get("duration_ms") + step_error = step_data.get("error") + + # Build message from step name and status + if step_error: + error_msg = step_error.get("message", "") if isinstance(step_error, dict) else str(step_error) + message = f"{step_name}: {step_status} - {error_msg}" + elif step_duration_ms is not None: + message = f"{step_name}: {step_status} ({step_duration_ms}ms)" + else: + message = f"{step_name}: {step_status}" + + # Determine log level from status + level = "INFO" + if step_status == "failed": + level = "ERROR" + elif step_status == "started": + level = "DEBUG" + + steps_list.append({ + "timestamp": step_timestamp, + "step_name": step_name, + "message": message, + "level": level, + "repository": repository, + "event_type": event_type, + "pr_number": pr_number, + "task_id": None, + "task_type": None, + "task_status": step_status, + "duration_ms": step_duration_ms, + "error": step_error, + "relative_time_ms": 0, # Will be calculated below + }) + + # Sort steps by timestamp and calculate relative times + steps_list.sort(key=lambda x: x.get("timestamp") or "") + if steps_list and start_time: + try: + base_time = datetime.datetime.fromisoformat(start_time.replace("Z", "+00:00")) + for step in steps_list: + step_ts = step.get("timestamp") + if step_ts: + step_time = datetime.datetime.fromisoformat(step_ts.replace("Z", "+00:00")) + step["relative_time_ms"] = int((step_time - base_time).total_seconds() * 1000) + except (ValueError, TypeError): + pass # Keep relative_time_ms as 0 if parsing fails + + return { + "hook_id": hook_id, + "start_time": start_time, + "total_duration_ms": total_duration_ms, + "step_count": len(steps_list), + "steps": steps_list, + "token_spend": entry.get("token_spend"), + } + async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: """Get workflow step timeline data for a specific hook ID. diff --git a/webhook_server/web/static/js/log_viewer.js b/webhook_server/web/static/js/log_viewer.js index 71bf040d..16cd91c1 100644 --- a/webhook_server/web/static/js/log_viewer.js +++ b/webhook_server/web/static/js/log_viewer.js @@ -839,14 +839,38 @@ function showFlowModal(hookId) { fetch(`/logs/api/workflow-steps/${encodeURIComponent(hookId)}`, { signal: currentFlowController.signal, }) - .then((response) => { + .then(async (response) => { if (!response.ok) { - if (response.status === 404) { + const status = response.status; + + // Try to parse error detail from JSON response + let errorDetail = null; + try { + const errorData = await response.json(); + errorDetail = errorData.detail; + } catch { + // JSON parsing failed, use default messages + } + + if (status === 404) { console.log("No flow data found for hook ID:", hookId); showFlowModalError("No workflow data found for this hook"); return; + } else if (status === 400) { + const message = errorDetail || "Invalid request"; + console.error("Bad request for hook ID:", hookId, message); + showFlowModalError(message); + return; + } else if (status >= 500) { + console.error("Server error for hook ID:", hookId, errorDetail); + showFlowModalError("Server error occurred. Please try again later."); + return; + } else { + const message = errorDetail || `HTTP ${status}: ${response.statusText}`; + console.error("Error fetching flow data:", message); + showFlowModalError(message); + return; } - throw new Error(`HTTP ${response.status}: ${response.statusText}`); } return response.json(); }) From 9c74860d07628e0fbc32ae29a90df2e7e2128fbe Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 16:01:38 +0200 Subject: [PATCH 02/15] fix(log-viewer): add missing context fields to workflow timeline response Add event_type, action, repository, sender, pr, success, and error fields to _format_timeline_data() response. These fields are needed by the frontend to render complete workflow context in the timeline modal. --- webhook_server/web/log_viewer.py | 21 ++++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 712db97b..db8a6679 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -589,7 +589,19 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) Returns: Dictionary in the format expected by renderFlowModal(): - - hook_id, start_time, total_duration_ms, step_count, steps, token_spend + - hook_id: The webhook delivery ID + - start_time: ISO timestamp when processing started + - total_duration_ms: Total processing duration in milliseconds + - step_count: Number of workflow steps + - steps: Array of step objects with timestamp, message, level, etc. + - token_spend: Optional token consumption count + - event_type: GitHub event type (e.g., "pull_request", "check_run") + - action: Event action (e.g., "opened", "synchronize") + - repository: Repository name (owner/repo) + - sender: GitHub username who triggered the event + - pr: Pull request info dict with number, title, etc. (or None) + - success: Boolean indicating if processing succeeded + - error: Error message if processing failed (or None) """ timing = entry.get("timing") or {} workflow_steps = entry.get("workflow_steps") or {} @@ -663,6 +675,13 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) "step_count": len(steps_list), "steps": steps_list, "token_spend": entry.get("token_spend"), + "event_type": event_type, + "action": entry.get("action"), + "repository": repository, + "sender": entry.get("sender"), + "pr": pr_info if pr_info else None, + "success": entry.get("success"), + "error": entry.get("error"), } async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: From c072bd1df0e59f1b78fe633f2fd331824e48d377 Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 16:53:16 +0200 Subject: [PATCH 03/15] fix(log-viewer): address CodeRabbit review comments for workflow timeline - Document new context fields (event_type, action, repository, sender, pr, success, error) in get_workflow_steps_json docstring - Fail fast on missing timing/workflow_steps instead of defaulting to empty values, raising HTTPException with clear error messages - Preserve task metadata (task_id, task_type) from JSON steps for grouping - Surface server-provided detail on 404 errors in JavaScript modal --- webhook_server/tests/test_log_viewer.py | 28 ++++++++++---------- webhook_server/web/log_viewer.py | 30 +++++++++++++++++----- webhook_server/web/static/js/log_viewer.js | 5 ++-- 3 files changed, 41 insertions(+), 22 deletions(-) diff --git a/webhook_server/tests/test_log_viewer.py b/webhook_server/tests/test_log_viewer.py index 1cb9283a..d45ba054 100644 --- a/webhook_server/tests/test_log_viewer.py +++ b/webhook_server/tests/test_log_viewer.py @@ -445,29 +445,29 @@ async def test_get_workflow_steps_json_searches_multiple_files( # Should find it assert result["hook_id"] == "target-hook" - async def test_get_workflow_steps_json_handles_missing_optional_fields(self, controller, tmp_path): - """Test get_workflow_steps_json handles missing optional fields gracefully.""" + async def test_get_workflow_steps_json_fails_fast_on_missing_required_fields(self, controller, tmp_path): + """Test get_workflow_steps_json raises HTTPException when required fields are missing. + + Required fields (timing, workflow_steps) must be present and valid. + Missing required fields indicate malformed log data and should fail fast. + """ log_dir = tmp_path / "logs" log_dir.mkdir() - # Create minimal JSON log entry + # Create minimal JSON log entry missing required timing/workflow_steps minimal_data = { "hook_id": "minimal-hook", - # Missing: event_type, action, sender, pr, workflow_steps, token_spend, timing + # Missing: timing, workflow_steps (required fields) } self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [minimal_data]) - # Get workflow steps - result = await controller.get_workflow_steps_json("minimal-hook") - - # Should handle missing fields with defaults in frontend-expected format - assert result["hook_id"] == "minimal-hook" - assert result["start_time"] is None # No timing info - assert result["total_duration_ms"] == 0 # Default to 0 - assert result["step_count"] == 0 # No workflow_steps - assert result["steps"] == [] # Empty array (not dict) - assert result["token_spend"] is None + # Should raise HTTPException 404 with clear error about missing timing field + with pytest.raises(HTTPException) as exc_info: + await controller.get_workflow_steps_json("minimal-hook") + + assert exc_info.value.status_code == 404 + assert "missing or invalid 'timing' field" in exc_info.value.detail async def test_stream_json_log_entries_handles_file_read_errors( self, controller, tmp_path, sample_json_webhook_data diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index db8a6679..9e267b57 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -561,6 +561,13 @@ async def get_workflow_steps_json(self, hook_id: str) -> dict[str, Any]: - step_count: Number of workflow steps - steps: Array of step objects with timestamp, message, level, etc. - token_spend: Optional token consumption count + - event_type: GitHub event type (str, e.g., "pull_request", "check_run") + - action: Event action (str, e.g., "opened", "synchronize") + - repository: Repository name (str, owner/repo format) + - sender: GitHub username who triggered the event (str) + - pr: Pull request info dict with number, title, etc. (dict or None) + - success: Whether processing succeeded (bool) + - error: Error message if processing failed (str or None) Raises: HTTPException: 404 if hook ID not found @@ -603,16 +610,27 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) - success: Boolean indicating if processing succeeded - error: Error message if processing failed (or None) """ - timing = entry.get("timing") or {} - workflow_steps = entry.get("workflow_steps") or {} + timing = entry.get("timing") + workflow_steps = entry.get("workflow_steps") + + # Fail-fast validation: required fields must be present and non-empty + if not timing or not isinstance(timing, dict): + raise ValueError(f"Malformed log entry for hook_id {hook_id}: missing or invalid 'timing' field") + if not workflow_steps or not isinstance(workflow_steps, dict): + raise ValueError(f"Malformed log entry for hook_id {hook_id}: missing or invalid 'workflow_steps' field") + if "started_at" not in timing: + raise ValueError(f"Malformed log entry for hook_id {hook_id}: timing missing 'started_at' field") + if "duration_ms" not in timing: + raise ValueError(f"Malformed log entry for hook_id {hook_id}: timing missing 'duration_ms' field") + repository = entry.get("repository") event_type = entry.get("event_type") pr_info = entry.get("pr") or {} pr_number = pr_info.get("number") if pr_info else None # Extract timing info - start_time = timing.get("started_at") - total_duration_ms = timing.get("duration_ms") or 0 + start_time = timing["started_at"] + total_duration_ms = timing["duration_ms"] or 0 # Transform workflow_steps dict to array format # Sort by timestamp to maintain execution order @@ -647,8 +665,8 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) "repository": repository, "event_type": event_type, "pr_number": pr_number, - "task_id": None, - "task_type": None, + "task_id": step_data.get("task_id"), + "task_type": step_data.get("task_type"), "task_status": step_status, "duration_ms": step_duration_ms, "error": step_error, diff --git a/webhook_server/web/static/js/log_viewer.js b/webhook_server/web/static/js/log_viewer.js index 16cd91c1..ff807ac3 100644 --- a/webhook_server/web/static/js/log_viewer.js +++ b/webhook_server/web/static/js/log_viewer.js @@ -853,8 +853,9 @@ function showFlowModal(hookId) { } if (status === 404) { - console.log("No flow data found for hook ID:", hookId); - showFlowModalError("No workflow data found for this hook"); + const message = errorDetail || "No workflow data found for this hook"; + console.log("No flow data found for hook ID:", hookId, message); + showFlowModalError(message); return; } else if (status === 400) { const message = errorDetail || "Invalid request"; From 7bfa2a5d4bd36d2fa6290e6d51d2d7e44ae9b2d6 Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 17:41:09 +0200 Subject: [PATCH 04/15] fix(log-viewer): address CodeRabbit review comments Fixes two issues identified in code review: - Remove 'or 0' fallback that masked valid zero-duration webhooks - Remove redundant truthiness check on pr_info by using entry.get("pr") directly --- webhook_server/web/log_viewer.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 9e267b57..559ffd37 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -625,12 +625,12 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) repository = entry.get("repository") event_type = entry.get("event_type") - pr_info = entry.get("pr") or {} + pr_info = entry.get("pr") pr_number = pr_info.get("number") if pr_info else None # Extract timing info start_time = timing["started_at"] - total_duration_ms = timing["duration_ms"] or 0 + total_duration_ms = timing["duration_ms"] # Transform workflow_steps dict to array format # Sort by timestamp to maintain execution order @@ -697,7 +697,7 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) "action": entry.get("action"), "repository": repository, "sender": entry.get("sender"), - "pr": pr_info if pr_info else None, + "pr": entry.get("pr"), "success": entry.get("success"), "error": entry.get("error"), } From 606b4a4a033bb58336b6e9e2ad45cc6560149632 Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 18:44:16 +0200 Subject: [PATCH 05/15] fix(log-viewer): add debug logging for timestamp parse failures Replace silent pass with debug logging in _transform_json_entry_to_timeline when timestamp parsing fails for relative time calculation. Logs the exception, hook_id, step name, and timestamp value to aid troubleshooting. Addresses CodeRabbit review comment about silent exception handling. --- webhook_server/web/log_viewer.py | 147 ++++++++++++++++++++++--------- 1 file changed, 106 insertions(+), 41 deletions(-) diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 559ffd37..1e898b39 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -40,6 +40,7 @@ def __init__(self, logger: logging.Logger) -> None: Args: logger: Logger instance for this controller + """ self.logger = logger self.config = Config(logger=self.logger) @@ -54,7 +55,7 @@ async def shutdown(self) -> None: close all WebSocket connections and prevent resource leaks. """ self.logger.info( - f"Shutting down LogViewerController with {len(self._websocket_connections)} active connections" + f"Shutting down LogViewerController with {len(self._websocket_connections)} active connections", ) # Create a copy of the connections set to avoid modification during iteration @@ -66,7 +67,7 @@ async def shutdown(self) -> None: self.logger.debug("Successfully closed WebSocket connection during shutdown") except Exception as e: # Log the error but continue closing other connections - self.logger.warning(f"Error closing WebSocket connection during shutdown: {e}") + self.logger.warning("Error closing WebSocket connection during shutdown: %s", e) # Clear the connections set self._websocket_connections.clear() @@ -80,6 +81,7 @@ async def get_log_page(self) -> HTMLResponse: Raises: HTTPException: 500 for other errors + """ try: html_content = await self._get_log_viewer_html() @@ -143,6 +145,7 @@ async def get_log_entries( Raises: HTTPException: 400 for invalid parameters, 500 for file access errors + """ try: # Validate parameters @@ -176,7 +179,16 @@ async def get_log_entries( # Apply filters early to reduce memory usage if not self._entry_matches_filters( - entry, hook_id, pr_number, repository, event_type, github_user, level, start_time, end_time, search + entry, + hook_id, + pr_number, + repository, + event_type, + github_user, + level, + start_time, + end_time, + search, ): continue @@ -214,7 +226,7 @@ async def get_log_entries( self.logger.debug("Operation cancelled") raise # Always re-raise CancelledError except ValueError as e: - self.logger.warning(f"Invalid parameters for log entries request: {e}") + self.logger.warning("Invalid parameters for log entries request: %s", e) raise HTTPException(status_code=400, detail=str(e)) from e except (OSError, PermissionError) as e: self.logger.exception("File access error loading log entries") @@ -246,6 +258,7 @@ def _entry_matches_filters( Returns: True if entry matches all filters, False otherwise + """ if hook_id is not None and entry.hook_id != hook_id: return False @@ -302,6 +315,7 @@ async def export_logs( Raises: HTTPException: 400 for invalid format, 413 if result set too large + """ try: if format_type != "json": @@ -330,7 +344,16 @@ async def export_logs( async for entry in self._stream_log_entries(max_files=25, max_entries=max_entries_to_process): if not self._entry_matches_filters( - entry, hook_id, pr_number, repository, event_type, github_user, level, start_time, end_time, search + entry, + hook_id, + pr_number, + repository, + event_type, + github_user, + level, + start_time, + end_time, + search, ): continue @@ -375,13 +398,12 @@ def generate() -> Generator[bytes]: raise # Always re-raise CancelledError except ValueError as e: if "Result set too large" in str(e): - self.logger.warning(f"Export request too large: {e}") + self.logger.warning("Export request too large: %s", e) raise HTTPException(status_code=413, detail=str(e)) from e - else: - self.logger.warning(f"Invalid export parameters: {e}") - raise HTTPException(status_code=400, detail=str(e)) from e + self.logger.warning("Invalid export parameters: %s", e) + raise HTTPException(status_code=400, detail=str(e)) from e except Exception as e: - self.logger.error(f"Error generating export: {e}") + self.logger.error("Error generating export: %s", e) raise HTTPException(status_code=500, detail="Export generation failed") from e async def handle_websocket( @@ -404,6 +426,7 @@ async def handle_websocket( event_type: Filter by GitHub event type github_user: Filter by GitHub user (api_user) level: Filter by log level + """ await websocket.accept() self._websocket_connections.add(websocket) @@ -446,7 +469,7 @@ async def handle_websocket( except WebSocketDisconnect: self.logger.info("WebSocket client disconnected") except Exception as e: - self.logger.error(f"Error in WebSocket handler: {e}") + self.logger.error("Error in WebSocket handler: %s", e) try: await websocket.close(code=1011, reason="Internal server error") except Exception: @@ -465,6 +488,7 @@ async def get_pr_flow_data(self, hook_id: str) -> dict[str, Any]: Raises: HTTPException: 404 if no data found for hook_id + """ try: # Parse hook_id to determine if it's a hook ID or PR number @@ -504,13 +528,12 @@ async def get_pr_flow_data(self, hook_id: str) -> dict[str, Any]: raise # Always re-raise CancelledError except ValueError as e: if "No data found" in str(e): - self.logger.warning(f"PR flow data not found: {e}") + self.logger.warning("PR flow data not found: %s", e) raise HTTPException(status_code=404, detail=str(e)) from e - else: - self.logger.warning(f"Invalid PR flow hook_id: {e}") - raise HTTPException(status_code=400, detail=str(e)) from e + self.logger.warning("Invalid PR flow hook_id: %s", e) + raise HTTPException(status_code=400, detail=str(e)) from e except Exception as e: - self.logger.error(f"Error getting PR flow data: {e}") + self.logger.error("Error getting PR flow data: %s", e) raise HTTPException(status_code=500, detail="Internal server error") from e def _build_log_prefix_from_context( @@ -532,6 +555,7 @@ def _build_log_prefix_from_context( Returns: Formatted log prefix string + """ log_prefix_parts = [] if repository: @@ -571,6 +595,7 @@ async def get_workflow_steps_json(self, hook_id: str) -> dict[str, Any]: Raises: HTTPException: 404 if hook ID not found + """ try: # Search JSON logs for this hook_id @@ -609,6 +634,7 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) - pr: Pull request info dict with number, title, etc. (or None) - success: Boolean indicating if processing succeeded - error: Error message if processing failed (or None) + """ timing = entry.get("timing") workflow_steps = entry.get("workflow_steps") @@ -683,8 +709,19 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) if step_ts: step_time = datetime.datetime.fromisoformat(step_ts.replace("Z", "+00:00")) step["relative_time_ms"] = int((step_time - base_time).total_seconds() * 1000) - except (ValueError, TypeError): - pass # Keep relative_time_ms as 0 if parsing fails + except (ValueError, TypeError) as ex: + # Log parse failure for troubleshooting, keep relative_time_ms as 0 + local_vars = locals() + failed_step = local_vars.get("step", {}) + failed_step_name = failed_step.get("message", "unknown") if failed_step else "unknown" + failed_timestamp = local_vars.get("step_ts") or start_time + self.logger.debug( + "Failed to parse timestamp for relative time calculation: %s. hook_id=%s, step=%s, timestamp=%s", + ex, + hook_id, + failed_step_name, + failed_timestamp, + ) return { "hook_id": hook_id, @@ -713,6 +750,7 @@ async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: Raises: HTTPException: 404 if no steps found for hook ID + """ try: # First try JSON logs (more efficient and complete) @@ -759,11 +797,15 @@ async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: token_spend = entries_with_token_spend[-1].token_spend # Format log message using prepare_log_prefix format so it's parseable and clickable log_prefix = self._build_log_prefix_from_context( - repository, event_type, hook_id, github_user, pr_number + repository, + event_type, + hook_id, + github_user, + pr_number, ) self.logger.info( f"{log_prefix}Found token spend {token_spend} for hook {hook_id} " - f"from {len(entries_with_token_spend)} entries" + f"from {len(entries_with_token_spend)} entries", ) else: # Check if any entries contain "token" or "API calls" in message (for debugging) @@ -773,12 +815,16 @@ async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: if entries_with_token_keywords: # Format log message using prepare_log_prefix format log_prefix = self._build_log_prefix_from_context( - repository, event_type, hook_id, github_user, pr_number + repository, + event_type, + hook_id, + github_user, + pr_number, ) self.logger.warning( f"{log_prefix}Found {len(entries_with_token_keywords)} entries with token keywords " f"for hook {hook_id}, but token_spend is None. " - f"Sample: {entries_with_token_keywords[0].message[:150]}" + f"Sample: {entries_with_token_keywords[0].message[:150]}", ) # Try to extract token spend directly from the message as fallback for entry in reversed(entries_with_token_keywords): @@ -787,11 +833,17 @@ async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: token_spend = extracted # Format log message using prepare_log_prefix format log_prefix = self._build_log_prefix_from_context( - repository, event_type, hook_id, github_user, pr_number + repository, + event_type, + hook_id, + github_user, + pr_number, ) self.logger.info( - f"{log_prefix}Extracted token spend {token_spend} directly from message " - f"for hook {hook_id}" + "%sExtracted token spend %s directly from message for hook %s", + log_prefix, + token_spend, + hook_id, ) break @@ -806,13 +858,12 @@ async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: raise # Always re-raise CancelledError except ValueError as e: if "No data found" in str(e) or "No workflow steps found" in str(e): - self.logger.warning(f"Workflow steps not found: {e}") + self.logger.warning("Workflow steps not found: %s", e) raise HTTPException(status_code=404, detail=str(e)) from e - else: - self.logger.warning(f"Invalid hook ID: {e}") - raise HTTPException(status_code=400, detail=str(e)) from e + self.logger.warning("Invalid hook ID: %s", e) + raise HTTPException(status_code=400, detail=str(e)) from e except Exception as e: - self.logger.error(f"Error getting workflow steps: {e}") + self.logger.error("Error getting workflow steps: %s", e) raise HTTPException(status_code=500, detail="Internal server error") from e def _build_workflow_timeline(self, workflow_steps: list[LogEntry], hook_id: str) -> dict[str, Any]: @@ -824,6 +875,7 @@ def _build_workflow_timeline(self, workflow_steps: list[LogEntry], hook_id: str) Returns: Dictionary with timeline data structure including task correlation fields + """ # Sort steps by timestamp sorted_steps = sorted(workflow_steps, key=lambda x: x.timestamp) @@ -865,7 +917,10 @@ def _build_workflow_timeline(self, workflow_steps: list[LogEntry], hook_id: str) } async def _stream_log_entries( - self, max_files: int = 10, _chunk_size: int = 1000, max_entries: int = 50000 + self, + max_files: int = 10, + _chunk_size: int = 1000, + max_entries: int = 50000, ) -> AsyncGenerator[LogEntry]: """Stream log entries from configured log files in chunks to reduce memory usage. @@ -881,11 +936,12 @@ async def _stream_log_entries( Yields: LogEntry objects in timestamp order (newest first) + """ log_dir = self._get_log_directory() if not log_dir.exists(): - self.logger.warning(f"Log directory not found: {log_dir}") + self.logger.warning("Log directory not found: %s", log_dir) return # Find all log files including rotated ones and JSON files @@ -949,10 +1005,12 @@ def sort_key(f: Path) -> tuple[int, float]: self.logger.debug("Operation cancelled") raise # Always re-raise CancelledError except Exception as e: - self.logger.warning(f"Error streaming log file {log_file}: {e}") + self.logger.warning("Error streaming log file %s: %s", log_file, e) async def _stream_json_log_entries( - self, max_files: int = 10, max_entries: int = 50000 + self, + max_files: int = 10, + max_entries: int = 50000, ) -> AsyncGenerator[dict[str, Any]]: """Stream raw JSON log entries from webhooks_*.json files. @@ -965,6 +1023,7 @@ async def _stream_json_log_entries( Yields: Raw JSON dictionaries from log files (newest first) + """ log_dir = self._get_log_directory() @@ -1006,7 +1065,7 @@ async def _stream_json_log_entries( self.logger.debug("Operation cancelled") raise # Always re-raise CancelledError except Exception as e: - self.logger.warning(f"Error streaming JSON log file {log_file}: {e}") + self.logger.warning("Error streaming JSON log file %s: %s", log_file, e) async def _load_log_entries(self) -> list[LogEntry]: """Load log entries using streaming approach for memory efficiency. @@ -1016,6 +1075,7 @@ async def _load_log_entries(self) -> list[LogEntry]: Returns: List of parsed log entries (limited to prevent memory exhaustion) + """ # Use streaming with reasonable limits to prevent memory issues entries = [entry async for entry in self._stream_log_entries(max_files=10, max_entries=10000)] @@ -1027,6 +1087,7 @@ def _get_log_directory(self) -> Path: Returns: Path to log directory + """ # Use the same log directory as the main application log_dir_path = os.path.join(self.config.data_dir, "logs") @@ -1041,6 +1102,7 @@ async def _get_log_viewer_html(self) -> str: Raises: FileNotFoundError: If template file cannot be found IOError: If template file cannot be read + """ template_path = Path(__file__).parent / "templates" / "log_viewer.html" @@ -1048,7 +1110,7 @@ async def _get_log_viewer_html(self) -> str: async with aiofiles.open(template_path, encoding="utf-8") as f: return await f.read() except FileNotFoundError: - self.logger.exception(f"Log viewer template not found at {template_path}") + self.logger.exception("Log viewer template not found at %s", template_path) return self._get_fallback_html() except OSError: self.logger.exception("Failed to read log viewer template") @@ -1059,6 +1121,7 @@ def _get_fallback_html(self) -> str: Returns: Basic HTML page with error message + """ return """ @@ -1114,6 +1177,7 @@ def _generate_json_export(self, entries: list[LogEntry], filters: dict[str, Any] Returns: JSON content as string + """ export_data = { "export_metadata": { @@ -1135,6 +1199,7 @@ def _analyze_pr_flow(self, entries: list[LogEntry], hook_id: str) -> dict[str, A Returns: Dictionary with flow stages and timing data + """ # Sort entries by timestamp sorted_entries = sorted(entries, key=lambda x: x.timestamp) @@ -1204,6 +1269,7 @@ def _estimate_total_log_count(self) -> str: Returns: String representing estimated total log count + """ try: log_dir = self._get_log_directory() @@ -1228,7 +1294,7 @@ def _estimate_total_log_count(self) -> str: estimated_lines = file_size // 200 total_estimate += estimated_lines except (OSError, PermissionError) as ex: - self.logger.debug(f"Failed to stat log file {log_file}: {ex}") + self.logger.debug("Failed to stat log file %s: %s", log_file, ex) continue # If we processed fewer than all files, extrapolate @@ -1239,11 +1305,10 @@ def _estimate_total_log_count(self) -> str: # Return formatted string if total_estimate > 1000000: return f"{total_estimate // 1000000:.1f}M" - elif total_estimate > 1000: + if total_estimate > 1000: return f"{total_estimate // 1000:.1f}K" - else: - return str(total_estimate) + return str(total_estimate) except Exception as e: - self.logger.warning(f"Error estimating total log count: {e}") + self.logger.warning("Error estimating total log count: %s", e) return "Unknown" From 2016994c113f7fa127c83113b549b37e7153ca50 Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 20:09:26 +0200 Subject: [PATCH 06/15] fix(log-viewer): address CodeRabbit review comments - Replace percent-style logging with f-strings for consistency - Use logger.exception instead of logger.error to preserve tracebacks - Return 500 for malformed log entries vs 404 for not-found - Use float division for log count formatting (e.g., 1.5K vs 1K) --- webhook_server/tests/test_log_viewer.py | 9 ++-- webhook_server/web/log_viewer.py | 58 +++++++++++++------------ 2 files changed, 35 insertions(+), 32 deletions(-) diff --git a/webhook_server/tests/test_log_viewer.py b/webhook_server/tests/test_log_viewer.py index d45ba054..0d0c6566 100644 --- a/webhook_server/tests/test_log_viewer.py +++ b/webhook_server/tests/test_log_viewer.py @@ -449,7 +449,7 @@ async def test_get_workflow_steps_json_fails_fast_on_missing_required_fields(sel """Test get_workflow_steps_json raises HTTPException when required fields are missing. Required fields (timing, workflow_steps) must be present and valid. - Missing required fields indicate malformed log data and should fail fast. + Missing required fields indicate malformed log data and should return 500. """ log_dir = tmp_path / "logs" log_dir.mkdir() @@ -462,12 +462,13 @@ async def test_get_workflow_steps_json_fails_fast_on_missing_required_fields(sel self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [minimal_data]) - # Should raise HTTPException 404 with clear error about missing timing field + # Should raise HTTPException 500 for malformed log entry + # (distinguishing from 404 "not found" case) with pytest.raises(HTTPException) as exc_info: await controller.get_workflow_steps_json("minimal-hook") - assert exc_info.value.status_code == 404 - assert "missing or invalid 'timing' field" in exc_info.value.detail + assert exc_info.value.status_code == 500 + assert exc_info.value.detail == "Malformed log entry" async def test_stream_json_log_entries_handles_file_read_errors( self, controller, tmp_path, sample_json_webhook_data diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 1e898b39..444a5ea5 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -67,7 +67,7 @@ async def shutdown(self) -> None: self.logger.debug("Successfully closed WebSocket connection during shutdown") except Exception as e: # Log the error but continue closing other connections - self.logger.warning("Error closing WebSocket connection during shutdown: %s", e) + self.logger.warning(f"Error closing WebSocket connection during shutdown: {e}") # Clear the connections set self._websocket_connections.clear() @@ -226,7 +226,7 @@ async def get_log_entries( self.logger.debug("Operation cancelled") raise # Always re-raise CancelledError except ValueError as e: - self.logger.warning("Invalid parameters for log entries request: %s", e) + self.logger.warning(f"Invalid parameters for log entries request: {e}") raise HTTPException(status_code=400, detail=str(e)) from e except (OSError, PermissionError) as e: self.logger.exception("File access error loading log entries") @@ -398,12 +398,12 @@ def generate() -> Generator[bytes]: raise # Always re-raise CancelledError except ValueError as e: if "Result set too large" in str(e): - self.logger.warning("Export request too large: %s", e) + self.logger.warning(f"Export request too large: {e}") raise HTTPException(status_code=413, detail=str(e)) from e - self.logger.warning("Invalid export parameters: %s", e) + self.logger.warning(f"Invalid export parameters: {e}") raise HTTPException(status_code=400, detail=str(e)) from e except Exception as e: - self.logger.error("Error generating export: %s", e) + self.logger.exception("Error generating export") raise HTTPException(status_code=500, detail="Export generation failed") from e async def handle_websocket( @@ -468,8 +468,8 @@ async def handle_websocket( except WebSocketDisconnect: self.logger.info("WebSocket client disconnected") - except Exception as e: - self.logger.error("Error in WebSocket handler: %s", e) + except Exception: + self.logger.exception("Error in WebSocket handler") try: await websocket.close(code=1011, reason="Internal server error") except Exception: @@ -528,12 +528,12 @@ async def get_pr_flow_data(self, hook_id: str) -> dict[str, Any]: raise # Always re-raise CancelledError except ValueError as e: if "No data found" in str(e): - self.logger.warning("PR flow data not found: %s", e) + self.logger.warning(f"PR flow data not found: {e}") raise HTTPException(status_code=404, detail=str(e)) from e - self.logger.warning("Invalid PR flow hook_id: %s", e) + self.logger.warning(f"Invalid PR flow hook_id: {e}") raise HTTPException(status_code=400, detail=str(e)) from e except Exception as e: - self.logger.error("Error getting PR flow data: %s", e) + self.logger.exception("Error getting PR flow data") raise HTTPException(status_code=500, detail="Internal server error") from e def _build_log_prefix_from_context( @@ -597,17 +597,19 @@ async def get_workflow_steps_json(self, hook_id: str) -> dict[str, Any]: HTTPException: 404 if hook ID not found """ - try: - # Search JSON logs for this hook_id - async for entry in self._stream_json_log_entries(max_files=25, max_entries=50000): - if entry.get("hook_id") == hook_id: - # Found the entry - transform to frontend-expected format + # Search JSON logs for this hook_id + async for entry in self._stream_json_log_entries(max_files=25, max_entries=50000): + if entry.get("hook_id") == hook_id: + # Found the entry - transform to frontend-expected format + try: return self._transform_json_entry_to_timeline(entry, hook_id) + except ValueError: + # Malformed log entry - log and return 500 + self.logger.exception(f"Malformed log entry for hook ID: {hook_id}") + raise HTTPException(status_code=500, detail="Malformed log entry") from None - raise ValueError(f"No JSON log entry found for hook ID: {hook_id}") - - except ValueError as e: - raise HTTPException(status_code=404, detail=str(e)) from e + # Hook ID not found in any log file + raise HTTPException(status_code=404, detail=f"No JSON log entry found for hook ID: {hook_id}") def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) -> dict[str, Any]: """Transform JSON log entry to the timeline format expected by the frontend. @@ -858,12 +860,12 @@ async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: raise # Always re-raise CancelledError except ValueError as e: if "No data found" in str(e) or "No workflow steps found" in str(e): - self.logger.warning("Workflow steps not found: %s", e) + self.logger.warning(f"Workflow steps not found: {e}") raise HTTPException(status_code=404, detail=str(e)) from e - self.logger.warning("Invalid hook ID: %s", e) + self.logger.warning(f"Invalid hook ID: {e}") raise HTTPException(status_code=400, detail=str(e)) from e except Exception as e: - self.logger.error("Error getting workflow steps: %s", e) + self.logger.exception("Error getting workflow steps") raise HTTPException(status_code=500, detail="Internal server error") from e def _build_workflow_timeline(self, workflow_steps: list[LogEntry], hook_id: str) -> dict[str, Any]: @@ -941,7 +943,7 @@ async def _stream_log_entries( log_dir = self._get_log_directory() if not log_dir.exists(): - self.logger.warning("Log directory not found: %s", log_dir) + self.logger.warning(f"Log directory not found: {log_dir}") return # Find all log files including rotated ones and JSON files @@ -1005,7 +1007,7 @@ def sort_key(f: Path) -> tuple[int, float]: self.logger.debug("Operation cancelled") raise # Always re-raise CancelledError except Exception as e: - self.logger.warning("Error streaming log file %s: %s", log_file, e) + self.logger.warning(f"Error streaming log file {log_file}: {e}") async def _stream_json_log_entries( self, @@ -1065,7 +1067,7 @@ async def _stream_json_log_entries( self.logger.debug("Operation cancelled") raise # Always re-raise CancelledError except Exception as e: - self.logger.warning("Error streaming JSON log file %s: %s", log_file, e) + self.logger.warning(f"Error streaming JSON log file {log_file}: {e}") async def _load_log_entries(self) -> list[LogEntry]: """Load log entries using streaming approach for memory efficiency. @@ -1304,11 +1306,11 @@ def _estimate_total_log_count(self) -> str: # Return formatted string if total_estimate > 1000000: - return f"{total_estimate // 1000000:.1f}M" + return f"{total_estimate / 1000000:.1f}M" if total_estimate > 1000: - return f"{total_estimate // 1000:.1f}K" + return f"{total_estimate / 1000:.1f}K" return str(total_estimate) except Exception as e: - self.logger.warning("Error estimating total log count: %s", e) + self.logger.warning(f"Error estimating total log count: {e}") return "Unknown" From d0f50bed68bc8852bf5b21509050ef30750ff70e Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 22:26:25 +0200 Subject: [PATCH 07/15] fix(log-viewer): address CodeRabbit review comments - Replace locals() pattern with explicit current_step and current_step_ts variables - Use f-string formatting instead of %s placeholders in logging calls --- webhook_server/web/log_viewer.py | 29 +++++++++++++---------------- 1 file changed, 13 insertions(+), 16 deletions(-) diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 444a5ea5..b8648aea 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -704,25 +704,24 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) # Sort steps by timestamp and calculate relative times steps_list.sort(key=lambda x: x.get("timestamp") or "") if steps_list and start_time: + # Track current step for error reporting + current_step: dict[str, Any] | None = None + current_step_ts: str | None = None try: base_time = datetime.datetime.fromisoformat(start_time.replace("Z", "+00:00")) for step in steps_list: - step_ts = step.get("timestamp") - if step_ts: - step_time = datetime.datetime.fromisoformat(step_ts.replace("Z", "+00:00")) + current_step = step + current_step_ts = step.get("timestamp") + if current_step_ts: + step_time = datetime.datetime.fromisoformat(current_step_ts.replace("Z", "+00:00")) step["relative_time_ms"] = int((step_time - base_time).total_seconds() * 1000) except (ValueError, TypeError) as ex: # Log parse failure for troubleshooting, keep relative_time_ms as 0 - local_vars = locals() - failed_step = local_vars.get("step", {}) - failed_step_name = failed_step.get("message", "unknown") if failed_step else "unknown" - failed_timestamp = local_vars.get("step_ts") or start_time + failed_step_name = current_step.get("message", "unknown") if current_step else "unknown" + failed_timestamp = current_step_ts or start_time self.logger.debug( - "Failed to parse timestamp for relative time calculation: %s. hook_id=%s, step=%s, timestamp=%s", - ex, - hook_id, - failed_step_name, - failed_timestamp, + f"Failed to parse timestamp for relative time calculation: {ex}. " + f"hook_id={hook_id}, step={failed_step_name}, timestamp={failed_timestamp}", ) return { @@ -842,10 +841,8 @@ async def get_workflow_steps(self, hook_id: str) -> dict[str, Any]: pr_number, ) self.logger.info( - "%sExtracted token spend %s directly from message for hook %s", - log_prefix, - token_spend, - hook_id, + f"{log_prefix}Extracted token spend {token_spend} directly from message " + f"for hook {hook_id}", ) break From 6ffad81d98f329ad4b50e2feb74ef5f0620b3371 Mon Sep 17 00:00:00 2001 From: rnetser Date: Mon, 19 Jan 2026 23:59:08 +0200 Subject: [PATCH 08/15] fix(log-viewer): address CodeRabbit review comments Add type validation for step_data and convert logger formatting to f-strings: - Validate step_data is a dict before calling .get() methods - Use f-strings for logging at template loading and file stat errors --- webhook_server/web/log_viewer.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index b8648aea..8b3fea40 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -664,6 +664,10 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) # Sort by timestamp to maintain execution order steps_list = [] for step_name, step_data in workflow_steps.items(): + # Validate step_data is a dict before accessing its fields + if not isinstance(step_data, dict): + raise ValueError(f"malformed log: step_data for {step_name} is not a dict") + step_timestamp = step_data.get("timestamp") step_status = step_data.get("status", "unknown") step_duration_ms = step_data.get("duration_ms") @@ -1109,7 +1113,7 @@ async def _get_log_viewer_html(self) -> str: async with aiofiles.open(template_path, encoding="utf-8") as f: return await f.read() except FileNotFoundError: - self.logger.exception("Log viewer template not found at %s", template_path) + self.logger.exception(f"Log viewer template not found at {template_path}") return self._get_fallback_html() except OSError: self.logger.exception("Failed to read log viewer template") @@ -1293,7 +1297,7 @@ def _estimate_total_log_count(self) -> str: estimated_lines = file_size // 200 total_estimate += estimated_lines except (OSError, PermissionError) as ex: - self.logger.debug("Failed to stat log file %s: %s", log_file, ex) + self.logger.debug(f"Failed to stat log file {log_file}: {ex}") continue # If we processed fewer than all files, extrapolate From d6d20413516e9ff98b16a6f054753e820bb42b4c Mon Sep 17 00:00:00 2001 From: rnetser Date: Tue, 20 Jan 2026 00:33:40 +0200 Subject: [PATCH 09/15] fix(log-viewer): add type validation for pr_info and fix error message format Address CodeRabbit review comments: - Add isinstance check for pr_info to validate it's a dict before calling .get() - Standardize error message format to 'Malformed log entry for hook_id {hook_id}: ...' --- webhook_server/web/log_viewer.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 8b3fea40..7811420e 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -654,6 +654,9 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) repository = entry.get("repository") event_type = entry.get("event_type") pr_info = entry.get("pr") + # Validate pr_info type: None is valid (no PR), dict is valid, anything else is malformed + if pr_info is not None and not isinstance(pr_info, dict): + raise ValueError(f"Malformed log entry for hook_id {hook_id}: 'pr' field is not a dict") pr_number = pr_info.get("number") if pr_info else None # Extract timing info @@ -666,7 +669,7 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) for step_name, step_data in workflow_steps.items(): # Validate step_data is a dict before accessing its fields if not isinstance(step_data, dict): - raise ValueError(f"malformed log: step_data for {step_name} is not a dict") + raise ValueError(f"Malformed log entry for hook_id {hook_id}: step_data for {step_name} is not a dict") step_timestamp = step_data.get("timestamp") step_status = step_data.get("status", "unknown") From b67f830e43f4c66622ded054fe03b234981c1a9a Mon Sep 17 00:00:00 2001 From: rnetser Date: Tue, 20 Jan 2026 19:18:27 +0200 Subject: [PATCH 10/15] fix(log-viewer): use step_name for log search instead of full message The step logs modal was showing 'No logs found for this step' because it searched using the synthesized full message (e.g., 'webhook_routing: completed (2286ms)') which doesn't match actual log entries. Now uses step.step_name (e.g., 'webhook_routing') which correctly matches the log content. --- webhook_server/web/static/js/log_viewer.js | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/webhook_server/web/static/js/log_viewer.js b/webhook_server/web/static/js/log_viewer.js index ff807ac3..c5ed3541 100644 --- a/webhook_server/web/static/js/log_viewer.js +++ b/webhook_server/web/static/js/log_viewer.js @@ -1747,8 +1747,9 @@ async function showStepLogsInModal(step, logsContainer) { currentStepLogsController = new AbortController(); try { - // Using full message for precision to avoid ambiguous matches - const searchText = step.message; + // Use step_name for search (e.g., "webhook_routing") instead of the full message + // (e.g., "webhook_routing: completed (2286ms)") which won't match log entries + const searchText = step.step_name || step.message; const hookId = currentFlowData.hook_id; const params = new URLSearchParams({ From ed6c3c669f82c5fde34bd8b82ecaefd2301df780 Mon Sep 17 00:00:00 2001 From: rnetser Date: Tue, 20 Jan 2026 19:43:48 +0200 Subject: [PATCH 11/15] feat(log-viewer): add time-based log retrieval for workflow steps When clicking on a step in the Workflow Flow Timeline modal, the UI now fetches and displays actual log entries that occurred during that step's execution window using time-based correlation. - Add get_step_logs method to retrieve logs within step's time window - Add /logs/api/step-logs/{hook_id}/{step_name} endpoint - Update frontend to fetch and render step logs with loading state - Add CSS styles for step logs display - Add input validation and max results limit (500 entries) --- webhook_server/app.py | 33 ++ webhook_server/tests/test_log_viewer.py | 295 ++++++++++++++++++ webhook_server/web/log_viewer.py | 93 ++++++ webhook_server/web/static/css/log_viewer.css | 299 +++++++++++++++++++ webhook_server/web/static/js/log_viewer.js | 257 ++++++++++++---- 5 files changed, 927 insertions(+), 50 deletions(-) diff --git a/webhook_server/app.py b/webhook_server/app.py index 4ea6a777..b63bef4c 100644 --- a/webhook_server/app.py +++ b/webhook_server/app.py @@ -17,6 +17,7 @@ Depends, FastAPI, HTTPException, + Path, Query, Request, Response, @@ -1144,6 +1145,38 @@ async def get_workflow_steps(hook_id: str, controller: LogViewerController = con return await get_workflow_steps_core(controller=controller, hook_id=hook_id) +@FASTAPI_APP.get( + "/logs/api/step-logs/{hook_id}/{step_name}", + operation_id="get_step_logs", + dependencies=[Depends(require_log_server_enabled)], +) +async def get_step_logs( + hook_id: str = Path(..., min_length=1, max_length=100), + step_name: str = Path(..., min_length=1, max_length=100), + controller: LogViewerController = controller_dependency, +) -> dict[str, Any]: + """Retrieve log entries that occurred during a specific workflow step's execution. + + This endpoint provides time-based correlation of log entries with workflow steps, + allowing detailed analysis of what happened during each step's execution window. + + Parameters: + - hook_id: GitHub webhook delivery ID + - step_name: Name of the workflow step (e.g., "clone_repository", "webhook_routing") + + Returns: + - step: Metadata about the step (name, status, timestamp, duration_ms, error) + - logs: Array of log entries that occurred during the step's execution + - log_count: Number of log entries found + + Error Conditions: + - 404: Hook ID not found in logs + - 404: Step name not found in workflow steps for the given hook ID + - 500: Internal server error + """ + return await controller.get_step_logs(hook_id=hook_id, step_name=step_name) + + @FASTAPI_APP.websocket("/logs/ws") async def websocket_log_stream( websocket: WebSocket, diff --git a/webhook_server/tests/test_log_viewer.py b/webhook_server/tests/test_log_viewer.py index 0d0c6566..32f072b8 100644 --- a/webhook_server/tests/test_log_viewer.py +++ b/webhook_server/tests/test_log_viewer.py @@ -1247,3 +1247,298 @@ def test_generate_json_export(self, controller): assert "log_entries" in data assert data["export_metadata"]["total_entries"] == 1 assert data["export_metadata"]["filters_applied"] == filters + + +class TestLogViewerGetStepLogs: + """Test cases for get_step_logs method.""" + + @pytest.fixture + def mock_logger(self): + """Create a mock logger for testing.""" + return Mock() + + @pytest.fixture + def controller(self, mock_logger, tmp_path): + """Create a LogViewerController instance with mocked config.""" + with patch("webhook_server.web.log_viewer.Config") as mock_config: + mock_config_instance = Mock() + mock_config_instance.data_dir = str(tmp_path) + mock_config.return_value = mock_config_instance + return LogViewerController(logger=mock_logger) + + @pytest.fixture + def sample_json_webhook_data(self) -> dict: + """Create sample JSON webhook log data with workflow steps.""" + return { + "hook_id": "test-hook-123", + "event_type": "pull_request", + "action": "opened", + "repository": "org/test-repo", + "sender": "test-user", + "pr": { + "number": 456, + "title": "Test PR", + "url": "https://github.com/org/test-repo/pull/456", + }, + "timing": { + "started_at": "2025-01-05T10:00:00.000000Z", + "completed_at": "2025-01-05T10:00:05.000000Z", + "duration_ms": 5000, + }, + "workflow_steps": { + "clone_repository": { + "timestamp": "2025-01-05T10:00:01.000000Z", + "status": "completed", + "duration_ms": 1500, + }, + "assign_reviewers": { + "timestamp": "2025-01-05T10:00:02.500000Z", + "status": "completed", + "duration_ms": 800, + }, + "apply_labels": { + "timestamp": "2025-01-05T10:00:03.500000Z", + "status": "failed", + "duration_ms": 200, + "error": {"type": "ValueError", "message": "Label not found"}, + }, + }, + "token_spend": 35, + "success": False, + } + + def create_json_log_file(self, log_dir: Path, filename: str, entries: list[dict]) -> Path: + """Create a test JSON log file with entries.""" + log_file = log_dir / filename + with open(log_file, "w", encoding="utf-8") as f: + for entry in entries: + f.write(json.dumps(entry) + "\n") + return log_file + + def create_text_log_file(self, log_dir: Path, filename: str, log_lines: list[str]) -> Path: + """Create a test text log file with log lines.""" + log_file = log_dir / filename + with open(log_file, "w", encoding="utf-8") as f: + for line in log_lines: + f.write(line + "\n") + return log_file + + async def test_get_step_logs_returns_step_metadata_and_logs(self, controller, tmp_path, sample_json_webhook_data): + """Test get_step_logs returns step metadata and associated log entries.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create JSON log file + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + + # Create text log file with entries during clone_repository step + log_lines = [ + "2025-01-05T10:00:01.100000 GithubWebhook INFO org/test-repo " + "[pull_request][test-hook-123][test-user][PR 456]: Cloning repository...", + "2025-01-05T10:00:01.500000 GithubWebhook DEBUG org/test-repo " + "[pull_request][test-hook-123][test-user][PR 456]: Clone completed", + # Entry outside the step time window + "2025-01-05T10:00:05.000000 GithubWebhook INFO org/test-repo " + "[pull_request][test-hook-123][test-user][PR 456]: Processing complete", + ] + self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + + # Get logs for clone_repository step + result = await controller.get_step_logs("test-hook-123", "clone_repository") + + # Verify step metadata + assert result["step"]["name"] == "clone_repository" + assert result["step"]["status"] == "completed" + assert result["step"]["timestamp"] == "2025-01-05T10:00:01.000000Z" + assert result["step"]["duration_ms"] == 1500 + assert result["step"]["error"] is None + + # Verify logs are within time window (1500ms from step start) + assert result["log_count"] == 2 + assert len(result["logs"]) == 2 + # Check that both expected messages are present (order may vary due to streaming) + log_messages = [log["message"] for log in result["logs"]] + assert any("Cloning repository" in msg for msg in log_messages) + assert any("Clone completed" in msg for msg in log_messages) + + async def test_get_step_logs_hook_id_not_found(self, controller, tmp_path, sample_json_webhook_data): + """Test get_step_logs raises 404 when hook_id is not found.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create JSON log file with different hook_id + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + + # Try to get logs for non-existent hook_id + with pytest.raises(HTTPException) as exc: + await controller.get_step_logs("non-existent-hook", "clone_repository") + + assert exc.value.status_code == 404 + assert "No JSON log entry found" in str(exc.value.detail) + + async def test_get_step_logs_step_name_not_found(self, controller, tmp_path, sample_json_webhook_data): + """Test get_step_logs raises 404 when step_name is not found.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create JSON log file + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + + # Try to get logs for non-existent step_name + with pytest.raises(HTTPException) as exc: + await controller.get_step_logs("test-hook-123", "non_existent_step") + + assert exc.value.status_code == 404 + assert "Step 'non_existent_step' not found" in str(exc.value.detail) + + async def test_get_step_logs_with_failed_step(self, controller, tmp_path, sample_json_webhook_data): + """Test get_step_logs returns error information for failed step.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create JSON log file + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + + # Get logs for failed step + result = await controller.get_step_logs("test-hook-123", "apply_labels") + + # Verify step metadata includes error + assert result["step"]["name"] == "apply_labels" + assert result["step"]["status"] == "failed" + assert result["step"]["error"]["message"] == "Label not found" + + async def test_get_step_logs_uses_default_duration_when_missing(self, controller, tmp_path): + """Test get_step_logs uses 60 second default when duration_ms is missing.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create webhook data with step missing duration_ms + webhook_data = { + "hook_id": "test-hook-456", + "event_type": "pull_request", + "repository": "org/repo", + "pr": {"number": 789}, + "timing": { + "started_at": "2025-01-05T10:00:00.000000Z", + "duration_ms": 5000, + }, + "workflow_steps": { + "step_no_duration": { + "timestamp": "2025-01-05T10:00:01.000000Z", + "status": "completed", + # No duration_ms field + }, + }, + } + + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) + + # Create text log with entry within 60 second default window + log_lines = [ + "2025-01-05T10:00:30.000000 GithubWebhook INFO org/repo " + "[pull_request][test-hook-456][user][PR 789]: Within default window", + # Entry outside 60 second window + "2025-01-05T10:02:00.000000 GithubWebhook INFO org/repo " + "[pull_request][test-hook-456][user][PR 789]: Outside window", + ] + self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + + result = await controller.get_step_logs("test-hook-456", "step_no_duration") + + # Verify default duration is used + assert result["step"]["duration_ms"] is None + # Should only include entry within 60 second default window + assert result["log_count"] == 1 + assert "Within default window" in result["logs"][0]["message"] + + async def test_get_step_logs_handles_invalid_timestamp_gracefully(self, controller, tmp_path): + """Test get_step_logs handles invalid step timestamp gracefully.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create webhook data with invalid timestamp + webhook_data = { + "hook_id": "test-hook-789", + "event_type": "pull_request", + "repository": "org/repo", + "pr": {"number": 123}, + "timing": { + "started_at": "2025-01-05T10:00:00.000000Z", + "duration_ms": 5000, + }, + "workflow_steps": { + "step_bad_timestamp": { + "timestamp": "invalid-timestamp", + "status": "completed", + "duration_ms": 1000, + }, + }, + } + + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) + + # Create text log file + log_lines = [ + "2025-01-05T10:00:01.000000 GithubWebhook INFO org/repo " + "[pull_request][test-hook-789][user][PR 123]: Log entry", + ] + self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + + result = await controller.get_step_logs("test-hook-789", "step_bad_timestamp") + + # Should return step metadata without crashing + assert result["step"]["name"] == "step_bad_timestamp" + assert result["step"]["timestamp"] == "invalid-timestamp" + # Without valid timestamp filtering, it returns logs matching hook_id + assert "logs" in result + + async def test_get_step_logs_empty_logs_when_no_entries_in_window( + self, controller, tmp_path, sample_json_webhook_data + ): + """Test get_step_logs returns empty logs when no entries match time window.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create JSON log file + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + + # Create text log file with entries outside step time window + log_lines = [ + # Entry before clone_repository step + "2025-01-05T09:59:00.000000 GithubWebhook INFO org/test-repo " + "[pull_request][test-hook-123][test-user][PR 456]: Before step", + # Entry after clone_repository step (step ends at 10:00:02.500) + "2025-01-05T10:00:10.000000 GithubWebhook INFO org/test-repo " + "[pull_request][test-hook-123][test-user][PR 456]: After step", + ] + self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + + result = await controller.get_step_logs("test-hook-123", "clone_repository") + + # Should return step metadata with empty logs + assert result["step"]["name"] == "clone_repository" + assert result["log_count"] == 0 + assert result["logs"] == [] + + async def test_get_step_logs_filters_by_hook_id(self, controller, tmp_path, sample_json_webhook_data): + """Test get_step_logs only returns logs matching the hook_id.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create JSON log file + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + + # Create text log file with entries from different hook_ids + log_lines = [ + "2025-01-05T10:00:01.100000 GithubWebhook INFO org/test-repo " + "[pull_request][test-hook-123][test-user][PR 456]: Correct hook", + "2025-01-05T10:00:01.200000 GithubWebhook INFO org/test-repo " + "[pull_request][other-hook-999][other-user][PR 789]: Wrong hook", + ] + self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + + result = await controller.get_step_logs("test-hook-123", "clone_repository") + + # Should only include entries with matching hook_id + assert result["log_count"] == 1 + assert "Correct hook" in result["logs"][0]["message"] diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 7811420e..02c0fdf9 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -22,6 +22,13 @@ class LogViewerController: """Controller for log viewer functionality.""" + # Maximum log entries to return for a single step to prevent unbounded responses + _MAX_STEP_LOGS = 500 + + # Default time window in milliseconds when step duration is unknown + # 60 seconds provides a reasonable maximum window for log correlation + _DEFAULT_STEP_DURATION_MS = 60000 + # Workflow stage patterns for PR flow analysis # These patterns match log messages to identify workflow stages and can be updated # when log message formats change without modifying the analysis logic @@ -568,6 +575,92 @@ def _build_log_prefix_from_context( log_prefix_parts.append(f"[PR {pr_number}]") return " ".join(log_prefix_parts) + ": " if log_prefix_parts else "" + async def get_step_logs(self, hook_id: str, step_name: str) -> dict[str, Any]: + """Get log entries that occurred during a specific workflow step's execution. + + Args: + hook_id: The hook ID to get step logs for + step_name: The name of the workflow step to get logs for + + Returns: + Dictionary with step metadata and associated log entries: + - step: The step metadata (name, status, timestamp, duration_ms, error) + - logs: Array of log entries that occurred during the step + - log_count: Number of logs found + + Raises: + HTTPException: 404 if hook_id not found or step_name not found in workflow steps + + """ + # Get workflow steps data + workflow_data = await self.get_workflow_steps_json(hook_id) + + # Find the step with matching step_name + steps = workflow_data.get("steps", []) + matching_step: dict[str, Any] | None = None + for step in steps: + if step.get("step_name") == step_name: + matching_step = step + break + + if matching_step is None: + raise HTTPException( + status_code=404, + detail=f"Step '{step_name}' not found for hook ID: {hook_id}", + ) + + # Extract step metadata + step_timestamp = matching_step.get("timestamp") + step_duration_ms = matching_step.get("duration_ms") + step_status = matching_step.get("task_status", "unknown") + step_error = matching_step.get("error") + + # Calculate time window + duration_ms = step_duration_ms if step_duration_ms is not None else self._DEFAULT_STEP_DURATION_MS + + # Parse timestamps for time window filtering + step_start: datetime.datetime | None = None + step_end: datetime.datetime | None = None + + if step_timestamp: + try: + step_start = datetime.datetime.fromisoformat(step_timestamp.replace("Z", "+00:00")) + step_end = step_start + datetime.timedelta(milliseconds=duration_ms) + except (ValueError, TypeError) as ex: + self.logger.warning(f"Failed to parse step timestamp '{step_timestamp}': {ex}") + + # Collect log entries within the time window + log_entries: list[dict[str, Any]] = [] + + async for entry in self._stream_log_entries(max_files=25, max_entries=50000): + # Filter by hook_id + if not self._entry_matches_filters(entry, hook_id=hook_id): + continue + + # Filter by time window if we have valid timestamps + if step_start is not None and step_end is not None: + if entry.timestamp < step_start or entry.timestamp > step_end: + continue + + log_entries.append(entry.to_dict()) + if len(log_entries) >= self._MAX_STEP_LOGS: + break + + # Build step metadata for response + step_metadata = { + "name": step_name, + "status": step_status, + "timestamp": step_timestamp, + "duration_ms": step_duration_ms, + "error": step_error, + } + + return { + "step": step_metadata, + "logs": log_entries, + "log_count": len(log_entries), + } + async def get_workflow_steps_json(self, hook_id: str) -> dict[str, Any]: """Get workflow steps directly from JSON logs for a specific hook ID. diff --git a/webhook_server/web/static/css/log_viewer.css b/webhook_server/web/static/css/log_viewer.css index ccaca2ce..ad337980 100644 --- a/webhook_server/web/static/css/log_viewer.css +++ b/webhook_server/web/static/css/log_viewer.css @@ -1151,3 +1151,302 @@ body { .task-group-steps .flow-step-container.nested::before { left: -1px; } + +/* Step Details Styles - for workflow step metadata display */ +.step-details-entry { + background: var(--container-bg); + border: 1px solid var(--border-color); + border-radius: 8px; + padding: 16px; + font-family: monospace; + font-size: 13px; +} + +.step-details-header { + display: flex; + align-items: center; + gap: 16px; + margin-bottom: 12px; + padding-bottom: 12px; + border-bottom: 1px solid var(--border-color); +} + +.step-details-timestamp { + color: var(--timestamp-color); + font-size: 12px; +} + +.step-details-name { + font-weight: 700; + font-size: 15px; + color: var(--text-color); +} + +.step-details-status-row { + display: flex; + align-items: center; + gap: 16px; + margin-bottom: 12px; +} + +.step-details-badge { + padding: 4px 12px; + border-radius: 4px; + font-size: 11px; + font-weight: 700; + text-transform: uppercase; + letter-spacing: 0.5px; +} + +.step-status-completed, +.step-status-success { + background: rgba(40, 167, 69, 0.15); + color: #28a745; + border: 1px solid rgba(40, 167, 69, 0.3); +} + +.step-status-failed, +.step-status-error { + background: rgba(220, 53, 69, 0.15); + color: #dc3545; + border: 1px solid rgba(220, 53, 69, 0.3); +} + +.step-status-in_progress, +.step-status-processing, +.step-status-step { + background: rgba(0, 123, 255, 0.15); + color: #007bff; + border: 1px solid rgba(0, 123, 255, 0.3); +} + +.step-status-warning { + background: rgba(255, 193, 7, 0.15); + color: #856404; + border: 1px solid rgba(255, 193, 7, 0.3); +} + +.step-status-info { + background: var(--level-info-bg); + color: var(--level-info-border); + border: 1px solid var(--level-info-border); +} + +.step-details-duration { + color: var(--level-info-border); + font-weight: 600; + font-size: 13px; +} + +.step-details-message { + color: var(--text-color); + padding: 12px; + background: var(--log-debug-bg); + border-radius: 4px; + margin-bottom: 12px; + word-break: break-word; + line-height: 1.5; +} + +.step-details-error { + background: rgba(220, 53, 69, 0.1); + border: 1px solid rgba(220, 53, 69, 0.3); + border-left: 4px solid #dc3545; + padding: 12px; + border-radius: 4px; + margin-bottom: 12px; +} + +.step-details-error-label { + color: #dc3545; + font-weight: 700; +} + +.step-details-error-text { + color: var(--text-color); + word-break: break-word; +} + +.step-details-metadata { + display: flex; + flex-wrap: wrap; + gap: 8px; + margin-top: 8px; +} + +.step-details-metadata span { + padding: 4px 8px; + background: var(--tag-bg); + border-radius: 4px; + font-size: 12px; + color: var(--text-secondary); +} + +.step-meta-repository { + color: var(--level-info-border) !important; +} + +.step-meta-pr_number { + color: #28a745 !important; +} + +.step-meta-github_user { + color: #6f42c1 !important; +} + +.step-meta-hook_id { + color: var(--timestamp-color) !important; +} + +/* Flow in-progress status */ +.flow-in-progress { + background: rgba(0, 123, 255, 0.1); + border: 1px solid #007bff; + border-left: 4px solid #007bff; + padding: 16px; + border-radius: 8px; + text-align: center; + margin-top: 24px; +} + +.flow-in-progress h3 { + color: #007bff; + margin: 0; + font-size: 18px; +} + +/* Step Logs Styles - for fetched log entries within workflow steps */ +.step-logs-loading { + padding: 16px; + text-align: center; + color: var(--timestamp-color); + font-style: italic; + background: var(--log-debug-bg); + border-radius: 4px; + margin-top: 12px; +} + +.step-logs-list { + margin-top: 16px; + border: 1px solid var(--border-color); + border-radius: 8px; + overflow: hidden; + background: var(--container-bg); +} + +.step-logs-header { + padding: 10px 16px; + background: var(--tag-bg); + border-bottom: 1px solid var(--border-color); + font-weight: 600; + font-size: 13px; + color: var(--text-secondary); +} + +.step-log-entry { + display: flex; + align-items: flex-start; + gap: 12px; + padding: 10px 16px; + border-bottom: 1px solid var(--log-entry-border); + font-family: monospace; + font-size: 12px; + transition: background-color 0.2s ease; +} + +.step-log-entry:last-child { + border-bottom: none; +} + +.step-log-entry:hover { + background-color: var(--log-entry-border); +} + +.step-log-entry.log-level-error { + background-color: rgba(220, 53, 69, 0.05); +} + +.step-log-entry.log-level-warning { + background-color: rgba(255, 193, 7, 0.05); +} + +.step-log-entry.log-level-success { + background-color: rgba(40, 167, 69, 0.05); +} + +.step-log-timestamp { + flex-shrink: 0; + width: 80px; + color: var(--timestamp-color); + font-size: 11px; +} + +.step-log-level { + flex-shrink: 0; + width: 60px; + padding: 2px 6px; + border-radius: 3px; + font-size: 10px; + font-weight: 700; + text-align: center; + text-transform: uppercase; +} + +.log-level-badge-info { + background: var(--level-info-bg); + color: var(--level-info-border); +} + +.log-level-badge-error { + background: rgba(220, 53, 69, 0.15); + color: #dc3545; +} + +.log-level-badge-warning { + background: rgba(255, 193, 7, 0.15); + color: #856404; +} + +.log-level-badge-debug { + background: var(--tag-bg); + color: var(--text-secondary); +} + +.log-level-badge-step { + background: rgba(0, 123, 255, 0.15); + color: #007bff; +} + +.log-level-badge-success { + background: rgba(40, 167, 69, 0.15); + color: #28a745; +} + +.step-log-message { + flex: 1; + word-break: break-word; + overflow-wrap: anywhere; + color: var(--text-color); + line-height: 1.4; +} + +.step-logs-empty { + padding: 16px; + text-align: center; + color: var(--timestamp-color); + font-style: italic; + background: var(--log-debug-bg); + border-radius: 4px; + margin-top: 12px; +} + +.step-logs-error { + padding: 12px 16px; + margin-top: 12px; + background: rgba(220, 53, 69, 0.1); + border: 1px solid rgba(220, 53, 69, 0.3); + border-left: 4px solid #dc3545; + border-radius: 4px; + color: #dc3545; + font-size: 13px; +} diff --git a/webhook_server/web/static/js/log_viewer.js b/webhook_server/web/static/js/log_viewer.js index c5ed3541..31e95411 100644 --- a/webhook_server/web/static/js/log_viewer.js +++ b/webhook_server/web/static/js/log_viewer.js @@ -1731,68 +1731,225 @@ async function filterByStep(stepIndex) { await showStepLogsInModal(step, logsContainer); } -async function showStepLogsInModal(step, logsContainer) { - if (!logsContainer) return; +/** + * Renders step details as a formatted log-like entry. + * Displays the step's own metadata (status, duration, error) instead of searching logs. + * + * @param {Object} step - The step object from workflow_steps + * @returns {HTMLElement} - The rendered step details element + */ +function renderStepDetails(step) { + const detailsContainer = document.createElement("div"); + detailsContainer.className = "step-details-entry"; + + // Header row with timestamp and step name + const headerRow = document.createElement("div"); + headerRow.className = "step-details-header"; + + // Timestamp + if (step.timestamp) { + const timestampSpan = document.createElement("span"); + timestampSpan.className = "step-details-timestamp"; + timestampSpan.textContent = new Date(step.timestamp).toLocaleString(); + headerRow.appendChild(timestampSpan); + } + + // Step name with status badge + const stepNameSpan = document.createElement("span"); + stepNameSpan.className = "step-details-name"; + const stepName = step.step_name || "unknown_step"; + stepNameSpan.textContent = stepName; + headerRow.appendChild(stepNameSpan); + + detailsContainer.appendChild(headerRow); + + // Status row + const statusRow = document.createElement("div"); + statusRow.className = "step-details-status-row"; + + // Status badge + const statusBadge = document.createElement("span"); + const status = step.step_status || step.level || "INFO"; + statusBadge.className = `step-details-badge step-status-${status.toLowerCase()}`; + statusBadge.textContent = status.toUpperCase(); + statusRow.appendChild(statusBadge); - // Show loading state - logsContainer.style.display = "block"; - logsContainer.textContent = "Loading logs..."; + // Duration + const durationMs = step.step_duration_ms || step.duration_ms; + if (durationMs !== undefined && durationMs !== null) { + const durationSpan = document.createElement("span"); + durationSpan.className = "step-details-duration"; + if (durationMs >= 1000) { + durationSpan.textContent = `Duration: ${(durationMs / 1000).toFixed(2)}s`; + } else { + durationSpan.textContent = `Duration: ${durationMs}ms`; + } + statusRow.appendChild(durationSpan); + } - // Cancel previous fetch if still in progress - if (currentStepLogsController) { - currentStepLogsController.abort(); + detailsContainer.appendChild(statusRow); + + // Message (if different from step_name) + if (step.message && step.message !== stepName) { + const messageRow = document.createElement("div"); + messageRow.className = "step-details-message"; + messageRow.textContent = step.message; + detailsContainer.appendChild(messageRow); } - // Create new AbortController for this fetch - currentStepLogsController = new AbortController(); + // Error details (if step failed) + const stepError = step.step_error || step.error; + if (stepError) { + const errorRow = document.createElement("div"); + errorRow.className = "step-details-error"; - try { - // Use step_name for search (e.g., "webhook_routing") instead of the full message - // (e.g., "webhook_routing: completed (2286ms)") which won't match log entries - const searchText = step.step_name || step.message; - const hookId = currentFlowData.hook_id; - - const params = new URLSearchParams({ - hook_id: hookId, - search: searchText, - limit: "100", - }); + const errorLabel = document.createElement("span"); + errorLabel.className = "step-details-error-label"; + errorLabel.textContent = "Error: "; + errorRow.appendChild(errorLabel); - const response = await fetch(`/logs/api/entries?${params}`, { - signal: currentStepLogsController.signal, - }); - if (!response.ok) throw new Error("Failed to fetch logs"); + const errorText = document.createElement("span"); + errorText.className = "step-details-error-text"; + errorText.textContent = stepError; + errorRow.appendChild(errorText); - const data = await response.json(); + detailsContainer.appendChild(errorRow); + } - // Clear and display logs using safe DOM methods - logsContainer.textContent = ""; + // Additional metadata (if present) + const metadataFields = ["repository", "pr_number", "github_user", "hook_id"]; + const metadataRow = document.createElement("div"); + metadataRow.className = "step-details-metadata"; - if (data.entries.length === 0) { - const emptyMsg = document.createElement("div"); - emptyMsg.textContent = "No logs found for this step"; - emptyMsg.style.textAlign = "center"; - emptyMsg.style.color = "var(--timestamp-color)"; - emptyMsg.style.padding = "12px"; - logsContainer.appendChild(emptyMsg); - return; + metadataFields.forEach((field) => { + if (step[field]) { + const metaSpan = document.createElement("span"); + metaSpan.className = `step-meta-${field}`; + if (field === "pr_number") { + metaSpan.textContent = `[PR: #${step[field]}]`; + } else if (field === "github_user") { + metaSpan.textContent = `[User: ${step[field]}]`; + } else if (field === "hook_id") { + metaSpan.textContent = `[Hook: ${step[field]}]`; + } else { + metaSpan.textContent = `[${step[field]}]`; + } + metadataRow.appendChild(metaSpan); } + }); - // Render log entries - data.entries.forEach((entry) => { - // Reuse the main log entry creator for consistency - const logEntry = createLogEntryElement(entry); - logsContainer.appendChild(logEntry); - }); + if (metadataRow.children.length > 0) { + detailsContainer.appendChild(metadataRow); + } - // Scroll to the logs container - logsContainer.scrollIntoView({ behavior: "smooth", block: "nearest" }); - } catch (error) { - if (error.name === "AbortError") { - // Request was cancelled, ignore silently - return; + return detailsContainer; +} + +async function showStepLogsInModal(step, logsContainer) { + if (!logsContainer) return; + + // Cancel any previous step logs fetch + if (currentStepLogsController) { + currentStepLogsController.abort(); + } + currentStepLogsController = new AbortController(); + + // Show the container and display step details immediately + logsContainer.style.display = "block"; + logsContainer.textContent = ""; + + // Render the step's own data first - this is the primary information + const stepDetails = renderStepDetails(step); + logsContainer.appendChild(stepDetails); + + // Fetch actual log entries for this step + const stepName = step.step_name; + const hookId = currentFlowData?.hook_id; + + if (stepName && hookId) { + // Show loading indicator + const loadingDiv = document.createElement("div"); + loadingDiv.className = "step-logs-loading"; + loadingDiv.textContent = "Loading logs..."; + logsContainer.appendChild(loadingDiv); + + try { + const response = await fetch( + `/logs/api/step-logs/${encodeURIComponent(hookId)}/${encodeURIComponent(stepName)}`, + { signal: currentStepLogsController.signal } + ); + loadingDiv.remove(); + + if (response.ok) { + const data = await response.json(); + if (data.logs && data.logs.length > 0) { + // Create container for logs + const logsDiv = document.createElement("div"); + logsDiv.className = "step-logs-list"; + + // Add header + const header = document.createElement("div"); + header.className = "step-logs-header"; + header.textContent = `Log entries during step (${data.log_count} found)`; + logsDiv.appendChild(header); + + // Render each log entry + data.logs.forEach((log) => { + const logEntry = document.createElement("div"); + const levelLower = (log.level || "info").toLowerCase(); + logEntry.className = `step-log-entry log-level-${levelLower}`; + + const timestamp = document.createElement("span"); + timestamp.className = "step-log-timestamp"; + timestamp.textContent = new Date(log.timestamp).toLocaleTimeString(); + + const level = document.createElement("span"); + level.className = `step-log-level log-level-badge-${levelLower}`; + level.textContent = log.level || "INFO"; + + const message = document.createElement("span"); + message.className = "step-log-message"; + message.textContent = log.message; + + logEntry.appendChild(timestamp); + logEntry.appendChild(level); + logEntry.appendChild(message); + logsDiv.appendChild(logEntry); + }); + + logsContainer.appendChild(logsDiv); + } else { + const noLogs = document.createElement("div"); + noLogs.className = "step-logs-empty"; + noLogs.textContent = "No log entries found during this step's execution."; + logsContainer.appendChild(noLogs); + } + } else if (response.status === 404) { + // Step not found - show as empty state rather than error + const notFoundDiv = document.createElement("div"); + notFoundDiv.className = "step-logs-empty"; + notFoundDiv.textContent = "Step not found in workflow data."; + logsContainer.appendChild(notFoundDiv); + } else { + // Handle other errors + const errorDiv = document.createElement("div"); + errorDiv.className = "step-logs-error"; + errorDiv.textContent = `Could not load logs: ${response.status}`; + logsContainer.appendChild(errorDiv); + } + } catch (error) { + if (error.name === "AbortError") { + // Request was cancelled, ignore silently + return; + } + loadingDiv?.remove(); + const errorDiv = document.createElement("div"); + errorDiv.className = "step-logs-error"; + errorDiv.textContent = `Error loading logs: ${error.message}`; + logsContainer.appendChild(errorDiv); } - console.error("Error fetching step logs:", error); - logsContainer.textContent = "Error loading logs"; } + + // Scroll to the logs container + logsContainer.scrollIntoView({ behavior: "smooth", block: "nearest" }); } From 0952f57199899770abd064961ba54dbdec201a8d Mon Sep 17 00:00:00 2001 From: rnetser Date: Tue, 20 Jan 2026 20:36:41 +0200 Subject: [PATCH 12/15] fix(log-viewer): address CodeRabbit review comments for step-logs - Add require_trusted_network dependency to step-logs endpoint - Fail fast with HTTPException 500 on invalid/missing step timestamps - Fix status badge to prefer task_status over step_status - Handle error objects properly to avoid "[object Object]" display --- webhook_server/app.py | 43 ++++++++++++++++- webhook_server/tests/test_log_viewer.py | 54 ++++++++++++++++------ webhook_server/web/log_viewer.py | 30 ++++++------ webhook_server/web/static/js/log_viewer.js | 13 +++++- 4 files changed, 110 insertions(+), 30 deletions(-) diff --git a/webhook_server/app.py b/webhook_server/app.py index b63bef4c..e33da587 100644 --- a/webhook_server/app.py +++ b/webhook_server/app.py @@ -100,6 +100,47 @@ def require_log_server_enabled() -> None: ) +async def require_trusted_network(request: Request) -> None: + """Dependency to restrict log viewer access to trusted networks only. + + This provides an additional layer of security for log viewer endpoints by + checking if the client IP is from a trusted/private network. Currently checks + for private IP ranges (RFC 1918), loopback, and link-local addresses. + + Security Warning: + This check can be bypassed if the server is behind a reverse proxy that + doesn't properly set X-Forwarded-For headers. For production deployments, + always deploy log viewer endpoints on trusted networks (VPN, internal network). + """ + client_host = request.client.host if request.client else None + + if not client_host: + # No client IP available - deny access + raise HTTPException( + status_code=status.HTTP_403_FORBIDDEN, + detail="Access denied: Unable to determine client IP address.", + ) + + try: + client_ip = ipaddress.ip_address(client_host) + except ValueError: + # Invalid IP address format - deny access + raise HTTPException( + status_code=status.HTTP_403_FORBIDDEN, + detail="Access denied: Invalid client IP address format.", + ) from None + + # Allow private networks (RFC 1918), loopback, and link-local + is_trusted = client_ip.is_private or client_ip.is_loopback or client_ip.is_link_local + + if not is_trusted: + LOGGER.warning(f"Log viewer access denied from untrusted IP: {client_host}") + raise HTTPException( + status_code=status.HTTP_403_FORBIDDEN, + detail="Access denied: Log viewer is only accessible from trusted networks.", + ) + + @asynccontextmanager async def lifespan(_app: FastAPI) -> AsyncGenerator[None]: global _lifespan_http_client @@ -1148,7 +1189,7 @@ async def get_workflow_steps(hook_id: str, controller: LogViewerController = con @FASTAPI_APP.get( "/logs/api/step-logs/{hook_id}/{step_name}", operation_id="get_step_logs", - dependencies=[Depends(require_log_server_enabled)], + dependencies=[Depends(require_log_server_enabled), Depends(require_trusted_network)], ) async def get_step_logs( hook_id: str = Path(..., min_length=1, max_length=100), diff --git a/webhook_server/tests/test_log_viewer.py b/webhook_server/tests/test_log_viewer.py index 32f072b8..41b92c03 100644 --- a/webhook_server/tests/test_log_viewer.py +++ b/webhook_server/tests/test_log_viewer.py @@ -1451,8 +1451,8 @@ async def test_get_step_logs_uses_default_duration_when_missing(self, controller assert result["log_count"] == 1 assert "Within default window" in result["logs"][0]["message"] - async def test_get_step_logs_handles_invalid_timestamp_gracefully(self, controller, tmp_path): - """Test get_step_logs handles invalid step timestamp gracefully.""" + async def test_get_step_logs_raises_on_invalid_timestamp(self, controller, tmp_path): + """Test get_step_logs raises HTTPException for invalid step timestamp.""" log_dir = tmp_path / "logs" log_dir.mkdir() @@ -1477,20 +1477,46 @@ async def test_get_step_logs_handles_invalid_timestamp_gracefully(self, controll self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) - # Create text log file - log_lines = [ - "2025-01-05T10:00:01.000000 GithubWebhook INFO org/repo " - "[pull_request][test-hook-789][user][PR 123]: Log entry", - ] - self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + # Should raise HTTPException 500 for invalid timestamp + with pytest.raises(HTTPException) as exc: + await controller.get_step_logs("test-hook-789", "step_bad_timestamp") - result = await controller.get_step_logs("test-hook-789", "step_bad_timestamp") + assert exc.value.status_code == 500 + assert "Invalid timestamp 'invalid-timestamp'" in exc.value.detail + assert "step_bad_timestamp" in exc.value.detail - # Should return step metadata without crashing - assert result["step"]["name"] == "step_bad_timestamp" - assert result["step"]["timestamp"] == "invalid-timestamp" - # Without valid timestamp filtering, it returns logs matching hook_id - assert "logs" in result + async def test_get_step_logs_raises_on_missing_timestamp(self, controller, tmp_path): + """Test get_step_logs raises HTTPException for missing step timestamp.""" + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create webhook data with missing timestamp + webhook_data = { + "hook_id": "test-hook-missing", + "event_type": "pull_request", + "repository": "org/repo", + "pr": {"number": 123}, + "timing": { + "started_at": "2025-01-05T10:00:00.000000Z", + "duration_ms": 5000, + }, + "workflow_steps": { + "step_no_timestamp": { + "status": "completed", + "duration_ms": 1000, + }, + }, + } + + self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) + + # Should raise HTTPException 500 for missing timestamp + with pytest.raises(HTTPException) as exc: + await controller.get_step_logs("test-hook-missing", "step_no_timestamp") + + assert exc.value.status_code == 500 + assert "has no timestamp" in exc.value.detail + assert "step_no_timestamp" in exc.value.detail async def test_get_step_logs_empty_logs_when_no_entries_in_window( self, controller, tmp_path, sample_json_webhook_data diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 02c0fdf9..7e8d2ac3 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -618,16 +618,21 @@ async def get_step_logs(self, hook_id: str, step_name: str) -> dict[str, Any]: # Calculate time window duration_ms = step_duration_ms if step_duration_ms is not None else self._DEFAULT_STEP_DURATION_MS - # Parse timestamps for time window filtering - step_start: datetime.datetime | None = None - step_end: datetime.datetime | None = None + # Parse timestamps for time window filtering - fail fast if invalid + if not step_timestamp: + raise HTTPException( + status_code=500, + detail=f"Step '{step_name}' has no timestamp - cannot determine log time window", + ) - if step_timestamp: - try: - step_start = datetime.datetime.fromisoformat(step_timestamp.replace("Z", "+00:00")) - step_end = step_start + datetime.timedelta(milliseconds=duration_ms) - except (ValueError, TypeError) as ex: - self.logger.warning(f"Failed to parse step timestamp '{step_timestamp}': {ex}") + try: + step_start = datetime.datetime.fromisoformat(step_timestamp.replace("Z", "+00:00")) + step_end = step_start + datetime.timedelta(milliseconds=duration_ms) + except (ValueError, TypeError) as ex: + raise HTTPException( + status_code=500, + detail=f"Invalid timestamp '{step_timestamp}' for step '{step_name}': {ex}", + ) from ex # Collect log entries within the time window log_entries: list[dict[str, Any]] = [] @@ -637,10 +642,9 @@ async def get_step_logs(self, hook_id: str, step_name: str) -> dict[str, Any]: if not self._entry_matches_filters(entry, hook_id=hook_id): continue - # Filter by time window if we have valid timestamps - if step_start is not None and step_end is not None: - if entry.timestamp < step_start or entry.timestamp > step_end: - continue + # Filter by time window + if entry.timestamp < step_start or entry.timestamp > step_end: + continue log_entries.append(entry.to_dict()) if len(log_entries) >= self._MAX_STEP_LOGS: diff --git a/webhook_server/web/static/js/log_viewer.js b/webhook_server/web/static/js/log_viewer.js index 31e95411..34e8ac9a 100644 --- a/webhook_server/web/static/js/log_viewer.js +++ b/webhook_server/web/static/js/log_viewer.js @@ -1769,7 +1769,7 @@ function renderStepDetails(step) { // Status badge const statusBadge = document.createElement("span"); - const status = step.step_status || step.level || "INFO"; + const status = step.task_status || step.step_status || step.level || "INFO"; statusBadge.className = `step-details-badge step-status-${status.toLowerCase()}`; statusBadge.textContent = status.toUpperCase(); statusRow.appendChild(statusBadge); @@ -1810,7 +1810,16 @@ function renderStepDetails(step) { const errorText = document.createElement("span"); errorText.className = "step-details-error-text"; - errorText.textContent = stepError; + // Properly handle error objects to avoid "[object Object]" + let errorMessage; + if (typeof stepError === "string") { + errorMessage = stepError; + } else if (stepError.message) { + errorMessage = stepError.message; + } else { + errorMessage = JSON.stringify(stepError); + } + errorText.textContent = errorMessage; errorRow.appendChild(errorText); detailsContainer.appendChild(errorRow); From 3a05fc01fd6ef3bf7265682617dea102caf4f4b5 Mon Sep 17 00:00:00 2001 From: rnetser Date: Wed, 21 Jan 2026 14:50:51 +0200 Subject: [PATCH 13/15] refactor(tests): extract shared fixtures and fail fast on missing timestamps - Move mock_logger, sample_json_webhook_data, create_json_log_file to conftest.py - Add fail-fast validation for missing step timestamps in workflow steps - Add test for missing timestamp validation --- webhook_server/tests/conftest.py | 123 ++++++++ webhook_server/tests/test_log_viewer.py | 369 ++++++++++-------------- webhook_server/web/log_viewer.py | 3 + 3 files changed, 285 insertions(+), 210 deletions(-) diff --git a/webhook_server/tests/conftest.py b/webhook_server/tests/conftest.py index d9c90894..114ecfeb 100644 --- a/webhook_server/tests/conftest.py +++ b/webhook_server/tests/conftest.py @@ -1,7 +1,10 @@ +import json import logging as python_logging import os from dataclasses import dataclass from datetime import datetime, timedelta +from pathlib import Path +from unittest.mock import Mock import pytest import yaml @@ -200,3 +203,123 @@ def owners_files_test_data(): Uses centralized OWNERS_TEST_DATA constant to ensure consistency. """ return {path: yaml.dump(data) for path, data in OWNERS_TEST_DATA.items()} + + +# === Log Viewer Shared Fixtures === + + +@pytest.fixture +def mock_logger(): + """Create a mock logger for testing log viewer components.""" + return Mock() + + +@pytest.fixture +def sample_json_webhook_data() -> dict: + """Create sample JSON webhook log data with workflow steps. + + Used by test_log_viewer.py tests for JSON log parsing and workflow step retrieval. + """ + return { + "hook_id": "test-hook-123", + "event_type": "pull_request", + "action": "opened", + "repository": "org/test-repo", + "sender": "test-user", + "pr": { + "number": 456, + "title": "Test PR", + "url": "https://github.com/org/test-repo/pull/456", + }, + "timing": { + "started_at": "2025-01-05T10:00:00.000000Z", + "completed_at": "2025-01-05T10:00:05.000000Z", + "duration_ms": 5000, + }, + "workflow_steps": { + "clone_repository": { + "timestamp": "2025-01-05T10:00:01.000000Z", + "status": "completed", + "duration_ms": 1500, + }, + "assign_reviewers": { + "timestamp": "2025-01-05T10:00:02.500000Z", + "status": "completed", + "duration_ms": 800, + }, + "apply_labels": { + "timestamp": "2025-01-05T10:00:03.500000Z", + "status": "failed", + "duration_ms": 200, + "error": {"type": "ValueError", "message": "Label not found"}, + }, + }, + "token_spend": 35, + "success": False, + } + + +@pytest.fixture +def create_json_log_file(tmp_path): + """Factory fixture to create test JSON log files. + + Returns a callable that creates JSON log files in the provided directory. + + Usage: + def test_example(create_json_log_file, tmp_path): + log_dir = tmp_path / "logs" + log_dir.mkdir() + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [entry_dict]) + """ + + def _create_json_log_file(log_dir: Path, filename: str, entries: list[dict]) -> Path: + """Create a test JSON log file with entries. + + Args: + log_dir: Directory to create the log file in + filename: Name of the log file + entries: List of JSON webhook data dictionaries + + Returns: + Path to created log file + """ + log_file = log_dir / filename + with open(log_file, "w", encoding="utf-8") as f: + for entry in entries: + f.write(json.dumps(entry) + "\n") + return log_file + + return _create_json_log_file + + +@pytest.fixture +def create_text_log_file(tmp_path): + """Factory fixture to create test text log files. + + Returns a callable that creates text log files in the provided directory. + + Usage: + def test_example(create_text_log_file, tmp_path): + log_dir = tmp_path / "logs" + log_dir.mkdir() + create_text_log_file(log_dir, "webhook-server.log", ["line1", "line2"]) + """ + + def _create_text_log_file(log_dir: Path, filename: str, log_lines: list[str]) -> Path: + """Create a test text log file with log lines. + + Args: + log_dir: Directory to create the log file in + filename: Name of the log file + log_lines: List of log line strings + + Returns: + Path to created log file + """ + log_file = log_dir / filename + with open(log_file, "w", encoding="utf-8") as f: + for line in log_lines: + f.write(line + "\n") + return log_file + + return _create_text_log_file diff --git a/webhook_server/tests/test_log_viewer.py b/webhook_server/tests/test_log_viewer.py index 41b92c03..78221de3 100644 --- a/webhook_server/tests/test_log_viewer.py +++ b/webhook_server/tests/test_log_viewer.py @@ -54,7 +54,6 @@ import datetime import json from collections.abc import AsyncIterator -from pathlib import Path from unittest.mock import Mock, patch import pytest @@ -67,11 +66,6 @@ class TestLogViewerJSONMethods: """Test cases for LogViewerController JSON log methods.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger for testing.""" - return Mock() - @pytest.fixture def controller(self, mock_logger, tmp_path): """Create a LogViewerController instance with mocked config.""" @@ -82,70 +76,43 @@ def controller(self, mock_logger, tmp_path): return LogViewerController(logger=mock_logger) @pytest.fixture - def sample_json_webhook_data(self) -> dict: - """Create sample JSON webhook log data.""" - return { - "hook_id": "test-hook-123", - "event_type": "pull_request", - "action": "opened", - "repository": "org/test-repo", - "sender": "test-user", - "pr": { - "number": 456, - "title": "Test PR", - "url": "https://github.com/org/test-repo/pull/456", + def json_webhook_data_simple(self, sample_json_webhook_data) -> dict: + """Create simple webhook data with step1/step2 instead of clone_repository/etc. + + This fixture adapts the shared sample_json_webhook_data for tests that + expect simpler step names (step1, step2). + """ + data = copy.deepcopy(sample_json_webhook_data) + data["workflow_steps"] = { + "step1": { + "timestamp": "2025-01-05T10:00:01.000000Z", + "status": "completed", + "duration_ms": 1000, }, - "timing": { - "started_at": "2025-01-05T10:00:00.000000Z", - "completed_at": "2025-01-05T10:00:05.000000Z", - "duration_ms": 5000, + "step2": { + "timestamp": "2025-01-05T10:00:03.000000Z", + "status": "completed", + "duration_ms": 2000, }, - "workflow_steps": { - "step1": { - "timestamp": "2025-01-05T10:00:01.000000Z", - "status": "completed", - "duration_ms": 1000, - }, - "step2": { - "timestamp": "2025-01-05T10:00:03.000000Z", - "status": "completed", - "duration_ms": 2000, - }, - }, - "token_spend": 35, - "success": True, } + data["success"] = True + return data - def create_json_log_file(self, log_dir: Path, filename: str, entries: list[dict]) -> Path: - """Create a test JSON log file with entries. - - Args: - log_dir: Directory to create the log file in - filename: Name of the log file - entries: List of JSON webhook data dictionaries - - Returns: - Path to created log file - """ - log_file = log_dir / filename - with open(log_file, "w", encoding="utf-8") as f: - for entry in entries: - f.write(json.dumps(entry) + "\n") - return log_file - - async def test_stream_json_log_entries_yields_entries(self, controller, tmp_path, sample_json_webhook_data): + async def test_stream_json_log_entries_yields_entries( + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file + ): """Test that _stream_json_log_entries yields JSON entries from log files.""" # Create logs directory log_dir = tmp_path / "logs" log_dir.mkdir() # Create a JSON log file with multiple entries - entry1 = sample_json_webhook_data.copy() - entry2 = sample_json_webhook_data.copy() + entry1 = json_webhook_data_simple.copy() + entry2 = json_webhook_data_simple.copy() entry2["hook_id"] = "test-hook-456" entry2["pr"]["number"] = 789 - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [entry1, entry2]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [entry1, entry2]) # Stream JSON entries entries = [entry async for entry in controller._stream_json_log_entries(max_files=10, max_entries=100)] @@ -156,7 +123,7 @@ async def test_stream_json_log_entries_yields_entries(self, controller, tmp_path assert entries[1]["hook_id"] == "test-hook-123" async def test_stream_json_log_entries_respects_max_files_limit( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file ): """Test that _stream_json_log_entries respects max_files limit.""" log_dir = tmp_path / "logs" @@ -164,9 +131,9 @@ async def test_stream_json_log_entries_respects_max_files_limit( # Create 5 JSON log files for i in range(5): - entry = sample_json_webhook_data.copy() + entry = json_webhook_data_simple.copy() entry["hook_id"] = f"hook-file-{i}" - self.create_json_log_file(log_dir, f"webhooks_2025-01-0{i}.json", [entry]) + create_json_log_file(log_dir, f"webhooks_2025-01-0{i}.json", [entry]) # Stream with max_files=2 entries = [entry async for entry in controller._stream_json_log_entries(max_files=2, max_entries=100)] @@ -175,7 +142,7 @@ async def test_stream_json_log_entries_respects_max_files_limit( assert len(entries) == 2 async def test_stream_json_log_entries_respects_max_entries_limit( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file ): """Test that _stream_json_log_entries respects max_entries limit.""" log_dir = tmp_path / "logs" @@ -184,11 +151,11 @@ async def test_stream_json_log_entries_respects_max_entries_limit( # Create a JSON log file with 10 entries entries_data = [] for i in range(10): - entry = sample_json_webhook_data.copy() + entry = json_webhook_data_simple.copy() entry["hook_id"] = f"hook-{i}" entries_data.append(entry) - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", entries_data) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", entries_data) # Stream with max_entries=5 entries = [entry async for entry in controller._stream_json_log_entries(max_files=10, max_entries=5)] @@ -197,7 +164,7 @@ async def test_stream_json_log_entries_respects_max_entries_limit( assert len(entries) == 5 async def test_stream_json_log_entries_skips_invalid_json_lines( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, json_webhook_data_simple ): """Test that _stream_json_log_entries skips invalid JSON lines.""" log_dir = tmp_path / "logs" @@ -207,12 +174,12 @@ async def test_stream_json_log_entries_skips_invalid_json_lines( log_file = log_dir / "webhooks_2025-01-05.json" with open(log_file, "w", encoding="utf-8") as f: # Valid JSON - f.write(json.dumps(sample_json_webhook_data) + "\n") + f.write(json.dumps(json_webhook_data_simple) + "\n") # Invalid JSON lines f.write("not valid json\n") f.write('{"incomplete": \n') # Another valid JSON - entry2 = sample_json_webhook_data.copy() + entry2 = json_webhook_data_simple.copy() entry2["hook_id"] = "hook-valid-2" f.write(json.dumps(entry2) + "\n") @@ -244,23 +211,25 @@ async def test_stream_json_log_entries_empty_directory(self, controller, tmp_pat # Should yield nothing assert len(entries) == 0 - async def test_stream_json_log_entries_newest_first_ordering(self, controller, tmp_path, sample_json_webhook_data): + async def test_stream_json_log_entries_newest_first_ordering( + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file + ): """Test that _stream_json_log_entries returns newest files first.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create multiple JSON log files with different modification times # Older file - entry1 = sample_json_webhook_data.copy() + entry1 = json_webhook_data_simple.copy() entry1["hook_id"] = "old-hook" - self.create_json_log_file(log_dir, "webhooks_2025-01-01.json", [entry1]) + create_json_log_file(log_dir, "webhooks_2025-01-01.json", [entry1]) await asyncio.sleep(0.01) # Ensure different mtime # Newer file - entry2 = sample_json_webhook_data.copy() + entry2 = json_webhook_data_simple.copy() entry2["hook_id"] = "new-hook" - file2 = self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [entry2]) + file2 = create_json_log_file(log_dir, "webhooks_2025-01-05.json", [entry2]) # Ensure file2 has a newer mtime file2.touch() @@ -274,13 +243,15 @@ async def test_stream_json_log_entries_newest_first_ordering(self, controller, t assert entries[0]["hook_id"] == "new-hook" assert entries[1]["hook_id"] == "old-hook" - async def test_get_workflow_steps_json_returns_workflow_data(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_workflow_steps_json_returns_workflow_data( + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file + ): """Test get_workflow_steps_json returns workflow steps in frontend-expected format.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [json_webhook_data_simple]) # Get workflow steps result = await controller.get_workflow_steps_json("test-hook-123") @@ -314,14 +285,14 @@ async def test_get_workflow_steps_json_returns_workflow_data(self, controller, t assert "relative_time_ms" in step async def test_get_workflow_steps_json_returns_none_for_unknown_hook_id( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file ): """Test get_workflow_steps_json raises HTTPException for unknown hook_id.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file with different hook_id - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [json_webhook_data_simple]) # Try to get workflow steps for non-existent hook_id with pytest.raises(HTTPException) as exc: @@ -343,13 +314,15 @@ async def test_get_workflow_steps_json_no_log_files(self, controller, tmp_path): # Should raise 404 assert exc.value.status_code == 404 - async def test_get_workflow_steps_json_with_error_in_log(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_workflow_steps_json_with_error_in_log( + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file + ): """Test get_workflow_steps_json with webhook that has error step.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log entry with failed step - error_data = copy.deepcopy(sample_json_webhook_data) + error_data = copy.deepcopy(json_webhook_data_simple) error_data["workflow_steps"]["failed_step"] = { "timestamp": "2025-01-05T10:00:04.000000Z", "status": "failed", @@ -357,7 +330,7 @@ async def test_get_workflow_steps_json_with_error_in_log(self, controller, tmp_p "error": {"type": "ValueError", "message": "Test error occurred"}, } - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [error_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [error_data]) # Get workflow steps result = await controller.get_workflow_steps_json("test-hook-123") @@ -370,13 +343,15 @@ async def test_get_workflow_steps_json_with_error_in_log(self, controller, tmp_p assert failed_steps[0]["error"]["message"] == "Test error occurred" assert failed_steps[0]["level"] == "ERROR" - async def test_get_workflow_steps_uses_json_when_available(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_workflow_steps_uses_json_when_available( + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file + ): """Test get_workflow_steps uses JSON logs when available.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [json_webhook_data_simple]) # Get workflow steps (should use JSON, not fall back to text) result = await controller.get_workflow_steps("test-hook-123") @@ -420,24 +395,24 @@ async def test_get_workflow_steps_falls_back_to_text_logs(self, controller, tmp_ assert result["token_spend"] == 15 async def test_get_workflow_steps_json_searches_multiple_files( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file ): """Test get_workflow_steps_json searches through multiple JSON log files.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create multiple JSON log files - entry1 = sample_json_webhook_data.copy() + entry1 = json_webhook_data_simple.copy() entry1["hook_id"] = "hook-file1" - self.create_json_log_file(log_dir, "webhooks_2025-01-01.json", [entry1]) + create_json_log_file(log_dir, "webhooks_2025-01-01.json", [entry1]) - entry2 = sample_json_webhook_data.copy() + entry2 = json_webhook_data_simple.copy() entry2["hook_id"] = "hook-file2" - self.create_json_log_file(log_dir, "webhooks_2025-01-02.json", [entry2]) + create_json_log_file(log_dir, "webhooks_2025-01-02.json", [entry2]) - entry3 = sample_json_webhook_data.copy() + entry3 = json_webhook_data_simple.copy() entry3["hook_id"] = "target-hook" - self.create_json_log_file(log_dir, "webhooks_2025-01-03.json", [entry3]) + create_json_log_file(log_dir, "webhooks_2025-01-03.json", [entry3]) # Search for hook in third file result = await controller.get_workflow_steps_json("target-hook") @@ -445,7 +420,9 @@ async def test_get_workflow_steps_json_searches_multiple_files( # Should find it assert result["hook_id"] == "target-hook" - async def test_get_workflow_steps_json_fails_fast_on_missing_required_fields(self, controller, tmp_path): + async def test_get_workflow_steps_json_fails_fast_on_missing_required_fields( + self, controller, tmp_path, create_json_log_file + ): """Test get_workflow_steps_json raises HTTPException when required fields are missing. Required fields (timing, workflow_steps) must be present and valid. @@ -460,7 +437,7 @@ async def test_get_workflow_steps_json_fails_fast_on_missing_required_fields(sel # Missing: timing, workflow_steps (required fields) } - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [minimal_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [minimal_data]) # Should raise HTTPException 500 for malformed log entry # (distinguishing from 404 "not found" case) @@ -470,19 +447,62 @@ async def test_get_workflow_steps_json_fails_fast_on_missing_required_fields(sel assert exc_info.value.status_code == 500 assert exc_info.value.detail == "Malformed log entry" + async def test_get_workflow_steps_json_fails_fast_on_step_missing_timestamp( + self, controller, tmp_path, create_json_log_file + ): + """Test get_workflow_steps_json raises HTTPException when a step is missing timestamp. + + Each workflow step must have a timestamp. Missing timestamps indicate malformed + log data and should fail fast with 500 instead of flowing bad data to UI. + """ + log_dir = tmp_path / "logs" + log_dir.mkdir() + + # Create JSON log entry with valid structure but step missing timestamp + data_with_missing_step_timestamp = { + "hook_id": "hook-missing-step-ts", + "event_type": "pull_request", + "repository": "org/repo", + "timing": { + "started_at": "2025-01-05T10:00:00.000000Z", + "duration_ms": 5000, + }, + "workflow_steps": { + "step_with_timestamp": { + "timestamp": "2025-01-05T10:00:01.000000Z", + "status": "completed", + "duration_ms": 1000, + }, + "step_missing_timestamp": { + # Missing timestamp field + "status": "completed", + "duration_ms": 500, + }, + }, + } + + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [data_with_missing_step_timestamp]) + + # Should raise HTTPException 500 for malformed log entry + with pytest.raises(HTTPException) as exc_info: + await controller.get_workflow_steps_json("hook-missing-step-ts") + + assert exc_info.value.status_code == 500 + assert exc_info.value.detail == "Malformed log entry" + async def test_stream_json_log_entries_handles_file_read_errors( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file ): """Test _stream_json_log_entries handles file read errors gracefully.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create a valid JSON log file - self.create_json_log_file(log_dir, "webhooks_valid.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_valid.json", [json_webhook_data_simple]) # Create a file that will cause read error (simulate by making it unreadable) bad_file = log_dir / "webhooks_bad.json" - bad_file.write_text(json.dumps(sample_json_webhook_data)) + bad_file.write_text(json.dumps(json_webhook_data_simple)) bad_file.chmod(0o000) # Remove all permissions try: @@ -499,26 +519,26 @@ async def test_stream_json_log_entries_handles_file_read_errors( bad_file.chmod(0o644) async def test_get_workflow_steps_json_with_multiple_entries_same_file( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, json_webhook_data_simple, create_json_log_file ): """Test get_workflow_steps_json finds correct entry in file with multiple hooks.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file with multiple hook entries (deep copy to avoid reference issues) - entry1 = copy.deepcopy(sample_json_webhook_data) + entry1 = copy.deepcopy(json_webhook_data_simple) entry1["hook_id"] = "hook-1" entry1["pr"]["number"] = 100 - entry2 = copy.deepcopy(sample_json_webhook_data) + entry2 = copy.deepcopy(json_webhook_data_simple) entry2["hook_id"] = "target-hook" entry2["pr"]["number"] = 200 - entry3 = copy.deepcopy(sample_json_webhook_data) + entry3 = copy.deepcopy(json_webhook_data_simple) entry3["hook_id"] = "hook-3" entry3["pr"]["number"] = 300 - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [entry1, entry2, entry3]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [entry1, entry2, entry3]) # Search for middle entry result = await controller.get_workflow_steps_json("target-hook") @@ -767,11 +787,6 @@ async def test_stream_log_entries_empty_json_file(self, controller, tmp_path): class TestLogViewerGetLogEntries: """Test cases for get_log_entries method.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger for testing.""" - return Mock() - @pytest.fixture def controller(self, mock_logger, tmp_path): """Create a LogViewerController instance with mocked config.""" @@ -977,11 +992,6 @@ async def mock_stream_error(*args: object, **kwargs: object) -> AsyncIterator[Lo class TestLogViewerExportLogs: """Test cases for export_logs method.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger for testing.""" - return Mock() - @pytest.fixture def controller(self, mock_logger, tmp_path): """Create a LogViewerController instance with mocked config.""" @@ -1050,11 +1060,6 @@ async def test_export_logs_with_filters(self, controller, tmp_path): class TestLogViewerShutdown: """Test cases for shutdown method.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger for testing.""" - return Mock() - @pytest.fixture def controller(self, mock_logger, tmp_path): """Create a LogViewerController instance with mocked config.""" @@ -1110,11 +1115,6 @@ async def mock_close_error(code: int, reason: str) -> None: class TestLogViewerGetLogPage: """Test cases for get_log_page method.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger for testing.""" - return Mock() - @pytest.fixture def controller(self, mock_logger, tmp_path): """Create a LogViewerController instance with mocked config.""" @@ -1151,11 +1151,6 @@ async def mock_get_html() -> str: class TestLogViewerHelpers: """Test cases for helper methods.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger for testing.""" - return Mock() - @pytest.fixture def controller(self, mock_logger, tmp_path): """Create a LogViewerController instance with mocked config.""" @@ -1252,11 +1247,6 @@ def test_generate_json_export(self, controller): class TestLogViewerGetStepLogs: """Test cases for get_step_logs method.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger for testing.""" - return Mock() - @pytest.fixture def controller(self, mock_logger, tmp_path): """Create a LogViewerController instance with mocked config.""" @@ -1266,70 +1256,15 @@ def controller(self, mock_logger, tmp_path): mock_config.return_value = mock_config_instance return LogViewerController(logger=mock_logger) - @pytest.fixture - def sample_json_webhook_data(self) -> dict: - """Create sample JSON webhook log data with workflow steps.""" - return { - "hook_id": "test-hook-123", - "event_type": "pull_request", - "action": "opened", - "repository": "org/test-repo", - "sender": "test-user", - "pr": { - "number": 456, - "title": "Test PR", - "url": "https://github.com/org/test-repo/pull/456", - }, - "timing": { - "started_at": "2025-01-05T10:00:00.000000Z", - "completed_at": "2025-01-05T10:00:05.000000Z", - "duration_ms": 5000, - }, - "workflow_steps": { - "clone_repository": { - "timestamp": "2025-01-05T10:00:01.000000Z", - "status": "completed", - "duration_ms": 1500, - }, - "assign_reviewers": { - "timestamp": "2025-01-05T10:00:02.500000Z", - "status": "completed", - "duration_ms": 800, - }, - "apply_labels": { - "timestamp": "2025-01-05T10:00:03.500000Z", - "status": "failed", - "duration_ms": 200, - "error": {"type": "ValueError", "message": "Label not found"}, - }, - }, - "token_spend": 35, - "success": False, - } - - def create_json_log_file(self, log_dir: Path, filename: str, entries: list[dict]) -> Path: - """Create a test JSON log file with entries.""" - log_file = log_dir / filename - with open(log_file, "w", encoding="utf-8") as f: - for entry in entries: - f.write(json.dumps(entry) + "\n") - return log_file - - def create_text_log_file(self, log_dir: Path, filename: str, log_lines: list[str]) -> Path: - """Create a test text log file with log lines.""" - log_file = log_dir / filename - with open(log_file, "w", encoding="utf-8") as f: - for line in log_lines: - f.write(line + "\n") - return log_file - - async def test_get_step_logs_returns_step_metadata_and_logs(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_step_logs_returns_step_metadata_and_logs( + self, controller, tmp_path, sample_json_webhook_data, create_json_log_file, create_text_log_file + ): """Test get_step_logs returns step metadata and associated log entries.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) # Create text log file with entries during clone_repository step log_lines = [ @@ -1341,7 +1276,7 @@ async def test_get_step_logs_returns_step_metadata_and_logs(self, controller, tm "2025-01-05T10:00:05.000000 GithubWebhook INFO org/test-repo " "[pull_request][test-hook-123][test-user][PR 456]: Processing complete", ] - self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + create_text_log_file(log_dir, "webhook-server.log", log_lines) # Get logs for clone_repository step result = await controller.get_step_logs("test-hook-123", "clone_repository") @@ -1361,13 +1296,15 @@ async def test_get_step_logs_returns_step_metadata_and_logs(self, controller, tm assert any("Cloning repository" in msg for msg in log_messages) assert any("Clone completed" in msg for msg in log_messages) - async def test_get_step_logs_hook_id_not_found(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_step_logs_hook_id_not_found( + self, controller, tmp_path, sample_json_webhook_data, create_json_log_file + ): """Test get_step_logs raises 404 when hook_id is not found.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file with different hook_id - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) # Try to get logs for non-existent hook_id with pytest.raises(HTTPException) as exc: @@ -1376,13 +1313,15 @@ async def test_get_step_logs_hook_id_not_found(self, controller, tmp_path, sampl assert exc.value.status_code == 404 assert "No JSON log entry found" in str(exc.value.detail) - async def test_get_step_logs_step_name_not_found(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_step_logs_step_name_not_found( + self, controller, tmp_path, sample_json_webhook_data, create_json_log_file + ): """Test get_step_logs raises 404 when step_name is not found.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) # Try to get logs for non-existent step_name with pytest.raises(HTTPException) as exc: @@ -1391,13 +1330,15 @@ async def test_get_step_logs_step_name_not_found(self, controller, tmp_path, sam assert exc.value.status_code == 404 assert "Step 'non_existent_step' not found" in str(exc.value.detail) - async def test_get_step_logs_with_failed_step(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_step_logs_with_failed_step( + self, controller, tmp_path, sample_json_webhook_data, create_json_log_file + ): """Test get_step_logs returns error information for failed step.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) # Get logs for failed step result = await controller.get_step_logs("test-hook-123", "apply_labels") @@ -1407,7 +1348,9 @@ async def test_get_step_logs_with_failed_step(self, controller, tmp_path, sample assert result["step"]["status"] == "failed" assert result["step"]["error"]["message"] == "Label not found" - async def test_get_step_logs_uses_default_duration_when_missing(self, controller, tmp_path): + async def test_get_step_logs_uses_default_duration_when_missing( + self, controller, tmp_path, create_json_log_file, create_text_log_file + ): """Test get_step_logs uses 60 second default when duration_ms is missing.""" log_dir = tmp_path / "logs" log_dir.mkdir() @@ -1431,7 +1374,7 @@ async def test_get_step_logs_uses_default_duration_when_missing(self, controller }, } - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) # Create text log with entry within 60 second default window log_lines = [ @@ -1441,7 +1384,7 @@ async def test_get_step_logs_uses_default_duration_when_missing(self, controller "2025-01-05T10:02:00.000000 GithubWebhook INFO org/repo " "[pull_request][test-hook-456][user][PR 789]: Outside window", ] - self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + create_text_log_file(log_dir, "webhook-server.log", log_lines) result = await controller.get_step_logs("test-hook-456", "step_no_duration") @@ -1451,7 +1394,7 @@ async def test_get_step_logs_uses_default_duration_when_missing(self, controller assert result["log_count"] == 1 assert "Within default window" in result["logs"][0]["message"] - async def test_get_step_logs_raises_on_invalid_timestamp(self, controller, tmp_path): + async def test_get_step_logs_raises_on_invalid_timestamp(self, controller, tmp_path, create_json_log_file): """Test get_step_logs raises HTTPException for invalid step timestamp.""" log_dir = tmp_path / "logs" log_dir.mkdir() @@ -1475,7 +1418,7 @@ async def test_get_step_logs_raises_on_invalid_timestamp(self, controller, tmp_p }, } - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) # Should raise HTTPException 500 for invalid timestamp with pytest.raises(HTTPException) as exc: @@ -1485,8 +1428,13 @@ async def test_get_step_logs_raises_on_invalid_timestamp(self, controller, tmp_p assert "Invalid timestamp 'invalid-timestamp'" in exc.value.detail assert "step_bad_timestamp" in exc.value.detail - async def test_get_step_logs_raises_on_missing_timestamp(self, controller, tmp_path): - """Test get_step_logs raises HTTPException for missing step timestamp.""" + async def test_get_step_logs_raises_on_missing_timestamp(self, controller, tmp_path, create_json_log_file): + """Test get_step_logs raises HTTPException for missing step timestamp. + + Note: Steps missing timestamps are caught during early validation in + _transform_json_entry_to_timeline and return a generic "Malformed log entry" + error to avoid exposing internal details. + """ log_dir = tmp_path / "logs" log_dir.mkdir() @@ -1508,25 +1456,24 @@ async def test_get_step_logs_raises_on_missing_timestamp(self, controller, tmp_p }, } - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [webhook_data]) - # Should raise HTTPException 500 for missing timestamp + # Should raise HTTPException 500 for malformed log entry (missing timestamp caught early) with pytest.raises(HTTPException) as exc: await controller.get_step_logs("test-hook-missing", "step_no_timestamp") assert exc.value.status_code == 500 - assert "has no timestamp" in exc.value.detail - assert "step_no_timestamp" in exc.value.detail + assert exc.value.detail == "Malformed log entry" async def test_get_step_logs_empty_logs_when_no_entries_in_window( - self, controller, tmp_path, sample_json_webhook_data + self, controller, tmp_path, sample_json_webhook_data, create_json_log_file, create_text_log_file ): """Test get_step_logs returns empty logs when no entries match time window.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) # Create text log file with entries outside step time window log_lines = [ @@ -1537,7 +1484,7 @@ async def test_get_step_logs_empty_logs_when_no_entries_in_window( "2025-01-05T10:00:10.000000 GithubWebhook INFO org/test-repo " "[pull_request][test-hook-123][test-user][PR 456]: After step", ] - self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + create_text_log_file(log_dir, "webhook-server.log", log_lines) result = await controller.get_step_logs("test-hook-123", "clone_repository") @@ -1546,13 +1493,15 @@ async def test_get_step_logs_empty_logs_when_no_entries_in_window( assert result["log_count"] == 0 assert result["logs"] == [] - async def test_get_step_logs_filters_by_hook_id(self, controller, tmp_path, sample_json_webhook_data): + async def test_get_step_logs_filters_by_hook_id( + self, controller, tmp_path, sample_json_webhook_data, create_json_log_file, create_text_log_file + ): """Test get_step_logs only returns logs matching the hook_id.""" log_dir = tmp_path / "logs" log_dir.mkdir() # Create JSON log file - self.create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) + create_json_log_file(log_dir, "webhooks_2025-01-05.json", [sample_json_webhook_data]) # Create text log file with entries from different hook_ids log_lines = [ @@ -1561,7 +1510,7 @@ async def test_get_step_logs_filters_by_hook_id(self, controller, tmp_path, samp "2025-01-05T10:00:01.200000 GithubWebhook INFO org/test-repo " "[pull_request][other-hook-999][other-user][PR 789]: Wrong hook", ] - self.create_text_log_file(log_dir, "webhook-server.log", log_lines) + create_text_log_file(log_dir, "webhook-server.log", log_lines) result = await controller.get_step_logs("test-hook-123", "clone_repository") diff --git a/webhook_server/web/log_viewer.py b/webhook_server/web/log_viewer.py index 7e8d2ac3..5f186225 100644 --- a/webhook_server/web/log_viewer.py +++ b/webhook_server/web/log_viewer.py @@ -769,6 +769,9 @@ def _transform_json_entry_to_timeline(self, entry: dict[str, Any], hook_id: str) raise ValueError(f"Malformed log entry for hook_id {hook_id}: step_data for {step_name} is not a dict") step_timestamp = step_data.get("timestamp") + # Fail fast if timestamp is missing - don't flow bad data to UI + if not step_timestamp: + raise ValueError(f"Malformed log entry for hook_id {hook_id}: step '{step_name}' is missing timestamp") step_status = step_data.get("status", "unknown") step_duration_ms = step_data.get("duration_ms") step_error = step_data.get("error") From 1570ba1e61a1ea3596796a0accfe4b9cc2410ec4 Mon Sep 17 00:00:00 2001 From: rnetser Date: Wed, 21 Jan 2026 19:29:39 +0200 Subject: [PATCH 14/15] fix(tests): remove unused tmp_path parameters from fixtures Remove unused tmp_path fixture parameters from create_json_log_file and create_text_log_file fixtures to fix ARG001 linting warnings. --- webhook_server/tests/conftest.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/webhook_server/tests/conftest.py b/webhook_server/tests/conftest.py index 114ecfeb..9e441316 100644 --- a/webhook_server/tests/conftest.py +++ b/webhook_server/tests/conftest.py @@ -260,10 +260,11 @@ def sample_json_webhook_data() -> dict: @pytest.fixture -def create_json_log_file(tmp_path): +def create_json_log_file(): """Factory fixture to create test JSON log files. - Returns a callable that creates JSON log files in the provided directory. + Returns a callable that accepts log_dir, filename, and entries parameters. + Tests pass their own tmp_path to the returned factory function. Usage: def test_example(create_json_log_file, tmp_path): @@ -293,10 +294,11 @@ def _create_json_log_file(log_dir: Path, filename: str, entries: list[dict]) -> @pytest.fixture -def create_text_log_file(tmp_path): +def create_text_log_file(): """Factory fixture to create test text log files. - Returns a callable that creates text log files in the provided directory. + Returns a callable that accepts log_dir, filename, and log_lines parameters. + Tests pass their own tmp_path to the returned factory function. Usage: def test_example(create_text_log_file, tmp_path): From cdb2902999e7cb0d74a1ade448a1c748ec4a9fcd Mon Sep 17 00:00:00 2001 From: rnetser Date: Wed, 21 Jan 2026 20:34:33 +0200 Subject: [PATCH 15/15] fix(tests): improve test fixtures to mirror production behavior - Update mock_logger to use spec=logging.Logger with realistic attributes - Add error field to sample_json_webhook_data when success is False - Document JSONL format in create_json_log_file fixture --- webhook_server/tests/conftest.py | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-) diff --git a/webhook_server/tests/conftest.py b/webhook_server/tests/conftest.py index 9e441316..355fb183 100644 --- a/webhook_server/tests/conftest.py +++ b/webhook_server/tests/conftest.py @@ -210,8 +210,11 @@ def owners_files_test_data(): @pytest.fixture def mock_logger(): - """Create a mock logger for testing log viewer components.""" - return Mock() + """Create a mock logger that mirrors production logger attributes.""" + mock = Mock(spec=python_logging.Logger) + mock.name = "webhook_server.tests" + mock.level = python_logging.INFO + return mock @pytest.fixture @@ -256,6 +259,10 @@ def sample_json_webhook_data() -> dict: }, "token_spend": 35, "success": False, + "error": { + "type": "TestError", + "message": "Test failure message for unit tests", + }, } @@ -274,7 +281,11 @@ def test_example(create_json_log_file, tmp_path): """ def _create_json_log_file(log_dir: Path, filename: str, entries: list[dict]) -> Path: - """Create a test JSON log file with entries. + """Create a test JSON log file with entries in JSONL format. + + The log viewer expects JSONL format (JSON Lines): one compact JSON object per line. + This matches production behavior where each webhook log entry is written as a single + line for efficient streaming and parsing. Args: log_dir: Directory to create the log file in @@ -287,6 +298,8 @@ def _create_json_log_file(log_dir: Path, filename: str, entries: list[dict]) -> log_file = log_dir / filename with open(log_file, "w", encoding="utf-8") as f: for entry in entries: + # JSONL format: one compact JSON object per line (no indentation) + # This matches production log format and log_viewer._stream_json_log_entries() f.write(json.dumps(entry) + "\n") return log_file