diff --git a/server/Fury/Kernel/Logging.php b/server/Fury/Kernel/Logging.php index bae8d20..a0419b4 100644 --- a/server/Fury/Kernel/Logging.php +++ b/server/Fury/Kernel/Logging.php @@ -38,12 +38,12 @@ } /** - * Set new log item + * Set new log item (legacy session-based API) * * @method set * * @param string $place String in format "Classname@methname" or "funcname" - * @param string $title Title of log. + * @param string $title Title of log. * @param string $message Any text message */ public function set($place, $title, $message){ @@ -68,9 +68,188 @@ return true; } + // ============================================================ + // Structured JSON Lines logging (new) + // ============================================================ + + const LEVEL_TRACE = 'TRACE'; + const LEVEL_DEBUG = 'DEBUG'; + const LEVEL_INFO = 'INFO'; + const LEVEL_WARN = 'WARN'; + const LEVEL_ERROR = 'ERROR'; + const LEVEL_FATAL = 'FATAL'; + + protected static $write_counter = 0; /** - * Dumping session logs to json file + * Get current request/session correlation id + */ + public function get_request_id(): string { + return $this -> session_id; + } + + public function trace(string $source, string $message, array $context = []){ + return $this -> log(self::LEVEL_TRACE, $source, $message, $context); + } + + public function debug(string $source, string $message, array $context = []){ + return $this -> log(self::LEVEL_DEBUG, $source, $message, $context); + } + + public function info(string $source, string $message, array $context = []){ + return $this -> log(self::LEVEL_INFO, $source, $message, $context); + } + + public function warn(string $source, string $message, array $context = []){ + return $this -> log(self::LEVEL_WARN, $source, $message, $context); + } + + public function error(string $source, string $message, array $context = []){ + return $this -> log(self::LEVEL_ERROR, $source, $message, $context); + } + + public function fatal(string $source, string $message, array $context = []){ + return $this -> log(self::LEVEL_FATAL, $source, $message, $context); + } + + /** + * Write a structured log entry immediately to JSON Lines file + */ + public function log(string $level, string $source, string $message, array $context = []){ + if(!FCONF['logs_enable']) + return false; + + if($this -> is_level_below_min($level)) + return false; + + if(!$this -> is_source_allowed($source)) + return false; + + $entry = [ + 'ts' => date('c'), + 'level' => $level, + 'source' => $source, + 'request_id' => $this -> session_id, + 'message' => $message, + 'context' => $this -> redact($context), + ]; + + $line = json_encode($entry, JSON_UNESCAPED_UNICODE | JSON_UNESCAPED_SLASHES) . "\n"; + + $path = $this -> get_jsonl_path(); + $this -> rotate_if_needed($path); + $this -> cleanup_if_needed(); + + $fp = fopen($path, 'a'); + if($fp === false) + return false; + + if(flock($fp, LOCK_EX)){ + fwrite($fp, $line); + fflush($fp); + flock($fp, LOCK_UN); + } + fclose($fp); + chmod($path, 0644); + + return true; + } + + // ============================================================ + // Config helpers + // ============================================================ + + private function conf(string $key, $default = null){ + return FCONF[$key] ?? $default; + } + + private function is_level_below_min(string $level): bool { + $map = [ + self::LEVEL_TRACE => 0, + self::LEVEL_DEBUG => 1, + self::LEVEL_INFO => 2, + self::LEVEL_WARN => 3, + self::LEVEL_ERROR => 4, + self::LEVEL_FATAL => 5, + ]; + $min = strtoupper($this -> conf('logs_min_level', self::LEVEL_INFO)); + return ($map[$level] ?? 2) < ($map[$min] ?? 2); + } + + private function is_source_allowed(string $source): bool { + $allowed = $this -> conf('logs_sources', []); + if(empty($allowed)) + return true; + return in_array($source, $allowed, true); + } + + // ============================================================ + // File path, rotation, cleanup + // ============================================================ + + private function get_jsonl_path(): string { + $folder = $this -> logs_folder; + if(!is_dir($folder)){ + mkdir($folder, 0750, true); + } + return $folder . '/' . date('Y-m-d') . '.jsonl'; + } + + private function rotate_if_needed(string $path): void { + if(!file_exists($path)) + return; + + $max_mb = (int) $this -> conf('logs_max_file_size_mb', 50); + $max_bytes = $max_mb * 1024 * 1024; + if(filesize($path) < $max_bytes) + return; + + $rotated = $path . '.' . date('Y-m-d_H-i-s'); + @rename($path, $rotated); + } + + private function cleanup_if_needed(): void { + self::$write_counter++; + if(self::$write_counter % 100 !== 0) + return; + + $max_days = (int) $this -> conf('logs_max_days', 30); + $cutoff = time() - ($max_days * 86400); + $folder = $this -> logs_folder; + + foreach(glob($folder . '/*.jsonl*') as $file){ + if(filemtime($file) < $cutoff){ + @unlink($file); + } + } + } + + // ============================================================ + // Redaction + // ============================================================ + + private function redact(array $context): array { + $pattern = '/password|token|authorization|secret|key/i'; + return $this -> redact_recursive($context, $pattern); + } + + private function redact_recursive($data, string $pattern) { + if(is_array($data)){ + $result = []; + foreach($data as $k => $v){ + if(preg_match($pattern, (string)$k)){ + $result[$k] = '***'; + }else{ + $result[$k] = $this -> redact_recursive($v, $pattern); + } + } + return $result; + } + return $data; + } + + /** + * Dumping session logs to json file (legacy format) * * @method dump * diff --git a/server/Fury/Modules/ErrorHandler/ErrorHandler.php b/server/Fury/Modules/ErrorHandler/ErrorHandler.php index 3005fad..a7267e9 100644 --- a/server/Fury/Modules/ErrorHandler/ErrorHandler.php +++ b/server/Fury/Modules/ErrorHandler/ErrorHandler.php @@ -42,6 +42,13 @@ } public function exception_handler(\Throwable $e) { + logging() -> error('php:ErrorHandler', $e -> getMessage(), [ + 'code' => $e -> getCode(), + 'file' => $e -> getFile(), + 'line' => $e -> getLine(), + 'trace' => $e -> getTraceAsString(), + ]); + $this -> error_handler( (int) $e -> getCode(), $e -> getMessage(), @@ -56,6 +63,13 @@ public function fatal_error_handler(){ $error = error_get_last(); if ($error){ + $err_type = $this -> get_err_type($error["type"]); + logging() -> fatal('php:ErrorHandler', $error["message"], [ + 'type' => $err_type, + 'file' => $error["file"], + 'line' => $error["line"], + ]); + $this -> view_fatal_error($error["type"], $error["message"], $error["file"], $error["line"]); } } @@ -69,6 +83,13 @@ return true; } + logging() -> error('php:ErrorHandler', $errstr, [ + 'errno' => $errno, + 'errtype' => $err_type, + 'errfile' => $errfile, + 'errline' => $errline, + ]); + $this -> view_fatal_error($errno, $errstr, $errfile, $errline); return true; } diff --git a/server/Fury/Modules/ThinBuilder/ThinBuilder.php b/server/Fury/Modules/ThinBuilder/ThinBuilder.php index d2f272c..ac0fda9 100644 --- a/server/Fury/Modules/ThinBuilder/ThinBuilder.php +++ b/server/Fury/Modules/ThinBuilder/ThinBuilder.php @@ -55,6 +55,10 @@ $sql = "SELECT {$fields_sql} FROM `{$tablename}` {$where_sql} {$order_sql} {$limit_sql}"; + if($this -> driver){ + $this -> driver -> event_ready_sql($sql); + } + if($this -> gen_sql_only) { $this -> gen_sql_only = false; return $sql; @@ -85,6 +89,10 @@ $sql = "INSERT INTO `{$tablename}` (`" . implode('`,`', $fields) . "`) VALUES (" . implode(',', $placeholders) . ")"; + if($this -> driver){ + $this -> driver -> event_ready_sql($sql); + } + if($this -> gen_sql_only) { $this -> gen_sql_only = false; return $sql; @@ -98,6 +106,10 @@ $this -> history -> add($sql, $id); } + if($this -> driver){ + $this -> driver -> event_query($sql, $id); + } + return $id; } @@ -113,6 +125,10 @@ $sql = "UPDATE `{$tablename}` SET " . implode(',', $set_sql) . " {$where_sql}"; + if($this -> driver){ + $this -> driver -> event_ready_sql($sql); + } + if($this -> gen_sql_only) { $this -> gen_sql_only = false; return $sql; @@ -120,8 +136,13 @@ $stmt = $this -> pdo -> prepare($sql); $stmt -> execute(array_merge(array_values($data), $where_params)); + $row_count = $stmt -> rowCount(); - return $stmt -> rowCount(); + if($this -> driver){ + $this -> driver -> event_query($sql, $row_count); + } + + return $row_count; } public function delete(String $tablename, $where = []){ @@ -130,6 +151,10 @@ $sql = "DELETE FROM `{$tablename}` {$where_sql}"; + if($this -> driver){ + $this -> driver -> event_ready_sql($sql); + } + if($this -> gen_sql_only) { $this -> gen_sql_only = false; return $sql; @@ -137,8 +162,13 @@ $stmt = $this -> pdo -> prepare($sql); $stmt -> execute($where_params); + $row_count = $stmt -> rowCount(); - return $stmt -> rowCount(); + if($this -> driver){ + $this -> driver -> event_query($sql, $row_count); + } + + return $row_count; } public function drop(String $tablename){ @@ -230,11 +260,20 @@ list($where_sql, $where_params) = $this -> where_processing($where); $sql = "SELECT COUNT(*) FROM `{$tablename}` {$where_sql}"; + if($this -> driver){ + $this -> driver -> event_ready_sql($sql); + } + $stmt = $this -> pdo -> prepare($sql); $stmt -> execute($where_params); $result = $stmt -> fetch(\PDO::FETCH_NUM); + $count = $result ? intval($result[0]) : 0; - return $result ? intval($result[0]) : 0; + if($this -> driver){ + $this -> driver -> event_query($sql, $count); + } + + return $count; } public function history(){ diff --git a/server/SHServ/App.php b/server/SHServ/App.php index e9f2ced..21b5f25 100644 --- a/server/SHServ/App.php +++ b/server/SHServ/App.php @@ -49,6 +49,9 @@ $this -> events_handlers = new EventsHandlers(); $this -> events_handlers -> handlers(); + $this -> request_logger = new \SHServ\Middleware\RequestLogger(); + $this -> sql_logger = new \SHServ\Middleware\SqlQueryLogger(); + // CUSTOM $this -> utils = new Utils(); $this -> factory = new Factory(); diff --git a/server/SHServ/Middleware/RequestLogger.php b/server/SHServ/Middleware/RequestLogger.php new file mode 100644 index 0000000..78e52dc --- /dev/null +++ b/server/SHServ/Middleware/RequestLogger.php @@ -0,0 +1,127 @@ + register_cli_handlers($argv); + } else { + $this -> register_http_handlers(); + } + } + + // ============================================================ + // HTTP + // ============================================================ + + protected function register_http_handlers(): void { + self::$start_time = microtime(true); + self::$completed = false; + + $uri = $_SERVER['REQUEST_URI'] ?? ''; + if (strpos($uri, '?') !== false) { + list($path, $query) = explode('?', $uri, 2); + } else { + $path = $uri; + $query = ''; + } + + logging() -> info('php:RequestLogger', 'Request started', [ + 'method' => $_SERVER['REQUEST_METHOD'] ?? 'UNKNOWN', + 'path' => $path, + 'query' => $query, + 'ip' => $_SERVER['REMOTE_ADDR'] ?? '', + 'ua' => $_SERVER['HTTP_USER_AGENT'] ?? '', + 'content_length' => $_SERVER['CONTENT_LENGTH'] ?? 0, + 'content_type' => $_SERVER['CONTENT_TYPE'] ?? '', + ]); + + events() -> handler('kernel:CallControl.leading_call', function(Array $params) { + $action = is_string($params['action'] ?? null) + ? $params['action'] + : 'anon'; + self::$action_name = $action; + + logging() -> debug('php:RequestLogger', 'Action dispatch', [ + 'action' => $action, + 'type' => $params['type'] ?? '', + ]); + }); + + events() -> handler('kernel:Bootstrap.app_finished', function(Array $params) { + self::$completed = true; + $this -> log_request_end(); + }); + + register_shutdown_function(function() { + if (self::$completed) { + return; + } + logging() -> warn('php:RequestLogger', 'Request aborted or exited before app_finished', [ + 'duration_ms' => self::$start_time !== null + ? round((microtime(true) - self::$start_time) * 1000, 3) + : null, + 'aborted' => true, + ]); + }); + } + + protected function log_request_end(): void { + $duration = self::$start_time !== null + ? round((microtime(true) - self::$start_time) * 1000, 3) + : null; + + $code = http_response_code(); + if ($code === 0 || $code === false) { + $code = 200; + } + + logging() -> info('php:RequestLogger', 'Request completed', [ + 'duration_ms' => $duration, + 'memory_peak_mb' => round(memory_get_peak_usage(true) / 1024 / 1024, 2), + 'status_code' => $code, + 'action' => self::$action_name, + ]); + } + + // ============================================================ + // CLI + // ============================================================ + + protected function register_cli_handlers(array $argv): void { + self::$start_time = microtime(true); + + logging() -> info('php:RequestLogger', 'Console command started', [ + 'argv' => $argv, + ]); + + register_shutdown_function(function() use ($argv) { + $duration = self::$start_time !== null + ? round((microtime(true) - self::$start_time) * 1000, 3) + : null; + + logging() -> info('php:RequestLogger', 'Console command finished', [ + 'argv' => $argv, + 'duration_ms' => $duration, + ]); + }); + } +} diff --git a/server/SHServ/Middleware/SqlQueryLogger.php b/server/SHServ/Middleware/SqlQueryLogger.php new file mode 100644 index 0000000..5e29aac --- /dev/null +++ b/server/SHServ/Middleware/SqlQueryLogger.php @@ -0,0 +1,74 @@ +1000 мс) как WARN. + * + * Работает через события ThinBuilder: + * - module:ThinBuilder.ready_sql → фиксируем SQL + стартовое время + * - module:ThinBuilder.query → вычисляем длительность, пишем лог + * + * Поддерживает gen_sql_only (orphan SQL остаётся в pending до конца запроса). + */ +class SqlQueryLogger { + protected static array $pending = []; + + public function __construct() { + events() -> handler('module:ThinBuilder.ready_sql', function(Array $params) { + $sql = $params['sql'] ?? ''; + if ($sql === '') { + return; + } + self::$pending[$sql] = microtime(true); + }); + + events() -> handler('module:ThinBuilder.query', function(Array $params) { + $sql = $params['sql'] ?? ''; + $result = $params['result'] ?? null; + + if ($sql === '' || !isset(self::$pending[$sql])) { + return; + } + + $start = self::$pending[$sql]; + unset(self::$pending[$sql]); + + $duration_ms = round((microtime(true) - $start) * 1000, 3); + $level = $duration_ms > 1000 ? 'WARN' : 'INFO'; + $message = $duration_ms > 1000 ? 'Slow query' : 'Query executed'; + + $row_count = null; + if (is_array($result)) { + $row_count = count($result); + } elseif (is_int($result) || is_numeric($result)) { + $row_count = (int) $result; + } + + $context = [ + 'sql' => $sql, + 'duration_ms' => $duration_ms, + ]; + + if ($row_count !== null) { + $context['row_count'] = $row_count; + } + + logging() -> log($level, 'php:ThinBuilder', $message, $context); + }); + + // Очистка orphan SQL (например, при gen_sql_only) + events() -> handler('kernel:Bootstrap.app_finished', function(Array $params) { + if (empty(self::$pending)) { + return; + } + foreach (self::$pending as $sql => $start) { + logging() -> info('php:ThinBuilder', 'Query planned but not executed', [ + 'sql' => $sql, + ]); + } + self::$pending = []; + }); + } +} diff --git a/server/SHServ/Tools/DeviceAPI/Base.php b/server/SHServ/Tools/DeviceAPI/Base.php index 1b91764..bb4e0ef 100644 --- a/server/SHServ/Tools/DeviceAPI/Base.php +++ b/server/SHServ/Tools/DeviceAPI/Base.php @@ -132,6 +132,13 @@ */ public function updateFirmware(string $binPath): array { $url = $this->base_url . '/update'; + $request_start = microtime(true); + + logging() -> debug('php:DeviceAPI', 'Firmware update request', [ + 'url' => $url, + 'file' => basename($binPath), + 'size_kb'=> file_exists($binPath) ? round(filesize($binPath) / 1024, 2) : null, + ]); $ch = curl_init(); if ($ch === false) { @@ -175,6 +182,14 @@ $rawBody = substr($raw, $headerSize); + logging() -> debug('php:DeviceAPI', 'Firmware update response', [ + 'url' => $url, + 'http_code' => (int) $httpCode, + 'duration_ms' => round((microtime(true) - $request_start) * 1000, 3), + 'error' => $err, + 'raw_preview' => $rawBody !== '' ? substr($rawBody, 0, 2048) : null, + ]); + return [ 'http_code' => (int) $httpCode, 'headers' => [], @@ -217,6 +232,13 @@ } $url = $this->base_url . $path; + $request_start = microtime(true); + + logging() -> debug('php:DeviceAPI', 'Device request', [ + 'method' => $method, + 'url' => $url, + 'require_token' => $require_token, + ]); $ch = curl_init(); if ($ch === false) { @@ -299,12 +321,20 @@ if ($raw_response === false) { curl_close($ch); + $err = $error_message ?? 'Unknown cURL error'; + logging() -> error('php:DeviceAPI', 'Device request failed', [ + 'url' => $url, + 'method' => $method, + 'error' => $err, + 'duration_ms' => round((microtime(true) - $request_start) * 1000, 3), + ]); + return [ 'http_code' => 0, 'headers' => [], 'raw' => null, 'data' => null, - 'error' => $error_message ?? 'Unknown cURL error', + 'error' => $err, ]; } @@ -333,6 +363,15 @@ } } + logging() -> debug('php:DeviceAPI', 'Device response', [ + 'url' => $url, + 'method' => $method, + 'http_code' => (int) $http_code, + 'duration_ms' => round((microtime(true) - $request_start) * 1000, 3), + 'error' => $error, + 'raw_preview' => $raw_body !== '' ? substr($raw_body, 0, 2048) : null, + ]); + return [ 'http_code' => (int)$http_code, 'headers' => $parsed_headers, diff --git a/server/SHServ/Tools/DeviceScanner.php b/server/SHServ/Tools/DeviceScanner.php index c84b7c9..6e163d4 100644 --- a/server/SHServ/Tools/DeviceScanner.php +++ b/server/SHServ/Tools/DeviceScanner.php @@ -115,6 +115,12 @@ $devices = array_merge($devices, $retry_devices); } + logging() -> info('php:DeviceScanner', 'Scan batch completed', [ + 'found' => count($devices), + 'total_ips' => count($ips), + 'retry_count'=> count($failed_ips), + ]); + return $devices; } @@ -123,6 +129,12 @@ * Прерывается если клиент разорвал соединение. */ private function scan_batch_multi(array $ips, int $port, float $timeout): array { + logging() -> info('php:DeviceScanner', 'Scan batch started', [ + 'batch_size' => count($ips), + 'port' => $port, + 'timeout_ms' => (int) round($timeout * 1000), + ]); + $multi = curl_multi_init(); $handles = []; @@ -182,11 +194,26 @@ curl_close($ch); if ($curl_err !== 0 || $http !== 200 || !$body) { + logging() -> debug('php:DeviceScanner', 'Scan result', [ + 'ip' => $ip, + 'url' => $url, + 'http_code' => $http, + 'curl_err' => $curl_err, + 'found' => false, + ]); continue; } $json = json_decode($body, true); if (!is_array($json)) { + logging() -> debug('php:DeviceScanner', 'Scan result', [ + 'ip' => $ip, + 'url' => $url, + 'http_code' => $http, + 'curl_err' => $curl_err, + 'found' => false, + 'reason' => 'invalid_json', + ]); continue; } @@ -203,6 +230,15 @@ 'http_code' => $http, ]; + logging() -> debug('php:DeviceScanner', 'Scan result', [ + 'ip' => $ip, + 'url' => $url, + 'http_code' => $http, + 'curl_err' => $curl_err, + 'found' => true, + 'device_type'=> $json['device_type'] ?? 'unknown', + ]); + $devices[] = $json; } diff --git a/server/SHServ/config.php b/server/SHServ/config.php index 238f358..1aa32f0 100644 --- a/server/SHServ/config.php +++ b/server/SHServ/config.php @@ -32,6 +32,10 @@ "templates_folder" => "Templates", "logs_enable" => true, "logs_folder" => dirname(__DIR__, 2) . "/Logs", + "logs_min_level" => $env['LOG_LEVEL'] ?? "INFO", + "logs_sources" => [], + "logs_max_file_size_mb" => 50, + "logs_max_days" => 30, "devmode" => ($env['DEVMODE'] ?? "false") === "true", "controllers_folder" => "Controllers",