diff --git a/src/agents/acknowledgment_agent/agent.py b/src/agents/acknowledgment_agent/agent.py index 80b6e58..a1c882a 100644 --- a/src/agents/acknowledgment_agent/agent.py +++ b/src/agents/acknowledgment_agent/agent.py @@ -2,16 +2,16 @@ Intelligent Acknowledgment Agent for evaluating violation acknowledgment requests. """ -import logging from typing import Any +import structlog from langchain_core.messages import HumanMessage, SystemMessage from langgraph.graph import StateGraph from src.agents.acknowledgment_agent.prompts import create_evaluation_prompt, get_system_prompt from src.agents.base import AgentResult, BaseAgent -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class AcknowledgmentAgent(BaseAgent): @@ -29,7 +29,7 @@ def __init__(self, max_retries: int = 3, timeout: float = 30.0): # Call super class __init__ first super().__init__(max_retries=max_retries) self.timeout = timeout - logger.info(f"🧠 Acknowledgment agent initialized with timeout: {timeout}s") + logger.info("acknowledgment_agent_initialized_with_timeout_s", timeout=timeout) def _build_graph(self) -> StateGraph: """ @@ -62,7 +62,7 @@ async def _evaluate_node(self, state): ) return result except Exception as e: - logger.error(f"🧠 Error in evaluation node: {e}") + logger.error("error_in_evaluation_node", e=e) return AgentResult(success=False, message=f"Evaluation failed: {str(e)}", data={"error": str(e)}) @staticmethod @@ -85,8 +85,8 @@ async def evaluate_acknowledgment( Intelligently evaluate an acknowledgment request based on rule descriptions and context. """ try: - logger.info(f"🧠 Evaluating acknowledgment request from {commenter}") - logger.info(f"🧠 Reason: {acknowledgment_reason}") + logger.info("evaluating_acknowledgment_request_from", commenter=commenter) + logger.info("reason", acknowledgment_reason=acknowledgment_reason) logger.info(f"🧠 Violations to evaluate: {len(violations)}") # Validate inputs @@ -101,7 +101,7 @@ async def evaluate_acknowledgment( evaluation_prompt = create_evaluation_prompt(acknowledgment_reason, violations, pr_data, commenter, rules) # Get LLM evaluation with structured output - logger.info("🧠 Requesting LLM evaluation with structured output...") + logger.info("requesting_llm_evaluation_with_structured_output") # Use the same pattern as engine agent: direct structured output from langchain_openai import ChatOpenAI @@ -117,12 +117,12 @@ async def evaluate_acknowledgment( structured_result = await self._execute_with_timeout(structured_llm.ainvoke(messages), timeout=self.timeout) if not structured_result: - logger.error("🧠 Empty LLM response received") + logger.error("empty_llm_response_received") return AgentResult( success=False, message="Empty response from LLM", data={"error": "LLM returned empty response"} ) - logger.info("🧠 Successfully received structured LLM evaluation result") + logger.info("successfully_received_structured_llm_evaluation_result") # Map LLM decisions back to original violations using rule_description acknowledgable_violations = [] @@ -143,11 +143,9 @@ async def evaluate_acknowledgment( # Fallback: try to find by rule_description original_violation = self._find_violation_by_rule_description(rule_description, violations) if original_violation: - logger.info(f"🧠 Found violation by rule description: '{rule_description}'") + logger.info("found_violation_by_rule_description", rule_description=rule_description) else: - logger.warning( - f"🧠 LLM returned rule_description '{rule_description}' not found in original violations" - ) + logger.warning("llm_returned_ruledescription_not_found_in", rule_description=rule_description) if original_violation: violation_copy = original_violation.copy() @@ -173,11 +171,9 @@ async def evaluate_acknowledgment( # Fallback: try to find by rule_description original_violation = self._find_violation_by_rule_description(rule_description, violations) if original_violation: - logger.info(f"🧠 Found violation by rule description: '{rule_description}'") + logger.info("found_violation_by_rule_description", rule_description=rule_description) else: - logger.warning( - f"🧠 LLM returned rule_description '{rule_description}' not found in original violations" - ) + logger.warning("llm_returned_ruledescription_not_found_in", rule_description=rule_description) if original_violation: violation_copy = original_violation.copy() @@ -185,12 +181,12 @@ async def evaluate_acknowledgment( violation_copy.update({"fix_reason": llm_violation.reason, "priority": llm_violation.priority}) require_fixes.append(violation_copy) - logger.info("🧠 Intelligent evaluation completed:") - logger.info(f" Valid: {structured_result.is_valid}") - logger.info(f" Reasoning: {structured_result.reasoning}") + logger.info("intelligent_evaluation_completed") + logger.info("valid", is_valid=structured_result.is_valid) + logger.info("reasoning", reasoning=structured_result.reasoning) logger.info(f" Acknowledged violations: {len(acknowledgable_violations)}") logger.info(f" Require fixes: {len(require_fixes)}") - logger.info(f" Confidence: {structured_result.confidence}") + logger.info("confidence", confidence=structured_result.confidence) return AgentResult( success=True, @@ -206,7 +202,7 @@ async def evaluate_acknowledgment( ) except Exception as e: - logger.error(f"🧠 Error in acknowledgment evaluation: {e}") + logger.error("error_in_acknowledgment_evaluation", e=e) import traceback logger.error(f"🧠 Traceback: {traceback.format_exc()}") @@ -218,5 +214,5 @@ async def execute(self, event_type: str, event_data: dict[str, Any], rules: list """ Legacy method for compatibility - not used for acknowledgment evaluation. """ - logger.warning("🧠 execute() method called on AcknowledgmentAgent - this should not happen") + logger.warning("execute_method_called_on_acknowledgmentagent_this") return AgentResult(success=False, message="AcknowledgmentAgent does not support execute() method", data={}) diff --git a/src/agents/acknowledgment_agent/test_agent.py b/src/agents/acknowledgment_agent/test_agent.py index 5bf5b58..bbf8aa0 100644 --- a/src/agents/acknowledgment_agent/test_agent.py +++ b/src/agents/acknowledgment_agent/test_agent.py @@ -3,13 +3,13 @@ """ import asyncio -import logging + +import structlog from .agent import AcknowledgmentAgent # Set up logging -logging.basicConfig(level=logging.INFO) -logger = logging.getLogger(__name__) +logger = structlog.get_logger() async def test_acknowledgment_agent(): @@ -69,7 +69,7 @@ async def test_acknowledgment_agent(): }, ] - logger.info("🧠 Testing Intelligent Acknowledgment Agent...") + logger.info("testing_intelligent_acknowledgment_agent") try: # Test evaluation @@ -82,7 +82,7 @@ async def test_acknowledgment_agent(): ) if result.success: - logger.info("āœ… Acknowledgment evaluation completed successfully") + logger.info("acknowledgment_evaluation_completed_successfully") logger.info(f" Valid: {result.data.get('is_valid', False)}") logger.info(f" Reasoning: {result.data.get('reasoning', 'No reasoning')}") logger.info(f" Acknowledged violations: {len(result.data.get('acknowledgable_violations', []))}") @@ -91,25 +91,25 @@ async def test_acknowledgment_agent(): # Print detailed results if result.data.get("acknowledgable_violations"): - logger.info("\nšŸ“‹ Acknowledged Violations:") + logger.info("n_acknowledged_violations") for violation in result.data["acknowledgable_violations"]: logger.info(f" • {violation.get('rule_name')} - {violation.get('reason')}") if result.data.get("require_fixes"): - logger.info("\nāš ļø Violations Requiring Fixes:") + logger.info("n_violations_requiring_fixes") for violation in result.data["require_fixes"]: logger.info(f" • {violation.get('rule_name')} - {violation.get('reason')}") if result.data.get("recommendations"): - logger.info("\nšŸ’” Recommendations:") + logger.info("n_recommendations") for rec in result.data["recommendations"]: - logger.info(f" • {rec}") + logger.info("event", rec=rec) else: - logger.error(f"āŒ Acknowledgment evaluation failed: {result.message}") + logger.error("acknowledgment_evaluation_failed", message=result.message) except Exception as e: - logger.error(f"āŒ Test failed with error: {e}") + logger.error("test_failed_with_error", e=e) if __name__ == "__main__": diff --git a/src/agents/base.py b/src/agents/base.py index caf167c..7c4005a 100644 --- a/src/agents/base.py +++ b/src/agents/base.py @@ -3,15 +3,15 @@ """ import asyncio -import logging from abc import ABC, abstractmethod from typing import Any, TypeVar +import structlog from langchain_openai import ChatOpenAI from src.core.config import config -logger = logging.getLogger(__name__) +logger = structlog.get_logger() T = TypeVar("T") @@ -53,7 +53,7 @@ def __init__(self, max_retries: int = 3, retry_delay: float = 1.0): temperature=config.ai.temperature, ) self.graph = self._build_graph() - logger.info(f"šŸ”§ {self.__class__.__name__} initialized with max_retries={max_retries}") + logger.info("initialized_with_maxretries", __name__=self.__class__.__name__, max_retries=max_retries) @abstractmethod def _build_graph(self): @@ -82,15 +82,15 @@ async def _retry_structured_output(self, llm, output_model, prompt, **kwargs) -> try: result = await structured_llm.ainvoke(prompt, **kwargs) if attempt > 0: - logger.info(f"āœ… Structured output succeeded on attempt {attempt + 1}") + logger.info("structured_output_succeeded_on_attempt") return result except Exception as e: if attempt == self.max_retries - 1: - logger.error(f"āŒ Structured output failed after {self.max_retries} attempts: {e}") + logger.error("structured_output_failed_after_attempts", max_retries=self.max_retries, e=e) raise Exception(f"Structured output failed after {self.max_retries} attempts: {str(e)}") from e wait_time = self.retry_delay * (2**attempt) - logger.warning(f"āš ļø Structured output attempt {attempt + 1} failed, retrying in {wait_time}s: {e}") + logger.warning("structured_output_attempt_failed_retrying_in", wait_time=wait_time, e=e) await asyncio.sleep(wait_time) raise Exception(f"Structured output failed after {self.max_retries} attempts") diff --git a/src/agents/engine_agent/agent.py b/src/agents/engine_agent/agent.py index f64c307..e5ec30b 100644 --- a/src/agents/engine_agent/agent.py +++ b/src/agents/engine_agent/agent.py @@ -4,10 +4,10 @@ Focuses on rule descriptions and parameters, using fast validators with LLM reasoning as fallback. """ -import logging import time from typing import Any +import structlog from langgraph.graph import END, START, StateGraph from src.agents.base import AgentResult, BaseAgent @@ -28,7 +28,7 @@ ) from src.rules.validators import get_validator_descriptions -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class RuleEngineAgent(BaseAgent): @@ -47,9 +47,9 @@ def __init__(self, max_retries: int = 3, timeout: float = 60.0): super().__init__(max_retries=max_retries) self.timeout = timeout - logger.info("šŸ”§ Rule Engine agent initializing...") + logger.info("rule_engine_agent_initializing") logger.info(f"šŸ”§ Available validators: {list(get_validator_descriptions())}") - logger.info("šŸ”§ Validation strategy: Hybrid (validators + LLM fallback)") + logger.info("validation_strategy_hybrid_validators_llm_fallback") def _build_graph(self) -> StateGraph: """Build the LangGraph workflow for hybrid rule evaluation.""" @@ -102,13 +102,13 @@ async def execute(self, event_type: str, event_data: dict[str, Any], rules: list llm_usage=0, ) - logger.info("šŸ”§ Rule Engine initial state prepared") + logger.info("rule_engine_initial_state_prepared") # Run the hybrid graph with timeout result = await self._execute_with_timeout(self.graph.ainvoke(initial_state), timeout=self.timeout) execution_time = time.time() - start_time - logger.info(f"šŸ”§ Rule Engine evaluation completed in {execution_time:.2f}s") + logger.info("rule_engine_evaluation_completed_in_s") # Extract violations from result violations = result.violations if hasattr(result, "violations") else [] @@ -143,9 +143,9 @@ async def execute(self, event_type: str, event_data: dict[str, Any], rules: list llm_usage=result.llm_usage if hasattr(result, "llm_usage") else 0, ) - logger.info("šŸ”§ Rule Engine evaluation completed successfully") - logger.info(f"šŸ”§ Validator usage: {evaluation_result.validator_usage}") - logger.info(f"šŸ”§ LLM usage: {evaluation_result.llm_usage} calls") + logger.info("rule_engine_evaluation_completed_successfully") + logger.info("validator_usage", validator_usage=evaluation_result.validator_usage) + logger.info("llm_usage_calls", llm_usage=evaluation_result.llm_usage) return AgentResult( success=len(violations) == 0, @@ -160,7 +160,7 @@ async def execute(self, event_type: str, event_data: dict[str, Any], rules: list ) except Exception as e: execution_time = time.time() - start_time - logger.error(f"šŸ”§ Error in Rule Engine evaluation: {e}") + logger.error("error_in_rule_engine_evaluation", e=e) return AgentResult( success=False, message=f"Rule Engine evaluation failed: {str(e)}", @@ -233,5 +233,5 @@ async def evaluate( async def evaluate_pull_request(self, rules: list[Any], event_data: dict[str, Any]) -> dict[str, Any]: """Legacy method for backwards compatibility.""" - logger.warning("evaluate_pull_request is deprecated. Use evaluate() with event_type='pull_request'") + logger.warning("evaluatepullrequest_is_deprecated_use_evaluate_with") return await self.evaluate("pull_request", rules, event_data, "") diff --git a/src/agents/engine_agent/models.py b/src/agents/engine_agent/models.py index 16af0a8..213c0df 100644 --- a/src/agents/engine_agent/models.py +++ b/src/agents/engine_agent/models.py @@ -2,13 +2,13 @@ Data models for the Rule Engine Agent. """ -from enum import Enum +from enum import StrEnum from typing import Any from pydantic import BaseModel, Field -class ValidationStrategy(str, Enum): +class ValidationStrategy(StrEnum): """Validation strategies for rule evaluation.""" VALIDATOR = "validator" # Use fast validator diff --git a/src/agents/engine_agent/nodes.py b/src/agents/engine_agent/nodes.py index 703cbb9..82a4f65 100644 --- a/src/agents/engine_agent/nodes.py +++ b/src/agents/engine_agent/nodes.py @@ -3,10 +3,10 @@ """ import asyncio -import logging import time from typing import Any +import structlog from langchain_core.messages import HumanMessage, SystemMessage from langchain_openai import ChatOpenAI @@ -27,7 +27,7 @@ from src.core.config import config from src.rules.validators import VALIDATOR_REGISTRY -logger = logging.getLogger(__name__) +logger = structlog.get_logger() async def analyze_rule_descriptions(state: EngineState) -> EngineState: @@ -53,11 +53,11 @@ async def analyze_rule_descriptions(state: EngineState) -> EngineState: state.rule_descriptions = applicable_rules state.analysis_steps.append(f"Found {len(applicable_rules)} applicable rules out of {len(state.rules)} total") - analysis_time = (time.time() - start_time) * 1000 - logger.info(f"šŸ” Rule analysis completed in {analysis_time:.2f}ms") + (time.time() - start_time) * 1000 + logger.info("rule_analysis_completed_in_ms") except Exception as e: - logger.error(f"āŒ Error in rule analysis: {e}") + logger.error("error_in_rule_analysis", e=e) state.analysis_steps.append(f"Error in rule analysis: {str(e)}") return state @@ -93,18 +93,18 @@ async def select_validation_strategy(state: EngineState) -> EngineState: logger.info(f"šŸŽÆ Rule '{rule_desc.description[:50]}...' using {rule_desc.validation_strategy} strategy") if rule_desc.validator_name: - logger.info(f"šŸŽÆ Selected validator: {rule_desc.validator_name}") + logger.info("selected_validator", validator_name=rule_desc.validator_name) except Exception as e: logger.warning(f"āš ļø LLM strategy selection failed for rule '{rule_desc.description[:50]}...': {e}") rule_desc.validation_strategy = ValidationStrategy.HYBRID rule_desc.validator_name = None - strategy_time = (time.time() - start_time) * 1000 - logger.info(f"šŸŽÆ Strategy selection completed in {strategy_time:.2f}ms") + (time.time() - start_time) * 1000 + logger.info("strategy_selection_completed_in_ms") except Exception as e: - logger.error(f"āŒ Error in validation strategy selection: {e}") + logger.error("error_in_validation_strategy_selection", e=e) state.analysis_steps.append(f"Error in strategy selection: {str(e)}") return state @@ -123,7 +123,7 @@ async def execute_validator_evaluation(state: EngineState) -> EngineState: logger.info(f"⚔ Executing {len(validator_rules)} validator evaluations") if not validator_rules: - logger.info("⚔ No validator rules to evaluate") + logger.info("no_validator_rules_to_evaluate") return state # Execute validators concurrently @@ -154,11 +154,11 @@ async def execute_validator_evaluation(state: EngineState) -> EngineState: if validator_name: state.validator_usage[validator_name] = state.validator_usage.get(validator_name, 0) + 1 - validator_time = (time.time() - start_time) * 1000 - logger.info(f"⚔ Validator evaluation completed in {validator_time:.2f}ms") + (time.time() - start_time) * 1000 + logger.info("validator_evaluation_completed_in_ms") except Exception as e: - logger.error(f"āŒ Error in validator evaluation: {e}") + logger.error("error_in_validator_evaluation", e=e) state.analysis_steps.append(f"Error in validator evaluation: {str(e)}") return state @@ -179,7 +179,7 @@ async def execute_llm_fallback(state: EngineState) -> EngineState: logger.info(f"🧠 Executing {len(llm_rules)} LLM evaluations") if not llm_rules: - logger.info("🧠 No LLM rules to evaluate") + logger.info("no_llm_rules_to_evaluate") return state # Execute LLM evaluations concurrently (with rate limiting) @@ -217,11 +217,11 @@ async def execute_llm_fallback(state: EngineState) -> EngineState: # Track LLM usage state.llm_usage = len(llm_rules) - llm_time = (time.time() - start_time) * 1000 - logger.info(f"🧠 LLM evaluation completed in {llm_time:.2f}ms") + (time.time() - start_time) * 1000 + logger.info("llm_evaluation_completed_in_ms") except Exception as e: - logger.error(f"āŒ Error in LLM evaluation: {e}") + logger.error("error_in_llm_evaluation", e=e) state.analysis_steps.append(f"Error in LLM evaluation: {str(e)}") return state @@ -328,7 +328,7 @@ async def _generate_dynamic_how_to_fix( return how_to_fix_result.how_to_fix except Exception as e: - logger.error(f"āŒ Error generating how to fix message: {e}") + logger.error("error_generating_how_to_fix_message", e=e) # Fallback to generic message return f"Review and address the requirements for rule: {rule_desc.description}" diff --git a/src/agents/feasibility_agent/agent.py b/src/agents/feasibility_agent/agent.py index f7e5737..b4b3175 100644 --- a/src/agents/feasibility_agent/agent.py +++ b/src/agents/feasibility_agent/agent.py @@ -3,16 +3,16 @@ """ import asyncio -import logging import time +import structlog from langgraph.graph import END, START, StateGraph from src.agents.base import AgentResult, BaseAgent from src.agents.feasibility_agent.models import FeasibilityState from src.agents.feasibility_agent.nodes import analyze_rule_feasibility, generate_yaml_config -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class RuleFeasibilityAgent(BaseAgent): @@ -29,7 +29,7 @@ class RuleFeasibilityAgent(BaseAgent): def __init__(self, max_retries: int = 3, timeout: float = 30.0): super().__init__(max_retries=max_retries) self.timeout = timeout - logger.info(f"šŸ”§ FeasibilityAgent initialized with max_retries={max_retries}, timeout={timeout}s") + logger.info("feasibilityagent_initialized_with_maxretries_timeout_s", max_retries=max_retries, timeout=timeout) def _build_graph(self) -> StateGraph: """Build the LangGraph workflow for rule feasibility checking.""" @@ -51,7 +51,7 @@ def _build_graph(self) -> StateGraph: workflow.add_edge("generate_yaml", END) - logger.info("šŸ”§ FeasibilityAgent graph built with conditional structured output workflow") + logger.info("feasibilityagent_graph_built_with_conditional_structured") return workflow.compile() async def execute(self, rule_description: str) -> AgentResult: @@ -74,9 +74,12 @@ async def execute(self, rule_description: str) -> AgentResult: result = FeasibilityState(**result) execution_time = time.time() - start_time - logger.info(f"āœ… Feasibility analysis completed in {execution_time:.2f}s") + logger.info("feasibility_analysis_completed_in_s") logger.info( - f"āœ… Results: feasible={result.is_feasible}, type={result.rule_type}, confidence={result.confidence_score}" + "results_feasible_type_confidence", + is_feasible=result.is_feasible, + rule_type=result.rule_type, + confidence_score=result.confidence_score, ) # Convert to AgentResult with metadata @@ -99,7 +102,7 @@ async def execute(self, rule_description: str) -> AgentResult: except TimeoutError: execution_time = time.time() - start_time - logger.error(f"āŒ Feasibility analysis timed out after {execution_time:.2f}s") + logger.error("feasibility_analysis_timed_out_after_s") return AgentResult( success=False, message=f"Feasibility analysis timed out after {self.timeout}s", @@ -113,7 +116,7 @@ async def execute(self, rule_description: str) -> AgentResult: except Exception as e: execution_time = time.time() - start_time - logger.error(f"āŒ Feasibility analysis failed: {e}") + logger.error("feasibility_analysis_failed", e=e) return AgentResult( success=False, message=f"Feasibility analysis failed: {str(e)}", @@ -133,7 +136,7 @@ async def execute_with_retry(self, rule_description: str) -> AgentResult: result.metadata["retry_count"] = attempt return result else: - logger.warning(f"āš ļø Feasibility analysis failed on attempt {attempt + 1}") + logger.warning("feasibility_analysis_failed_on_attempt") if attempt == self.max_retries - 1: return result @@ -141,7 +144,7 @@ async def execute_with_retry(self, rule_description: str) -> AgentResult: await asyncio.sleep(self.retry_delay * (2**attempt)) except Exception as e: - logger.error(f"āŒ Exception on attempt {attempt + 1}: {e}") + logger.error("exception_on_attempt", e=e) if attempt == self.max_retries - 1: return AgentResult( success=False, diff --git a/src/agents/feasibility_agent/nodes.py b/src/agents/feasibility_agent/nodes.py index 4e6a676..b413d01 100644 --- a/src/agents/feasibility_agent/nodes.py +++ b/src/agents/feasibility_agent/nodes.py @@ -2,15 +2,14 @@ LangGraph nodes for the Rule Feasibility Agent with enhanced error handling. """ -import logging - +import structlog from langchain_openai import ChatOpenAI from src.agents.feasibility_agent.models import FeasibilityAnalysis, FeasibilityState, YamlGeneration from src.agents.feasibility_agent.prompts import RULE_FEASIBILITY_PROMPT, YAML_GENERATION_PROMPT from src.core.config import config -logger = logging.getLogger(__name__) +logger = structlog.get_logger() async def analyze_rule_feasibility(state: FeasibilityState) -> FeasibilityState: @@ -43,13 +42,13 @@ async def analyze_rule_feasibility(state: FeasibilityState) -> FeasibilityState: state.feedback = result.feedback state.analysis_steps = result.analysis_steps - logger.info(f"šŸ” Rule feasibility analysis completed: {state.is_feasible}") - logger.info(f"šŸ” Rule type identified: {state.rule_type}") - logger.info(f"šŸ” Confidence score: {state.confidence_score}") + logger.info("rule_feasibility_analysis_completed", is_feasible=state.is_feasible) + logger.info("rule_type_identified", rule_type=state.rule_type) + logger.info("confidence_score", confidence_score=state.confidence_score) logger.info(f"šŸ” Analysis steps: {len(state.analysis_steps)} steps") except Exception as e: - logger.error(f"āŒ Error in rule feasibility analysis: {e}") + logger.error("error_in_rule_feasibility_analysis", e=e) state.is_feasible = False state.feedback = f"Analysis failed: {str(e)}" state.confidence_score = 0.0 @@ -64,7 +63,7 @@ async def generate_yaml_config(state: FeasibilityState) -> FeasibilityState: This node only runs if the rule is feasible. """ if not state.is_feasible or not state.rule_type: - logger.info("šŸ”§ Skipping YAML generation - rule not feasible or no rule type") + logger.info("skipping_yaml_generation_rule_not_feasible") return state try: @@ -89,14 +88,14 @@ async def generate_yaml_config(state: FeasibilityState) -> FeasibilityState: # Basic validation of generated YAML if not state.yaml_content or len(state.yaml_content) < 10: - logger.warning("āš ļø Generated YAML seems too short, may be invalid") + logger.warning("generated_yaml_seems_too_short_may") state.feedback += "\nWarning: Generated YAML may be incomplete" - logger.info(f"šŸ”§ YAML configuration generated for rule type: {state.rule_type}") + logger.info("yaml_configuration_generated_for_rule_type", rule_type=state.rule_type) logger.info(f"šŸ”§ Generated YAML length: {len(state.yaml_content)} characters") except Exception as e: - logger.error(f"āŒ Error generating YAML configuration: {e}") + logger.error("error_generating_yaml_configuration", e=e) state.feedback += f"\nYAML generation failed: {str(e)}" state.yaml_content = "" diff --git a/src/agents/supervisor_agent/agent.py b/src/agents/supervisor_agent/agent.py index 303ca58..4cf25c7 100644 --- a/src/agents/supervisor_agent/agent.py +++ b/src/agents/supervisor_agent/agent.py @@ -3,10 +3,10 @@ """ import asyncio -import logging import time from typing import Any +import structlog from langgraph.graph import END, START, StateGraph from src.agents.acknowledgment_agent import AcknowledgmentAgent @@ -16,7 +16,7 @@ from src.agents.supervisor_agent.models import AgentTask, SupervisorAgentResult, SupervisorState from src.agents.supervisor_agent.nodes import coordinate_agents, synthesize_final_result, validate_results -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class RuleSupervisorAgent(SupervisorAgent): @@ -43,8 +43,8 @@ def __init__(self, max_concurrent_agents: int = 3, timeout: float = 60.0, **kwar } logger.info(f"šŸ”§ RuleSupervisorAgent initialized with {len(self.sub_agents)} sub-agents") - logger.info(f"šŸ”§ Max concurrent agents: {max_concurrent_agents}") - logger.info(f"šŸ”§ Timeout: {timeout}s") + logger.info("max_concurrent_agents", max_concurrent_agents=max_concurrent_agents) + logger.info("timeout_s", timeout=timeout) def _build_graph(self) -> StateGraph: """Build the LangGraph workflow for supervisor coordination.""" @@ -61,7 +61,7 @@ def _build_graph(self) -> StateGraph: workflow.add_edge("validate_results", "synthesize_final_result") workflow.add_edge("synthesize_final_result", END) - logger.info("šŸ”§ RuleSupervisorAgent graph built with coordination workflow") + logger.info("rulesupervisoragent_graph_built_with_coordination_workflow") return workflow.compile() async def execute( @@ -73,7 +73,7 @@ async def execute( start_time = time.time() try: - logger.info(f"šŸš€ RuleSupervisorAgent starting coordinated evaluation for {event_type}") + logger.info("rulesupervisoragent_starting_coordinated_evaluation_for", event_type=event_type) logger.info(f"šŸš€ Processing {len(rules)} rules with {len(self.sub_agents)} agents") # Prepare initial state @@ -89,7 +89,7 @@ async def execute( result = await self._execute_with_timeout(self.graph.ainvoke(initial_state), timeout=self.timeout) execution_time = time.time() - start_time - logger.info(f"āœ… RuleSupervisorAgent coordination completed in {execution_time:.2f}s") + logger.info("rulesupervisoragent_coordination_completed_in_s") # Extract coordination result coordination_result = result.get("coordination_result") @@ -114,7 +114,7 @@ async def execute( except TimeoutError: execution_time = time.time() - start_time - logger.error(f"ā° RuleSupervisorAgent coordination timed out after {execution_time:.2f}s") + logger.error("rulesupervisoragent_coordination_timed_out_after_s") return AgentResult( success=False, message=f"Supervisor coordination timed out after {self.timeout}s", @@ -128,7 +128,7 @@ async def execute( except Exception as e: execution_time = time.time() - start_time - logger.error(f"āŒ RuleSupervisorAgent coordination failed: {e}") + logger.error("rulesupervisoragent_coordination_failed", e=e) return AgentResult( success=False, message=f"Supervisor coordination failed: {str(e)}", @@ -141,7 +141,7 @@ async def coordinate_agents(self, task: str, **kwargs) -> AgentResult: Coordinate multiple agents to complete a complex task. """ try: - logger.info(f"šŸ”§ Coordinating agents for task: {task}") + logger.info("coordinating_agents_for_task", task=task) # Create tasks for each sub-agent tasks = [] @@ -162,7 +162,7 @@ async def coordinate_agents(self, task: str, **kwargs) -> AgentResult: agent_results = [] for result in results: if isinstance(result, Exception): - logger.error(f"āŒ Agent task failed: {result}") + logger.error("agent_task_failed", result=result) agent_results.append( SupervisorAgentResult(success=False, message=f"Agent task failed: {str(result)}", data={}) ) @@ -177,7 +177,7 @@ async def coordinate_agents(self, task: str, **kwargs) -> AgentResult: ) except Exception as e: - logger.error(f"āŒ Agent coordination failed: {e}") + logger.error("agent_coordination_failed", e=e) return AgentResult( success=False, message=f"Agent coordination failed: {str(e)}", @@ -194,7 +194,7 @@ async def _execute_agent_task(self, task: AgentTask) -> SupervisorAgentResult: if not agent: raise Exception(f"Unknown agent: {task.agent_name}") - logger.info(f"šŸ”§ Executing {task.agent_name} agent for {task.task_type}") + logger.info("executing_agent_for", agent_name=task.agent_name, task_type=task.task_type) # Execute the agent with timeout result = await asyncio.wait_for(agent.execute(**task.parameters), timeout=task.timeout) @@ -211,7 +211,7 @@ async def _execute_agent_task(self, task: AgentTask) -> SupervisorAgentResult: ) except TimeoutError: - logger.error(f"ā° {task.agent_name} agent timed out after {task.timeout}s") + logger.error("agent_timed_out_after_s", agent_name=task.agent_name, timeout=task.timeout) return SupervisorAgentResult( success=False, message=f"{task.agent_name} agent timed out after {task.timeout}s", @@ -220,7 +220,7 @@ async def _execute_agent_task(self, task: AgentTask) -> SupervisorAgentResult: ) except Exception as e: - logger.error(f"āŒ {task.agent_name} agent failed: {e}") + logger.error("agent_failed", agent_name=task.agent_name, e=e) return SupervisorAgentResult( success=False, message=f"{task.agent_name} agent failed: {str(e)}", diff --git a/src/agents/supervisor_agent/nodes.py b/src/agents/supervisor_agent/nodes.py index 80ac198..6f4fe03 100644 --- a/src/agents/supervisor_agent/nodes.py +++ b/src/agents/supervisor_agent/nodes.py @@ -3,12 +3,13 @@ """ import asyncio -import logging import time +import structlog + from src.agents.supervisor_agent.models import AgentTask, CoordinationResult, SupervisorAgentResult, SupervisorState -logger = logging.getLogger(__name__) +logger = structlog.get_logger() async def coordinate_agents(state: SupervisorState) -> SupervisorState: @@ -16,7 +17,7 @@ async def coordinate_agents(state: SupervisorState) -> SupervisorState: Coordinate multiple agents to execute tasks in parallel. """ try: - logger.info(f"šŸ”§ Starting agent coordination for {state.event_type}") + logger.info("starting_agent_coordination_for", event_type=state.event_type) # Create tasks for each agent based on the event type and rules tasks = _create_agent_tasks(state) @@ -35,7 +36,7 @@ async def coordinate_agents(state: SupervisorState) -> SupervisorState: logger.info(f"šŸ”§ Successful executions: {len(successful_results)}/{len(results)}") except Exception as e: - logger.error(f"āŒ Error in agent coordination: {e}") + logger.error("error_in_agent_coordination", e=e) state.errors.append(f"Coordination failed: {str(e)}") return state @@ -46,7 +47,7 @@ async def validate_results(state: SupervisorState) -> SupervisorState: Validate and cross-check results from multiple agents. """ try: - logger.info("šŸ” Validating agent results") + logger.info("validating_agent_results") # Check for conflicting results conflicts = _detect_result_conflicts(state.agent_results) @@ -60,10 +61,10 @@ async def validate_results(state: SupervisorState) -> SupervisorState: logger.warning(f"āš ļø Found {len(quality_issues)} quality issues") state.errors.extend(quality_issues) - logger.info("šŸ” Result validation completed") + logger.info("result_validation_completed") except Exception as e: - logger.error(f"āŒ Error in result validation: {e}") + logger.error("error_in_result_validation", e=e) state.errors.append(f"Validation failed: {str(e)}") return state @@ -74,7 +75,7 @@ async def synthesize_final_result(state: SupervisorState) -> SupervisorState: Synthesize final decision from multiple agent results. """ try: - logger.info("🧠 Synthesizing final result from agent outputs") + logger.info("synthesizing_final_result_from_agent_outputs") # Create coordination result coordination_result = _synthesize_coordination_result(state) @@ -83,11 +84,11 @@ async def synthesize_final_result(state: SupervisorState) -> SupervisorState: # Set end time state.end_time = time.time() - logger.info(f"āœ… Final synthesis completed: success={coordination_result.overall_success}") - logger.info(f"āœ… Confidence score: {coordination_result.confidence_score}") + logger.info("final_synthesis_completed_success", overall_success=coordination_result.overall_success) + logger.info("confidence_score", confidence_score=coordination_result.confidence_score) except Exception as e: - logger.error(f"āŒ Error in final synthesis: {e}") + logger.error("error_in_final_synthesis", e=e) state.errors.append(f"Synthesis failed: {str(e)}") # Create fallback result diff --git a/src/core/models.py b/src/core/models.py index 57a140b..0cb8e84 100644 --- a/src/core/models.py +++ b/src/core/models.py @@ -23,9 +23,10 @@ class WebhookEvent: fully prepared and enriched by our integration logic. """ - def __init__(self, event_type: EventType, payload: dict[str, Any]): + def __init__(self, event_type: EventType, payload: dict[str, Any], delivery_id: str | None = None): self.event_type = event_type self.payload = payload + self.delivery_id = delivery_id self.repository = payload.get("repository", {}) self.sender = payload.get("sender", {}) self.installation_id = payload.get("installation", {}).get("id") diff --git a/src/core/utils/event_filter.py b/src/core/utils/event_filter.py new file mode 100644 index 0000000..5698133 --- /dev/null +++ b/src/core/utils/event_filter.py @@ -0,0 +1,108 @@ +""" +Event filtering for GitHub webhooks. + +Centralized logic to skip rule evaluation on irrelevant events: +branch deletions, closed/merged PRs, archived repos, etc. +""" + +from dataclasses import dataclass +from typing import Any + +import structlog + +from src.core.models import EventType, WebhookEvent + +logger = structlog.get_logger() + + +NULL_SHA = "0000000000000000000000000000000000000000" + +PR_ACTIONS_PROCESS = frozenset({"opened", "synchronize", "reopened"}) + + +@dataclass(frozen=True) +class FilterResult: + """Result of event filter check.""" + + should_process: bool + reason: str = "" + + +def should_process_event(event: WebhookEvent) -> FilterResult: + """ + Determine if an event should trigger rule evaluation. + + Returns FilterResult with should_process=True to process, False to skip. + Logs filtered events for observability. + """ + payload = event.payload + event_type = event.event_type + + result = _apply_filters(event_type, payload) + + if not result.should_process: + logger.info( + "event_filtered", + operation="should_process_event", + subject_ids={"repo": event.repo_full_name, "delivery_id": event.delivery_id}, + decision="skip", + event_type=event_type.value if hasattr(event_type, "value") else str(event_type), + reason=result.reason, + ) + + return result + + +def _apply_filters(event_type: EventType, payload: dict[str, Any]) -> FilterResult: + """Apply all filters to determine if an event should be processed.""" + if _is_repo_archived(payload): + return FilterResult(should_process=False, reason="Repository is archived") + + if event_type == EventType.PULL_REQUEST: + return _filter_pull_request(payload) + + if event_type == EventType.PUSH: + return _filter_push(payload) + + return FilterResult(should_process=True) + + +def _filter_pull_request(payload: dict[str, Any]) -> FilterResult: + """Filter pull request events based on action and state.""" + action = payload.get("action") + + if action not in PR_ACTIONS_PROCESS: + return FilterResult(should_process=False, reason=f"PR action '{action}' not processed") + + pr = payload.get("pull_request", {}) + state = pr.get("state", "") + + if state != "open": + return FilterResult(should_process=False, reason=f"PR state '{state}' not open") + + if pr.get("merged"): + return FilterResult(should_process=False, reason="PR already merged") + + if pr.get("draft"): + return FilterResult(should_process=False, reason="PR is draft") + + return FilterResult(should_process=True) + + +def _filter_push(payload: dict[str, Any]) -> FilterResult: + """Filter push events based on deletion and commit SHA.""" + if payload.get("deleted"): + return FilterResult(should_process=False, reason="Branch deletion event") + + after = payload.get("after") + + if not after or after == NULL_SHA: + return FilterResult(should_process=False, reason="No valid commit SHA (deleted or empty push)") + + return FilterResult(should_process=True) + + +def _is_repo_archived(payload: dict[str, Any]) -> bool: + """Check if the repository is archived.""" + repo = payload.get("repository", {}) + return isinstance(repo, dict) and bool(repo.get("archived")) diff --git a/src/event_processors/base.py b/src/event_processors/base.py index 3dac7d8..f645438 100644 --- a/src/event_processors/base.py +++ b/src/event_processors/base.py @@ -1,7 +1,7 @@ -import logging from abc import ABC, abstractmethod from typing import Any +import structlog from pydantic import BaseModel, Field from src.core.models import WebhookEvent @@ -10,7 +10,7 @@ from src.rules.interface import RuleLoader from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class ProcessingResult(BaseModel): diff --git a/src/event_processors/check_run.py b/src/event_processors/check_run.py index 712e85c..fdeced9 100644 --- a/src/event_processors/check_run.py +++ b/src/event_processors/check_run.py @@ -1,12 +1,13 @@ -import logging import time from typing import Any +import structlog + from src.agents.engine_agent.agent import RuleEngineAgent from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class CheckRunProcessor(BaseEventProcessor): @@ -29,13 +30,13 @@ async def process(self, task: Task) -> ProcessingResult: # Ignore our own check runs to prevent infinite loops if "watchflow" in check_run.get("name", "").lower(): - logger.info("Ignoring Watchflow's own check run to prevent recursive loops.") + logger.info("ignoring_watchflows_own_check_run_to") return ProcessingResult( success=True, violations=[], api_calls_made=0, processing_time_ms=int((time.time() - start_time) * 1000) ) logger.info("=" * 80) - logger.info(f"šŸš€ Processing CHECK RUN event for {task.repo_full_name}") + logger.info("processing_check_run_event_for", repo_full_name=task.repo_full_name) logger.info(f" Name: {check_run.get('name')}") logger.info(f" Status: {check_run.get('status')}") logger.info(f" Conclusion: {check_run.get('conclusion')}") diff --git a/src/event_processors/deployment.py b/src/event_processors/deployment.py index 0441c50..c2ff6ab 100644 --- a/src/event_processors/deployment.py +++ b/src/event_processors/deployment.py @@ -1,11 +1,12 @@ -import logging import time from typing import Any +import structlog + from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentProcessor(BaseEventProcessor): @@ -29,16 +30,16 @@ async def process(self, task: Task) -> ProcessingResult: deployment_id = deployment.get("id") logger.info("=" * 80) - logger.info(f"šŸš€ Processing DEPLOYMENT event for {task.repo_full_name}") - logger.info(f" Environment: {environment}") - logger.info(f" Creator: {creator}") - logger.info(f" Ref: {ref}") - logger.info(f" Deployment ID: {deployment_id}") + logger.info("processing_deployment_event_for", repo_full_name=task.repo_full_name) + logger.info("environment", environment=environment) + logger.info("creator", creator=creator) + logger.info("ref", ref=ref) + logger.info("deployment_id", deployment_id=deployment_id) logger.info("=" * 80) # Just log the deployment creation - no rule evaluation here # Rule evaluation will be handled by deployment_protection_rule events - logger.info(f"šŸ“‹ Deployment {deployment_id} created for {environment}") + logger.info("deployment_created_for", deployment_id=deployment_id, environment=environment) logger.info("=" * 80) logger.info(f"šŸ DEPLOYMENT processing completed in {int((time.time() - start_time) * 1000)}ms") logger.info("=" * 80) diff --git a/src/event_processors/deployment_protection_rule.py b/src/event_processors/deployment_protection_rule.py index 7c5a7ee..a0f5a9a 100644 --- a/src/event_processors/deployment_protection_rule.py +++ b/src/event_processors/deployment_protection_rule.py @@ -1,13 +1,18 @@ -import logging +import asyncio import time from typing import Any +import structlog + from src.agents.engine_agent.agent import RuleEngineAgent from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.scheduler.deployment_scheduler import get_deployment_scheduler from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() + + +AGENT_TIMEOUT_SECONDS = 30 class DeploymentProtectionRuleProcessor(BaseEventProcessor): @@ -25,6 +30,7 @@ def get_event_type(self) -> str: async def process(self, task: Task) -> ProcessingResult: start_time = time.time() + repo_full_name = task.repo_full_name try: payload = task.payload @@ -37,14 +43,18 @@ async def process(self, task: Task) -> ProcessingResult: repo_full_name = task.repo_full_name logger.info("=" * 80) - logger.info(f"šŸš€ Processing DEPLOYMENT_PROTECTION_RULE event for {repo_full_name}") - logger.info(f" Environment: {environment} | Deployment ID: {deployment_id}") + logger.info( + "processing_deployment_protection_rule", + operation="process", + subject_ids={"repo": repo_full_name, "deployment_id": deployment_id}, + environment=environment, + ) logger.info("=" * 80) rules = await self.rule_provider.get_rules(repo_full_name, installation_id) if not rules: - logger.info("šŸ“‹ No rules found for repository") + logger.info("no_rules_found", repo=repo_full_name) if deployment_callback_url and environment: await self._approve_deployment( deployment_callback_url, environment, "No rules configured", installation_id @@ -63,14 +73,18 @@ async def process(self, task: Task) -> ProcessingResult: elif isinstance(r, dict): event_types = r.get("event_types", []) else: - logger.error(f"Rule is not a dict or object: {r} (type: {type(r)})") + logger.error( + "invalid_rule_type", + operation="process", + rule_type=str(type(r)), + ) continue if "deployment" in event_types: deployment_rules.append(r) if not deployment_rules: - logger.info("šŸ“‹ No deployment rules found") + logger.info("no_deployment_rules_found", repo=repo_full_name) if deployment_callback_url and environment: await self._approve_deployment( deployment_callback_url, environment, "No deployment rules configured", installation_id @@ -82,7 +96,7 @@ async def process(self, task: Task) -> ProcessingResult: processing_time_ms=int((time.time() - start_time) * 1000), ) - logger.info(f"šŸ“‹ Found {len(deployment_rules)} applicable rules for deployment") + logger.info("deployment_rules_found", num_rules=len(deployment_rules)) formatted_rules = self._convert_rules_to_new_format(deployment_rules) @@ -97,44 +111,74 @@ async def process(self, task: Task) -> ProcessingResult: "github_client": self.github_client, # Pass GitHub client for validators } - analysis_result = await self.engine_agent.execute( - event_type="deployment", - event_data=event_data, - rules=formatted_rules, - ) + try: + analysis_result = await asyncio.wait_for( + self.engine_agent.execute( + event_type="deployment", + event_data=event_data, + rules=formatted_rules, + ), + timeout=AGENT_TIMEOUT_SECONDS, + ) + except TimeoutError: + logger.warning( + "agent_execution_timeout", + operation="process", + subject_ids={"repo": repo_full_name, "deployment_id": deployment_id}, + timeout_seconds=AGENT_TIMEOUT_SECONDS, + ) + if deployment_callback_url and environment: + await self._approve_deployment( + deployment_callback_url, + environment, + "Deployment approved due to evaluation timeout. Review rules for performance issues.", + installation_id, + ) + return ProcessingResult( + success=True, + violations=[], + api_calls_made=1, + processing_time_ms=int((time.time() - start_time) * 1000), + ) # Extract violations from AgentResult - same pattern as acknowledgment processor violations = [] if analysis_result.data and "evaluation_result" in analysis_result.data: eval_result = analysis_result.data["evaluation_result"] if hasattr(eval_result, "violations"): - # Convert RuleViolation objects to dictionaries + # Convert RuleViolation objects to dictionaries with defensive access for violation in eval_result.violations: violation_dict = { - "rule_description": violation.rule_description, - "severity": violation.severity, - "message": violation.message, - "details": violation.details, - "how_to_fix": violation.how_to_fix, - "docs_url": violation.docs_url, - "validation_strategy": violation.validation_strategy.value - if hasattr(violation.validation_strategy, "value") - else violation.validation_strategy, - "execution_time_ms": violation.execution_time_ms, + "rule_description": getattr(violation, "rule_description", None), + "severity": getattr(violation, "severity", "medium"), + "message": getattr(violation, "message", ""), + "details": getattr(violation, "details", None), + "how_to_fix": getattr(violation, "how_to_fix", None), + "docs_url": getattr(violation, "docs_url", None), + "validation_strategy": getattr(violation, "validation_strategy", None), + "execution_time_ms": getattr(violation, "execution_time_ms", None), } + if violation_dict["validation_strategy"] and hasattr( + violation_dict["validation_strategy"], "value" + ): + violation_dict["validation_strategy"] = violation_dict["validation_strategy"].value violations.append(violation_dict) - logger.info("šŸ” Analysis completed:") - logger.info(f" Violations found: {len(violations)}") + logger.info( + "analysis_completed", + operation="process", + subject_ids={"repo": repo_full_name}, + violations_found=len(violations), + ) for violation in violations: - logger.info(f" • {violation.get('message', 'Unknown violation')}") + logger.info("violation_found", message=violation.get("message", "Unknown violation")) if not violations: if deployment_callback_url and environment: await self._approve_deployment( deployment_callback_url, environment, "All deployment rules passed", installation_id ) - logger.info("āœ… All rules passed - deployment approved!") + logger.info("all_rules_passed", repo=repo_full_name) else: time_based_violations = self._check_time_based_violations(violations) if time_based_violations: @@ -152,17 +196,22 @@ async def process(self, task: Task) -> ProcessingResult: "callback_url": deployment_callback_url, } ) - logger.info("ā° Time-based violations detected - added to scheduler for re-evaluation") + logger.info("time_based_violations_added_to_scheduler", num_violations=len(time_based_violations)) if deployment_callback_url and environment: await self._reject_deployment(deployment_callback_url, environment, violations, installation_id) - logger.info(f"āŒ Deployment rejected due to {len(violations)} violations") + logger.info("deployment_rejected", num_violations=len(violations)) processing_time = int((time.time() - start_time) * 1000) logger.info("=" * 80) - logger.info(f"šŸ DEPLOYMENT_PROTECTION_RULE processing completed in {processing_time}ms") - logger.info(f" State: {'approved' if not violations else 'rejected'}") - logger.info(f" Violations: {len(violations)}") + logger.info( + "deployment_protection_complete", + operation="process", + subject_ids={"repo": repo_full_name, "deployment_id": deployment_id}, + state="approved" if not violations else "rejected", + violations=len(violations), + latency_ms=processing_time, + ) logger.info("=" * 80) return ProcessingResult( @@ -170,7 +219,12 @@ async def process(self, task: Task) -> ProcessingResult: ) except Exception as e: - logger.error(f"āŒ Error processing deployment protection rule: {str(e)}") + logger.error( + "deployment_protection_error", + operation="process", + subject_ids={"repo": repo_full_name if "repo_full_name" in locals() else "unknown"}, + error=str(e), + ) return ProcessingResult( success=False, violations=[], @@ -197,11 +251,25 @@ async def _approve_deployment(self, callback_url: str, environment: str, comment installation_id=installation_id, ) if result is None: - logger.error("Failed to approve deployment - API call returned None") + logger.error( + "approve_deployment_failed", + operation="approve_deployment", + environment=environment, + reason="api_returned_none", + ) else: - logger.info("Successfully approved deployment") + logger.info( + "deployment_approved", + operation="approve_deployment", + environment=environment, + ) except Exception as e: - logger.error(f"Error approving deployment: {e}") + logger.error( + "approve_deployment_error", + operation="approve_deployment", + environment=environment, + error=str(e), + ) async def _reject_deployment( self, callback_url: str, environment: str, violations: list[dict[str, Any]], installation_id: int @@ -216,13 +284,27 @@ async def _reject_deployment( installation_id=installation_id, ) if result is None: - logger.error("Failed to reject deployment - API call returned None") + logger.error( + "reject_deployment_failed", + operation="reject_deployment", + environment=environment, + num_violations=len(violations), + reason="api_returned_none", + ) else: - logger.info(f"Successfully rejected deployment with {len(violations)} violations") + logger.info( + "deployment_rejected", + operation="reject_deployment", + environment=environment, + num_violations=len(violations), + ) except Exception as e: - logger.error(f"Error rejecting deployment: {e}") - # Note: We can't create a fallback deployment status here because we don't have the repo name - # The deployment will remain in "waiting" state, which is better than failing completely + logger.error( + "reject_deployment_error", + operation="reject_deployment", + environment=environment, + error=str(e), + ) def _convert_rules_to_new_format(self, rules: list[Any]) -> list[dict[str, Any]]: formatted_rules = [] diff --git a/src/event_processors/deployment_review.py b/src/event_processors/deployment_review.py index 2e47167..0b9e1e8 100644 --- a/src/event_processors/deployment_review.py +++ b/src/event_processors/deployment_review.py @@ -1,12 +1,13 @@ -import logging import time from typing import Any +import structlog + from src.agents.engine_agent.agent import RuleEngineAgent from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentReviewProcessor(BaseEventProcessor): @@ -28,7 +29,7 @@ async def process(self, task: Task) -> ProcessingResult: deployment_review = payload.get("deployment_review", {}) logger.info("=" * 80) - logger.info(f"šŸš€ Processing DEPLOYMENT REVIEW event for {task.repo_full_name}") + logger.info("processing_deployment_review_event_for", repo_full_name=task.repo_full_name) logger.info(f" State: {deployment_review.get('state')}") logger.info(f" Environment: {deployment_review.get('environment')}") logger.info("=" * 80) @@ -78,7 +79,7 @@ async def process(self, task: Task) -> ProcessingResult: deployment_review_rules.append(r) if not deployment_review_rules: - logger.info("šŸ“‹ No deployment_review rules found") + logger.info("no_deploymentreview_rules_found") return ProcessingResult( success=True, violations=[], api_calls_made=1, processing_time_ms=int((time.time() - start_time) * 1000) ) diff --git a/src/event_processors/deployment_status.py b/src/event_processors/deployment_status.py index e0a7aa4..70ab4fa 100644 --- a/src/event_processors/deployment_status.py +++ b/src/event_processors/deployment_status.py @@ -1,11 +1,12 @@ -import logging import time from typing import Any +import structlog + from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentStatusProcessor(BaseEventProcessor): @@ -29,23 +30,23 @@ async def process(self, task: Task) -> ProcessingResult: creator = deployment.get("creator", {}).get("login", "") logger.info("=" * 80) - logger.info(f"šŸ“Š Processing DEPLOYMENT_STATUS event for {task.repo_full_name}") - logger.info(f" State: {state}") - logger.info(f" Environment: {environment}") - logger.info(f" Creator: {creator}") + logger.info("processing_deploymentstatus_event_for", repo_full_name=task.repo_full_name) + logger.info("state", state=state) + logger.info("environment", environment=environment) + logger.info("creator", creator=creator) logger.info("=" * 80) # Log different states for monitoring purposes if state == "error": - logger.info(f"šŸ’„ Deployment to {environment} had an error") + logger.info("deployment_to_had_an_error", environment=environment) elif state == "waiting": - logger.info(f"ā³ Deployment to {environment} is waiting for protection rule review") + logger.info("deployment_to_is_waiting_for_protection", environment=environment) elif state == "success": - logger.info(f"āœ… Deployment to {environment} was successful") + logger.info("deployment_to_was_successful", environment=environment) elif state == "failure": - logger.info(f"āŒ Deployment to {environment} failed") + logger.info("deployment_to_failed", environment=environment) else: - logger.info(f"šŸ“‹ Deployment to {environment} has state: {state}") + logger.info("deployment_to_has_state", environment=environment, state=state) logger.info("=" * 80) logger.info(f"šŸ DEPLOYMENT_STATUS processing completed in {int((time.time() - start_time) * 1000)}ms") diff --git a/src/event_processors/pull_request.py b/src/event_processors/pull_request.py index 743f02f..4733913 100644 --- a/src/event_processors/pull_request.py +++ b/src/event_processors/pull_request.py @@ -1,14 +1,15 @@ -import logging import re import time from typing import Any +import structlog + from src.agents.engine_agent.agent import RuleEngineAgent from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.rules.github_provider import RulesFileNotFoundError from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class PullRequestProcessor(BaseEventProcessor): @@ -31,14 +32,38 @@ async def process(self, task: Task) -> ProcessingResult: try: logger.info("=" * 80) - logger.info(f"šŸš€ Processing PR event for {task.repo_full_name}") - logger.info(f" Action: {task.payload.get('action')}") - logger.info(f" PR Number: {task.payload.get('pull_request', {}).get('number')}") - logger.info(f" Title: {task.payload.get('pull_request', {}).get('title')}") + logger.info( + "processing_pr_event", + operation="process_pr", + subject_ids={ + "repo": task.repo_full_name, + "pr_number": task.payload.get("pull_request", {}).get("number"), + }, + action=task.payload.get("action"), + pr_title=task.payload.get("pull_request", {}).get("title"), + ) logger.info("=" * 80) pr_data = task.payload.get("pull_request", {}) - # user = pr_data.get("user", {}).get("login") + + if pr_data.get("state") == "closed" or pr_data.get("merged") or pr_data.get("draft"): + logger.info( + "pr_skipped_invalid_state", + operation="process_pr", + subject_ids={"repo": task.repo_full_name, "pr_number": pr_data.get("number")}, + decision="skip", + state=pr_data.get("state"), + merged=pr_data.get("merged"), + draft=pr_data.get("draft"), + latency_ms=int((time.time() - start_time) * 1000), + ) + return ProcessingResult( + success=True, + violations=[], + api_calls_made=0, + processing_time_ms=int((time.time() - start_time) * 1000), + ) + github_token = await self.github_client.get_installation_access_token(task.installation_id) # Prepare event_data for the agent @@ -50,7 +75,7 @@ async def process(self, task: Task) -> ProcessingResult: rules = await self.rule_provider.get_rules(task.repo_full_name, task.installation_id) api_calls += 1 except RulesFileNotFoundError as e: - logger.warning(f"Rules file not found: {e}") + logger.warning("rules_file_not_found", repo=task.repo_full_name, error=str(e)) # Create a neutral check run for missing rules file with helpful guidance await self._create_check_run( task, @@ -70,11 +95,14 @@ async def process(self, task: Task) -> ProcessingResult: formatted_rules = self._convert_rules_to_new_format(rules) # Debug logging - logger.info(f" Total rules loaded: {len(rules)}") - logger.info("šŸ“‹ Rules applicable to pull_request events:") + logger.info("rules_loaded", num_rules=len(rules)) for rule in formatted_rules: if "pull_request" in rule.get("event_types", []): - logger.info(f" - {rule.get('name', 'Unknown')} ({rule.get('id', 'unknown')})") + logger.info( + "rule_applicable", + rule_name=rule.get("name", "Unknown"), + rule_id=rule.get("id", "unknown"), + ) # Check for existing acknowledgments from previous comments first pr_data = task.payload.get("pull_request", {}) @@ -87,8 +115,11 @@ async def process(self, task: Task) -> ProcessingResult: task.repo_full_name, pr_number, task.installation_id ) if previous_acknowledgments: - logger.info(f"šŸ“‹ Found previous acknowledgments for PR #{pr_number}") - logger.info(f" Acknowledged rule IDs: {list(previous_acknowledgments.keys())}") + logger.info( + "previous_acknowledgments_found", + pr_number=pr_number, + acknowledged_rule_ids=list(previous_acknowledgments.keys()), + ) # Run engine-based rule evaluation result = await self.engine_agent.execute( @@ -114,14 +145,16 @@ async def process(self, task: Task) -> ProcessingResult: rule_description = violation.get("rule_description", "") if rule_description in previous_acknowledgments: # This violation was previously acknowledged - logger.info(f" Violation for rule '{rule_description}' was previously acknowledged") + logger.info("violation_previously_acknowledged", rule_description=rule_description) acknowledgable_violations.append(violation) else: # This violation requires acknowledgment require_acknowledgment_violations.append(violation) logger.info( - f"šŸ“Š Violation breakdown: {len(acknowledgable_violations)} acknowledged, {len(require_acknowledgment_violations)} requiring fixes" + "violation_breakdown", + acknowledged_count=len(acknowledgable_violations), + requiring_fix_count=len(require_acknowledgment_violations), ) # Use violations requiring fixes for final result @@ -141,29 +174,35 @@ async def process(self, task: Task) -> ProcessingResult: # Post violations as comments (if any) if violations: - logger.info(f"🚨 Found {len(violations)} violations, posting to PR...") + logger.info("posting_violations_to_pr", num_violations=len(violations)) await self._post_violations_to_github(task, violations) api_calls += 1 else: - logger.info("āœ… No violations found, skipping PR comment") + logger.info("no_violations_skipping_comment", repo=task.repo_full_name) # Summary logger.info("=" * 80) - logger.info(f"šŸ PR processing completed in {processing_time}ms") - logger.info(f" Rules evaluated: {len(formatted_rules)}") - logger.info(f" Violations found: {len(violations)}") - logger.info(f" API calls made: {api_calls}") + logger.info( + "pr_processing_complete", + operation="process_pr", + subject_ids={"repo": task.repo_full_name, "pr_number": pr_number}, + rules_evaluated=len(formatted_rules), + violations_found=len(violations), + api_calls=api_calls, + latency_ms=processing_time, + ) if violations: - logger.warning("🚨 VIOLATION SUMMARY:") - # Format violations for logging for i, violation in enumerate(violations, 1): - logger.info( - f" {i}. {violation.get('rule_description', 'Unknown')} ({violation.get('severity', 'medium')})" + logger.warning( + "violation_found", + num=i, + rule_description=violation.get("rule_description", "Unknown"), + severity=violation.get("severity", "medium"), + message=violation.get("message", ""), ) - logger.warning(f" {violation.get('message', '')}") else: - logger.info("āœ… All rules passed - no violations detected!") + logger.info("all_rules_passed", repo=task.repo_full_name) logger.info("=" * 80) @@ -175,7 +214,12 @@ async def process(self, task: Task) -> ProcessingResult: ) except Exception as e: - logger.error(f"āŒ Error processing PR event: {e}") + logger.error( + "pr_processing_error", + operation="process_pr", + subject_ids={"repo": task.repo_full_name}, + error=str(e), + ) # Create a failing check run for errors await self._create_check_run(task, [], "failure", error=str(e)) return ProcessingResult( @@ -219,7 +263,7 @@ async def _prepare_event_data_for_agent(self, task: Task, github_token: str) -> event_data["files"] = files or [] except Exception as e: - logger.warning(f"Error enriching event data: {e}") + logger.warning("error_enriching_event_data", error=str(e)) return event_data @@ -255,7 +299,11 @@ async def _create_check_run( sha = pr_data.get("head", {}).get("sha") if not sha: - logger.warning("No commit SHA found, skipping check run creation") + logger.warning( + "no_commit_sha", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name}, + ) return # Determine check run status @@ -284,12 +332,26 @@ async def _create_check_run( ) if result: - logger.info(f"āœ… Successfully created check run for commit {sha[:8]} with conclusion: {conclusion}") + logger.info( + "check_run_created", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name, "sha": sha[:8]}, + conclusion=conclusion, + ) else: - logger.error(f"āŒ Failed to create check run for commit {sha[:8]}") + logger.error( + "check_run_failed", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name, "sha": sha[:8]}, + ) except Exception as e: - logger.error(f"Error creating check run: {e}") + logger.error( + "check_run_error", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name}, + error=str(e), + ) def _format_check_run_output(self, violations: list[dict[str, Any]], error: str | None = None) -> dict[str, Any]: """Format violations for check run output.""" @@ -417,7 +479,11 @@ async def prepare_api_data(self, task: Task) -> dict[str, Any]: api_data["files"] = files or [] except Exception as e: - logger.error(f"Error fetching API data: {e}") + logger.error( + "fetch_api_data_error", + operation="prepare_api_data", + error=str(e), + ) return api_data @@ -426,25 +492,45 @@ async def _post_violations_to_github(self, task: Task, violations: list[dict[str try: pr_number = task.payload.get("pull_request", {}).get("number") if not pr_number: - logger.warning("No PR number found, skipping GitHub comment") + logger.warning( + "no_pr_number", + operation="post_violations_to_github", + subject_ids={"repo": task.repo_full_name}, + ) return - logger.info(f"šŸ“ Preparing to post {len(violations)} violations to PR #{pr_number}") + logger.info( + "posting_violations", + operation="post_violations_to_github", + subject_ids={"repo": task.repo_full_name, "pr_number": pr_number}, + num_violations=len(violations), + ) comment_body = self._format_violations_comment(violations) - logger.debug(f"Comment body: {comment_body[:200]}...") + logger.debug("comment_body_preview", body_preview=comment_body[:200]) result = await self.github_client.create_pull_request_comment( task.repo_full_name, pr_number, comment_body, task.installation_id ) if result: - logger.info(f"āœ… Successfully posted violations comment to PR #{pr_number}") + logger.info( + "violations_comment_posted", + operation="post_violations_to_github", + subject_ids={"repo": task.repo_full_name, "pr_number": pr_number}, + ) else: - logger.error(f"āŒ Failed to post violations comment to PR #{pr_number}") + logger.error( + "violations_comment_failed", + operation="post_violations_to_github", + subject_ids={"repo": task.repo_full_name, "pr_number": pr_number}, + ) except Exception as e: - logger.error(f"Error posting violations to GitHub: {e}") - logger.exception("Full traceback:") + logger.error( + "posting_violations_error", + operation="post_violations_to_github", + error=str(e), + ) def _format_violations_comment(self, violations: list[dict[str, Any]]) -> str: """Format violations as a GitHub comment.""" @@ -513,7 +599,11 @@ async def _get_previous_acknowledgments( return acknowledgments except Exception as e: - logger.error(f"Error fetching previous acknowledgments: {e}") + logger.error( + "fetch_acknowledgments_error", + operation="get_previous_acknowledgments", + error=str(e), + ) return {} def _is_acknowledgment_comment(self, comment_body: str) -> bool: @@ -675,7 +765,11 @@ async def _create_check_run_with_acknowledgment( ) except Exception as e: - logger.error(f"Error creating check run with acknowledgment: {e}") + logger.error( + "check_run_with_ack_error", + operation="create_check_run_with_acknowledgment", + error=str(e), + ) def _format_acknowledgment_summary( self, acknowledgable_violations: list[dict[str, Any]], acknowledgments: dict[str, dict[str, Any]] diff --git a/src/event_processors/push.py b/src/event_processors/push.py index 92d67f3..f32bb67 100644 --- a/src/event_processors/push.py +++ b/src/event_processors/push.py @@ -1,12 +1,14 @@ -import logging import time from typing import Any +import structlog + from src.agents.engine_agent.agent import RuleEngineAgent +from src.core.utils.event_filter import NULL_SHA from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class PushProcessor(BaseEventProcessor): @@ -30,11 +32,26 @@ async def process(self, task: Task) -> ProcessingResult: commits = payload.get("commits", []) logger.info("=" * 80) - logger.info(f"šŸš€ Processing PUSH event for {task.repo_full_name}") - logger.info(f" Ref: {ref}") - logger.info(f" Commits: {len(commits)}") + logger.info("šŸš€ Processing PUSH event for {repo}", repo=task.repo_full_name) + logger.info(" Ref: {ref}", ref=ref) + logger.info(" Commits: {num_commits}", num_commits=len(commits)) logger.info("=" * 80) + if payload.get("deleted") or not payload.get("after") or payload.get("after") == NULL_SHA: + logger.info( + "push_skipped_deleted_or_empty", + operation="process_push", + subject_ids={"repo": task.repo_full_name, "ref": ref}, + decision="skip", + latency_ms=int((time.time() - start_time) * 1000), + ) + return ProcessingResult( + success=True, + violations=[], + api_calls_made=0, + processing_time_ms=int((time.time() - start_time) * 1000), + ) + # Prepare event_data for the agent event_data = { "push": { @@ -55,12 +72,12 @@ async def process(self, task: Task) -> ProcessingResult: rules = await self.rule_provider.get_rules(task.repo_full_name, task.installation_id) if not rules: - logger.info("No rules found for this repository") + logger.info("no_rules_found", repo=task.repo_full_name) return ProcessingResult( success=True, violations=[], api_calls_made=1, processing_time_ms=int((time.time() - start_time) * 1000) ) - logger.info(f"šŸ“‹ Loaded {len(rules)} rules for evaluation") + logger.info("rules_loaded", num_rules=len(rules)) # Convert rules to the new format expected by the agent formatted_rules = self._convert_rules_to_new_format(rules) @@ -80,18 +97,27 @@ async def process(self, task: Task) -> ProcessingResult: # Summary logger.info("=" * 80) - logger.info(f"šŸ PUSH processing completed in {processing_time}ms") - logger.info(f" Rules evaluated: {len(formatted_rules)}") - logger.info(f" Violations found: {len(violations)}") - logger.info(f" API calls made: {api_calls}") + logger.info( + "push_processing_complete", + operation="process_push", + subject_ids={"repo": task.repo_full_name, "ref": ref}, + rules_evaluated=len(formatted_rules), + violations_found=len(violations), + api_calls=api_calls, + latency_ms=processing_time, + ) if violations: - logger.warning("🚨 VIOLATION SUMMARY:") for i, violation in enumerate(violations, 1): - logger.warning(f" {i}. {violation.get('rule', 'Unknown')} ({violation.get('severity', 'medium')})") - logger.warning(f" {violation.get('message', '')}") + logger.warning( + "violation_found", + num=i, + rule=violation.get("rule", "Unknown"), + severity=violation.get("severity", "medium"), + message=violation.get("message", ""), + ) else: - logger.info("āœ… All rules passed - no violations detected!") + logger.info("all_rules_passed", repo=task.repo_full_name) logger.info("=" * 80) @@ -145,11 +171,15 @@ async def prepare_api_data(self, task: Task) -> dict[str, Any]: async def _create_check_run(self, task: Task, violations: list[dict[str, Any]]): """Create a check run with violation results.""" try: - # head_commit = task.payload.get("head_commit") - sha = task.payload.get("after") # Use 'after' SHA instead of head_commit.id - - if not sha or sha == "0000000000000000000000000000000000000000": - logger.warning("No valid commit SHA found (likely branch deletion), skipping check run creation") + sha = task.payload.get("after") + + if not sha or sha == NULL_SHA: + logger.warning( + "no_valid_sha", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name}, + reason="likely branch deletion", + ) return # Determine check run status @@ -174,12 +204,26 @@ async def _create_check_run(self, task: Task, violations: list[dict[str, Any]]): ) if result: - logger.info(f"āœ… Successfully created check run for commit {sha[:8]} with conclusion: {conclusion}") + logger.info( + "check_run_created", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name, "sha": sha[:8]}, + conclusion=conclusion, + ) else: - logger.error(f"āŒ Failed to create check run for commit {sha[:8]}") + logger.error( + "check_run_failed", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name, "sha": sha[:8]}, + ) except Exception as e: - logger.error(f"Error creating check run: {e}") + logger.error( + "check_run_error", + operation="create_check_run", + subject_ids={"repo": task.repo_full_name}, + error=str(e), + ) def _format_check_run_output(self, violations: list[dict[str, Any]]) -> dict[str, Any]: """Format violations for check run output.""" diff --git a/src/event_processors/rule_creation.py b/src/event_processors/rule_creation.py index 12b9549..d676f3c 100644 --- a/src/event_processors/rule_creation.py +++ b/src/event_processors/rule_creation.py @@ -1,13 +1,14 @@ -import logging import re import time from typing import Any +import structlog + from src.agents.feasibility_agent.agent import RuleFeasibilityAgent from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class RuleCreationProcessor(BaseEventProcessor): @@ -29,7 +30,7 @@ async def process(self, task: Task) -> ProcessingResult: try: logger.info("=" * 80) - logger.info(f"šŸš€ Processing RULE CREATION command for {task.repo_full_name}") + logger.info("processing_rule_creation_command_for", repo_full_name=task.repo_full_name) logger.info("=" * 80) # Extract the rule description from the comment @@ -44,7 +45,7 @@ async def process(self, task: Task) -> ProcessingResult: error="No rule description found in comment", ) - logger.info(f"šŸ“ Rule description: {rule_description}") + logger.info("rule_description", rule_description=rule_description) # Use the feasibility agent to check if the rule is supported feasibility_result = await self.feasibility_agent.check_feasibility(rule_description) @@ -56,21 +57,21 @@ async def process(self, task: Task) -> ProcessingResult: # Summary logger.info("=" * 80) - logger.info(f"šŸ Rule creation processing completed in {processing_time}ms") - logger.info(f" Feasible: {feasibility_result.is_feasible}") - logger.info(" API calls made: 1") + logger.info("rule_creation_processing_completed_in_ms", processing_time=processing_time) + logger.info("feasible", is_feasible=feasibility_result.is_feasible) + logger.info("api_calls_made_1") if feasibility_result.is_feasible: - logger.info("āœ… Rule is feasible - YAML provided") + logger.info("rule_is_feasible_yaml_provided") else: - logger.info("āŒ Rule is not feasible - feedback provided") + logger.info("rule_is_not_feasible_feedback_provided") logger.info("=" * 80) return ProcessingResult(success=True, violations=[], api_calls_made=1, processing_time_ms=processing_time) except Exception as e: - logger.error(f"āŒ Error processing rule creation: {e}") + logger.error("error_processing_rule_creation", e=e) return ProcessingResult( success=False, violations=[], @@ -105,7 +106,7 @@ async def _post_result_to_comment(self, task: Task, feasibility_result): issue_number = issue.get("number") if not issue_number: - logger.warning("No issue number found in webhook payload, skipping reply") + logger.warning("no_issue_number_found_in_webhook") return reply_body = self._format_feasibility_reply(feasibility_result) @@ -116,12 +117,12 @@ async def _post_result_to_comment(self, task: Task, feasibility_result): ) if result: - logger.info(f"āœ… Successfully posted feasibility reply to issue/PR #{issue_number}") + logger.info("successfully_posted_feasibility_reply_to_issuepr", issue_number=issue_number) else: - logger.error(f"āŒ Failed to post feasibility reply to issue/PR #{issue_number}") + logger.error("failed_to_post_feasibility_reply_to", issue_number=issue_number) except Exception as e: - logger.error(f"Error posting feasibility reply: {e}") + logger.error("error_posting_feasibility_reply", e=e) def _format_feasibility_reply(self, feasibility_result) -> str: """Format the feasibility result as a comment reply.""" diff --git a/src/event_processors/violation_acknowledgment.py b/src/event_processors/violation_acknowledgment.py index 6659170..8d2502b 100644 --- a/src/event_processors/violation_acknowledgment.py +++ b/src/event_processors/violation_acknowledgment.py @@ -1,15 +1,16 @@ -import logging import re import time from typing import Any +import structlog + from src.agents.acknowledgment_agent.agent import AcknowledgmentAgent from src.agents.engine_agent.agent import RuleEngineAgent from src.core.models import EventType from src.event_processors.base import BaseEventProcessor, ProcessingResult from src.tasks.task_queue import Task -logger = logging.getLogger(__name__) +logger = structlog.get_logger() # Add at the top acknowledged_prs = set() @@ -47,8 +48,8 @@ async def process(self, task: Task) -> ProcessingResult: commenter = event_data.get("comment", {}).get("user", {}).get("login") logger.info("=" * 80) - logger.info(f"šŸ” Processing VIOLATION ACKNOWLEDGMENT for {repo}#{pr_number}") - logger.info(f" Commenter: {commenter}") + logger.info("processing_violation_acknowledgment_for", repo=repo, pr_number=pr_number) + logger.info("commenter", commenter=commenter) logger.info(f" Comment: {comment_body[:100]}...") logger.info("=" * 80) @@ -56,7 +57,7 @@ async def process(self, task: Task) -> ProcessingResult: acknowledgment_reason = self._extract_acknowledgment_reason(comment_body) if not acknowledgment_reason: - logger.info("āŒ No valid acknowledgment reason found in comment") + logger.info("no_valid_acknowledgment_reason_found_in") # Post a helpful comment explaining what went wrong help_comment = ( @@ -86,7 +87,7 @@ async def process(self, task: Task) -> ProcessingResult: api_calls += 1 if not github_token: - logger.error(f"āŒ Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return ProcessingResult( success=False, violations=[], @@ -168,7 +169,7 @@ async def process(self, task: Task) -> ProcessingResult: # Note: Rule Engine returns success=False when violations are found, which is correct # We need to check if there's actual data to determine if the analysis worked if not analysis_result.data or "evaluation_result" not in analysis_result.data: - logger.warning(f"āš ļø Rule analysis failed: {analysis_result.message}") + logger.warning("rule_analysis_failed", message=analysis_result.message) await self._post_comment( repo, pr_number, @@ -187,7 +188,7 @@ async def process(self, task: Task) -> ProcessingResult: ) if not all_violations: - logger.info("āœ… No violations found - acknowledgment not needed") + logger.info("no_violations_found_acknowledgment_not_needed") await self._post_comment( repo, pr_number, installation_id, "āœ… No rule violations detected. Acknowledgment not needed." ) @@ -259,7 +260,7 @@ async def process(self, task: Task) -> ProcessingResult: processing_time = int((time.time() - start_time) * 1000) logger.info("=" * 80) - logger.info(f"šŸ VIOLATION ACKNOWLEDGMENT processing completed in {processing_time}ms") + logger.info("violation_acknowledgment_processing_completed_in_ms", processing_time=processing_time) logger.info(f" Status: {'accepted' if evaluation_result['valid'] else 'rejected'}") logger.info("=" * 80) @@ -300,7 +301,7 @@ def _convert_rules_to_new_format(self, rules: list[Any]) -> list[dict[str, Any]] def _extract_acknowledgment_reason(self, comment_body: str) -> str: """Extract acknowledgment reason from comment.""" - logger.info(f"šŸ” Extracting acknowledgment reason from: '{comment_body}'") + logger.info("extracting_acknowledgment_reason_from", comment_body=comment_body) # Look for acknowledgment patterns with better quote handling patterns = [ @@ -314,7 +315,7 @@ def _extract_acknowledgment_reason(self, comment_body: str) -> str: r"/bypass\s+(.+)", ] - for i, pattern in enumerate(patterns): + for _i, pattern in enumerate(patterns): match = re.search(pattern, comment_body, re.IGNORECASE | re.DOTALL) if match: # For patterns with quotes, group 2 contains the reason @@ -324,13 +325,13 @@ def _extract_acknowledgment_reason(self, comment_body: str) -> str: else: reason = match.group(1).strip() - logger.info(f"āœ… Pattern {i + 1} matched! Reason: '{reason}'") + logger.info("pattern_matched_reason", reason=reason) if reason: # Make sure we got a non-empty reason return reason else: - logger.info(f"āŒ Pattern {i + 1} did not match") + logger.info("pattern_did_not_match") - logger.info("āŒ No patterns matched for acknowledgment reason") + logger.info("no_patterns_matched_for_acknowledgment_reason") return "" async def _evaluate_acknowledgment( @@ -345,7 +346,7 @@ async def _evaluate_acknowledgment( Use intelligent LLM-based evaluation to determine which violations can be acknowledged vs. require fixes. """ try: - logger.info("🧠 Using intelligent acknowledgment agent for evaluation") + logger.info("using_intelligent_acknowledgment_agent_for_evaluation") # Use the rules parameter that was passed in (already formatted) # Don't fetch rules again - use the ones passed from the calling method @@ -360,7 +361,7 @@ async def _evaluate_acknowledgment( ) if not agent_result.success: - logger.error(f"🧠 Acknowledgment agent failed: {agent_result.message}") + logger.error("acknowledgment_agent_failed", message=agent_result.message) return { "valid": False, "acknowledgable_violations": [], @@ -379,12 +380,12 @@ async def _evaluate_acknowledgment( confidence = evaluation_data.get("confidence", 0.5) recommendations = evaluation_data.get("recommendations", []) - logger.info("🧠 Intelligent evaluation completed:") - logger.info(f" Valid: {is_valid}") - logger.info(f" Reasoning: {reasoning}") + logger.info("intelligent_evaluation_completed") + logger.info("valid", is_valid=is_valid) + logger.info("reasoning", reasoning=reasoning) logger.info(f" Acknowledged violations: {len(acknowledgable_violations)}") logger.info(f" Require fixes: {len(require_fixes)}") - logger.info(f" Confidence: {confidence}") + logger.info("confidence", confidence=confidence) return { "valid": is_valid, @@ -401,7 +402,7 @@ async def _evaluate_acknowledgment( } except Exception as e: - logger.error(f"🧠 Error in intelligent acknowledgment evaluation: {e}") + logger.error("error_in_intelligent_acknowledgment_evaluation", e=e) return { "valid": False, "acknowledgable_violations": [], @@ -569,7 +570,7 @@ async def _update_check_run( sha = pr_data.get("head", {}).get("sha") if not sha: - logger.warning("No commit SHA found, skipping check run update") + logger.warning("no_commit_sha_found_skipping_check") return # The acknowledgable_violations and require_fixes are already passed as parameters @@ -603,7 +604,7 @@ async def _update_check_run( logger.error(f"āŒ Failed to update check run for commit {sha[:8]}") except Exception as e: - logger.error(f"Error updating check run: {e}") + logger.error("error_updating_check_run", e=e) def _format_check_run_output( self, acknowledgable_violations: list[dict[str, Any]], require_fixes: list[dict[str, Any]] diff --git a/src/integrations/codeowners.py b/src/integrations/codeowners.py index 567673a..2aa4b4a 100644 --- a/src/integrations/codeowners.py +++ b/src/integrations/codeowners.py @@ -2,11 +2,12 @@ Utilities for parsing and using CODEOWNERS files. """ -import logging import re from pathlib import Path -logger = logging.getLogger(__name__) +import structlog + +logger = structlog.get_logger() class CodeOwnersParser: @@ -35,7 +36,7 @@ def _parse_codeowners(self) -> list[tuple[str, list[str]]]: # Split on whitespace, first part is pattern, rest are owners parts = line.split() if len(parts) < 2: - logger.warning(f"Invalid CODEOWNERS line {line_num}: {line}") + logger.warning("invalid_codeowners_line", line_num=line_num, line=line) continue pattern = parts[0] @@ -95,7 +96,7 @@ def _matches_pattern(self, file_path: str, pattern: str) -> bool: try: return bool(re.match(regex_pattern, file_path)) except re.error: - logger.error(f"Invalid regex pattern: {regex_pattern}") + logger.error("invalid_regex_pattern", regex_pattern=regex_pattern) return False def _pattern_to_regex(self, pattern: str) -> str: @@ -170,7 +171,7 @@ def load_codeowners(repo_path: str = ".") -> CodeOwnersParser | None: codeowners_path = Path(repo_path) / "CODEOWNERS" if not codeowners_path.exists(): - logger.warning(f"CODEOWNERS file not found at {codeowners_path}") + logger.warning("codeowners_file_not_found_at", codeowners_path=codeowners_path) return None try: @@ -179,7 +180,7 @@ def load_codeowners(repo_path: str = ".") -> CodeOwnersParser | None: return CodeOwnersParser(content) except Exception as e: - logger.error(f"Error loading CODEOWNERS file: {e}") + logger.error("error_loading_codeowners_file", e=e) return None diff --git a/src/integrations/contributors.py b/src/integrations/contributors.py index e936599..d10002a 100644 --- a/src/integrations/contributors.py +++ b/src/integrations/contributors.py @@ -2,10 +2,11 @@ Utilities for analyzing repository contributors and determining contribution history. """ -import logging from datetime import datetime, timedelta -logger = logging.getLogger(__name__) +import structlog + +logger = structlog.get_logger() class ContributorAnalyzer: @@ -37,11 +38,11 @@ async def get_past_contributors( if cache_key in self._contributors_cache: cached_data = self._contributors_cache[cache_key] if datetime.now().timestamp() - cached_data.get("timestamp", 0) < self._cache_ttl: - logger.debug(f"Using cached past contributors for {repo}") + logger.debug("using_cached_past_contributors_for", repo=repo) return set(cached_data.get("contributors", [])) try: - logger.info(f"Fetching past contributors for {repo}") + logger.info("fetching_past_contributors_for", repo=repo) # Get contributors from GitHub API contributors = await self._fetch_contributors(repo, installation_id) @@ -69,7 +70,7 @@ async def get_past_contributors( return past_contributors except Exception as e: - logger.error(f"Error fetching past contributors for {repo}: {e}") + logger.error("error_fetching_past_contributors_for", repo=repo, e=e) return set() async def is_new_contributor( @@ -95,11 +96,11 @@ async def is_new_contributor( # Check if user is in the past contributors list is_new = username not in past_contributors - logger.debug(f"User {username} is {'new' if is_new else 'established'} contributor in {repo}") + logger.debug("user_is_contributor_in", username=username, repo=repo) return is_new except Exception as e: - logger.error(f"Error checking if {username} is new contributor in {repo}: {e}") + logger.error("error_checking_if_is_new_contributor", username=username, repo=repo, e=e) # Default to treating as new contributor on error return True @@ -161,7 +162,7 @@ async def get_user_contribution_stats(self, username: str, repo: str, installati return stats except Exception as e: - logger.error(f"Error getting contribution stats for {username} in {repo}: {e}") + logger.error("error_getting_contribution_stats_for_in", username=username, repo=repo, e=e) return { "username": username, "total_commits": 0, @@ -179,7 +180,7 @@ async def _fetch_contributors(self, repo: str, installation_id: int) -> list[dic contributors = await self.github_client.get_repository_contributors(repo, installation_id) return contributors or [] except Exception as e: - logger.error(f"Error fetching contributors for {repo}: {e}") + logger.error("error_fetching_contributors_for", repo=repo, e=e) return [] async def _has_recent_activity(self, repo: str, username: str, installation_id: int, cutoff_date: datetime) -> bool: @@ -208,7 +209,7 @@ async def _has_recent_activity(self, repo: str, username: str, installation_id: return False except Exception as e: - logger.error(f"Error checking recent activity for {username} in {repo}: {e}") + logger.error("error_checking_recent_activity_for_in", username=username, repo=repo, e=e) return False async def _fetch_user_commits(self, repo: str, username: str, installation_id: int, limit: int = 100) -> list[dict]: @@ -216,7 +217,7 @@ async def _fetch_user_commits(self, repo: str, username: str, installation_id: i try: return await self.github_client.get_user_commits(repo, username, installation_id, limit) except Exception as e: - logger.error(f"Error fetching commits for {username} in {repo}: {e}") + logger.error("error_fetching_commits_for_in", username=username, repo=repo, e=e) return [] async def _fetch_user_pull_requests( @@ -226,7 +227,7 @@ async def _fetch_user_pull_requests( try: return await self.github_client.get_user_pull_requests(repo, username, installation_id, limit) except Exception as e: - logger.error(f"Error fetching PRs for {username} in {repo}: {e}") + logger.error("error_fetching_prs_for_in", username=username, repo=repo, e=e) return [] async def _fetch_user_issues(self, repo: str, username: str, installation_id: int, limit: int = 100) -> list[dict]: @@ -234,7 +235,7 @@ async def _fetch_user_issues(self, repo: str, username: str, installation_id: in try: return await self.github_client.get_user_issues(repo, username, installation_id, limit) except Exception as e: - logger.error(f"Error fetching issues for {username} in {repo}: {e}") + logger.error("error_fetching_issues_for_in", username=username, repo=repo, e=e) return [] diff --git a/src/integrations/github_api.py b/src/integrations/github_api.py index 7e29db8..cf377e6 100644 --- a/src/integrations/github_api.py +++ b/src/integrations/github_api.py @@ -1,16 +1,16 @@ import base64 -import logging import time from typing import Any import aiohttp import httpx import jwt +import structlog from cachetools import TTLCache from src.core.config import config -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class GitHubClient: @@ -35,7 +35,7 @@ async def get_installation_access_token(self, installation_id: int) -> str | Non Caches the token to avoid regenerating it for every request. """ if installation_id in self._token_cache: - logger.debug(f"Using cached installation token for installation_id {installation_id}.") + logger.debug("using_cached_installation_token_for_installationid", installation_id=installation_id) return self._token_cache[installation_id] jwt_token = self._generate_jwt() @@ -51,7 +51,7 @@ async def get_installation_access_token(self, installation_id: int) -> str | Non data = await response.json() token = data["token"] self._token_cache[installation_id] = token - logger.info(f"Generated new installation token for installation_id {installation_id}.") + logger.info("generated_new_installation_token_for_installationid", installation_id=installation_id) return token else: error_text = await response.text() @@ -78,10 +78,10 @@ async def get_file_content(self, repo_full_name: str, file_path: str, installati session = await self._get_session() async with session.get(url, headers=headers) as response: if response.status == 200: - logger.info(f"Successfully fetched file '{file_path}' from '{repo_full_name}'.") + logger.info("successfully_fetched_file_from", file_path=file_path, repo_full_name=repo_full_name) return await response.text() elif response.status == 404: - logger.info(f"File '{file_path}' not found in '{repo_full_name}'.") + logger.info("file_not_found_in", file_path=file_path, repo_full_name=repo_full_name) return None else: error_text = await response.text() @@ -125,7 +125,7 @@ async def get_pr_checks(self, repo_full_name: str, pr_number: int, installation_ # Then get check runs for that SHA return await self.get_check_runs(repo_full_name, head_sha, installation_id) except Exception as e: - logger.error(f"Error getting checks for PR #{pr_number} in {repo_full_name}: {e}") + logger.error("error_getting_checks_for_pr_in", pr_number=pr_number, repo_full_name=repo_full_name, e=e) return [] async def get_user_teams(self, repo: str, username: str, installation_id: int) -> list: @@ -160,7 +160,7 @@ async def create_pull_request_comment( try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return {} headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -172,16 +172,20 @@ async def create_pull_request_comment( async with session.post(url, headers=headers, json=data) as response: if response.status == 201: result = await response.json() - logger.info(f"Created comment on PR #{pr_number} in {repo}") + logger.info("created_comment_on_pr_in", pr_number=pr_number, repo=repo) return result else: error_text = await response.text() logger.error( - f"Failed to create comment on PR #{pr_number} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_create_comment_on_pr", + pr_number=pr_number, + repo=repo, + status=response.status, + error_text=error_text, ) return {} except Exception as e: - logger.error(f"Error creating comment on PR #{pr_number} in {repo}: {e}") + logger.error("error_creating_comment_on_pr_in", pr_number=pr_number, repo=repo, e=e) return {} async def create_check_run( @@ -191,7 +195,7 @@ async def create_check_run( try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return {} headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -203,16 +207,20 @@ async def create_check_run( async with session.post(url, headers=headers, json=data) as response: if response.status == 201: result = await response.json() - logger.info(f"Created check run '{name}' for {repo}") + logger.info("created_check_run_for", name=name, repo=repo) return result else: error_text = await response.text() logger.error( - f"Failed to create check run '{name}' for {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_create_check_run_for", + name=name, + repo=repo, + status=response.status, + error_text=error_text, ) return {} except Exception as e: - logger.error(f"Error creating check run '{name}' for {repo}: {e}") + logger.error("error_creating_check_run_for", name=name, repo=repo, e=e) return {} async def update_check_run( @@ -222,7 +230,7 @@ async def update_check_run( try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return {} headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -234,16 +242,20 @@ async def update_check_run( async with session.patch(url, headers=headers, json=data) as response: if response.status == 200: result = await response.json() - logger.info(f"Updated check run {check_run_id} for {repo}") + logger.info("updated_check_run_for", check_run_id=check_run_id, repo=repo) return result else: error_text = await response.text() logger.error( - f"Failed to update check run {check_run_id} for {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_update_check_run_for", + check_run_id=check_run_id, + repo=repo, + status=response.status, + error_text=error_text, ) return {} except Exception as e: - logger.error(f"Error updating check run {check_run_id} for {repo}: {e}") + logger.error("error_updating_check_run_for", check_run_id=check_run_id, repo=repo, e=e) return {} async def get_check_runs(self, repo: str, sha: str, installation_id: int) -> list[dict[str, Any]]: @@ -251,7 +263,7 @@ async def get_check_runs(self, repo: str, sha: str, installation_id: int) -> lis try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return [] headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -266,11 +278,15 @@ async def get_check_runs(self, repo: str, sha: str, installation_id: int) -> lis else: error_text = await response.text() logger.error( - f"Failed to get check runs for {repo} commit {sha}. Status: {response.status}, Response: {error_text}" + "failed_to_get_check_runs_for", + repo=repo, + sha=sha, + status=response.status, + error_text=error_text, ) return [] except Exception as e: - logger.error(f"Error getting check runs for {repo} commit {sha}: {e}") + logger.error("error_getting_check_runs_for_commit", repo=repo, sha=sha, e=e) return [] async def get_pull_request_reviews(self, repo: str, pr_number: int, installation_id: int) -> list[dict[str, Any]]: @@ -278,7 +294,7 @@ async def get_pull_request_reviews(self, repo: str, pr_number: int, installation try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return [] headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -294,11 +310,15 @@ async def get_pull_request_reviews(self, repo: str, pr_number: int, installation else: error_text = await response.text() logger.error( - f"Failed to get reviews for PR #{pr_number} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_reviews_for_pr", + pr_number=pr_number, + repo=repo, + status=response.status, + error_text=error_text, ) return [] except Exception as e: - logger.error(f"Error getting reviews for PR #{pr_number} in {repo}: {e}") + logger.error("error_getting_reviews_for_pr_in", pr_number=pr_number, repo=repo, e=e) return [] async def get_pull_request_files(self, repo: str, pr_number: int, installation_id: int) -> list[dict[str, Any]]: @@ -306,7 +326,7 @@ async def get_pull_request_files(self, repo: str, pr_number: int, installation_i try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return [] headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -322,11 +342,15 @@ async def get_pull_request_files(self, repo: str, pr_number: int, installation_i else: error_text = await response.text() logger.error( - f"Failed to get files for PR #{pr_number} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_files_for_pr", + pr_number=pr_number, + repo=repo, + status=response.status, + error_text=error_text, ) return [] except Exception as e: - logger.error(f"Error getting files for PR #{pr_number} in {repo}: {e}") + logger.error("error_getting_files_for_pr_in", pr_number=pr_number, repo=repo, e=e) return [] async def create_comment_reply( @@ -336,7 +360,7 @@ async def create_comment_reply( try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return {} headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -347,16 +371,20 @@ async def create_comment_reply( session = await self._get_session() async with session.post(url, headers=headers, json=data) as response: if response.status == 201: - logger.info(f"Added reaction to comment {comment_id} in {repo}") + logger.info("added_reaction_to_comment_in", comment_id=comment_id, repo=repo) return await response.json() else: error_text = await response.text() logger.error( - f"Failed to add reaction to comment {comment_id} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_add_reaction_to_comment", + comment_id=comment_id, + repo=repo, + status=response.status, + error_text=error_text, ) return {} except Exception as e: - logger.error(f"Error adding reaction to comment {comment_id} in {repo}: {e}") + logger.error("error_adding_reaction_to_comment_in", comment_id=comment_id, repo=repo, e=e) return {} async def create_issue_comment( @@ -366,7 +394,7 @@ async def create_issue_comment( try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return {} headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -378,16 +406,20 @@ async def create_issue_comment( async with session.post(url, headers=headers, json=data) as response: if response.status == 201: result = await response.json() - logger.info(f"Created comment on issue #{issue_number} in {repo}") + logger.info("created_comment_on_issue_in", issue_number=issue_number, repo=repo) return result else: error_text = await response.text() logger.error( - f"Failed to create comment on issue #{issue_number} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_create_comment_on_issue", + issue_number=issue_number, + repo=repo, + status=response.status, + error_text=error_text, ) return {} except Exception as e: - logger.error(f"Error creating comment on issue #{issue_number} in {repo}: {e}") + logger.error("error_creating_comment_on_issue_in", issue_number=issue_number, repo=repo, e=e) return {} async def get_pull_request(self, repo: str, pr_number: int, installation_id: int) -> dict: @@ -395,7 +427,7 @@ async def get_pull_request(self, repo: str, pr_number: int, installation_id: int try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return {} headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -406,16 +438,20 @@ async def get_pull_request(self, repo: str, pr_number: int, installation_id: int async with session.get(url, headers=headers) as response: if response.status == 200: result = await response.json() - logger.info(f"Retrieved PR #{pr_number} details from {repo}") + logger.info("retrieved_pr_details_from", pr_number=pr_number, repo=repo) return result else: error_text = await response.text() logger.error( - f"Failed to get PR #{pr_number} from {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_pr_from_status", + pr_number=pr_number, + repo=repo, + status=response.status, + error_text=error_text, ) return None except Exception as e: - logger.error(f"Error getting PR #{pr_number} from {repo}: {e}") + logger.error("error_getting_pr_from", pr_number=pr_number, repo=repo, e=e) return {} async def create_deployment_status( @@ -432,7 +468,7 @@ async def create_deployment_status( try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return None headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -444,16 +480,20 @@ async def create_deployment_status( async with session.post(url, headers=headers, json=data) as response: if response.status == 201: result = await response.json() - logger.info(f"Created deployment status for deployment {deployment_id} in {repo}") + logger.info("created_deployment_status_for_deployment_in", deployment_id=deployment_id, repo=repo) return result else: error_text = await response.text() logger.error( - f"Failed to create deployment status for deployment {deployment_id} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_create_deployment_status_for", + deployment_id=deployment_id, + repo=repo, + status=response.status, + error_text=error_text, ) return None except Exception as e: - logger.error(f"Error creating deployment status for deployment {deployment_id} in {repo}: {e}") + logger.error("error_creating_deployment_status_for_deployment", deployment_id=deployment_id, repo=repo, e=e) return None async def review_deployment_protection_rule( @@ -463,7 +503,7 @@ async def review_deployment_protection_rule( try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id} to review deployment.") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return None headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github+json"} @@ -476,7 +516,7 @@ async def review_deployment_protection_rule( session = await self._get_session() async with session.post(callback_url, headers=headers, json=data) as response: if response.status in [200, 204]: # 204 No Content is also a success - logger.info(f"Successfully reviewed deployment protection rule with state {state}.") + logger.info("successfully_reviewed_deployment_protection_rule_with", state=state) if response.status == 200: return await response.json() else: @@ -484,13 +524,16 @@ async def review_deployment_protection_rule( else: error_text = await response.text() logger.error( - f"Failed to review deployment protection rule for environment {environment}. Status: {response.status}, Response: {error_text}" + "failed_to_review_deployment_protection_rule", + environment=environment, + status=response.status, + error_text=error_text, ) - logger.error(f"Request URL: {callback_url}") - logger.error(f"Request payload: {data}") + logger.error("request_url", callback_url=callback_url) + logger.error("request_payload", data=data) return None except Exception as e: - logger.error(f"Error reviewing deployment protection rule: {e}") + logger.error("error_reviewing_deployment_protection_rule", e=e) return None async def get_issue_comments(self, repo: str, issue_number: int, installation_id: int) -> list[dict[str, Any]]: @@ -498,7 +541,7 @@ async def get_issue_comments(self, repo: str, issue_number: int, installation_id try: token = await self.get_installation_access_token(installation_id) if not token: - logger.error(f"Failed to get installation token for {installation_id}") + logger.error("failed_to_get_installation_token_for", installation_id=installation_id) return [] headers = {"Authorization": f"Bearer {token}", "Accept": "application/vnd.github.v3+json"} @@ -514,11 +557,15 @@ async def get_issue_comments(self, repo: str, issue_number: int, installation_id else: error_text = await response.text() logger.error( - f"Failed to get comments for issue #{issue_number} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_comments_for_issue", + issue_number=issue_number, + repo=repo, + status=response.status, + error_text=error_text, ) return [] except Exception as e: - logger.error(f"Error getting comments for issue #{issue_number} in {repo}: {e}") + logger.error("error_getting_comments_for_issue_in", issue_number=issue_number, repo=repo, e=e) return [] async def update_deployment_status( @@ -539,16 +586,16 @@ async def update_deployment_status( async with session.post(callback_url, headers=headers, json=data) as response: if response.status == 200: result = await response.json() - logger.info(f"Updated deployment status to {state}") + logger.info("updated_deployment_status_to", state=state) return result else: error_text = await response.text() logger.error( - f"Failed to update deployment status. Status: {response.status}, Response: {error_text}" + "failed_to_update_deployment_status_status", status=response.status, error_text=error_text ) return None except Exception as e: - logger.error(f"Error updating deployment status: {e}") + logger.error("error_updating_deployment_status", e=e) return None async def get_repository_contributors(self, repo: str, installation_id: int) -> list[dict[str, Any]]: @@ -574,7 +621,7 @@ async def get_repository_contributors(self, repo: str, installation_id: int) -> else: error_text = await response.text() logger.error( - f"Failed to get contributors for {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_contributors_for_status", repo=repo, status=response.status, error_text=error_text ) return [] @@ -603,7 +650,11 @@ async def get_user_commits( else: error_text = await response.text() logger.error( - f"Failed to get commits by {username} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_commits_by_in", + username=username, + repo=repo, + status=response.status, + error_text=error_text, ) return [] @@ -632,7 +683,11 @@ async def get_user_pull_requests( else: error_text = await response.text() logger.error( - f"Failed to get PRs by {username} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_prs_by_in", + username=username, + repo=repo, + status=response.status, + error_text=error_text, ) return [] @@ -663,7 +718,11 @@ async def get_user_issues( else: error_text = await response.text() logger.error( - f"Failed to get issues by {username} in {repo}. Status: {response.status}, Response: {error_text}" + "failed_to_get_issues_by_in", + username=username, + repo=repo, + status=response.status, + error_text=error_text, ) return [] @@ -695,7 +754,7 @@ def _decode_private_key() -> str: decoded_key = base64.b64decode(config.github.private_key).decode("utf-8") return decoded_key except Exception as e: - logger.error(f"Failed to decode private key: {e}") + logger.error("failed_to_decode_private_key", e=e) raise ValueError("Invalid private key format. Expected base64-encoded PEM key.") from e diff --git a/src/main.py b/src/main.py index d3f96f3..7dc9614 100644 --- a/src/main.py +++ b/src/main.py @@ -1,7 +1,7 @@ import asyncio -import logging from contextlib import asynccontextmanager +import structlog from fastapi import FastAPI from fastapi.middleware.cors import CORSMiddleware @@ -24,10 +24,7 @@ # --- Application Setup --- -logging.basicConfig( - level=logging.INFO, - format="%(asctime)s %(levelname)8s %(message)s", -) +logger = structlog.get_logger() @asynccontextmanager @@ -65,7 +62,7 @@ async def lifespan(_app: FastAPI): # Start the deployment scheduler asyncio.create_task(get_deployment_scheduler().start_background_scheduler()) - logging.info("šŸš€ Deployment scheduler started") + logger.info("deployment_scheduler_started") yield diff --git a/src/rules/github_provider.py b/src/rules/github_provider.py index d9910f7..09547b3 100644 --- a/src/rules/github_provider.py +++ b/src/rules/github_provider.py @@ -1,6 +1,6 @@ -import logging from typing import Any +import structlog import yaml from src.core.config import config @@ -9,7 +9,7 @@ from src.rules.interface import RuleLoader from src.rules.models import Rule, RuleAction, RuleSeverity -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class RulesFileNotFoundError(Exception): @@ -35,12 +35,12 @@ async def get_rules(self, repository: str, installation_id: int) -> list[Rule]: logger.info(f"Fetching rules for repository: {repository} (installation: {installation_id})") content = await self.github_client.get_file_content(repository, rules_file_path, installation_id) if not content: - logger.warning(f"No rules.yaml file found in {repository}") + logger.warning("no_rulesyaml_file_found_in", repository=repository) raise RulesFileNotFoundError(f"Rules file not found: {rules_file_path}") rules_data = yaml.safe_load(content) if not rules_data or "rules" not in rules_data: - logger.warning(f"No rules found in {repository}/{rules_file_path}") + logger.warning("no_rules_found_in", repository=repository, rules_file_path=rules_file_path) return [] rules = [] @@ -51,7 +51,7 @@ async def get_rules(self, repository: str, installation_id: int) -> list[Rule]: rules.append(rule) except Exception as e: rule_description = rule_data.get("description", "unknown") - logger.error(f"Error parsing rule {rule_description}: {e}") + logger.error("error_parsing_rule", rule_description=rule_description, e=e) continue logger.info(f"Successfully loaded {len(rules)} rules from {repository}") @@ -60,7 +60,7 @@ async def get_rules(self, repository: str, installation_id: int) -> list[Rule]: # Re-raise this specific exception raise except Exception as e: - logger.error(f"Error fetching rules for {repository}: {e}") + logger.error("error_fetching_rules_for", repository=repository, e=e) raise def _parse_rule(self, rule_data: dict[str, Any]) -> Rule: @@ -75,7 +75,7 @@ def _parse_rule(self, rule_data: dict[str, Any]) -> Rule: event_type = EventType(event_type_str) event_types.append(event_type) except ValueError: - logger.warning(f"Unknown event type: {event_type_str}") + logger.warning("unknown_event_type", event_type_str=event_type_str) # No mapping: just pass parameters as-is parameters = rule_data.get("parameters", {}) diff --git a/src/rules/models.py b/src/rules/models.py index 8823bd3..149a05a 100644 --- a/src/rules/models.py +++ b/src/rules/models.py @@ -1,4 +1,4 @@ -from enum import Enum +from enum import StrEnum from typing import Any from pydantic import BaseModel, Field @@ -6,7 +6,7 @@ from src.core.models import EventType -class RuleSeverity(str, Enum): +class RuleSeverity(StrEnum): """Enumerates the severity levels of a rule violation.""" LOW = "low" diff --git a/src/rules/utils.py b/src/rules/utils.py index afd1017..5e8235e 100644 --- a/src/rules/utils.py +++ b/src/rules/utils.py @@ -1,12 +1,12 @@ -import logging from typing import Any +import structlog import yaml from src.integrations.github_api import github_client from src.rules.models import Rule -logger = logging.getLogger(__name__) +logger = structlog.get_logger() DOCS_URL = "https://github.com/warestack/watchflow/blob/main/docs/getting-started/configuration.md" @@ -21,7 +21,7 @@ async def validate_rules_yaml_from_repo(repo_full_name: str, installation_id: in comment=validation_result["message"], installation_id=installation_id, ) - logger.info(f"Posted validation result to PR #{pr_number} in {repo_full_name}") + logger.info("posted_validation_result_to_pr_in", pr_number=pr_number, repo_full_name=repo_full_name) async def _validate_rules_yaml(repo: str, installation_id: int) -> dict[str, Any]: diff --git a/src/rules/validators.py b/src/rules/validators.py index b04ac19..cebd354 100644 --- a/src/rules/validators.py +++ b/src/rules/validators.py @@ -1,10 +1,11 @@ -import logging import re from abc import ABC, abstractmethod from datetime import datetime from typing import Any -logger = logging.getLogger(__name__) +import structlog + +logger = structlog.get_logger() class Condition(ABC): @@ -54,17 +55,17 @@ class AuthorTeamCondition(Condition): async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> bool: team_name = parameters.get("team") if not team_name: - logger.warning("AuthorTeamCondition: No team specified in parameters") + logger.warning("authorteamcondition_no_team_specified_in_parameters") return False # Get author from event author_login = event.get("sender", {}).get("login", "") if not author_login: - logger.warning("AuthorTeamCondition: No sender login found in event") + logger.warning("authorteamcondition_no_sender_login_found_in") return False # Placeholder logic - replace with actual GitHub API call - logger.debug(f"Checking if {author_login} is in team {team_name}") + logger.debug("checking_if_is_in_team", author_login=author_login, team_name=team_name) # For testing purposes, let's assume certain users are in certain teams team_memberships = { @@ -90,14 +91,14 @@ class FilePatternCondition(Condition): async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> bool: pattern = parameters.get("pattern") if not pattern: - logger.warning("FilePatternCondition: No pattern specified in parameters") + logger.warning("filepatterncondition_no_pattern_specified_in_parameters") return False # Get the list of changed files from the event changed_files = self._get_changed_files(event) if not changed_files: - logger.debug("No files to check against pattern") + logger.debug("no_files_to_check_against_pattern") return False # Convert glob pattern to regex @@ -227,7 +228,11 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b if review.get("state") == "APPROVED": approved_count += 1 - logger.debug(f"MinApprovalsCondition: PR has {approved_count} approvals, requires {min_approvals}") + logger.debug( + "minapprovalscondition_pr_has_approvals_requires", + approved_count=approved_count, + min_approvals=min_approvals, + ) return approved_count >= min_approvals @@ -265,13 +270,13 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b is_restricted = weekday in days logger.debug( - f"DaysCondition: PR merged on {weekday}, restricted days: {days}, is_restricted: {is_restricted}" + "dayscondition_pr_merged_on_restricted_days", weekday=weekday, days=days, is_restricted=is_restricted ) return not is_restricted # Return True if NOT restricted (no violation) except Exception as e: - logger.error(f"DaysCondition: Error parsing merged_at timestamp '{merged_at}': {e}") + logger.error("dayscondition_error_parsing_mergedat_timestamp", merged_at=merged_at, e=e) return True # No violation if we can't parse the date @@ -301,10 +306,10 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b # Test the pattern try: matches = bool(re.match(pattern, title)) - logger.debug(f"TitlePatternCondition: Title '{title}' matches pattern '{pattern}': {matches}") + logger.debug("titlepatterncondition_title_matches_pattern", title=title, pattern=pattern, matches=matches) return matches except re.error as e: - logger.error(f"TitlePatternCondition: Invalid regex pattern '{pattern}': {e}") + logger.error("titlepatterncondition_invalid_regex_pattern", pattern=pattern, e=e) return True # No violation if pattern is invalid @@ -333,7 +338,10 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b is_valid = description_length >= min_length logger.debug( - f"MinDescriptionLengthCondition: Description length {description_length}, requires {min_length}: {is_valid}" + "mindescriptionlengthcondition_description_length_requires", + description_length=description_length, + min_length=min_length, + is_valid=is_valid, ) return is_valid @@ -366,7 +374,11 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b is_valid = len(missing_labels) == 0 logger.debug( - f"RequiredLabelsCondition: PR has labels {pr_labels}, requires {required_labels}, missing {missing_labels}: {is_valid}" + "requiredlabelscondition_pr_has_labels_requires_missing", + pr_labels=pr_labels, + required_labels=required_labels, + missing_labels=missing_labels, + is_valid=is_valid, ) return is_valid @@ -387,7 +399,7 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b # If no files data is available, we can't evaluate this rule if not files: - logger.debug("MaxFileSizeCondition: No files data available, skipping validation") + logger.debug("maxfilesizecondition_no_files_data_available_skipping") return True # No violation if we can't check # Check each file's size @@ -399,7 +411,7 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b filename = file.get("filename", "unknown") oversized_files.append(f"{filename} ({size_mb:.2f}MB)") logger.debug( - f"MaxFileSizeCondition: File {filename} exceeds size limit: {size_mb:.2f}MB > {max_size_mb}MB" + "maxfilesizecondition_file_exceeds_size_limit_mb", filename=filename, max_size_mb=max_size_mb ) is_valid = len(oversized_files) == 0 @@ -437,10 +449,10 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b try: matches = bool(re.match(pattern, title)) - logger.debug(f"PatternCondition: Title '{title}' matches pattern '{pattern}': {matches}") + logger.debug("patterncondition_title_matches_pattern", title=title, pattern=pattern, matches=matches) return matches except re.error as e: - logger.error(f"PatternCondition: Invalid regex pattern '{pattern}': {e}") + logger.error("patterncondition_invalid_regex_pattern", pattern=pattern, e=e) return True # No violation if pattern is invalid @@ -486,7 +498,10 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b is_protected = base_branch in protected_branches logger.debug( - f"ProtectedBranchesCondition: Base branch '{base_branch}' in protected list {protected_branches}: {is_protected}" + "protectedbranchescondition_base_branch_in_protected_list", + base_branch=base_branch, + protected_branches=protected_branches, + is_protected=is_protected, ) return not is_protected # Return True if NOT protected (no violation) @@ -556,13 +571,16 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b current_time = datetime.now(tz) except (ImportError, pytz.exceptions.UnknownTimeZoneError): # Fallback to UTC if pytz is not available or timezone is invalid - logger.warning(f"Invalid timezone '{timezone_str}', using UTC") + logger.warning("invalid_timezone_using_utc", timezone_str=timezone_str) current_time = datetime.now() current_hour = current_time.hour logger.debug( - f"AllowedHoursCondition: Current hour {current_hour} in timezone {timezone_str}, allowed hours: {allowed_hours}" + "allowedhourscondition_current_hour_in_timezone_allowed", + current_hour=current_hour, + timezone_str=timezone_str, + allowed_hours=allowed_hours, ) return current_hour in allowed_hours @@ -590,7 +608,12 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b is_allowed = base_branch in branches - logger.debug(f"BranchesCondition: Base branch '{base_branch}' in allowed branches {branches}: {is_allowed}") + logger.debug( + "branchescondition_base_branch_in_allowed_branches", + base_branch=base_branch, + branches=branches, + is_allowed=is_allowed, + ) return is_allowed @@ -631,7 +654,7 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b # Get the list of changed files from the event changed_files = self._get_changed_files(event) if not changed_files: - logger.debug("CodeOwnersCondition: No files to check") + logger.debug("codeownerscondition_no_files_to_check") return True # Check if any of the changed files require code owner review @@ -645,7 +668,9 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b ) logger.debug( - f"CodeOwnersCondition: Files {changed_files} require code owner review: {requires_code_owner_review}" + "codeownerscondition_files_require_code_owner_review", + changed_files=changed_files, + requires_code_owner_review=requires_code_owner_review, ) return not requires_code_owner_review # Return True if NO code owner review needed @@ -681,7 +706,7 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b author_login = pull_request.get("user", {}).get("login", "") if not author_login: - logger.warning("PastContributorApprovalCondition: No author found") + logger.warning("pastcontributorapprovalcondition_no_author_found") return False # Get repository and installation info from event @@ -689,13 +714,13 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b installation_id = event.get("installation", {}).get("id") if not repo or not installation_id: - logger.warning("PastContributorApprovalCondition: Missing repo or installation_id") + logger.warning("pastcontributorapprovalcondition_missing_repo_or_installationid") return False # Get GitHub client from event (passed by event processor) github_client = event.get("github_client") if not github_client: - logger.warning("PastContributorApprovalCondition: No GitHub client available") + logger.warning("pastcontributorapprovalcondition_no_github_client_available") return False # Check if author is a new contributor using the contributor analyzer @@ -704,13 +729,13 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b is_author_new = await is_new_contributor(author_login, repo, github_client, installation_id) if not is_author_new: - logger.debug(f"PastContributorApprovalCondition: {author_login} is not a new contributor") + logger.debug("pastcontributorapprovalcondition_is_not_a_new_contributor", author_login=author_login) return True # Get PR reviews reviews = event.get("reviews", []) if not reviews: - logger.debug(f"PastContributorApprovalCondition: No reviews found for new contributor {author_login}") + logger.debug("pastcontributorapprovalcondition_no_reviews_found_for_new", author_login=author_login) return False # Count approvals from past contributors @@ -725,7 +750,11 @@ async def validate(self, parameters: dict[str, Any], event: dict[str, Any]) -> b is_valid = past_contributor_approvals >= min_past_contributors logger.debug( - f"PastContributorApprovalCondition: {author_login} has {past_contributor_approvals} past contributor approvals, needs {min_past_contributors}: {is_valid}" + "pastcontributorapprovalcondition_has_past_contributor_approvals_needs", + author_login=author_login, + past_contributor_approvals=past_contributor_approvals, + min_past_contributors=min_past_contributors, + is_valid=is_valid, ) return is_valid diff --git a/src/tasks/scheduler/deployment_scheduler.py b/src/tasks/scheduler/deployment_scheduler.py index e0aaefe..82892e6 100644 --- a/src/tasks/scheduler/deployment_scheduler.py +++ b/src/tasks/scheduler/deployment_scheduler.py @@ -1,12 +1,13 @@ import asyncio -import logging -from datetime import datetime, timedelta +from datetime import UTC, datetime, timedelta from typing import Any +import structlog + from src.agents.engine_agent.agent import RuleEngineAgent from src.integrations.github_api import github_client -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentScheduler: @@ -29,12 +30,12 @@ def engine_agent(self) -> RuleEngineAgent: async def start(self): """Start the scheduler.""" if self.running: - logger.warning("Deployment scheduler is already running") + logger.warning("scheduler_already_running") return self.running = True self.scheduler_task = asyncio.create_task(self._scheduler_loop()) - logger.info("šŸ•’ Deployment scheduler started - checking every 15 minutes") + logger.info("scheduler_started", check_interval_minutes=15) async def stop(self): """Stop the scheduler.""" @@ -45,7 +46,7 @@ async def stop(self): await self.scheduler_task except asyncio.CancelledError: pass - logger.info("šŸ›‘ Deployment scheduler stopped") + logger.info("scheduler_stopped") async def add_pending_deployment(self, deployment_data: dict[str, Any]): """ @@ -62,9 +63,10 @@ async def add_pending_deployment(self, deployment_data: dict[str, Any]): - violations: Current violations - time_based_violations: Time-based violations - created_at: Timestamp when added + - callback_url: Deployment callback URL """ try: - # Validate required fields + # Validate required fields - add callback_url required_fields = [ "deployment_id", "repo", @@ -75,20 +77,32 @@ async def add_pending_deployment(self, deployment_data: dict[str, Any]): "violations", "time_based_violations", "created_at", + "callback_url", ] - missing_fields = [field for field in required_fields if not deployment_data.get(field)] + missing_fields = [field for field in required_fields if deployment_data.get(field) is None] if missing_fields: - logger.error(f"Missing required fields for deployment scheduler: {missing_fields}") + logger.error( + "missing_required_fields", + operation="add_pending_deployment", + missing_fields=missing_fields, + ) return - logger.info(f"ā° Adding deployment {deployment_data['deployment_id']} to scheduler") - logger.info(f" Repo: {deployment_data['repo']}") - logger.info(f" Installation: {deployment_data['installation_id']}") - logger.info(f" Time-based violations: {len(deployment_data.get('time_based_violations', []))}") + logger.info( + "adding_deployment_to_scheduler", + operation="add_pending_deployment", + subject_ids={"repo": deployment_data["repo"], "deployment_id": deployment_data["deployment_id"]}, + installation_id=deployment_data["installation_id"], + num_time_based_violations=len(deployment_data.get("time_based_violations", [])), + ) self.pending_deployments.append(deployment_data) except Exception as e: - logger.error(f"Error adding deployment to scheduler: {e}") + logger.error( + "add_deployment_error", + operation="add_pending_deployment", + error=str(e), + ) async def _scheduler_loop(self): """Main scheduler loop - runs every 15 minutes.""" @@ -98,10 +112,10 @@ async def _scheduler_loop(self): # Wait 15 minutes (900 seconds) await asyncio.sleep(900) except asyncio.CancelledError: - logger.info("Scheduler loop cancelled") + logger.info("scheduler_loop_cancelled") break except Exception as e: - logger.error(f"Scheduler error: {e}") + logger.error("scheduler_loop_error", error=str(e)) # Wait 1 minute on error before retrying await asyncio.sleep(60) @@ -110,9 +124,12 @@ async def _check_pending_deployments(self): if not self.pending_deployments: return - current_time = datetime.utcnow() + current_time = datetime.now(UTC) logger.info( - f"šŸ” Checking {len(self.pending_deployments)} pending deployments at {current_time.strftime('%Y-%m-%d %H:%M:%S')} UTC" + "checking_pending_deployments", + operation="_check_pending_deployments", + num_pending=len(self.pending_deployments), + current_time=current_time.isoformat(), ) deployments_to_remove = [] @@ -121,20 +138,27 @@ async def _check_pending_deployments(self): try: # Check if deployment is too old (remove after 7 days) created_at = deployment.get("created_at") - if created_at: + if created_at is not None: if isinstance(created_at, int | float): - # Convert timestamp to datetime - created_at = datetime.fromtimestamp(created_at) + # Convert timestamp to datetime with timezone awareness + created_at = datetime.fromtimestamp(created_at, tz=UTC) age = current_time - created_at if age > timedelta(days=7): logger.info( - f"ā° Removing expired deployment for {deployment.get('repo')} (age: {age.days} days)" + "removing_expired_deployment", + operation="_check_pending_deployments", + subject_ids={"repo": deployment.get("repo")}, + age_days=age.days, ) deployments_to_remove.append(i) continue else: # If no created_at timestamp, remove the deployment as it's invalid - logger.warning(f"ā° Removing deployment for {deployment.get('repo')} with no created_at timestamp") + logger.warning( + "removing_deployment_no_timestamp", + operation="_check_pending_deployments", + subject_ids={"repo": deployment.get("repo")}, + ) deployments_to_remove.append(i) continue @@ -149,42 +173,70 @@ async def _check_pending_deployments(self): await self._approve_deployment(deployment) deployments_to_remove.append(i) else: - logger.info(f"ā³ Deployment for {deployment.get('repo')} still blocked by time-based rules") + logger.info( + "deployment_still_blocked", + operation="_check_pending_deployments", + subject_ids={"repo": deployment.get("repo")}, + ) except Exception as e: - logger.error(f"Error re-evaluating deployment {deployment.get('repo', 'unknown')}: {e}") + logger.error( + "re_evaluate_error", + operation="_check_pending_deployments", + subject_ids={"repo": deployment.get("repo", "unknown")}, + error=str(e), + ) # Remove processed deployments (in reverse order to maintain indices) for i in reversed(deployments_to_remove): removed = self.pending_deployments.pop(i) - logger.info(f"āœ… Removed deployment for {removed.get('repo')} from scheduler") + logger.info( + "deployment_removed_from_scheduler", + operation="_check_pending_deployments", + subject_ids={"repo": removed.get("repo")}, + ) if self.pending_deployments: - logger.info(f"šŸ“‹ {len(self.pending_deployments)} deployments still pending") + logger.info("deployments_still_pending", num_pending=len(self.pending_deployments)) async def _re_evaluate_deployment(self, deployment: dict[str, Any]) -> bool: """Re-evaluate a deployment against current time-based rules.""" try: # Validate required fields required_fields = ["repo", "environment", "installation_id", "event_data", "rules"] - missing_fields = [field for field in required_fields if not deployment.get(field)] + missing_fields = [field for field in required_fields if deployment.get(field) is None] if missing_fields: - logger.error(f"Missing required fields for deployment re-evaluation: {missing_fields}") + logger.error( + "missing_required_fields", + operation="_re_evaluate_deployment", + missing_fields=missing_fields, + ) return False logger.info( - f"šŸ”„ Re-evaluating deployment for {deployment.get('repo')} environment {deployment.get('environment')}" + "re_evaluating_deployment", + operation="_re_evaluate_deployment", + subject_ids={"repo": deployment.get("repo")}, + environment=deployment.get("environment"), ) # Refresh the GitHub token (it might have expired) try: fresh_token = await github_client.get_installation_access_token(deployment["installation_id"]) - if not fresh_token: - logger.error(f"Failed to get fresh GitHub token for installation {deployment['installation_id']}") + if fresh_token is None: + logger.error( + "failed_to_get_token", + operation="_re_evaluate_deployment", + installation_id=deployment["installation_id"], + ) return False deployment["github_token"] = fresh_token except Exception as e: - logger.error(f"Failed to refresh GitHub token: {e}") + logger.error( + "token_refresh_error", + operation="_re_evaluate_deployment", + error=str(e), + ) return False # Convert rules to the format expected by the analysis agent @@ -200,7 +252,11 @@ async def _re_evaluate_deployment(self, deployment: dict[str, Any]) -> bool: violations = result.data.get("violations", []) if not violations: - logger.info("āœ… No violations found - deployment can be approved") + logger.info( + "no_violations_deployment_can_approve", + operation="_re_evaluate_deployment", + subject_ids={"repo": deployment.get("repo")}, + ) return True # Check if any violations are still time-based @@ -233,43 +289,70 @@ async def _re_evaluate_deployment(self, deployment: dict[str, Any]) -> bool: other_violations.append(violation) if other_violations: - logger.info(f"āŒ Deployment still has non-time-based violations: {len(other_violations)}") + logger.info( + "deployment_has_non_time_violations", + operation="_re_evaluate_deployment", + subject_ids={"repo": deployment.get("repo")}, + num_violations=len(other_violations), + ) # Remove from scheduler since these won't resolve automatically return False if time_based_violations: - logger.info(f"ā° Deployment still blocked by {len(time_based_violations)} time-based violations") + logger.info( + "deployment_still_blocked_by_time", + operation="_re_evaluate_deployment", + subject_ids={"repo": deployment.get("repo")}, + num_violations=len(time_based_violations), + ) return False # No violations left - logger.info("āœ… All violations resolved - deployment can be approved") + logger.info( + "all_violations_resolved", + operation="_re_evaluate_deployment", + subject_ids={"repo": deployment.get("repo")}, + ) return True except Exception as e: - logger.error(f"Error re-evaluating deployment: {e}") + logger.error( + "re_evaluate_error", + operation="_re_evaluate_deployment", + error=str(e), + ) return False async def _approve_deployment(self, deployment: dict[str, Any]): """Approve a previously rejected deployment.""" + repo = deployment.get("repo", "unknown") try: callback_url = deployment.get("callback_url") installation_id = deployment.get("installation_id") - repo = deployment.get("repo", "unknown") environment = deployment.get("environment", "unknown") - if not callback_url: - logger.error(f"No callback URL found for deployment {repo}") + if callback_url is None: + logger.error( + "no_callback_url", + operation="_approve_deployment", + subject_ids={"repo": repo}, + ) return - if not installation_id: - logger.error(f"No installation ID found for deployment {repo}") + if installation_id is None: + logger.error( + "no_installation_id", + operation="_approve_deployment", + subject_ids={"repo": repo}, + ) return + current_time = datetime.now(UTC) comment = ( "āœ… **Deployment Automatically Approved**\n\n" "Time-based restrictions have been lifted. The deployment can now proceed.\n\n" f"**Environment:** {environment}\n" - f"**Approved at:** {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S')} UTC\n\n" + f"**Approved at:** {current_time.strftime('%Y-%m-%d %H:%M:%S')} UTC\n\n" "The deployment will be automatically approved on GitHub." ) @@ -282,38 +365,60 @@ async def _approve_deployment(self, deployment: dict[str, Any]): installation_id=installation_id, ) - logger.info(f"āœ… Deployment {deployment.get('deployment_id')} automatically approved for {repo}") + logger.info( + "deployment_auto_approved", + operation="_approve_deployment", + subject_ids={"repo": repo, "deployment_id": deployment.get("deployment_id")}, + environment=environment, + ) except Exception as e: - logger.error(f"Error approving deployment {deployment.get('deployment_id')}: {e}") + logger.error( + "approve_deployment_error", + operation="_approve_deployment", + subject_ids={"repo": repo}, + error=str(e), + ) def get_status(self) -> dict[str, Any]: """Get current scheduler status.""" try: - return { - "running": self.running, - "pending_count": len(self.pending_deployments), - "pending_deployments": [ + pending_deployments = [] + for d in self.pending_deployments: + created_at = d.get("created_at") + created_at_iso = None + if created_at is not None: + if isinstance(created_at, int | float): + created_at_iso = datetime.fromtimestamp(created_at, tz=UTC).isoformat() + elif hasattr(created_at, "isoformat"): + created_at_iso = created_at.isoformat() + else: + created_at_iso = str(created_at) + + last_checked = d.get("last_checked") + last_checked_iso = ( + last_checked.isoformat() if last_checked and hasattr(last_checked, "isoformat") else None + ) + + pending_deployments.append( { "repo": d.get("repo"), "environment": d.get("environment"), "deployment_id": d.get("deployment_id"), - "created_at": datetime.fromtimestamp(d.get("created_at")).isoformat() - if d.get("created_at") and isinstance(d.get("created_at"), int | float) - else ( - d.get("created_at").isoformat() - if hasattr(d.get("created_at"), "isoformat") - else str(d.get("created_at")) - ), - "last_checked": d.get("last_checked").isoformat() if d.get("last_checked") else None, + "created_at": created_at_iso, + "last_checked": last_checked_iso, "violations_count": len(d.get("violations", [])), "time_based_violations_count": len(d.get("time_based_violations", [])), } - for d in self.pending_deployments - ], + ) + + return { + "running": self.running, + "pending_count": len(self.pending_deployments), + "pending_deployments": pending_deployments, } except Exception as e: - logger.error(f"Error getting scheduler status: {e}") + logger.error("get_status_error", error=str(e)) return {"running": self.running, "pending_count": len(self.pending_deployments), "error": str(e)} async def start_background_scheduler(self): @@ -344,8 +449,11 @@ def _convert_rules_to_new_format(self, rules: list[Any]) -> list[dict[str, Any]] formatted_rules.append(rule_dict) except Exception as e: - logger.error(f"Error converting rule to new format: {e}") - # Skip this rule if conversion fails + logger.error( + "rule_conversion_error", + operation="_convert_rules_to_new_format", + error=str(e), + ) continue return formatted_rules diff --git a/src/tasks/task_queue.py b/src/tasks/task_queue.py index ead9593..6a8e476 100644 --- a/src/tasks/task_queue.py +++ b/src/tasks/task_queue.py @@ -1,17 +1,17 @@ import asyncio import hashlib import json -import logging from datetime import datetime -from enum import Enum +from enum import StrEnum from typing import Any +import structlog from pydantic import BaseModel -logger = logging.getLogger(__name__) +logger = structlog.get_logger() -class TaskStatus(str, Enum): +class TaskStatus(StrEnum): PENDING = "pending" RUNNING = "running" COMPLETED = "completed" @@ -102,11 +102,11 @@ def _create_event_hash(self, event_type: str, repo_full_name: str, payload: dict # Debug logging for issue_comment events if event_type == "issue_comment": - logger.info(f"šŸ” Event hash debug for {event_type}:") + logger.info("event_hash_debug_for", event_type=event_type) logger.info(f" Comment ID: {event_data.get('comment_id')}") logger.info(f" Comment body: {event_data.get('comment_body', '')[:50]}...") logger.info(f" Comment created at: {event_data.get('comment_created_at')}") - logger.info(f" Event hash: {event_hash}") + logger.info("event_hash", event_hash=event_hash) return event_hash @@ -127,7 +127,7 @@ async def enqueue(self, event_type: str, repo_full_name: str, installation_id: i self.tasks[task_id] = task - logger.info(f"Enqueued task {task_id} for {repo_full_name}") + logger.info("enqueued_task_for", task_id=task_id, repo_full_name=repo_full_name) return task_id @@ -137,7 +137,7 @@ async def start_workers(self, num_workers: int = 3): for i in range(num_workers): worker = asyncio.create_task(self._worker(f"worker-{i}")) self.workers.append(worker) - logger.info(f"Started {num_workers} background workers") + logger.info("started_background_workers", num_workers=num_workers) async def stop_workers(self): """Stop background workers.""" @@ -145,11 +145,11 @@ async def stop_workers(self): for worker in self.workers: worker.cancel() await asyncio.gather(*self.workers, return_exceptions=True) - logger.info("Stopped all background workers") + logger.info("stopped_all_background_workers") async def _worker(self, worker_name: str): """Background worker that processes tasks.""" - logger.info(f"Worker {worker_name} started") + logger.info("worker_started", worker_name=worker_name) last_cleanup = datetime.now() cleanup_interval = 3600 # Clean up every hour @@ -173,10 +173,10 @@ async def _worker(self, worker_name: str): await asyncio.sleep(1) except Exception as e: - logger.error(f"Worker {worker_name} error: {e}") + logger.error("worker_error", worker_name=worker_name, e=e) await asyncio.sleep(5) - logger.info(f"Worker {worker_name} stopped") + logger.info("worker_stopped", worker_name=worker_name) async def _process_task(self, task: Task, worker_name: str): """Process a single task.""" @@ -184,7 +184,7 @@ async def _process_task(self, task: Task, worker_name: str): task.status = TaskStatus.RUNNING task.started_at = datetime.now() - logger.info(f"Worker {worker_name} processing task {task.id}") + logger.info("worker_processing_task", worker_name=worker_name, id=task.id) # Get the appropriate processor processor = self._get_processor(task.event_type) @@ -194,13 +194,13 @@ async def _process_task(self, task: Task, worker_name: str): task.completed_at = datetime.now() task.result = result.__dict__ if hasattr(result, "__dict__") else result - logger.info(f"Task {task.id} completed successfully") + logger.info("task_completed_successfully", id=task.id) except Exception as e: task.status = TaskStatus.FAILED task.completed_at = datetime.now() task.error = str(e) - logger.error(f"Task {task.id} failed: {e}") + logger.error("task_failed", id=task.id, e=e) def cleanup_old_tasks(self, max_age_hours: int = 24): """Clean up old completed tasks and their event hashes to prevent memory leaks.""" diff --git a/src/webhooks/auth.py b/src/webhooks/auth.py index 765e75a..3e888ab 100644 --- a/src/webhooks/auth.py +++ b/src/webhooks/auth.py @@ -1,12 +1,12 @@ import hashlib import hmac -import logging +import structlog from fastapi import HTTPException, Request from src.core.config import config -logger = logging.getLogger(__name__) +logger = structlog.get_logger() GITHUB_WEBHOOK_SECRET = config.github.webhook_secret @@ -26,7 +26,7 @@ async def verify_github_signature(request: Request) -> bool: """ signature = request.headers.get("X-Hub-Signature-256") if not signature: - logger.warning("Received a request without the X-Hub-Signature-256 header.") + logger.warning("received_a_request_without_the_xhubsignature256") raise HTTPException(status_code=401, detail="Missing GitHub webhook signature.") # Get the raw request payload as bytes @@ -38,8 +38,8 @@ async def verify_github_signature(request: Request) -> bool: # Securely compare the signatures if not hmac.compare_digest(signature, expected_signature): - logger.error("Invalid webhook signature.") + logger.error("invalid_webhook_signature") raise HTTPException(status_code=401, detail="Invalid GitHub webhook signature.") - logger.debug("GitHub webhook signature verified successfully.") + logger.debug("github_webhook_signature_verified_successfully") return True diff --git a/src/webhooks/dispatcher.py b/src/webhooks/dispatcher.py index a0603ff..6b488ab 100644 --- a/src/webhooks/dispatcher.py +++ b/src/webhooks/dispatcher.py @@ -1,10 +1,12 @@ -import logging from typing import Any +import structlog + from src.core.models import EventType, WebhookEvent +from src.core.utils.event_filter import should_process_event from src.webhooks.handlers.base import EventHandler # Import the base handler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class WebhookDispatcher: @@ -25,9 +27,9 @@ def register_handler(self, event_type: EventType, handler: EventHandler): handler: An instance of a class that implements the EventHandler interface. """ if event_type in self._handlers: - logger.warning(f"Handler for event type {event_type} is being overridden.") + logger.warning("handler_overridden", event_type=event_type.name) self._handlers[event_type] = handler - logger.info(f"Registered handler for {event_type.name}: {handler.__class__.__name__}") + logger.info("handler_registered", event_type=event_type.name, handler=handler.__class__.__name__) async def dispatch(self, event: WebhookEvent) -> dict[str, Any]: """ @@ -43,17 +45,46 @@ async def dispatch(self, event: WebhookEvent) -> dict[str, Any]: handler_instance = self._handlers.get(event.event_type) if not handler_instance: - logger.warning(f"No handler registered for event type {event.event_type}. Skipping.") + logger.warning( + "handler_not_found", + operation="dispatch", + subject_ids={"repo": event.repo_full_name}, + event_type=event.event_type.name, + ) return {"status": "skipped", "reason": f"No handler for event type {event.event_type.name}"} + # Apply event filtering before dispatching + filter_result = should_process_event(event) + if not filter_result.should_process: + logger.info( + "event_filtered", + operation="dispatch", + subject_ids={"repo": event.repo_full_name}, + event_type=event.event_type.name, + reason=filter_result.reason, + ) + return {"status": "filtered", "reason": filter_result.reason, "event_type": event.event_type.name} + try: handler_name = handler_instance.__class__.__name__ - logger.info(f"Dispatching event {event.event_type.name} to handler {handler_name}.") + logger.info( + "dispatching_event", + operation="dispatch", + subject_ids={"repo": event.repo_full_name}, + event_type=event.event_type.name, + handler=handler_name, + ) # Call the 'handle' method on the registered handler instance result = await handler_instance.handle(event) return {"status": "processed", "handler": handler_name, "result": result} except Exception as e: - logger.exception(f"Error executing handler for event {event.event_type.name}: {e}") + logger.exception( + "handler_error", + operation="dispatch", + subject_ids={"repo": event.repo_full_name}, + event_type=event.event_type.name, + error=str(e), + ) return {"status": "error", "reason": str(e)} diff --git a/src/webhooks/handlers/check_run.py b/src/webhooks/handlers/check_run.py index 8a1a637..978851a 100644 --- a/src/webhooks/handlers/check_run.py +++ b/src/webhooks/handlers/check_run.py @@ -1,10 +1,10 @@ -import logging +import structlog from src.core.models import WebhookEvent from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class CheckRunEventHandler(EventHandler): @@ -15,7 +15,7 @@ async def can_handle(self, event: WebhookEvent) -> bool: async def handle(self, event: WebhookEvent): """Handle check run events by enqueuing them for background processing.""" - logger.info(f"šŸ”„ Enqueuing check run event for {event.repo_full_name}") + logger.info("enqueuing_check_run_event_for", repo_full_name=event.repo_full_name) task_id = await task_queue.enqueue( event_type="check_run", @@ -24,6 +24,6 @@ async def handle(self, event: WebhookEvent): payload=event.payload, ) - logger.info(f"āœ… Check run event enqueued with task ID: {task_id}") + logger.info("check_run_event_enqueued_with_task", task_id=task_id) return {"status": "enqueued", "task_id": task_id, "message": "Check run event has been queued for processing"} diff --git a/src/webhooks/handlers/deployment.py b/src/webhooks/handlers/deployment.py index d7319e5..c9b0ddb 100644 --- a/src/webhooks/handlers/deployment.py +++ b/src/webhooks/handlers/deployment.py @@ -1,11 +1,12 @@ -import logging from typing import Any +import structlog + from src.core.models import EventType, WebhookEvent from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentEventHandler(EventHandler): @@ -21,15 +22,15 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: installation_id = payload.get("installation", {}).get("id") if not installation_id: - logger.error(f"No installation ID found in deployment event for {repo_full_name}") + logger.error("no_installation_id_found_in_deployment", repo_full_name=repo_full_name) return {"status": "error", "message": "Missing installation ID"} # Extract deployment info deployment = payload.get("deployment", {}) environment = deployment.get("environment", "unknown") - logger.info(f"šŸ”„ Enqueuing deployment event for {repo_full_name}") - logger.info(f" Environment: {environment}") + logger.info("enqueuing_deployment_event_for", repo_full_name=repo_full_name) + logger.info("environment", environment=environment) logger.info(f" Ref: {deployment.get('ref', 'unknown')}") # Enqueue the task using the global task_queue @@ -37,7 +38,7 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: event_type="deployment", repo_full_name=repo_full_name, installation_id=installation_id, payload=payload ) - logger.info(f"āœ… Deployment event enqueued with task ID: {task_id}") + logger.info("deployment_event_enqueued_with_task_id", task_id=task_id) return { "status": "success", diff --git a/src/webhooks/handlers/deployment_protection_rule.py b/src/webhooks/handlers/deployment_protection_rule.py index aa59e6b..1ba6278 100644 --- a/src/webhooks/handlers/deployment_protection_rule.py +++ b/src/webhooks/handlers/deployment_protection_rule.py @@ -1,10 +1,10 @@ -import logging +import structlog from src.core.models import WebhookEvent from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentProtectionRuleEventHandler(EventHandler): @@ -15,7 +15,7 @@ async def can_handle(self, event: WebhookEvent) -> bool: async def handle(self, event: WebhookEvent): """Handle deployment protection rule events by enqueuing them for background processing.""" - logger.info(f"šŸ”„ Enqueuing deployment protection rule event for {event.repo_full_name}") + logger.info("enqueuing_deployment_protection_rule_event", repo_full_name=event.repo_full_name) task_id = await task_queue.enqueue( event_type="deployment_protection_rule", @@ -24,7 +24,7 @@ async def handle(self, event: WebhookEvent): payload=event.payload, ) - logger.info(f"āœ… Deployment protection rule event enqueued with task ID: {task_id}") + logger.info("deployment_protection_rule_event_enqueued", task_id=task_id) return { "status": "enqueued", diff --git a/src/webhooks/handlers/deployment_review.py b/src/webhooks/handlers/deployment_review.py index e3e76f8..4e542f4 100644 --- a/src/webhooks/handlers/deployment_review.py +++ b/src/webhooks/handlers/deployment_review.py @@ -1,10 +1,10 @@ -import logging +import structlog from src.core.models import WebhookEvent from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentReviewEventHandler(EventHandler): @@ -15,7 +15,7 @@ async def can_handle(self, event: WebhookEvent) -> bool: async def handle(self, event: WebhookEvent): """Handle deployment review events by enqueuing them for background processing.""" - logger.info(f"šŸ”„ Enqueuing deployment review event for {event.repo_full_name}") + logger.info("enqueuing_deployment_review_event_for", repo_full_name=event.repo_full_name) task_id = await task_queue.enqueue( event_type="deployment_review", @@ -24,7 +24,7 @@ async def handle(self, event: WebhookEvent): payload=event.payload, ) - logger.info(f"āœ… Deployment review event enqueued with task ID: {task_id}") + logger.info("deployment_review_event_enqueued_with_task", task_id=task_id) return { "status": "enqueued", diff --git a/src/webhooks/handlers/deployment_status.py b/src/webhooks/handlers/deployment_status.py index 535489a..e8c0ae8 100644 --- a/src/webhooks/handlers/deployment_status.py +++ b/src/webhooks/handlers/deployment_status.py @@ -1,11 +1,12 @@ -import logging from typing import Any +import structlog + from src.core.models import EventType, WebhookEvent from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class DeploymentStatusEventHandler(EventHandler): @@ -21,7 +22,7 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: installation_id = payload.get("installation", {}).get("id") if not installation_id: - logger.error(f"No installation ID found in deployment_status event for {repo_full_name}") + logger.error("no_installation_id_found_in_deploymentstatus", repo_full_name=repo_full_name) return {"status": "error", "message": "Missing installation ID"} # Extract deployment status info @@ -29,8 +30,8 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: deployment = payload.get("deployment", {}) state = deployment_status.get("state", "") - logger.info(f"šŸ”„ Enqueuing deployment status event for {repo_full_name}") - logger.info(f" State: {state}") + logger.info("enqueuing_deployment_status_event_for", repo_full_name=repo_full_name) + logger.info("state", state=state) logger.info(f" Environment: {deployment.get('environment', 'unknown')}") # Enqueue the task using the global task_queue @@ -41,7 +42,7 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: payload=payload, ) - logger.info(f"āœ… Deployment status event enqueued with task ID: {task_id}") + logger.info("deployment_status_event_enqueued_with_task", task_id=task_id) return { "status": "success", diff --git a/src/webhooks/handlers/issue_comment.py b/src/webhooks/handlers/issue_comment.py index fe1f506..33dd22f 100644 --- a/src/webhooks/handlers/issue_comment.py +++ b/src/webhooks/handlers/issue_comment.py @@ -1,7 +1,8 @@ -import logging import re from typing import Any +import structlog + from src.agents.feasibility_agent.agent import RuleFeasibilityAgent from src.core.models import EventType, WebhookEvent from src.integrations.github_api import github_client @@ -9,7 +10,7 @@ from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class IssueCommentEventHandler(EventHandler): @@ -35,10 +36,10 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: # Ignore comments from the bot itself to prevent infinite loops bot_usernames = ["watchflow[bot]", "watchflow-bot", "watchflow", "watchflowbot", "watchflow_bot"] if commenter and any(bot_name.lower() in commenter.lower() for bot_name in bot_usernames): - logger.info(f"šŸ¤– Ignoring comment from bot user: {commenter}") + logger.info("ignoring_comment_from_bot_user", commenter=commenter) return {"status": "ignored", "reason": "Bot comment"} - logger.info(f"šŸ‘¤ Processing comment from human user: {commenter}") + logger.info("processing_comment_from_human_user", commenter=commenter) # Check if this is a help command if self._is_help_comment(comment_body): @@ -50,7 +51,7 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: "- @watchflow validate — Validate the .watchflow/rules.yaml file.\n" "- @watchflow help — Show this help message.\n" ) - logger.info("ā„¹ļø Responding to help command.") + logger.info("responding_to_help_command") pr_number = ( event.payload.get("issue", {}).get("number") or event.payload.get("pull_request", {}).get("number") @@ -63,10 +64,10 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: comment=help_message, installation_id=installation_id, ) - logger.info(f"ā„¹ļø Posted help message as a comment to PR/issue #{pr_number}.") + logger.info("posted_help_message_as_a_comment", pr_number=pr_number) return {"status": "help_posted"} else: - logger.warning("Could not determine PR or issue number to post help message.") + logger.warning("could_not_determine_pr_or_issue") return {"status": "help", "message": help_message} # Check if this is an acknowledgment comment @@ -78,7 +79,7 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: installation_id=installation_id, payload={**event.payload, "acknowledgment_reason": ack_reason}, ) - logger.info(f"āœ… Acknowledgment comment enqueued with task ID: {task_id}") + logger.info("acknowledgment_comment_enqueued_with_task_id", task_id=task_id) return {"status": "acknowledgment_queued", "task_id": task_id, "reason": ack_reason} # Check if this is an evaluate command @@ -109,15 +110,15 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: comment=comment, installation_id=installation_id, ) - logger.info(f"šŸ“ Posted feasibility evaluation result as a comment to PR/issue #{pr_number}.") + logger.info("posted_feasibility_evaluation_result_as_a", pr_number=pr_number) return {"status": "feasibility_evaluation_posted"} else: - logger.warning("Could not determine PR or issue number to post feasibility evaluation result.") + logger.warning("could_not_determine_pr_or_issue") return {"status": "feasibility_evaluation", "message": comment} # Check if this is a validate command if self._is_validate_comment(comment_body): - logger.info("šŸ” Processing validate command.") + logger.info("processing_validate_command") validation_result = await _validate_rules_yaml(repo, installation_id) pr_number = ( event.payload.get("issue", {}).get("number") @@ -131,14 +132,14 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: comment=validation_result, installation_id=installation_id, ) - logger.info(f"āœ… Posted validation result as a comment to PR/issue #{pr_number}.") + logger.info("posted_validation_result_as_a_comment", pr_number=pr_number) return {"status": "validation_posted"} else: - logger.warning("Could not determine PR or issue number to post validation result.") + logger.warning("could_not_determine_pr_or_issue") return {"status": "validation", "message": validation_result} else: - logger.info("šŸ“‹ Comment does not match any known patterns - ignoring") + logger.info("comment_does_not_match_any_known") return {"status": "ignored", "reason": "No matching patterns"} except Exception as e: @@ -149,7 +150,7 @@ def _extract_acknowledgment_reason(self, comment_body: str) -> str | None: """Extract the quoted reason from an acknowledgment command, or None if not present.""" comment_body = comment_body.strip() - logger.info(f"šŸ” Extracting acknowledgment reason from: '{comment_body}'") + logger.info("extracting_acknowledgment_reason_from", comment_body=comment_body) # Try different patterns for flexibility patterns = [ @@ -158,19 +159,19 @@ def _extract_acknowledgment_reason(self, comment_body: str) -> str | None: r"@watchflow\s+(acknowledge|ack)\s+([^\n\r]+)", # No quotes, until end of line ] - for i, pattern in enumerate(patterns): + for _i, pattern in enumerate(patterns): match = re.search(pattern, comment_body, re.IGNORECASE | re.DOTALL) if match: # For patterns with quotes, group 2 contains the reason # For pattern without quotes, group 2 contains the reason reason = match.group(2).strip() - logger.info(f"āœ… Pattern {i + 1} matched! Reason: '{reason}'") + logger.info("pattern_matched_reason", reason=reason) if reason: # Make sure we got a non-empty reason return reason else: - logger.info(f"āŒ Pattern {i + 1} did not match") + logger.info("pattern_did_not_match") - logger.info("āŒ No patterns matched for acknowledgment reason") + logger.info("no_patterns_matched_for_acknowledgment_reason") return None def _extract_evaluate_rule(self, comment_body: str) -> str | None: diff --git a/src/webhooks/handlers/pull_request.py b/src/webhooks/handlers/pull_request.py index 1f567cb..b36c22f 100644 --- a/src/webhooks/handlers/pull_request.py +++ b/src/webhooks/handlers/pull_request.py @@ -1,12 +1,13 @@ -import logging from typing import Any +import structlog + from src.core.models import WebhookEvent from src.rules.utils import validate_rules_yaml_from_repo from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class PullRequestEventHandler(EventHandler): @@ -17,7 +18,7 @@ async def can_handle(self, event: WebhookEvent) -> bool: async def handle(self, event: WebhookEvent) -> dict[str, Any]: """Handle pull request events by enqueuing them for background processing.""" - logger.info(f"šŸ”„ Enqueuing pull request event for {event.repo_full_name}") + logger.info("enqueuing_pull_request_event", repo_full_name=event.repo_full_name) # If the pull request is opened, validate the rules.yaml file if event.payload.get("action") == "opened": @@ -36,7 +37,7 @@ async def handle(self, event: WebhookEvent) -> dict[str, Any]: payload=event.payload, ) - logger.info(f"āœ… Pull request event enqueued with task ID: {task_id}") + logger.info("pull_request_event_enqueued", task_id=task_id) return { "status": "enqueued", diff --git a/src/webhooks/handlers/push.py b/src/webhooks/handlers/push.py index 02c3914..b1e2fc8 100644 --- a/src/webhooks/handlers/push.py +++ b/src/webhooks/handlers/push.py @@ -1,10 +1,10 @@ -import logging +import structlog from src.core.models import WebhookEvent from src.tasks.task_queue import task_queue from src.webhooks.handlers.base import EventHandler -logger = logging.getLogger(__name__) +logger = structlog.get_logger() class PushEventHandler(EventHandler): @@ -15,7 +15,7 @@ async def can_handle(self, event: WebhookEvent) -> bool: async def handle(self, event: WebhookEvent): """Handle push events by enqueuing them for background processing.""" - logger.info(f"šŸ”„ Enqueuing push event for {event.repo_full_name}") + logger.info("enqueuing_push_event", repo_full_name=event.repo_full_name) task_id = await task_queue.enqueue( event_type="push", @@ -24,6 +24,6 @@ async def handle(self, event: WebhookEvent): payload=event.payload, ) - logger.info(f"āœ… Push event enqueued with task ID: {task_id}") + logger.info("push_event_enqueued", task_id=task_id) return {"status": "enqueued", "task_id": task_id, "message": "Push event has been queued for processing"} diff --git a/src/webhooks/router.py b/src/webhooks/router.py index 0a2bf07..d67cdf8 100644 --- a/src/webhooks/router.py +++ b/src/webhooks/router.py @@ -1,12 +1,11 @@ -import logging - +import structlog from fastapi import APIRouter, Depends, HTTPException, Request from src.core.models import EventType, WebhookEvent from src.webhooks.auth import verify_github_signature from src.webhooks.dispatcher import WebhookDispatcher, dispatcher -logger = logging.getLogger(__name__) +logger = structlog.get_logger() router = APIRouter() @@ -24,13 +23,13 @@ def _create_event_from_request(event_name: str | None, payload: dict) -> Webhook # Normalize event name for events like deployment_review.requested normalized_event_name = event_name.split(".")[0] - logger.info(f"Received event: {event_name}, normalized: {normalized_event_name}") + logger.info("received_event_normalized", event_name=event_name, normalized_event_name=normalized_event_name) try: # Map the string from the header (e.g., "pull_request") to our enum event_type = EventType(normalized_event_name) except ValueError as e: - logger.warning(f"Received an unsupported event type: {event_name} - {e}") + logger.warning("received_an_unsupported_event_type", event_name=event_name, e=e) # If the event isn't in our enum, we can't process it. # We'll return a success response to GitHub to acknowledge receipt # but won't do any work. diff --git a/tests/unit/core/test_event_filter.py b/tests/unit/core/test_event_filter.py new file mode 100644 index 0000000..188641e --- /dev/null +++ b/tests/unit/core/test_event_filter.py @@ -0,0 +1,229 @@ +from src.core.models import EventType, WebhookEvent +from src.core.utils.event_filter import ( + NULL_SHA, + PR_ACTIONS_PROCESS, + FilterResult, + should_process_event, +) + + +def _make_event(event_type: EventType, payload: dict, delivery_id: str | None = None) -> WebhookEvent: + return WebhookEvent(event_type=event_type, payload=payload, delivery_id=delivery_id) + + +def test_pull_request_opened_processes(): + """Test that opened PR events are processed.""" + payload = { + "action": "opened", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "open", "merged": False, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is True + + +def test_pull_request_synchronize_processes(): + """Test that synchronize PR events are processed.""" + payload = { + "action": "synchronize", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "open", "merged": False, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is True + + +def test_pull_request_reopened_processes(): + """Test that reopened PR events are processed.""" + payload = { + "action": "reopened", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "open", "merged": False, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is True + + +def test_pull_request_closed_action_filtered(): + """Test that closed PR action is filtered.""" + payload = { + "action": "closed", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "closed", "merged": True}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is False + assert "closed" in result.reason or "not processed" in result.reason + + +def test_pull_request_merged_filtered(): + """Test that merged PRs are filtered.""" + payload = { + "action": "opened", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "closed", "merged": True, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is False + assert "merged" in result.reason or "not open" in result.reason + + +def test_pull_request_draft_filtered(): + """Test that draft PRs are filtered.""" + payload = { + "action": "opened", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "open", "merged": False, "draft": True}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is False + assert "draft" in result.reason + + +def test_pull_request_closed_state_filtered(): + """Test that closed state (not merged) PRs are filtered.""" + payload = { + "action": "opened", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "closed", "merged": False, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is False + assert "not open" in result.reason + + +def test_push_valid_processes(): + """Test that valid push events are processed.""" + payload = { + "repository": {"full_name": "owner/repo"}, + "ref": "refs/heads/main", + "deleted": False, + "after": "abc123", + "commits": [{}], + } + result = should_process_event(_make_event(EventType.PUSH, payload)) + assert result.should_process is True + + +def test_push_deleted_branch_filtered(): + """Test that deleted branch push events are filtered.""" + payload = { + "repository": {"full_name": "owner/repo"}, + "ref": "refs/heads/feature", + "deleted": True, + "after": NULL_SHA, + } + result = should_process_event(_make_event(EventType.PUSH, payload)) + assert result.should_process is False + assert "deletion" in result.reason or "Branch" in result.reason + + +def test_push_null_sha_filtered(): + """Test that null SHA push events are filtered.""" + payload = { + "repository": {"full_name": "owner/repo"}, + "ref": "refs/heads/main", + "deleted": False, + "after": NULL_SHA, + } + result = should_process_event(_make_event(EventType.PUSH, payload)) + assert result.should_process is False + + +def test_push_empty_after_filtered(): + """Test that empty 'after' push events are filtered.""" + payload = { + "repository": {"full_name": "owner/repo"}, + "ref": "refs/heads/main", + "deleted": False, + "after": "", + } + result = should_process_event(_make_event(EventType.PUSH, payload)) + assert result.should_process is False + + +def test_push_missing_after_filtered(): + """Test that missing 'after' push events are filtered.""" + payload = { + "repository": {"full_name": "owner/repo"}, + "ref": "refs/heads/main", + "deleted": False, + } + result = should_process_event(_make_event(EventType.PUSH, payload)) + assert result.should_process is False + + +def test_archived_repo_filtered(): + """Test that archived repositories are filtered.""" + payload = { + "repository": {"full_name": "owner/repo", "archived": True}, + "action": "opened", + "pull_request": {"state": "open", "merged": False, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is False + assert "archived" in result.reason + + +def test_other_event_types_process(): + """Test that other event types are processed (not filtered).""" + payload = {"repository": {"full_name": "owner/repo"}} + for evt in (EventType.CHECK_RUN, EventType.DEPLOYMENT, EventType.DEPLOYMENT_STATUS): + result = should_process_event(_make_event(evt, payload)) + assert result.should_process is True + + +def test_filter_result_dataclass(): + """Test FilterResult dataclass properties.""" + result = FilterResult(should_process=True, reason="test reason") + assert result.should_process is True + assert result.reason == "test reason" + + +def test_filter_result_frozen(): + """Test that FilterResult is frozen (immutable).""" + result = FilterResult(should_process=True, reason="test") + # Attempting to modify should raise an error + try: + result.should_process = False + raise AssertionError("Should have raised FrozenInstanceError") + except Exception: + pass # Expected + + +def test_pr_actions_process_constant(): + """Test PR_ACTIONS_PROCESS contains expected actions.""" + assert "opened" in PR_ACTIONS_PROCESS + assert "synchronize" in PR_ACTIONS_PROCESS + assert "reopened" in PR_ACTIONS_PROCESS + assert len(PR_ACTIONS_PROCESS) == 3 + + +def test_null_sha_constant(): + """Test NULL_SHA has expected value.""" + assert NULL_SHA == "0000000000000000000000000000000000000000" + assert len(NULL_SHA) == 40 + + +def test_pull_request_labeled_action_filtered(): + """Test that labeled PR action is filtered.""" + payload = { + "action": "labeled", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "open", "merged": False, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is False + assert "not processed" in result.reason + + +def test_pull_request_unlabeled_action_filtered(): + """Test that unlabeled PR action is filtered.""" + payload = { + "action": "unlabeled", + "repository": {"full_name": "owner/repo"}, + "pull_request": {"state": "open", "merged": False, "draft": False}, + } + result = should_process_event(_make_event(EventType.PULL_REQUEST, payload)) + assert result.should_process is False + assert "not processed" in result.reason