Эх сурвалжийг харах

refactor: implement enhanced logging system with HTTP access logging

- Add LoggerType enum to separate HTTP and INTERNAL logs
- Implement configurable log levels for different logger types
- Replace std::cout/std::cerr with structured logging in server.cpp and generation_queue.cpp
- Add HTTP access logging framework with logHttpAccess helper method
- Add HTTP-specific logging macros (HTTP_INFO, HTTP_ERROR, etc.)
- Update log format to include logger type for better organization
- Maintain systemd compatibility with structured output

This refactoring provides better control over logging output and separates
HTTP access logs from internal operation logs while eliminating uncontrolled
terminal output.
Fszontagh 3 сар өмнө
parent
commit
40ad7b3ea8
5 өөрчлөгдсөн 144 нэмэгдсэн , 50 устгасан
  1. 37 10
      include/logger.h
  2. 5 0
      include/server.h
  3. 11 10
      src/generation_queue.cpp
  4. 33 7
      src/logger.cpp
  5. 58 23
      src/server.cpp

+ 37 - 10
include/logger.h

@@ -19,6 +19,14 @@ enum class LogLevel {
     ERROR
 };
 
+/**
+ * @brief Logger type enumeration
+ */
+enum class LoggerType {
+    HTTP,       // HTTP access logs
+    INTERNAL   // Internal operation logs
+};
+
 /**
  * @brief Simple logger with file and console output support
  *
@@ -47,28 +55,39 @@ public:
      *
      * @param level Log level
      * @param message Message to log
+     * @param type Logger type (HTTP or INTERNAL)
      */
-    void log(LogLevel level, const std::string& message);
+    void log(LogLevel level, const std::string& message, LoggerType type = LoggerType::INTERNAL);
 
     /**
      * @brief Log debug message
      */
-    void debug(const std::string& message) { log(LogLevel::DEBUG, message); }
+    void debug(const std::string& message, LoggerType type = LoggerType::INTERNAL) { log(LogLevel::DEBUG, message, type); }
 
     /**
      * @brief Log info message
      */
-    void info(const std::string& message) { log(LogLevel::INFO, message); }
+    void info(const std::string& message, LoggerType type = LoggerType::INTERNAL) { log(LogLevel::INFO, message, type); }
 
     /**
      * @brief Log warning message
      */
-    void warning(const std::string& message) { log(LogLevel::WARNING, message); }
+    void warning(const std::string& message, LoggerType type = LoggerType::INTERNAL) { log(LogLevel::WARNING, message, type); }
 
     /**
      * @brief Log error message
      */
-    void error(const std::string& message) { log(LogLevel::ERROR, message); }
+    void error(const std::string& message, LoggerType type = LoggerType::INTERNAL) { log(LogLevel::ERROR, message, type); }
+
+    /**
+     * @brief Set minimum log level for specific logger type
+     */
+    void setLogLevel(LoggerType type, LogLevel level);
+
+    /**
+     * @brief Get minimum log level for specific logger type
+     */
+    LogLevel getLogLevel(LoggerType type) const;
 
     /**
      * @brief Check if file logging is enabled
@@ -96,18 +115,26 @@ private:
     std::string getCurrentTimestamp();
     std::string levelToString(LogLevel level);
     std::string levelToSystemdPriority(LogLevel level);
+    std::string typeToString(LoggerType type);
 
     bool m_fileLoggingEnabled = false;
     std::string m_logFilePath;
-    LogLevel m_minLevel = LogLevel::INFO;
+    LogLevel m_httpMinLevel = LogLevel::INFO;
+    LogLevel m_internalMinLevel = LogLevel::INFO;
     std::ofstream m_logFile;
     mutable std::mutex m_mutex;
 };
 
 // Convenience macros for logging
-#define LOG_DEBUG(msg) Logger::getInstance().debug(msg)
-#define LOG_INFO(msg) Logger::getInstance().info(msg)
-#define LOG_WARNING(msg) Logger::getInstance().warning(msg)
-#define LOG_ERROR(msg) Logger::getInstance().error(msg)
+#define LOG_DEBUG(msg) Logger::getInstance().debug(msg, LoggerType::INTERNAL)
+#define LOG_INFO(msg) Logger::getInstance().info(msg, LoggerType::INTERNAL)
+#define LOG_WARNING(msg) Logger::getInstance().warning(msg, LoggerType::INTERNAL)
+#define LOG_ERROR(msg) Logger::getInstance().error(msg, LoggerType::INTERNAL)
+
+// HTTP-specific logging macros
+#define HTTP_DEBUG(msg) Logger::getInstance().debug(msg, LoggerType::HTTP)
+#define HTTP_INFO(msg) Logger::getInstance().info(msg, LoggerType::HTTP)
+#define HTTP_WARNING(msg) Logger::getInstance().warning(msg, LoggerType::HTTP)
+#define HTTP_ERROR(msg) Logger::getInstance().error(msg, LoggerType::HTTP)
 
 #endif // LOGGER_H

+ 5 - 0
include/server.h

@@ -97,6 +97,11 @@ private:
      */
     void setupCORS();
 
