timmy-config/timmy-academy-audit-kt.md

[KT-001] Enable Full Audit Mode on Evennia Server

Status: Open
Priority: High
Assignee: @ezra
Labels: infrastructure, audit, evennia

---

Objective

Enable comprehensive audit logging on the Timmy Academy Evennia MUD server to track all player activity.

Background

The Evennia server currently only tracks basic login/logout events. We need full visibility into character movements, commands executed, and player sessions for accountability, debugging, and game history review.

---

Implementation Tasks

Task 1: Update Settings Configuration

File: server/conf/settings.py

Add the following configuration:

# FULL AUDIT MODE - Track everything
COMMAND_LOG_ENABLED = True
COMMAND_LOG_LEVEL = "DEBUG"
COMMAND_LOG_FILENAME = "command_audit.log"
AUDIT_LOG_ENABLED = True

# Custom logging configuration for full audit trail
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "timestamped": {
            "format": "%(asctime)s [%(levelname)s]: %(message)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
        "detailed": {
            "format": "%(asctime)s | %(name)s | %(levelname)s | %(message)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "timestamped",
            "level": "INFO",
        },
        "file_server": {
            "class": "logging.handlers.TimedRotatingFileHandler",
            "filename": "server/logs/server.log",
            "when": "midnight",
            "backupCount": 30,
            "formatter": "detailed",
            "level": "INFO",
        },
        "file_portal": {
            "class": "logging.handlers.TimedRotatingFileHandler",
            "filename": "server/logs/portal.log",
            "when": "midnight",
            "backupCount": 30,
            "formatter": "detailed",
            "level": "INFO",
        },
        "file_commands": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "server/logs/command_audit.log",
            "maxBytes": 10485760,  # 10MB
            "backupCount": 50,
            "formatter": "detailed",
            "level": "DEBUG",
        },
        "file_movement": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "server/logs/movement_audit.log",
            "maxBytes": 10485760,
            "backupCount": 50,
            "formatter": "detailed",
            "level": "DEBUG",
        },
        "file_player": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "server/logs/player_activity.log",
            "maxBytes": 10485760,
            "backupCount": 50,
            "formatter": "detailed",
            "level": "DEBUG",
        },
    },
    "loggers": {
        "evennia": {
            "handlers": ["console", "file_server"],
            "level": "INFO",
            "propagate": False,
        },
        "portal": {
            "handlers": ["console", "file_portal"],
            "level": "INFO",
            "propagate": False,
        },
        "evennia.commands": {
            "handlers": ["file_commands"],
            "level": "DEBUG",
            "propagate": False,
        },
        "evennia.objects": {
            "handlers": ["file_movement"],
            "level": "DEBUG",
            "propagate": False,
        },
        "evennia.accounts": {
            "handlers": ["file_player"],
            "level": "DEBUG",
            "propagate": False,
        },
    },
    "root": {
        "handlers": ["console"],
        "level": "WARNING",
    },
}

# Store additional character state for audit trail
CHARACTER_ATTRIBUTES_DEFAULT = {
    "last_location": None,
    "location_history": [],
    "command_count": 0,
    "playtime_seconds": 0,
    "last_command_time": None,
}

Task 2: Create AuditedCharacter Typeclass

File: typeclasses/audited_character.py

"""
AuditedCharacter - A character typeclass with full audit logging.
"""

import time
from datetime import datetime
from evennia import DefaultCharacter
from evennia.utils import logger


