add-runtime-logging (#35)

Set up logging framework and add runtime logging to foundational operations (database, sessions, auth).

Reviewed-on: https://gitea.subcultureofone.org/greg/tkr/pulls/35
Co-authored-by: Greg Sarjeant <greg@subcultureofone.org>
Co-committed-by: Greg Sarjeant <greg@subcultureofone.org>

.gitignore

@@ -9,6 +9,7 @@ phpunit
 *.sqlite
 *.txt
 storage/upload/css
+storage/logs
 
 # Testing stuff
 /docker-compose.yml

README.md

@@ -143,6 +143,19 @@ tkr stores profile information, custom emojis, and uploaded css metadata in a SQ
 
 You don't have to do any database setup. The database is automatically created and initialized on first run.
 
+## FAQ
+
+### Why don't I see the right IPs in the logs?
+
+This can happen for a few reasons. Some common ones are:
+
+**Docker Development:** If running via Docker, you may see `192.168.65.1` (Docker Desktop gateway). This is normal for development.
+
+**Behind a Proxy/CDN:** If you're behind Cloudflare (with proxy enabled), load balancers, or other proxies, all requests may appear to come from the proxy's IP addresses.
+
+- **For accurate IP logging:** Configure your web server to trust proxy headers. See your proxy provider's documentation for the required nginx/Apache configuration.
+
+
 ## Acknowledgements
 
 It's been a lot of fun to get back to building something. I'm grateful to the people and projects that inspired me to do it:

config/migrations/006_add_log_level_setting.sql

@@ -0,0 +1,2 @@
+ALTER TABLE settings
+ADD COLUMN log_level INTEGER NULL;

public/index.php

@@ -67,6 +67,7 @@ if (strpos($path, $config->basePath) === 0) {
 
 // strip the trailing slash from the resulting route
 $path = trim($path, '/');
+Log::debug("Path requested: {$path}");
 
 // if this is a POST and we aren't in setup,
 // make sure there's a valid session
@@ -75,12 +76,14 @@ if ($method === 'POST' && $path != 'setup') {
     if ($path != 'login'){
         if (!Session::isValid($_POST['csrf_token'])) {
             // Invalid session - redirect to /login
+            Log::info('Attempt to POST with invalid session. Redirecting to login.');
             header('Location: ' . $config->basePath . '/login');
             exit;
         }
     } else {
         if (!Session::isValidCsrfToken($_POST['csrf_token'])) {
             // Just die if the token is invalid on login
+            Log::error("Attempt to log in with invalid CSRF token.");
             die('Invalid CSRF token');
             exit;
         }
@@ -92,6 +95,7 @@ header('Content-Type: text/html; charset=utf-8');
 
 // Render the requested route or throw a 404
 if (!Router::route($path, $method)){
+    Log::error("No route found for path {$path}");
     http_response_code(404);
     echo "404 - Page Not Found";
     exit;

src/Controller/AdminController/AdminController.php

@@ -64,7 +64,7 @@ class AdminController extends Controller {
             $basePath            = trim($_POST['base_path'] ?? '/');
             $itemsPerPage        = (int) ($_POST['items_per_page'] ?? 25);
             $strictAccessibility = isset($_POST['strict_accessibility']);
-            $showTickMood        = isset($_POST['show_tick_mood']);
+            $logLevel            = (int) ($_POST['log_level'] ?? '');
 
             // Password
             $password        = $_POST['password'] ?? '';
@@ -114,6 +114,7 @@ class AdminController extends Controller {
                 $config->basePath = $basePath;
                 $config->itemsPerPage = $itemsPerPage;
                 $config->strictAccessibility = $strictAccessibility;
+                $config->logLevel = $logLevel;
 
                 // Save site settings and reload config from database
                 // TODO - raise and handle exception on failure
@@ -131,7 +132,7 @@ class AdminController extends Controller {
                 // Update the password if one was sent
                 // TODO - raise and handle exception on failure
                 if($password){
-                    $user->set_password($password);
+                    $user->setPassword($password);
                 }
 
                 Session::setFlashMessage('success', 'Settings updated');

src/Controller/AuthController/AuthController.php

@@ -20,21 +20,21 @@ class AuthController extends Controller {
             $username = $_POST['username'] ?? '';
             $password = $_POST['password'] ?? '';
 
-            // TODO: move into user model
+            Log::debug("Login attempt for user {$username}");
-            global $db;
-            $stmt = $db->prepare("SELECT id, username, password_hash FROM user WHERE username = ?");
-            $stmt->execute([$username]);
-            $user = $stmt->fetch();
 
+            $userModel = new UserModel();
+            $user = $userModel->getByUsername($username);
+
+            //if ($user && password_verify($password, $user['password_hash'])) {
             if ($user && password_verify($password, $user['password_hash'])) {
-                session_regenerate_id(true);
+                Log::info("Successful login for {$username}");
-                // TODO: move into session.php
+
-                $_SESSION['user_id'] = $user['id'];
+                Session::newLoginSession($user);
-                $_SESSION['username'] = $user['username'];
-                Session::generateCsrfToken(true);
                 header('Location: ' . $config->basePath);
                 exit;
             } else {
+                Log::warning("Failed login for {$username}");
+
                 // Set a flash message and reload the login page
                 Session::setFlashMessage('error', 'Invalid username or password');
                 header('Location: ' . $_SERVER['PHP_SELF']);
@@ -44,7 +44,9 @@ class AuthController extends Controller {
     }
 
     function handleLogout(){
+        Log::info("Logout from user " . $_SESSION['username']);
         Session::end();
+
         global $config;
         header('Location: ' . $config->basePath);
         exit;

src/Framework/Database/Database.php

@@ -60,6 +60,7 @@ class Database{
         foreach ($files as $file) {
             $version = $this->migrationNumberFromFile($file);
             if ($version > $currentVersion) {
+                Log::debug("Found pending migration ({$version}): " . basename($file));
                 $pending[$version] = $file;
             }
         }
@@ -72,9 +73,11 @@ class Database{
         $migrations = $this->getPendingMigrations();
 
         if (empty($migrations)) {
-            # TODO: log
+            Log::debug("No pending migrations");
             return;
         }
+        Log::info("Found " . count($migrations) . "pending migrations.");
+        Log::info("Updating database. Current Version: " . $this->getVersion());
 
         $db = self::get();
         $db->beginTransaction();
@@ -82,7 +85,7 @@ class Database{
         try {
             foreach ($migrations as $version => $file) {
                 $filename = basename($file);
-                // TODO: log properly
+                Log::debug("Starting migration: {$filename}");
 
                 $sql = file_get_contents($file);
                 if ($sql === false) {
@@ -96,17 +99,20 @@ class Database{
                 // Execute each statement
                 foreach ($statements as $statement){
                     if (!empty($statement)){
+                        Log::debug("Migration statement: {$statement}");
                         $db->exec($statement);
                     }
                 }
+
+                Log::info("Applied migration {$filename}");
             }
 
             // Update db version
             $db->commit();
             $this->setVersion($version);
-            //TODO: log properly
-            //echo "All migrations completed successfully.\n";
 
+            Log::info("Applied " . count($migrations) . " migrations.");
+            Log::info("Updated database version to " . $this->getVersion());
         } catch (Exception $e) {
             $db->rollBack();
             throw new SetupException(

src/Framework/Exception/SetupException.php

@@ -12,6 +12,14 @@ class SetupException extends Exception {
     // Exceptions don't generally define their own handlers,
     // but this is a very specific case.
     public function handle(){
+        // try to log the error, but keep going if it fails
+        try {
+            Log::error($this->setupIssue . ", " . $this->getMessage());
+        } catch (Exception $e) {
+            // Do nothing and move on to the normal error handling
+            // We don't want to short-circuit this if there's a problem logging
+        }
+
         switch ($this->setupIssue){
             case 'database_connection':
             case 'db_migration':

src/Framework/Log/Log.php

@@ -0,0 +1,89 @@
+<?php
+class Log {
+    const LEVELS = [
+        'DEBUG' => 1,
+        'INFO' => 2,
+        'WARNING' => 3,
+        'ERROR' => 4
+    ];
+
+    private static $logFile;
+    private static $maxLines = 1000;
+    private static $maxFiles = 5;
+
+    public static function init() {
+        self::$logFile = STORAGE_DIR . '/logs/tkr.log';
+
+        // Ensure log directory exists
+        // (should be handled by Prerequisites, but doesn't hurt)
+        $logDir = dirname(self::$logFile);
+        if (!is_dir($logDir)) {
+            mkdir($logDir, 0770, true);
+        }
+    }
+
+    public static function debug($message) {
+        self::write('DEBUG', $message);
+    }
+
+    public static function info($message) {
+        self::write('INFO', $message);
+    }
+
+    public static function error($message) {
+        self::write('ERROR', $message);
+    }
+
+    public static function warning($message) {
+        self::write('WARNING', $message);
+    }
+
+    private static function write($level, $message) {
+        global $config;
+        $logLevel = $config->logLevel ?? self::LEVELS['INFO'];
+
+        // Only log messages if they're at or above the configured log level.
+        if (self::LEVELS[$level] < $logLevel){
+            return;
+        }
+
+        if (!self::$logFile) {
+            self::init();
+        }
+
+        $timestamp = date('Y-m-d H:i:s');
+        $logEntry = "[{$timestamp}] {$level}: " . Util::getClientIp() . " - {$message}\n";
+
+        // Rotate if we're at the max file size (1000 lines)
+        if (file_exists(self::$logFile)) {
+            $lineCount = count(file(self::$logFile));
+            if ($lineCount >= self::$maxLines) {
+                self::rotate();
+                Log::info("Log rotated at {$timestamp}");
+            }
+        }
+
+        file_put_contents(self::$logFile, $logEntry, FILE_APPEND | LOCK_EX);
+    }
+
+    private static function rotate() {
+        // Rotate existing history files: tkr.4.log -> tkr.5.log, etc.
+        for ($i = self::$maxFiles - 1; $i >= 1; $i--) {
+            $oldFile = self::$logFile . '.' . $i;
+            $newFile = self::$logFile . '.' . ($i + 1);
+
+            if (file_exists($oldFile)) {
+                if ($i == self::$maxFiles - 1) {
+                    unlink($oldFile); // Delete oldest log if we already have 5 files of history
+                } else {
+                    rename($oldFile, $newFile); // Bump the file number up by one
+                }
+            }
+        }
+
+        // Move current active log to .1
+        if (file_exists(self::$logFile)) {
+            rename(self::$logFile, self::$logFile . '.1');
+        }
+    }
+}

src/Framework/Prerequisites/Prerequisites.php

@@ -37,7 +37,6 @@ class Prerequisites {
      */
     private function log($message, $overwrite=false) {
         $logDir = dirname($this->logFile);
-        //print("Log dir: {$logDir}");
         if (!is_dir($logDir)) {
             if (!@mkdir($logDir, 0770, true)) {
                 // Can't create storage dir - just output, don't log to file
@@ -48,6 +47,10 @@ class Prerequisites {
             }
         }
 
+        // Overwrite the log if $overwrite is set
+        // I overwrite the log for each new validation run,
+        // because prior results are irrelevant.
+        // This keeps it from growing without bound.
         $flags = LOCK_EX;
         if (!$overwrite) {
             $flags |= FILE_APPEND;
@@ -66,6 +69,7 @@ class Prerequisites {
         }
     }
 
+    // Record the result of a validation check.
     private function addCheck($name, $status, $message, $severity = 'info') {
         $this->checks[] = array(
             'name' => $name,
@@ -85,6 +89,7 @@ class Prerequisites {
     }
 
     private function checkPhpVersion() {
+        // TODO - move to bootstrap.php?
         $minVersion = '8.2.0';
         $currentVersion = PHP_VERSION;
         $versionOk = version_compare($currentVersion, $minVersion, '>=');
@@ -192,6 +197,7 @@ class Prerequisites {
         $storageDirs = array(
             'storage',
             'storage/db',
+            'storage/logs',
             'storage/upload',
             'storage/upload/css'
         );

src/Framework/Router/Router.php

@@ -33,6 +33,8 @@ class Router {
             $controller = $routeHandler[1];
             $methods = $routeHandler[2] ?? ['GET'];
 
+            Log::debug("Route: '{$routePattern}', Controller {$controller}, Methods: ". implode(',' , $methods));
+
             # Only allow valid route and filename characters
             # to prevent directory traversal and other attacks
             $routePattern = preg_replace('/\{([^}]+)\}/', '([a-zA-Z0-9._-]+)', $routePattern);
@@ -43,18 +45,21 @@ class Router {
                     // Save any path elements we're interested in
                     // (but discard the match on the entire path)
                     array_shift($matches);
+                    Log::debug("Captured path elements: " . implode(',', $matches));
 
                     if (strpos($controller, '@')) {
                         // Get the controller and method that handle this route
-                        [$controllerName, $methodName] = explode('@', $controller);
+                        [$controllerName, $functionName] = explode('@', $controller);
                     } else {
                         // Default to 'index' if no method specified
                         $controllerName = $controller;
-                        $methodName = 'index';
+                        $functionName = 'index';
                     }
 
+                    Log::debug("Handling request with Controller {$controllerName} and function {$functionName}");
+
                     $instance = new $controllerName();
-                    call_user_func_array([$instance, $methodName], $matches);
+                    call_user_func_array([$instance, $functionName], $matches);
                     return true;
                 }
             }

src/Framework/Session/Session.php

@@ -6,8 +6,28 @@ class Session {
     // global $_SESSION associative array
     public static function start(): void{
         if (session_status() === PHP_SESSION_NONE) {
+            $existingSessionId = $_COOKIE['PHPSESSID'] ?? null;
             session_start();
+
+            if ($existingSessionId && session_id() === $existingSessionId) {
+                Log::debug("Resumed existing login session: " . session_id());
+            } else {
+                Log::debug("Created new login session: " . session_id());
             }
+        } else {
+            Log::debug('Session already active in this request: ' . session_id());
+        }
+    }
+
+    public static function newLoginSession(Array $user){
+        Log::debug("Starting new login session for {$user['username']}");
+
+        session_regenerate_id(true);
+        $_SESSION['user_id'] = $user['id'];
+        $_SESSION['username'] = $user['username'];
+        self::generateCsrfToken(true);
+
+        Log::debug("Started new login session for {$user['username']}");
     }
 
     public static function generateCsrfToken(bool $regenerate = false): void{
@@ -59,6 +79,7 @@ class Session {
     }
 
     public static function end(): void {
+        Log::debug("Ending session: " . session_id());
         $_SESSION = [];
         session_destroy();
     }

src/Framework/Util/Util.php

@@ -1,5 +1,13 @@
 <?php
 class Util {
+    public static function getClientIp() {
+        return $_SERVER['HTTP_CLIENT_IP'] ??
+               $_SERVER['HTTP_X_FORWARDED_FOR'] ??
+               $_SERVER['HTTP_X_REAL_IP'] ??
+               $_SERVER['REMOTE_ADDR'] ??
+               'unknown';
+    }
+
     public static function escape_html(string $text): string {
         return htmlspecialchars($text, ENT_QUOTES, 'UTF-8');
     }

src/Model/ConfigModel/ConfigModel.php

@@ -9,6 +9,7 @@ class ConfigModel {
     public string $timezone = 'relative';
     public ?int $cssId = null;
     public bool $strictAccessibility = true;
+    public ?int $logLevel = null;
 
     // load config from sqlite database
     public static function load(): self {
@@ -24,7 +25,8 @@ class ConfigModel {
                                    base_path,
                                    items_per_page,
                                    css_id,
-                                   strict_accessibility
+                                   strict_accessibility,
+                                   log_level
                             FROM settings WHERE id=1");
 
         $row = $stmt->fetch(PDO::FETCH_ASSOC);
@@ -37,6 +39,7 @@ class ConfigModel {
             $c->itemsPerPage = (int) $row['items_per_page'];
             $c->cssId = (int) $row['css_id'];
             $c->strictAccessibility = (bool) $row['strict_accessibility'];
+            $c->logLevel = $row['log_level'];
         }
 
         return $c;
@@ -67,9 +70,10 @@ class ConfigModel {
                 base_path,
                 items_per_page,
                 css_id,
-                strict_accessibility
+                strict_accessibility,
+                log_level
                 )
-                VALUES (1, ?, ?, ?, ?, ?, ?, ?)");
+                VALUES (1, ?, ?, ?, ?, ?, ?, ?, ?)");
         } else {
             $stmt = $db->prepare("UPDATE settings SET
                 site_title=?,
@@ -78,9 +82,11 @@ class ConfigModel {
                 base_path=?,
                 items_per_page=?,
                 css_id=?,
-                strict_accessibility=?
+                strict_accessibility=?,
+                log_level=?
                 WHERE id=1");
         }
+
         $stmt->execute([$this->siteTitle,
                         $this->siteDescription,
                         $this->baseUrl,
@@ -88,6 +94,7 @@ class ConfigModel {
                         $this->itemsPerPage,
                         $this->cssId,
                         $this->strictAccessibility,
+                        $this->logLevel
                     ]);
 
         return self::load();

src/Model/UserModel/UserModel.php

@@ -42,11 +42,20 @@ class UserModel {
 
    // Making this a separate function to avoid
    // loading the password into memory
-   public function set_password(string $password): void {
+   public function setPassword(string $password): void {
         global $db;
 
         $hash = password_hash($password, PASSWORD_DEFAULT);
         $stmt = $db->prepare("UPDATE user SET password_hash=? WHERE id=1");
         $stmt->execute([$hash]);
    }
+
+   public function getByUsername($username){
+        global $db;
+        $stmt = $db->prepare("SELECT id, username, password_hash FROM user WHERE username = ?");
+        $stmt->execute([$username]);
+        $record = $stmt->fetch();
+
+        return $record;
+   }
 }

templates/partials/admin.php

@@ -67,6 +67,13 @@
                                name="strict_accessibility"
                                value="1"
                                <?php if ($config->strictAccessibility): ?> checked <?php endif; ?>>
+                        <label for="strict_accessibility">Log Level</label>
+                        <select id="log_level" name="log_level">
+                            <option value="1" <?= ($config->logLevel ?? 2) == 1 ? 'selected' : '' ?>>DEBUG</option>
+                            <option value="2" <?= ($config->logLevel ?? 2) == 2 ? 'selected' : '' ?>>INFO</option>
+                            <option value="3" <?= ($config->logLevel ?? 2) == 3 ? 'selected' : '' ?>>WARNING</option>
+                            <option value="4" <?= ($config->logLevel ?? 2) == 4 ? 'selected' : '' ?>>ERROR</option>
+                        </select>
                     </div>
                 </fieldset>
                 <fieldset>