villsim/backend/core/logger.py
2026-01-19 22:55:26 +03:00

313 lines
10 KiB
Python

"""Simulation logger for detailed step-by-step logging."""
import json
import logging
from dataclasses import dataclass, field, asdict
from datetime import datetime
from pathlib import Path
from typing import Optional, TextIO
@dataclass
class AgentLogEntry:
"""Log entry for a single agent's turn."""
agent_id: str
agent_name: str
profession: str
position: dict
stats_before: dict
stats_after: dict
decision: dict
action_result: dict
inventory_before: list
inventory_after: list
money_before: int
money_after: int
@dataclass
class TurnLogEntry:
"""Complete log entry for a simulation turn."""
turn: int
day: int
step_in_day: int
time_of_day: str
timestamp: str
agent_entries: list[AgentLogEntry] = field(default_factory=list)
market_orders_before: list = field(default_factory=list)
market_orders_after: list = field(default_factory=list)
trades: list = field(default_factory=list)
deaths: list = field(default_factory=list)
statistics: dict = field(default_factory=dict)
def to_dict(self) -> dict:
"""Convert to dictionary for JSON serialization."""
return {
"turn": self.turn,
"day": self.day,
"step_in_day": self.step_in_day,
"time_of_day": self.time_of_day,
"timestamp": self.timestamp,
"agent_entries": [asdict(e) for e in self.agent_entries],
"market_orders_before": self.market_orders_before,
"market_orders_after": self.market_orders_after,
"trades": self.trades,
"deaths": self.deaths,
"statistics": self.statistics,
}
class SimulationLogger:
"""Logger that dumps detailed simulation data to files."""
def __init__(self, log_dir: str = "logs"):
self.log_dir = Path(log_dir)
self.log_dir.mkdir(exist_ok=True)
# Create session-specific log file
timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
self.session_file = self.log_dir / f"sim_{timestamp}.jsonl"
self.summary_file = self.log_dir / f"sim_{timestamp}_summary.txt"
# File handles
self._json_file: Optional[TextIO] = None
self._summary_file: Optional[TextIO] = None
# Also set up standard Python logging
self.logger = logging.getLogger("simulation")
self.logger.setLevel(logging.DEBUG)
# File handler for detailed logs
file_handler = logging.FileHandler(self.log_dir / f"sim_{timestamp}.log")
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(logging.Formatter(
"%(asctime)s | %(levelname)s | %(message)s"
))
self.logger.addHandler(file_handler)
# Console handler for important events
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.INFO)
console_handler.setFormatter(logging.Formatter(
"%(asctime)s | %(message)s", datefmt="%H:%M:%S"
))
self.logger.addHandler(console_handler)
self._entries: list[TurnLogEntry] = []
self._current_entry: Optional[TurnLogEntry] = None
def start_session(self, config: dict) -> None:
"""Start a new logging session."""
self._json_file = open(self.session_file, "w")
self._summary_file = open(self.summary_file, "w")
# Write config as first line
self._json_file.write(json.dumps({"type": "config", "data": config}) + "\n")
self._json_file.flush()
self._summary_file.write(f"Simulation Session Started: {datetime.now()}\n")
self._summary_file.write("=" * 60 + "\n\n")
self._summary_file.flush()
self.logger.info(f"Logging session started: {self.session_file}")
def start_turn(self, turn: int, day: int, step_in_day: int, time_of_day: str) -> None:
"""Start logging a new turn."""
self._current_entry = TurnLogEntry(
turn=turn,
day=day,
step_in_day=step_in_day,
time_of_day=time_of_day,
timestamp=datetime.now().isoformat(),
)
self.logger.debug(f"Turn {turn} started (Day {day}, Step {step_in_day}, {time_of_day})")
def log_agent_before(
self,
agent_id: str,
agent_name: str,
profession: str,
position: dict,
stats: dict,
inventory: list,
money: int,
) -> None:
"""Log agent state before action."""
if self._current_entry is None:
return
# Create placeholder entry
entry = AgentLogEntry(
agent_id=agent_id,
agent_name=agent_name,
profession=profession,
position=position.copy(),
stats_before=stats.copy(),
stats_after={},
decision={},
action_result={},
inventory_before=inventory.copy(),
inventory_after=[],
money_before=money,
money_after=money,
)
self._current_entry.agent_entries.append(entry)
def log_agent_decision(self, agent_id: str, decision: dict) -> None:
"""Log agent's AI decision."""
if self._current_entry is None:
return
for entry in self._current_entry.agent_entries:
if entry.agent_id == agent_id:
entry.decision = decision.copy()
self.logger.debug(
f" {entry.agent_name}: decided to {decision.get('action', '?')} "
f"- {decision.get('reason', '')}"
)
break
def log_agent_after(
self,
agent_id: str,
stats: dict,
inventory: list,
money: int,
position: dict,
action_result: dict,
) -> None:
"""Log agent state after action."""
if self._current_entry is None:
return
for entry in self._current_entry.agent_entries:
if entry.agent_id == agent_id:
entry.stats_after = stats.copy()
entry.inventory_after = inventory.copy()
entry.money_after = money
entry.position = position.copy()
entry.action_result = action_result.copy()
break
def log_market_state(self, orders_before: list, orders_after: list) -> None:
"""Log market state."""
if self._current_entry is None:
return
self._current_entry.market_orders_before = orders_before
self._current_entry.market_orders_after = orders_after
def log_trade(self, trade: dict) -> None:
"""Log a trade transaction."""
if self._current_entry is None:
return
self._current_entry.trades.append(trade)
self.logger.debug(f" Trade: {trade.get('message', 'Unknown trade')}")
def log_death(self, agent_name: str, cause: str) -> None:
"""Log an agent death."""
if self._current_entry is None:
return
self._current_entry.deaths.append({"name": agent_name, "cause": cause})
self.logger.info(f" DEATH: {agent_name} died from {cause}")
def log_event(self, event_type: str, event_data: dict) -> None:
"""Log a general event (births, random events, etc.)."""
if self._current_entry is None:
return
if event_type == "birth":
self.logger.info(
f" BIRTH: {event_data.get('child_name', '?')} born to {event_data.get('parent_name', '?')}"
)
elif event_type == "random_event":
self.logger.info(
f" EVENT: {event_data.get('type', '?')} affecting {event_data.get('affected', [])}"
)
else:
self.logger.debug(f" Event [{event_type}]: {event_data}")
def log_statistics(self, stats: dict) -> None:
"""Log end-of-turn statistics."""
if self._current_entry is None:
return
self._current_entry.statistics = stats.copy()
def end_turn(self) -> None:
"""Finish logging the current turn and write to file."""
if self._current_entry is None:
return
self._entries.append(self._current_entry)
# Write to JSON lines file
if self._json_file:
self._json_file.write(
json.dumps({"type": "turn", "data": self._current_entry.to_dict()}) + "\n"
)
self._json_file.flush()
# Write summary
if self._summary_file:
entry = self._current_entry
self._summary_file.write(
f"Turn {entry.turn} | Day {entry.day} Step {entry.step_in_day} ({entry.time_of_day})\n"
)
for agent in entry.agent_entries:
action = agent.decision.get("action", "?")
result = "" if agent.action_result.get("success", False) else ""
self._summary_file.write(
f" [{agent.agent_name}] {action} {result} | "
f"E:{agent.stats_after.get('energy', '?')} "
f"H:{agent.stats_after.get('hunger', '?')} "
f"T:{agent.stats_after.get('thirst', '?')} "
f"${agent.money_after}\n"
)
if entry.deaths:
for death in entry.deaths:
self._summary_file.write(f" 💀 {death['name']} died: {death['cause']}\n")
self._summary_file.write("\n")
self._summary_file.flush()
self.logger.debug(f"Turn {self._current_entry.turn} completed")
self._current_entry = None
def close(self) -> None:
"""Close log files."""
if self._json_file:
self._json_file.close()
self._json_file = None
if self._summary_file:
self._summary_file.write(f"\nSession ended: {datetime.now()}\n")
self._summary_file.close()
self._summary_file = None
self.logger.info("Logging session closed")
def get_entries(self) -> list[TurnLogEntry]:
"""Get all logged entries."""
return self._entries.copy()
# Global logger instance
_logger: Optional[SimulationLogger] = None
def get_simulation_logger() -> SimulationLogger:
"""Get the global simulation logger."""
global _logger
if _logger is None:
_logger = SimulationLogger()
return _logger
def reset_simulation_logger() -> SimulationLogger:
"""Reset and create a new simulation logger."""
global _logger
if _logger:
_logger.close()
_logger = SimulationLogger()
return _logger