class AuditedCharacter(DefaultCharacter):
    """Character typeclass with comprehensive audit logging."""
    
    def at_object_creation(self):
        """Set up audit attributes when character is created."""
        super().at_object_creation()
        self.db.location_history = []
        self.db.command_count = 0
        self.db.total_playtime = 0
        self.db.session_start_time = None
        self.db.last_location = None
        logger.log_info(f"AUDIT: Character '{self.key}' created")
    
    def at_pre_move(self, destination, **kwargs):
        """Called before moving - log departure."""
        current = self.location
        if current:
            logger.log_info(f"AUDIT MOVE: {self.key} leaving {current.key}")
        return super().at_pre_move(destination, **kwargs)
    
    def at_post_move(self, source_location, **kwargs):
        """Called after moving - record arrival."""
        destination = self.location
        timestamp = datetime.utcnow().isoformat()
        history = self.db.location_history or []
        history.append({
            "from": source_location.key if source_location else "Nowhere",
            "to": destination.key if destination else "Nowhere",
            "timestamp": timestamp,
        })
        self.db.location_history = history[-1000:]  # Keep last 1000
        self.db.last_location = destination.key if destination else None
        logger.log_info(f"AUDIT MOVE: {self.key} arrived at {destination.key}")
        super().at_post_move(source_location, **kwargs)
    
    def at_pre_cmd(self, cmd, args):
        """Called before executing any command."""
        self.db.command_count = (self.db.command_count or 0) + 1
        self.db.last_command_time = datetime.utcnow().isoformat()
        cmd_name = cmd.key if cmd else "unknown"
        if cmd_name not in ("password", "@password"):
            logger.log_info(f"AUDIT CMD: {self.key} executed '{cmd_name}'")
        super().at_pre_cmd(cmd, args)
    
    def at_pre_puppet(self, account, session, **kwargs):
        """Called when account takes control of character."""
        self.db.session_start_time = time.time()
        logger.log_info(f"AUDIT SESSION: {self.key} puppeted by {account.key}")
        super().at_pre_puppet(account, session, **kwargs)
    
    def at_post_unpuppet(self, account, session, **kwargs):
        """Called when account releases control."""
        start_time = self.db.session_start_time
        if start_time:
            session_duration = time.time() - start_time
            self.db.total_playtime = (self.db.total_playtime or 0) + session_duration
            logger.log_info(f"AUDIT SESSION: {self.key} unpuppeted - session {session_duration:.0f}s")
        self.db.session_start_time = None
        super().at_post_unpuppet(account, session, **kwargs)
    
    def get_audit_summary(self):
        """Return a summary of this character's audit trail."""
        history = self.db.location_history or []
        return {
            "name": self.key,
            "location": self.location.key if self.location else "None",
            "commands_executed": self.db.command_count or 0,
            "total_playtime_hours": round((self.db.total_playtime or 0) / 3600, 2),
            "locations_visited": len(history),
            "last_location_change": history[-1] if history else None,
            "last_command": self.db.last_command_time,
        }

Task 3: Migrate Existing Characters

After implementing the above, run:

cd /root/workspace/timmy-academy
source ../evennia-venv/bin/activate
evennia reload

Then in Evennia shell:

from evennia.utils.search import search_object

# Migrate existing characters
for char in search_object("wizard"):
    char.swap_typeclass("typeclasses.audited_character.AuditedCharacter", run_start_hooks=False)
    print(f"Migrated: {char.key}")

---

Acceptance Criteria

Proof of Logs (REQUIRED)

Provide screenshots or terminal output showing:

• server/logs/command_audit.log exists and contains entries like:

  2025-04-02 18:30:15 | evennia.commands | INFO | AUDIT CMD: wizard executed 'look'
  

• server/logs/movement_audit.log exists and contains entries like:

  2025-04-02 18:31:22 | evennia.objects | INFO | AUDIT MOVE: wizard arrived at Library
  

• server/logs/player_activity.log exists and contains entries like:

  2025-04-02 18:30:10 | evennia.accounts | INFO | AUDIT SESSION: wizard puppeted by Alexander
  

Game History Link/Access (REQUIRED)

• Document the command to query audit data in-game:

  @py from evennia.utils.search import search_object; print(search_object("wizard")[0].get_audit_summary())
  

• Provide URL for viewing logs (if web access configured) OR

• Provide SSH/terminal command to tail logs:

  tail -f /root/workspace/timmy-academy/server/logs/command_audit.log
  

• Include sample get_audit_summary() output showing:

  • Character name
  • Current location
  • Commands executed count
  • Total playtime in hours
  • Locations visited count
  • Last activity timestamp

---

Verification Steps

1. Connect to game: telnet 167.99.126.228 4000
2. Login as: Alexander / WizardKing2025!
3. Execute commands: look, who, @users
4. Verify logs: Check that command_audit.log recorded these commands
5. Move between rooms: Walk to different locations
6. Verify movement: Check movement_audit.log for movement entries
7. Check audit summary: Run @py command from acceptance criteria

---

Definition of Done

• All three log files exist and are being written to
• Log entries include timestamps, player names, and action details
• In-game audit query command documented and tested
• At least one character migrated to AuditedCharacter class
• Sample audit summary output provided in ticket comments
• Link/command to view game history documented

---

Notes

• Reference implementation already exists on server at /root/workspace/timmy-academy/
• Contact @Allegro if implementation questions arise
• Server IP: 167.99.126.228
• Web client: http://167.99.126.228:4001/webclient

---

Created by: @Allegro
Date: 2025-04-02