402 lines
12 KiB
Python
402 lines
12 KiB
Python
import json
|
|
import sys
|
|
from datetime import datetime
|
|
from enum import Enum
|
|
from pathlib import Path
|
|
from typing import Dict, Any, Optional, List
|
|
from dataclasses import dataclass, asdict
|
|
|
|
|
|
class Phase(Enum):
|
|
ANALYZE = "ANALYZE"
|
|
PLAN = "PLAN"
|
|
BUILD = "BUILD"
|
|
VERIFY = "VERIFY"
|
|
DEPLOY = "DEPLOY"
|
|
|
|
|
|
class LogLevel(Enum):
|
|
DEBUG = "DEBUG"
|
|
INFO = "INFO"
|
|
WARNING = "WARNING"
|
|
ERROR = "ERROR"
|
|
CRITICAL = "CRITICAL"
|
|
|
|
|
|
@dataclass
|
|
class LogEntry:
|
|
timestamp: str
|
|
level: str
|
|
event: str
|
|
phase: Optional[str] = None
|
|
duration_ms: Optional[float] = None
|
|
message: Optional[str] = None
|
|
metadata: Dict[str, Any] = None
|
|
error: Optional[str] = None
|
|
|
|
def to_dict(self) -> Dict[str, Any]:
|
|
data = asdict(self)
|
|
if self.metadata is None:
|
|
data.pop('metadata', None)
|
|
if self.error is None:
|
|
data.pop('error', None)
|
|
return {k: v for k, v in data.items() if v is not None}
|
|
|
|
|
|
class StructuredLogger:
|
|
"""
|
|
Structured JSON logging with phase tracking and metrics.
|
|
|
|
Replaces verbose unstructured logs with clean JSON output
|
|
enabling easier debugging and monitoring.
|
|
"""
|
|
|
|
def __init__(
|
|
self,
|
|
log_file: Optional[Path] = None,
|
|
stdout_output: bool = True,
|
|
):
|
|
self.log_file = log_file or Path.home() / '.local/share/rp/structured.log'
|
|
self.stdout_output = stdout_output
|
|
self.log_file.parent.mkdir(parents=True, exist_ok=True)
|
|
self.current_phase: Optional[Phase] = None
|
|
self.phase_start_time: Optional[datetime] = None
|
|
self.entries: List[LogEntry] = []
|
|
|
|
def log_phase_transition(
|
|
self,
|
|
phase: Phase,
|
|
metadata: Optional[Dict[str, Any]] = None,
|
|
) -> None:
|
|
"""
|
|
Log transition to a new phase.
|
|
|
|
Args:
|
|
phase: Phase enum value
|
|
metadata: Optional metadata about the phase
|
|
"""
|
|
if self.current_phase:
|
|
duration = self._get_phase_duration()
|
|
self._log_entry(
|
|
level=LogLevel.INFO,
|
|
event='phase_complete',
|
|
phase=self.current_phase.value,
|
|
duration_ms=duration,
|
|
metadata={'previous_phase': self.current_phase.value},
|
|
)
|
|
|
|
self.current_phase = phase
|
|
self.phase_start_time = datetime.now()
|
|
|
|
self._log_entry(
|
|
level=LogLevel.INFO,
|
|
event='phase_transition',
|
|
phase=phase.value,
|
|
metadata=metadata or {},
|
|
)
|
|
|
|
def log_tool_execution(
|
|
self,
|
|
tool: str,
|
|
success: bool,
|
|
duration: float,
|
|
error: Optional[str] = None,
|
|
metadata: Optional[Dict[str, Any]] = None,
|
|
) -> None:
|
|
"""
|
|
Log tool execution with result and metrics.
|
|
|
|
Args:
|
|
tool: Tool name
|
|
success: Whether execution succeeded
|
|
duration: Execution duration in seconds
|
|
error: Error message if failed
|
|
metadata: Additional metadata
|
|
"""
|
|
self._log_entry(
|
|
level=LogLevel.INFO if success else LogLevel.ERROR,
|
|
event='tool_execution',
|
|
phase=self.current_phase.value if self.current_phase else None,
|
|
duration_ms=duration * 1000,
|
|
message=f"Tool: {tool}, Status: {'SUCCESS' if success else 'FAILED'}",
|
|
error=error,
|
|
metadata=metadata or {'tool': tool, 'success': success},
|
|
)
|
|
|
|
def log_file_operation(
|
|
self,
|
|
operation: str,
|
|
filepath: str,
|
|
success: bool,
|
|
error: Optional[str] = None,
|
|
) -> None:
|
|
"""
|
|
Log file operation (read, write, delete).
|
|
|
|
Args:
|
|
operation: Operation type (read/write/delete)
|
|
filepath: File path
|
|
success: Whether successful
|
|
error: Error message if failed
|
|
"""
|
|
self._log_entry(
|
|
level=LogLevel.INFO if success else LogLevel.ERROR,
|
|
event='file_operation',
|
|
phase=self.current_phase.value if self.current_phase else None,
|
|
error=error,
|
|
metadata={
|
|
'operation': operation,
|
|
'filepath': filepath,
|
|
'success': success,
|
|
},
|
|
)
|
|
|
|
def log_error_recovery(
|
|
self,
|
|
error: str,
|
|
recovery_strategy: str,
|
|
attempt: int,
|
|
backoff_duration: Optional[float] = None,
|
|
) -> None:
|
|
"""
|
|
Log error recovery attempt.
|
|
|
|
Args:
|
|
error: Error message
|
|
recovery_strategy: Recovery strategy applied
|
|
attempt: Attempt number
|
|
backoff_duration: Backoff duration if applicable
|
|
"""
|
|
self._log_entry(
|
|
level=LogLevel.WARNING,
|
|
event='error_recovery',
|
|
phase=self.current_phase.value if self.current_phase else None,
|
|
duration_ms=backoff_duration * 1000 if backoff_duration else None,
|
|
error=error,
|
|
metadata={
|
|
'recovery_strategy': recovery_strategy,
|
|
'attempt': attempt,
|
|
},
|
|
)
|
|
|
|
def log_dependency_conflict(
|
|
self,
|
|
package: str,
|
|
issue: str,
|
|
recommended_fix: str,
|
|
) -> None:
|
|
"""
|
|
Log dependency conflict detection.
|
|
|
|
Args:
|
|
package: Package name
|
|
issue: Issue description
|
|
recommended_fix: Recommended fix
|
|
"""
|
|
self._log_entry(
|
|
level=LogLevel.WARNING,
|
|
event='dependency_conflict',
|
|
phase=self.current_phase.value if self.current_phase else None,
|
|
message=f"Dependency conflict: {package}",
|
|
metadata={
|
|
'package': package,
|
|
'issue': issue,
|
|
'recommended_fix': recommended_fix,
|
|
},
|
|
)
|
|
|
|
def log_checkpoint(
|
|
self,
|
|
checkpoint_id: str,
|
|
step_index: int,
|
|
file_count: int,
|
|
state_size: int,
|
|
) -> None:
|
|
"""
|
|
Log checkpoint creation.
|
|
|
|
Args:
|
|
checkpoint_id: Checkpoint ID
|
|
step_index: Step index
|
|
file_count: Number of files in checkpoint
|
|
state_size: State size in bytes
|
|
"""
|
|
self._log_entry(
|
|
level=LogLevel.INFO,
|
|
event='checkpoint_created',
|
|
phase=self.current_phase.value if self.current_phase else None,
|
|
metadata={
|
|
'checkpoint_id': checkpoint_id,
|
|
'step_index': step_index,
|
|
'file_count': file_count,
|
|
'state_size': state_size,
|
|
},
|
|
)
|
|
|
|
def log_cost_tracking(
|
|
self,
|
|
operation: str,
|
|
tokens: int,
|
|
cost: float,
|
|
cached: bool = False,
|
|
) -> None:
|
|
"""
|
|
Log cost tracking information.
|
|
|
|
Args:
|
|
operation: Operation name
|
|
tokens: Token count
|
|
cost: Cost in dollars
|
|
cached: Whether result was cached
|
|
"""
|
|
self._log_entry(
|
|
level=LogLevel.INFO,
|
|
event='cost_tracking',
|
|
phase=self.current_phase.value if self.current_phase else None,
|
|
metadata={
|
|
'operation': operation,
|
|
'tokens': tokens,
|
|
'cost': f"${cost:.6f}",
|
|
'cached': cached,
|
|
},
|
|
)
|
|
|
|
def log_validation_result(
|
|
self,
|
|
validation_type: str,
|
|
passed: bool,
|
|
errors: Optional[List[str]] = None,
|
|
warnings: Optional[List[str]] = None,
|
|
) -> None:
|
|
"""
|
|
Log validation result.
|
|
|
|
Args:
|
|
validation_type: Type of validation
|
|
passed: Whether validation passed
|
|
errors: List of errors if any
|
|
warnings: List of warnings if any
|
|
"""
|
|
self._log_entry(
|
|
level=LogLevel.INFO if passed else LogLevel.ERROR,
|
|
event='validation_result',
|
|
phase=self.current_phase.value if self.current_phase else None,
|
|
metadata={
|
|
'validation_type': validation_type,
|
|
'passed': passed,
|
|
'error_count': len(errors) if errors else 0,
|
|
'warning_count': len(warnings) if warnings else 0,
|
|
'errors': errors,
|
|
'warnings': warnings,
|
|
},
|
|
)
|
|
|
|
def _log_entry(
|
|
self,
|
|
level: LogLevel,
|
|
event: str,
|
|
phase: Optional[str] = None,
|
|
duration_ms: Optional[float] = None,
|
|
message: Optional[str] = None,
|
|
error: Optional[str] = None,
|
|
metadata: Optional[Dict[str, Any]] = None,
|
|
) -> None:
|
|
"""Internal method to create and log entry."""
|
|
entry = LogEntry(
|
|
timestamp=datetime.now().isoformat(),
|
|
level=level.value,
|
|
event=event,
|
|
phase=phase,
|
|
duration_ms=duration_ms,
|
|
message=message,
|
|
metadata=metadata,
|
|
error=error,
|
|
)
|
|
|
|
self.entries.append(entry)
|
|
|
|
entry_dict = entry.to_dict()
|
|
json_line = json.dumps(entry_dict)
|
|
|
|
if self.stdout_output and level.value in ['ERROR', 'CRITICAL']:
|
|
print(json_line, file=sys.stderr)
|
|
|
|
self._write_to_file(json_line)
|
|
|
|
def _write_to_file(self, json_line: str) -> None:
|
|
"""Append JSON log entry to log file."""
|
|
try:
|
|
with open(self.log_file, 'a') as f:
|
|
f.write(json_line + '\n')
|
|
except Exception:
|
|
pass
|
|
|
|
def _get_phase_duration(self) -> Optional[float]:
|
|
"""Get duration of current phase in milliseconds."""
|
|
if not self.phase_start_time:
|
|
return None
|
|
|
|
duration = datetime.now() - self.phase_start_time
|
|
return duration.total_seconds() * 1000
|
|
|
|
def get_phase_summary(self) -> Dict[Phase, Dict[str, Any]]:
|
|
"""Get summary of all phases logged."""
|
|
phases = {}
|
|
|
|
for entry in self.entries:
|
|
if entry.phase:
|
|
if entry.phase not in phases:
|
|
phases[entry.phase] = {
|
|
'events': 0,
|
|
'errors': 0,
|
|
'total_duration_ms': 0,
|
|
}
|
|
|
|
phases[entry.phase]['events'] += 1
|
|
if entry.level == 'ERROR':
|
|
phases[entry.phase]['errors'] += 1
|
|
if entry.duration_ms:
|
|
phases[entry.phase]['total_duration_ms'] += entry.duration_ms
|
|
|
|
return phases
|
|
|
|
def get_error_summary(self) -> Dict[str, Any]:
|
|
"""Get summary of errors logged."""
|
|
errors = [e for e in self.entries if e.level in ['ERROR', 'CRITICAL']]
|
|
|
|
return {
|
|
'total_errors': len(errors),
|
|
'errors_by_event': self._count_by_field(errors, 'event'),
|
|
'recent_errors': [
|
|
{
|
|
'timestamp': e.timestamp,
|
|
'event': e.event,
|
|
'error': e.error,
|
|
'phase': e.phase,
|
|
}
|
|
for e in errors[-10:]
|
|
],
|
|
}
|
|
|
|
def export_logs(self, export_path: Path) -> bool:
|
|
"""Export all logs to file."""
|
|
try:
|
|
lines = [json.dumps(e.to_dict()) for e in self.entries]
|
|
export_path.write_text('\n'.join(lines))
|
|
return True
|
|
except Exception:
|
|
return False
|
|
|
|
def _count_by_field(self, entries: List[LogEntry], field: str) -> Dict[str, int]:
|
|
"""Count occurrences of a field value."""
|
|
counts = {}
|
|
for entry in entries:
|
|
value = getattr(entry, field, None)
|
|
if value:
|
|
counts[value] = counts.get(value, 0) + 1
|
|
return counts
|
|
|
|
def clear(self) -> None:
|
|
"""Clear in-memory log entries."""
|
|
self.entries = []
|