+    /**
+     * @brief Log HTTP access request
+     */
+    void logHttpAccess(const httplib::Request& req, httplib::Response& res, const std::string& endpoint = "");
+
     /**
      * @brief Health check endpoint handler
      */

+ 11 - 10
src/generation_queue.cpp

@@ -2,6 +2,7 @@
 #include "model_manager.h"
 #include "stable_diffusion_wrapper.h"
 #include "utils.h"
+#include "logger.h"
 #include <iostream>
 #include <random>
 #include <sstream>
@@ -57,7 +58,7 @@ public:
 
     // Worker thread function
     void workerThreadFunction() {
-        std::cout << "GenerationQueue worker thread started" << std::endl;
+        LOG_INFO("GenerationQueue worker thread started");
 
         while (running.load() && !stopRequested.load()) {
             std::unique_lock<std::mutex> lock(queueMutex);
@@ -85,7 +86,7 @@ public:
             processRequest(request);
         }
 
-        std::cout << "GenerationQueue worker thread stopped" << std::endl;
+        LOG_INFO("GenerationQueue worker thread stopped");
     }
 
     void processRequest(const GenerationRequest& request) {
@@ -141,9 +142,9 @@ public:
 
         activeGenerations.store(1); // Only one generation at a time
 
-        std::cout << "Processing generation request: " << request.id
-                  << " (prompt: " << request.prompt.substr(0, 50)
-                  << (request.prompt.length() > 50 ? "..." : "") << ")" << std::endl;
+        LOG_INFO("Processing generation request: " + request.id +
+                 " (prompt: " + request.prompt.substr(0, 50) +
+                 (request.prompt.length() > 50 ? "..." : "") + ")");
 
         // Real generation logic using stable-diffusion.cpp with progress tracking
         GenerationResult result = performActualGeneration(request, request.id);
@@ -205,13 +206,13 @@ public:
         activeGenerations.store(0);
         totalJobsProcessed.fetch_add(1);
 
-        std::cout << "Completed generation request: " << request.id
-                  << " (success: " << (result.success ? "true" : "false")
-                  << ", time: " << result.generationTime << "ms)";
+        std::string completionMsg = "Completed generation request: " + request.id +
+                                     " (success: " + (result.success ? "true" : "false") +
+                                     ", time: " + std::to_string(result.generationTime) + "ms)";
         if (!result.success && !result.errorMessage.empty()) {
-            std::cout << " - Error: " << result.errorMessage;
+            completionMsg += " - Error: " + result.errorMessage;
         }
-        std::cout << std::endl;
+        LOG_INFO(completionMsg);
     }
 
     // Progress callback that updates the job info

+ 33 - 7
src/logger.cpp

