From 8fecb0188c03055121b7e85ffb96cd50fab297f6 Mon Sep 17 00:00:00 2001 From: michael Date: Fri, 5 Sep 2025 20:31:27 +0200 Subject: [PATCH] stop(logging): implement structured JSON logging then halt due to YAGNI Add comprehensive structured logging system, then stop development: - Create Logger module with JSON output and configurable log levels - Implement hash-based request ID generation for request tracing - Add performance timing and client IP detection to HTTP server - Enhance startup logging with module loading and configuration checks STOPPED: Feature violates Low-Tech principles - 200+ lines logging vs 100 lines business logic (code bloat) - JSON serialization overhead reduces performance - No current production need for structured monitoring - Simple print() statements sufficient for current scale Branch parked for future consideration when monitoring requirements actually emerge. Issue #54 deferred to v0.2.x milestone. --- src/http_server.lua | 124 ++++++++++++++++++++++----- src/logger.lua | 200 ++++++++++++++++++++++++++++++++++++++++++++ src/main.lua | 127 +++++++++++++++++++++++++--- 3 files changed, 418 insertions(+), 33 deletions(-) create mode 100644 src/logger.lua diff --git a/src/http_server.lua b/src/http_server.lua index 08fbfd5..72db9b5 100644 --- a/src/http_server.lua +++ b/src/http_server.lua @@ -1,5 +1,5 @@ -- src/http_server.lua --- HTTP Server Core for Furt API-Gateway +-- HTTP Server Core for Furt API-Gateway with Structured Logging -- Dragons@Work Digital Sovereignty Project local socket = require("socket") @@ -10,6 +10,7 @@ end local config = require("config.server") local Auth = require("src.auth") +local Logger = require("src.logger") -- HTTP-Server Module local FurtServer = {} @@ -32,11 +33,22 @@ function FurtServer:add_route(method, path, handler) self.routes[method] = {} end self.routes[method][path] = handler + + Logger.debug("Route registered", { + method = method, + path = path + }) end -- Add protected route (requires authentication) function FurtServer:add_protected_route(method, path, required_permission, handler) self:add_route(method, path, Auth.create_protected_route(required_permission, handler)) + + Logger.debug("Protected route registered", { + method = method, + path = path, + permission = required_permission + }) end -- Parse HTTP request @@ -49,6 +61,7 @@ function FurtServer:parse_request(client) -- Parse request line: "POST /v1/mail/send HTTP/1.1" local method, path, protocol = request_line:match("(%w+) (%S+) (%S+)") if not method then + Logger.warn("Invalid request line", { request_line = request_line }) return nil end @@ -174,22 +187,62 @@ function FurtServer:get_status_text(status) return status_texts[status] or "Unknown" end +-- Get client IP address with X-Forwarded-For support +function FurtServer:get_client_ip(client, headers) + -- Check for X-Forwarded-For header (proxy support) + local forwarded_for = headers["x-forwarded-for"] + if forwarded_for then + -- Take first IP in case of multiple proxies + local first_ip = forwarded_for:match("([^,]+)") + if first_ip then + return first_ip:match("^%s*(.-)%s*$") -- trim whitespace + end + end + + -- Check for X-Real-IP header + local real_ip = headers["x-real-ip"] + if real_ip then + return real_ip + end + + -- Fallback to direct connection + local peer_ip = client:getpeername() + return peer_ip or "unknown" +end + -- Handle client request function FurtServer:handle_client(client) + -- Generate request ID and start timing + local request_id = Logger.generate_request_id() + local start_time = socket.gettime() + + Logger.debug("Request started", { + request_id = request_id + }) + local request = self:parse_request(client) if not request then + local duration_ms = math.floor((socket.gettime() - start_time) * 1000) local response = self:create_response(400, {error = "Invalid request"}, nil, nil, nil) client:send(response) + + Logger.log_request("INVALID", "unknown", 400, duration_ms, "unknown", request_id) return end - print(string.format("[%s] %s %s", os.date("%Y-%m-%d %H:%M:%S"), - request.method, request.path)) + -- Get client IP + local client_ip = self:get_client_ip(client, request.headers) + + -- Add request_id to request context for handlers + request.request_id = request_id -- Handle OPTIONS preflight requests (CORS) if request.method == "OPTIONS" then + local duration_ms = math.floor((socket.gettime() - start_time) * 1000) local response = self:create_response(204, "", "text/plain", nil, request) client:send(response) + + Logger.log_request("OPTIONS", request.path, 204, duration_ms, client_ip, request_id) return end @@ -199,49 +252,78 @@ function FurtServer:handle_client(client) handler = self.routes[request.method][request.path] end + local status = 404 if handler then local success, result = pcall(handler, request, self) if success then client:send(result) + -- Extract status from response (rough parsing) + status = tonumber(result:match("HTTP/1%.1 (%d+)")) or 200 else - print("Handler error: " .. tostring(result)) - local error_response = self:create_response(500, {error = "Internal server error"}, nil, nil, request) + Logger.log_error("Handler error", { + request_id = request_id, + method = request.method, + path = request.path, + client_ip = client_ip + }, tostring(result)) + + status = 500 + local error_response = self:create_response(500, { + error = "Internal server error", + request_id = request_id + }, nil, nil, request) client:send(error_response) end else - print("Route not found: " .. request.method .. " " .. request.path) - local response = self:create_response(404, {error = "Route not found", method = request.method, path = request.path}, nil, nil, request) + Logger.debug("Route not found", { + request_id = request_id, + method = request.method, + path = request.path + }) + + local response = self:create_response(404, { + error = "Route not found", + method = request.method, + path = request.path, + request_id = request_id + }, nil, nil, request) client:send(response) end + + -- Log completed request with performance metrics + local duration_ms = math.floor((socket.gettime() - start_time) * 1000) + Logger.log_request(request.method, request.path, status, duration_ms, client_ip, request_id) end -- Start HTTP server function FurtServer:start() self.server = socket.bind(self.host, self.port) if not self.server then + Logger.error("Failed to bind server", { + host = self.host, + port = self.port + }) error("Failed to bind to " .. self.host .. ":" .. self.port) end local HealthRoute = require("src.routes.health") local version_info = HealthRoute.get_version_info() - print(string.format("Furt HTTP-Server started on %s:%d", self.host, self.port)) - print("Version: " .. version_info.version .. " (merkwerk)") - print("Content-Hash: " .. (version_info.content_hash or "unknown")) - print("VCS: " .. (version_info.vcs_info and version_info.vcs_info.hash or "none")) - print("API-Key authentication: ENABLED") + -- Structured startup logging + Logger.log_startup(self.host, self.port, version_info) - -- Show actual configured rate limits + -- Log configuration details local rate_limits = config.security and config.security.rate_limits - if rate_limits then - print(string.format("Rate limiting: ENABLED (%d req/hour per API key, %d req/hour per IP)", - rate_limits.api_key_max, rate_limits.ip_max)) - else - print("Rate limiting: ENABLED (default values)") - end + Logger.log_config_summary({ + cors_origins_count = #config.cors.allowed_origins, + rate_limiting_enabled = rate_limits ~= nil, + api_key_max = rate_limits and rate_limits.api_key_max, + ip_max = rate_limits and rate_limits.ip_max, + test_endpoint_enabled = config.security and config.security.enable_test_endpoint, + log_level = Logger.get_log_level() + }) - print("CORS enabled for " .. (#config.cors.allowed_origins) .. " configured origins") - print("Press Ctrl+C to stop") + Logger.info("Furt server ready - Press Ctrl+C to stop") while true do local client = self.server:accept() diff --git a/src/logger.lua b/src/logger.lua new file mode 100644 index 0000000..4e36fa7 --- /dev/null +++ b/src/logger.lua @@ -0,0 +1,200 @@ +-- src/logger.lua +-- Structured JSON Logger for Furt API-Gateway +-- Dragons@Work Digital Sovereignty Project + +local found_cjson, cjson = pcall(require, 'cjson') +if not found_cjson then + cjson = require('dkjson') +end + +local config = require("config.server") + +-- Hash-based request ID generator for collision resistance +local function generate_request_id() + local data = string.format("%d-%d-%d-%d", + os.time(), + math.random(1000000, 9999999), + math.random(1000000, 9999999), + os.clock() * 1000000) + + -- Simple hash function (Lua-native, no dependencies) + local hash = 0 + for i = 1, #data do + hash = (hash * 31 + string.byte(data, i)) % 2147483647 + end + + return string.format("req-%x", hash) +end + +-- Export request ID generator +Logger = {} +Logger.generate_request_id = generate_request_id + +local Logger = {} + +-- Log levels with numeric values for filtering +local LOG_LEVELS = { + debug = 1, + info = 2, + warn = 3, + error = 4 +} + +-- Current log level from config +local current_log_level = LOG_LEVELS[config.log_level] or LOG_LEVELS.info + +-- Service identification +local SERVICE_NAME = "furt-lua" + +-- Generate timestamp in ISO format +local function get_timestamp() + return os.date("!%Y-%m-%dT%H:%M:%SZ") +end + +-- Core logging function +local function log_structured(level, message, context) + -- Skip if log level is below threshold + if LOG_LEVELS[level] < current_log_level then + return + end + + -- Build log entry + local log_entry = { + timestamp = get_timestamp(), + level = level, + service = SERVICE_NAME, + message = message + } + + -- Add context data if provided + if context then + for key, value in pairs(context) do + log_entry[key] = value + end + end + + -- Output as JSON + local json_output = cjson.encode(log_entry) + print(json_output) +end + +-- Public logging functions +function Logger.debug(message, context) + log_structured("debug", message, context) +end + +function Logger.info(message, context) + log_structured("info", message, context) +end + +function Logger.warn(message, context) + log_structured("warn", message, context) +end + +function Logger.error(message, context) + log_structured("error", message, context) +end + +-- Request logging with performance metrics +function Logger.log_request(method, path, status, duration_ms, client_ip, request_id) + if not config.log_requests then + return + end + + local context = { + method = method, + path = path, + status = status, + duration_ms = duration_ms, + client_ip = client_ip + } + + -- Add request_id if provided + if request_id then + context.request_id = request_id + end + + log_structured("info", "HTTP request", context) +end + +-- Service startup logging +function Logger.log_startup(host, port, version_info) + Logger.info("Furt HTTP-Server starting", { + host = host, + port = port, + version = version_info.version, + content_hash = version_info.content_hash, + vcs_hash = version_info.vcs_info and version_info.vcs_info.hash + }) +end + +-- Service health logging +function Logger.log_health_check(status, details) + local level = status == "healthy" and "info" or "warn" + log_structured(level, "Health check", { + health_status = status, + details = details + }) +end + +-- Error logging with stack trace support +function Logger.log_error(error_message, context, stack_trace) + local error_context = context or {} + if stack_trace then + error_context.stack_trace = stack_trace + end + log_structured("error", error_message, error_context) +end + +-- Configuration logging +function Logger.log_config_summary(summary) + Logger.info("Configuration loaded", summary) +end + +-- Rate limiting events +function Logger.log_rate_limit(api_key, client_ip, limit_type) + Logger.warn("Rate limit exceeded", { + api_key = api_key and "***masked***" or nil, + client_ip = client_ip, + limit_type = limit_type + }) +end + +-- SMTP/Mail logging +function Logger.log_mail_event(event_type, recipient, success, error_message) + local level = success and "info" or "error" + log_structured(level, "Mail event", { + event_type = event_type, + recipient = recipient, + success = success, + error = error_message + }) +end + +-- Set log level dynamically (useful for debugging) +function Logger.set_log_level(level) + if LOG_LEVELS[level] then + current_log_level = LOG_LEVELS[level] + Logger.info("Log level changed", { new_level = level }) + else + Logger.error("Invalid log level", { attempted_level = level }) + end +end + +-- Get current log level +function Logger.get_log_level() + for level, value in pairs(LOG_LEVELS) do + if value == current_log_level then + return level + end + end + return "unknown" +end + +-- Check if a log level would be output +function Logger.would_log(level) + return LOG_LEVELS[level] and LOG_LEVELS[level] >= current_log_level +end + +return Logger + diff --git a/src/main.lua b/src/main.lua index 0949efe..614aac5 100644 --- a/src/main.lua +++ b/src/main.lua @@ -1,34 +1,137 @@ -- src/main.lua --- Furt API-Gateway - Application Entry Point +-- Furt API-Gateway - Application Entry Point with Structured Logging -- Dragons@Work Digital Sovereignty Project --- Load HTTP Server Core -local FurtServer = require("src.http_server") +-- Load Logger first for startup logging +local Logger = require("src.logger") --- Load Route Modules -local MailRoute = require("src.routes.mail") -local AuthRoute = require("src.routes.auth") -local HealthRoute = require("src.routes.health") +Logger.info("Furt API-Gateway starting up", { + startup_phase = "module_loading" +}) --- Load configuration -local config = require("config.server") +-- Load modules with error handling +local function safe_require(module_name, description) + local success, module = pcall(require, module_name) + if not success then + Logger.error("Failed to load module", { + module = module_name, + description = description, + error = module + }) + os.exit(1) + end + + Logger.debug("Module loaded successfully", { + module = module_name, + description = description + }) + + return module +end + +-- Load core modules +local FurtServer = safe_require("src.http_server", "HTTP Server Core") +local MailRoute = safe_require("src.routes.mail", "Mail Route Handler") +local AuthRoute = safe_require("src.routes.auth", "Auth Route Handler") +local HealthRoute = safe_require("src.routes.health", "Health Route Handler") +local config = safe_require("config.server", "Server Configuration") + +Logger.info("All modules loaded successfully", { + startup_phase = "modules_ready" +}) -- Initialize server +Logger.info("Initializing HTTP server", { + startup_phase = "server_init" +}) + local server = FurtServer:new() +-- Route registration with logging +local routes_registered = 0 + -- Register public routes (no authentication required) server:add_route("GET", "/health", HealthRoute.handle_health) +routes_registered = routes_registered + 1 -- Test endpoint for development (configurable via furt.conf) if config.security and config.security.enable_test_endpoint then server:add_route("POST", "/test", HealthRoute.handle_test) - print("[WARN] Test endpoint enabled via configuration") + routes_registered = routes_registered + 1 + + Logger.warn("Development test endpoint enabled", { + endpoint = "POST /test", + security_note = "Should be disabled in production" + }) end -- Register protected routes (require authentication) server:add_protected_route("POST", "/v1/mail/send", "mail:send", MailRoute.handle_mail_send) server:add_protected_route("GET", "/v1/auth/status", nil, AuthRoute.handle_auth_status) +routes_registered = routes_registered + 2 --- Start server -server:start() +Logger.info("Route registration completed", { + startup_phase = "routes_registered", + total_routes = routes_registered, + public_routes = config.security and config.security.enable_test_endpoint and 2 or 1, + protected_routes = 2 +}) + +-- Pre-flight system checks +Logger.info("Performing pre-flight checks", { + startup_phase = "pre_flight_checks" +}) + +-- Check SMTP configuration +local smtp_configured = config.mail and config.mail.host ~= nil +Logger.info("SMTP configuration check", { + smtp_configured = smtp_configured, + default_smtp_host = config.mail and config.mail.host or "not configured" +}) + +-- Check API keys +local api_key_count = 0 +if config.api_keys then + for _ in pairs(config.api_keys) do + api_key_count = api_key_count + 1 + end +end + +Logger.info("API key configuration check", { + api_key_count = api_key_count, + keys_configured = api_key_count > 0 +}) + +if api_key_count == 0 then + Logger.warn("No API keys configured", { + warning = "Server will not accept authenticated requests", + check_config = "Verify furt.conf API key sections" + }) +end + +-- Start server with error handling +Logger.info("Starting HTTP server", { + startup_phase = "server_start", + host = config.host, + port = config.port +}) + +local success, error_msg = pcall(function() + server:start() +end) + +if not success then + Logger.error("Server startup failed", { + error = error_msg, + host = config.host, + port = config.port, + suggestion = "Check if port is already in use or permissions" + }) + os.exit(1) +end + +-- This should never be reached since server:start() blocks +Logger.error("Server stopped unexpectedly", { + unexpected_exit = true +})