@@ -16,7 +16,8 @@ void Logger::initialize(bool enableFileLogging, const std::string& logFilePath,
 
     m_fileLoggingEnabled = enableFileLogging;
     m_logFilePath = logFilePath;
-    m_minLevel = minLevel;
+    m_internalMinLevel = minLevel;
+    m_httpMinLevel = minLevel;
 
     if (m_fileLoggingEnabled && !m_logFilePath.empty()) {
         m_logFile.open(m_logFilePath, std::ios::app);
@@ -31,6 +32,20 @@ void Logger::initialize(bool enableFileLogging, const std::string& logFilePath,
     }
 }
 
+void Logger::setLogLevel(LoggerType type, LogLevel level) {
+    std::lock_guard<std::mutex> lock(m_mutex);
+    if (type == LoggerType::HTTP) {
+        m_httpMinLevel = level;
+    } else {
+        m_internalMinLevel = level;
+    }
+}
+
+LogLevel Logger::getLogLevel(LoggerType type) const {
+    std::lock_guard<std::mutex> lock(m_mutex);
+    return (type == LoggerType::HTTP) ? m_httpMinLevel : m_internalMinLevel;
+}
+
 void Logger::close() {
     std::lock_guard<std::mutex> lock(m_mutex);
     if (m_logFile.is_open()) {
@@ -64,6 +79,14 @@ std::string Logger::levelToString(LogLevel level) {
     }
 }
 
+std::string Logger::typeToString(LoggerType type) {
+    switch (type) {
+        case LoggerType::HTTP:     return "HTTP";
+        case LoggerType::INTERNAL: return "INTERNAL";
+        default:                   return "UNKNOWN";
+    }
+}
+
 std::string Logger::levelToSystemdPriority(LogLevel level) {
     // systemd journal priority levels:
     // 0=emerg, 1=alert, 2=crit, 3=err, 4=warning, 5=notice, 6=info, 7=debug
@@ -76,8 +99,10 @@ std::string Logger::levelToSystemdPriority(LogLevel level) {
     }
 }
 
-void Logger::log(LogLevel level, const std::string& message) {
-    if (level < m_minLevel) {
+void Logger::log(LogLevel level, const std::string& message, LoggerType type) {
+    LogLevel minLevel = (type == LoggerType::HTTP) ? m_httpMinLevel : m_internalMinLevel;
+    
+    if (level < minLevel) {
         return;
     }
 
@@ -85,16 +110,17 @@ void Logger::log(LogLevel level, const std::string& message) {
 
     std::string timestamp = getCurrentTimestamp();
     std::string levelStr = levelToString(level);
+    std::string typeStr = typeToString(type);
     std::string priority = levelToSystemdPriority(level);
 
-    // Console output with systemd priority prefix
+    // Console output with systemd priority prefix and type
     std::cout << priority << "[" << timestamp << "] "
-              << levelStr << ": " << message << std::endl;
+              << typeStr << " " << levelStr << ": " << message << std::endl;
 
-    // File output (without systemd priority)
+    // File output (without systemd priority, with type)
     if (m_fileLoggingEnabled && m_logFile.is_open()) {
         m_logFile << "[" << timestamp << "] "
-                  << levelStr << ": " << message << std::endl;
+                  << typeStr << " " << levelStr << ": " << message << std::endl;
         m_logFile.flush();
     }
 }

+ 58 - 23
src/server.cpp

@@ -6,6 +6,7 @@
 #include "auth_middleware.h"
 #include "user_manager.h"
 #include "version.h"
+#include "logger.h"
 #include <httplib.h>
 #include <nlohmann/json.hpp>
 #include <iostream>
@@ -156,6 +157,7 @@ void Server::registerEndpoints() {
 
     // Health check endpoint (public)
     m_httpServer->Get("/api/health", [this](const httplib::Request& req, httplib::Response& res) {
+        std::cout << "DEBUG: Health endpoint lambda called" << std::endl;
         handleHealthCheck(req, res);
     });
 
@@ -350,7 +352,7 @@ void Server::registerEndpoints() {
 
     // Serve static web UI files if uiDir is configured
     if (!m_uiDir.empty() && std::filesystem::exists(m_uiDir)) {
-        std::cout << "Serving static UI files from: " << m_uiDir << " at /ui" << std::endl;
+        LOG_INFO("Serving static UI files from: " + m_uiDir + " at /ui");
 
         // Read UI version from version.nlohmann::json if available
         std::string uiVersion = "unknown";
@@ -366,10 +368,10 @@ void Server::registerEndpoints() {
                     versionFile.close();
                 }
             } catch (const std::exception& e) {
-                std::cerr << "Failed to read UI version: " << e.what() << std::endl;
+                LOG_ERROR("Failed to read UI version: " + std::string(e.what()));
             }
         }
-        std::cout << "UI version: " << uiVersion << std::endl;
+        LOG_INFO("UI version: " + uiVersion);
 
         // Serve dynamic config.js that provides runtime configuration to the web UI
         m_httpServer->Get("/ui/config.js", [this, uiVersion](const httplib::Request& /*req*/, httplib::Response& res) {
@@ -946,7 +948,8 @@ void Server::setupCORS() {
     });
 }
 
-void Server::handleHealthCheck(const httplib::Request& /*req*/, httplib::Response& res) {
+void Server::handleHealthCheck(const httplib::Request& req, httplib::Response& res) {
+    std::cout << "DEBUG: handleHealthCheck called" << std::endl;
     try {
         nlohmann::json response = {
             {"status", "healthy"},
@@ -955,8 +958,12 @@ void Server::handleHealthCheck(const httplib::Request& /*req*/, httplib::Respons
             {"version", sd_rest::VERSION_INFO.version_full}
         };
         sendJsonResponse(res, response);
+        std::cout << "DEBUG: About to call logHttpAccess" << std::endl;
+        logHttpAccess(req, res, "health-check");
+        std::cout << "DEBUG: logHttpAccess returned" << std::endl;
     } catch (const std::exception& e) {
         sendErrorResponse(res, std::string("Health check failed: ") + e.what(), 500);
+        logHttpAccess(req, res, "health-check-error");
     }
 }
 
@@ -3107,7 +3114,10 @@ void Server::handleText2Img(const httplib::Request& req, httplib::Response& res)
         sendErrorResponse(res, std::string("Invalid JSON: ") + e.what(), 400, "JSON_PARSE_ERROR", requestId);
     } catch (const std::exception& e) {
         sendErrorResponse(res, std::string("Text-to-image request failed: ") + e.what(), 500, "INTERNAL_ERROR", requestId);
+        logHttpAccess(req, res, "text2img-error");
     }
+    
+    logHttpAccess(req, res, "text2img");
 }
 
 void Server::handleImg2Img(const httplib::Request& req, httplib::Response& res) {
@@ -5514,10 +5524,10 @@ void Server::handleModelRequirements(const httplib::Request& req, httplib::Respo
 
 void Server::serverThreadFunction(const std::string& host, int port) {
     try {
-        std::cout << "Server thread starting, attempting to bind to " << host << ":" << port << std::endl;
+        LOG_INFO("Server thread starting, attempting to bind to " + host + ":" + std::to_string(port));
 
         // Check if port is available before attempting to bind
-        std::cout << "Checking if port " << port << " is available..." << std::endl;
+        LOG_INFO("Checking if port " + std::to_string(port) + " is available...");
 
         // Try to create a test socket to check if port is in use
         int test_socket = socket(AF_INET, SOCK_STREAM, 0);
@@ -5525,14 +5535,14 @@ void Server::serverThreadFunction(const std::string& host, int port) {
             // Set SO_REUSEADDR to avoid TIME_WAIT issues
             int opt = 1;
             if (setsockopt(test_socket, SOL_SOCKET, SO_REUSEADDR, &opt, sizeof(opt)) < 0) {
-                std::cerr << "Warning: Failed to set SO_REUSEADDR on test socket: " << strerror(errno) << std::endl;
+                LOG_WARNING("Failed to set SO_REUSEADDR on test socket: " + std::string(strerror(errno)));
             }
 
             // Also set SO_REUSEPORT if available (for better concurrent binding handling)
             #ifdef SO_REUSEPORT
             int reuseport = 1;
             if (setsockopt(test_socket, SOL_SOCKET, SO_REUSEPORT, &reuseport, sizeof(reuseport)) < 0) {
-                std::cerr << "Warning: Failed to set SO_REUSEPORT on test socket: " << strerror(errno) << std::endl;
+                LOG_WARNING("Failed to set SO_REUSEPORT on test socket: " + std::string(strerror(errno)));
             }
             #endif
 
@@ -5544,16 +5554,15 @@ void Server::serverThreadFunction(const std::string& host, int port) {
             // Try to bind to the port
             if (bind(test_socket, (struct sockaddr*)&addr, sizeof(addr)) < 0) {
                 close(test_socket);
-                std::cerr << "ERROR: Port " << port << " is already in use! Cannot start server." << std::endl;
-                std::cerr << "This could be due to:" << std::endl;
-                std::cerr << "1. Another instance is already running on this port" << std::endl;
-                std::cerr << "2. A previous instance crashed and the socket is in TIME_WAIT state" << std::endl;
-                std::cerr << "3. The port is being used by another application" << std::endl;
-                std::cerr << std::endl;
-                std::cerr << "Solutions:" << std::endl;
-                std::cerr << "- Wait 30-60 seconds for TIME_WAIT to expire (if server crashed)" << std::endl;
-                std::cerr << "- Kill any existing processes: sudo lsof -ti:" << port << " | xargs kill -9" << std::endl;
-                std::cerr << "- Use a different port with -p <port>" << std::endl;
+                LOG_ERROR("Port " + std::to_string(port) + " is already in use! Cannot start server.");
+                LOG_ERROR("This could be due to:");
+                LOG_ERROR("1. Another instance is already running on this port");
+                LOG_ERROR("2. A previous instance crashed and the socket is in TIME_WAIT state");
+                LOG_ERROR("3. The port is being used by another application");
+                LOG_ERROR("Solutions:");
+                LOG_ERROR("- Wait 30-60 seconds for TIME_WAIT to expire (if server crashed)");
+                LOG_ERROR("- Kill any existing processes: sudo lsof -ti:" + std::to_string(port) + " | xargs kill -9");
+                LOG_ERROR("- Use a different port with -p <port>");
                 m_isRunning.store(false);
                 m_startupFailed.store(true);
                 return;
@@ -5561,8 +5570,8 @@ void Server::serverThreadFunction(const std::string& host, int port) {
             close(test_socket);
         }
 
-        std::cout << "Port " << port << " is available, proceeding with server startup..." << std::endl;
-        std::cout << "Calling listen()..." << std::endl;
+        LOG_INFO("Port " + std::to_string(port) + " is available, proceeding with server startup...");
+        LOG_INFO("Calling listen()...");
 
         // We need to set m_isRunning after successful bind but before blocking
         // cpp-httplib doesn't provide a callback, so we set it optimistically
@@ -5571,13 +5580,13 @@ void Server::serverThreadFunction(const std::string& host, int port) {
 
         bool listenResult = m_httpServer->listen(host.c_str(), port);
 
-        std::cout << "listen() returned: " << (listenResult ? "true" : "false") << std::endl;
+        LOG_INFO("listen() returned: " + std::string(listenResult ? "true" : "false"));
 
         // If we reach here, server has stopped (either normally or due to error)
         m_isRunning.store(false);
 
         if (!listenResult) {
-            std::cerr << "Server listen failed! This usually means port is in use or permission denied." << std::endl;
+            LOG_ERROR("Server listen failed! This usually means port is in use or permission denied.");
         }
 
     } catch (const std::exception& e) {
@@ -5640,8 +5649,34 @@ std::string Server::generateThumbnail(const std::string& imagePath, int size) {
         return placeholderThumbnail;
 
     } catch (const std::exception& e) {
-        std::cerr << "Exception in generateThumbnail: " << e.what() << std::endl;
+        LOG_ERROR("Exception in generateThumbnail: " + std::string(e.what()));
         return "";
     }
 }
 
+void Server::logHttpAccess(const httplib::Request& req, httplib::Response& res, const std::string& endpoint) {
+    // Debug: Always print to see if function is called
+    std::cout << "DEBUG: logHttpAccess called for " << req.method << " " << req.path << std::endl;
+    
+    std::string clientIP = req.get_header_value("X-Forwarded-For");
+    if (clientIP.empty()) {
+        clientIP = req.remote_addr;
+    }
+    
+    std::string userAgent = req.get_header_value("User-Agent");
+    if (userAgent.length() > 100) {
+        userAgent = userAgent.substr(0, 100) + "...";
+    }
+    
+    std::string logMessage = clientIP + " " + req.method + " " + req.path + 
+                           " -> " + std::to_string(res.status) + 
+                           " (" + std::to_string(res.body.length()) + " bytes)";
+    
+    if (!endpoint.empty()) {
+        logMessage += " [" + endpoint + "]";
+    }
+    
+    // Use LOG_INFO for now to ensure it shows up
+    LOG_INFO("HTTP: " + logMessage);
+}
+