From b0e2bfd9fc1cc3f8d3e678d17564911d88f038c3 Mon Sep 17 00:00:00 2001 From: ildyria Date: Sun, 4 Jan 2026 22:17:42 +0100 Subject: [PATCH 1/3] add query logging --- app/Listeners/LogQueryTimeout.php | 70 +++++++++++ app/Providers/AppServiceProvider.php | 69 +++++++++- app/Providers/EventServiceProvider.php | 7 ++ docs/specs/2-how-to/sql-timeout-logging.md | 140 +++++++++++++++++++++ 4 files changed, 285 insertions(+), 1 deletion(-) create mode 100644 app/Listeners/LogQueryTimeout.php create mode 100644 docs/specs/2-how-to/sql-timeout-logging.md diff --git a/app/Listeners/LogQueryTimeout.php b/app/Listeners/LogQueryTimeout.php new file mode 100644 index 00000000000..737dea479b9 --- /dev/null +++ b/app/Listeners/LogQueryTimeout.php @@ -0,0 +1,70 @@ +sql . serialize($event->bindings)); + $cache_key = self::CACHE_PREFIX . $query_hash; + + // Remove from cache (it completed) + Cache::forget($cache_key); + + // Log if query is dangerously slow + if ($event->time >= $critical_threshold) { + Log::error('🚨 CRITICAL: Query approaching timeout', [ + 'execution_time_ms' => $event->time, + 'execution_time_s' => round($event->time / 1000, 2), + 'timeout_limit_s' => $max_execution_time / 1000, + 'percentage' => round(($event->time / $max_execution_time) * 100, 1) . '%', + 'sql' => $event->sql, + 'bindings' => $event->bindings, + 'connection' => $event->connectionName, + 'url' => request()?->fullUrl() ?? 'N/A', + ]); + } elseif ($event->time >= $warning_threshold) { + Log::warning('⚠️ WARNING: Slow query detected', [ + 'execution_time_ms' => $event->time, + 'execution_time_s' => round($event->time / 1000, 2), + 'timeout_limit_s' => $max_execution_time / 1000, + 'percentage' => round(($event->time / $max_execution_time) * 100, 1) . '%', + 'sql' => $event->sql, + 'bindings' => $event->bindings, + 'connection' => $event->connectionName, + 'url' => request()?->fullUrl() ?? 'N/A', + ]); + } + } +} diff --git a/app/Providers/AppServiceProvider.php b/app/Providers/AppServiceProvider.php index a0e7f364539..6133d9d42ba 100644 --- a/app/Providers/AppServiceProvider.php +++ b/app/Providers/AppServiceProvider.php @@ -194,7 +194,29 @@ private function registerDatabaseOptions(): void DB::prohibitDestructiveCommands(config('app.env', 'production') !== 'dev'); if (config('database.db_log_sql', false) === true) { // @codeCoverageIgnoreStart - DB::listen(fn ($q) => $this->logSQL($q)); + // Log queries when they start + DB::beforeExecuting(fn ($sql, $bindings, $connection) => $this->logSQLStart($sql, $bindings, $connection)); + + // Log queries as they execute (for successful queries) + DB::listen(fn (QueryExecuted $q): null => $this->logSQL($q)); + + // Register shutdown function to catch queries that timeout + // This logs queries that were running when PHP times out + register_shutdown_function(function (): void { + $error = error_get_last(); + if ($error !== null && in_array($error['type'], [E_ERROR, E_CORE_ERROR, E_COMPILE_ERROR, E_RECOVERABLE_ERROR], true)) { + // Check if it's a timeout error + if (str_contains($error['message'], 'Maximum execution time') || str_contains($error['message'], 'timeout')) { + Log::error('🔥 PHP TIMEOUT DETECTED', [ + 'error' => $error['message'], + 'file' => $error['file'], + 'line' => $error['line'], + 'url' => request()?->fullUrl() ?? 'N/A', + 'method' => request()?->method() ?? 'N/A', + ]); + } + } + }); // @codeCoverageIgnoreEnd } @@ -232,6 +254,51 @@ private function registerLoggerAccess(): void }); } + /** + * @codeCoverageIgnore + */ + private function logSQLStart(string $sql, array $bindings, string $connection): void + { + // Quick exit + if ( + Str::contains(request()->getRequestUri(), 'logs', true) || + Str::contains($sql, $this->ignore_log_SQL) + ) { + return; + } + + // Get the call stack to find where the query originated + $trace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 15); + $caller = null; + + // Skip framework internals and find the first app file + foreach ($trace as $frame) { + if (isset($frame['file']) && + !Str::contains($frame['file'], 'vendor/') && + !Str::contains($frame['file'], 'AppServiceProvider.php')) { + $caller = [ + 'file' => str_replace(base_path() . '/', '', $frame['file']), + 'line' => $frame['line'] ?? 0, + ]; + break; + } + } + + // Get message with binding + $msg = 'START: ' . $sql . ' [' . implode(', ', $bindings) . ']'; + + $context = [ + 'connection' => $connection, + 'url' => request()?->fullUrl() ?? 'N/A', + ]; + + if ($caller !== null) { + $context['origin'] = $caller['file'] . ':' . $caller['line']; + } + + Log::debug($msg, $context); + } + /** * @codeCoverageIgnore */ diff --git a/app/Providers/EventServiceProvider.php b/app/Providers/EventServiceProvider.php index 03e9f972519..ff62f914f68 100644 --- a/app/Providers/EventServiceProvider.php +++ b/app/Providers/EventServiceProvider.php @@ -24,6 +24,7 @@ use App\Events\TaggedRouteCacheUpdated; use App\Listeners\AlbumCacheCleaner; use App\Listeners\CacheListener; +use App\Listeners\LogQueryTimeout; use App\Listeners\MetricsListener; use App\Listeners\OrderCompletedListener; use App\Listeners\RecomputeAlbumSizeOnAlbumChange; @@ -36,6 +37,7 @@ use Illuminate\Cache\Events\CacheMissed; use Illuminate\Cache\Events\KeyForgotten; use Illuminate\Cache\Events\KeyWritten; +use Illuminate\Database\Events\QueryExecuted; use Illuminate\Foundation\Support\Providers\EventServiceProvider as ServiceProvider; use Illuminate\Support\Facades\Event; use SocialiteProviders\Amazon\AmazonExtendSocialite; @@ -91,6 +93,11 @@ public function boot(): void Event::listen(AlbumRouteCacheUpdated::class, AlbumCacheCleaner::class . '@handle'); Event::listen(TaggedRouteCacheUpdated::class, TaggedRouteCacheCleaner::class . '@handle'); + // Log slow/timeout SQL queries when DB_LOG_SQL is enabled + if (config('database.db_log_sql', false) === true) { + Event::listen(QueryExecuted::class, LogQueryTimeout::class . '@handle'); + } + Event::listen(AlbumDownload::class, MetricsListener::class . '@handle'); Event::listen(AlbumShared::class, MetricsListener::class . '@handle'); Event::listen(AlbumVisit::class, MetricsListener::class . '@handle'); diff --git a/docs/specs/2-how-to/sql-timeout-logging.md b/docs/specs/2-how-to/sql-timeout-logging.md new file mode 100644 index 00000000000..dc05cb64deb --- /dev/null +++ b/docs/specs/2-how-to/sql-timeout-logging.md @@ -0,0 +1,140 @@ +# SQL Timeout Logging + +This document explains how to log SQL requests that are timing out or approaching timeout limits in Lychee. + +## Overview + +When running with Laravel Octane (FrankenPHP/Swoole/RoadRunner), requests have a maximum execution time (default: 30 seconds as configured in `config/octane.php`). SQL queries that take too long can cause the entire request to timeout. + +The logging system tracks: +1. **Slow queries** - Queries taking longer than configured threshold +2. **Queries approaching timeout** - Queries using >70% of max execution time +3. **Critical queries** - Queries using >90% of max execution time +4. **PHP timeouts** - When the entire request times out + +## Configuration + +### Enable SQL Logging + +Set the following in your `.env` file: + +```env +# Enable SQL query logging +DB_LOG_SQL=true + +# Optional: Minimum execution time to log (in milliseconds, default: 100) +DB_LOG_SQL_MIN_TIME=100 + +# Optional: Enable EXPLAIN for MySQL SELECT queries +DB_LOG_SQL_EXPLAIN=true +``` + +### Timeout Settings + +The max execution time is configured in `config/octane.php`: + +```php +'max_execution_time' => 30, // seconds +``` + +## How It Works + +### 1. Query Execution Logging + +**Location**: [app/Providers/AppServiceProvider.php:238-300](app/Providers/AppServiceProvider.php#L238-L300) + +The `logSQL()` method logs queries after they complete with severity based on execution time: +- **Debug**: Normal slow queries (>100ms) +- **Warning**: Queries taking >1 second +- **Error**: Queries approaching timeout (>80% of max_execution_time) + +### 2. Timeout Detection Listener + +**Location**: [app/Listeners/LogQueryTimeout.php](app/Listeners/LogQueryTimeout.php) + +Registered in [app/Providers/EventServiceProvider.php:97-99](app/Providers/EventServiceProvider.php#L97-L99) + +This listener provides detailed logging for queries that exceed warning/critical thresholds: +- **70% threshold**: WARNING level log +- **90% threshold**: CRITICAL/ERROR level log + +### 3. PHP Timeout Handler + +**Location**: [app/Providers/AppServiceProvider.php:200-216](app/Providers/AppServiceProvider.php#L200-L216) + +A shutdown function that catches when PHP times out entirely, logging: +- Error message +- File and line where timeout occurred +- Request URL and method + +## Log Files + +Logs are written to different files based on severity: + +- `storage/logs/errors.log` - Critical/slow queries (>80% timeout) +- `storage/logs/warning.log` - Slow queries (>70% timeout or >1s) +- `storage/logs/daily.log` - All SQL queries (when DB_LOG_SQL=true) + +## Example Log Entries + +### Slow Query Warning +``` +[2026-01-04 10:15:32] warning.WARNING: ⚠️ WARNING: Slow query detected {"execution_time_ms":21000,"execution_time_s":21,"timeout_limit_s":30,"percentage":"70%","sql":"SELECT * FROM photos WHERE album_id = ?","bindings":[123],"connection":"mysql","url":"https://lychee.local/api/albums/123/photos"} +``` + +### Critical Query Near Timeout +``` +[2026-01-04 10:20:45] error.ERROR: 🚨 CRITICAL: Query approaching timeout {"execution_time_ms":27500,"execution_time_s":27.5,"timeout_limit_s":30,"percentage":"91.7%","sql":"SELECT * FROM photos WHERE...","bindings":[...],"connection":"mysql","url":"https://lychee.local/api/..."} +``` + +### PHP Timeout Detected +``` +[2026-01-04 10:25:12] error.ERROR: 🔥 PHP TIMEOUT DETECTED {"error":"Maximum execution time of 30 seconds exceeded","file":"/app/vendor/laravel/framework/src/Illuminate/Database/Connection.php","line":742,"url":"https://lychee.local/api/albums/delete","method":"DELETE"} +``` + +## Troubleshooting Timeouts + +When you see timeout logs: + +1. **Check the SQL query** - Look for missing indexes, inefficient joins, or full table scans +2. **Use EXPLAIN** - Enable `DB_LOG_SQL_EXPLAIN=true` to see query execution plans +3. **Add indexes** - Common fixes involve adding database indexes +4. **Optimize queries** - Rewrite queries to be more efficient +5. **Increase timeout** - As a last resort, increase `max_execution_time` in `config/octane.php` +6. **Use queues** - Move long-running operations to background jobs + +## Performance Impact + +SQL logging has minimal performance impact when disabled. When enabled: +- Each query execution triggers event listeners +- EXPLAIN queries add overhead for SELECT statements (MySQL only) +- Logs are written asynchronously via Monolog + +**Recommendation**: Only enable in development or temporarily in production for debugging. + +## Related Configuration + +### Database Connection Timeouts + +MySQL connection settings in [config/database.php:111-113](config/database.php#L111-L113): + +```php +PDO::ATTR_TIMEOUT => 5, // Connection timeout (5 seconds) +PDO::MYSQL_ATTR_INIT_COMMAND => 'SET SESSION wait_timeout=28800', // 8 hours +``` + +### Octane Database Ping + +The AppServiceProvider pings database connections every 30 seconds to prevent timeouts: [app/Providers/AppServiceProvider.php:340-341](app/Providers/AppServiceProvider.php#L340-L341) + +## Viewing Logs + +Logs can be viewed via: +1. **Log Viewer** - Built-in at `/log-viewer` (requires admin access) +2. **Command line**: `tail -f storage/logs/errors.log` +3. **Docker**: `docker logs ` + +## Additional Notes + +- Timeout detection works best with FrankenPHP, Swoole, or RoadRunner +- Traditional PHP-FPM may not trigger all timeout handlers consistently From dd99f51c416e43468114a218cadbf96f3db5e5bf Mon Sep 17 00:00:00 2001 From: ildyria Date: Mon, 5 Jan 2026 12:23:56 +0100 Subject: [PATCH 2/3] improve coverage and fix issues --- app/Listeners/LogQueryTimeout.php | 10 --- app/Providers/AppServiceProvider.php | 3 +- app/Providers/EventServiceProvider.php | 2 + docs/specs/2-how-to/sql-timeout-logging.md | 2 +- tests/Unit/Listeners/LogQueryTimeoutTest.php | 82 ++++++++++++++++++++ 5 files changed, 87 insertions(+), 12 deletions(-) create mode 100644 tests/Unit/Listeners/LogQueryTimeoutTest.php diff --git a/app/Listeners/LogQueryTimeout.php b/app/Listeners/LogQueryTimeout.php index 737dea479b9..6f94b0d7e1f 100644 --- a/app/Listeners/LogQueryTimeout.php +++ b/app/Listeners/LogQueryTimeout.php @@ -9,7 +9,6 @@ namespace App\Listeners; use Illuminate\Database\Events\QueryExecuted; -use Illuminate\Support\Facades\Cache; use Illuminate\Support\Facades\Log; /** @@ -20,8 +19,6 @@ */ class LogQueryTimeout { - private const CACHE_PREFIX = 'query_tracking_'; - /** * Handle the event when a query is executed. * @@ -35,13 +32,6 @@ public function handle(QueryExecuted $event): void $critical_threshold = $max_execution_time * 0.9; // 90% of timeout $warning_threshold = $max_execution_time * 0.7; // 70% of timeout - // Generate a unique key for this query - $query_hash = md5($event->sql . serialize($event->bindings)); - $cache_key = self::CACHE_PREFIX . $query_hash; - - // Remove from cache (it completed) - Cache::forget($cache_key); - // Log if query is dangerously slow if ($event->time >= $critical_threshold) { Log::error('🚨 CRITICAL: Query approaching timeout', [ diff --git a/app/Providers/AppServiceProvider.php b/app/Providers/AppServiceProvider.php index 6133d9d42ba..dd01e8604e9 100644 --- a/app/Providers/AppServiceProvider.php +++ b/app/Providers/AppServiceProvider.php @@ -259,9 +259,10 @@ private function registerLoggerAccess(): void */ private function logSQLStart(string $sql, array $bindings, string $connection): void { + $uri = request()?->getRequestUri() ?? ''; // Quick exit if ( - Str::contains(request()->getRequestUri(), 'logs', true) || + Str::contains($uri, 'logs', true) || Str::contains($sql, $this->ignore_log_SQL) ) { return; diff --git a/app/Providers/EventServiceProvider.php b/app/Providers/EventServiceProvider.php index ff62f914f68..4e6dab0a795 100644 --- a/app/Providers/EventServiceProvider.php +++ b/app/Providers/EventServiceProvider.php @@ -94,9 +94,11 @@ public function boot(): void Event::listen(TaggedRouteCacheUpdated::class, TaggedRouteCacheCleaner::class . '@handle'); // Log slow/timeout SQL queries when DB_LOG_SQL is enabled + // @codeCoverageIgnoreStart if (config('database.db_log_sql', false) === true) { Event::listen(QueryExecuted::class, LogQueryTimeout::class . '@handle'); } + // @codeCoverageIgnoreEnd Event::listen(AlbumDownload::class, MetricsListener::class . '@handle'); Event::listen(AlbumShared::class, MetricsListener::class . '@handle'); diff --git a/docs/specs/2-how-to/sql-timeout-logging.md b/docs/specs/2-how-to/sql-timeout-logging.md index dc05cb64deb..414d7619acb 100644 --- a/docs/specs/2-how-to/sql-timeout-logging.md +++ b/docs/specs/2-how-to/sql-timeout-logging.md @@ -46,7 +46,7 @@ The max execution time is configured in `config/octane.php`: The `logSQL()` method logs queries after they complete with severity based on execution time: - **Debug**: Normal slow queries (>100ms) - **Warning**: Queries taking >1 second -- **Error**: Queries approaching timeout (>80% of max_execution_time) +- **Error**: Queries approaching timeout (>90% of max_execution_time) ### 2. Timeout Detection Listener diff --git a/tests/Unit/Listeners/LogQueryTimeoutTest.php b/tests/Unit/Listeners/LogQueryTimeoutTest.php new file mode 100644 index 00000000000..03dba65d82f --- /dev/null +++ b/tests/Unit/Listeners/LogQueryTimeoutTest.php @@ -0,0 +1,82 @@ +never(); + Log::shouldReceive('warning')->never(); + + Config::set('octane.max_execution_time', 30); + + $listener = new LogQueryTimeout(); + $event = new QueryExecuted( + 'SELECT * FROM users', + [], + 10000, // 10 seconds (below 70% of 30s = 21s) + new \Illuminate\Database\Connection(new \PDO('sqlite::memory:')) + ); + + $listener->handle($event); + } + + public function testQueryAtWarningThreshold(): void + { + Log::shouldReceive('error')->never(); + Log::shouldReceive('warning')->once()->with('⚠️ WARNING: Slow query detected', \Mockery::type('array')); + + Config::set('octane.max_execution_time', 30); + + $listener = new LogQueryTimeout(); + $event = new QueryExecuted( + 'SELECT * FROM large_table', + ['param1'], + 22000, // 22 seconds (above 70% of 30s = 21s, below 90% = 27s) + new \Illuminate\Database\Connection(new \PDO('sqlite::memory:')) + ); + + $listener->handle($event); + } + + public function testQueryAtCriticalThreshold(): void + { + Log::shouldReceive('warning')->never(); + Log::shouldReceive('error')->once()->with('🚨 CRITICAL: Query approaching timeout', \Mockery::type('array')); + + Config::set('octane.max_execution_time', 30); + + $listener = new LogQueryTimeout(); + $event = new QueryExecuted( + 'SELECT * FROM very_large_table', + ['param1', 'param2'], + 28000, // 28 seconds (above 90% of 30s = 27s) + new \Illuminate\Database\Connection(new \PDO('sqlite::memory:')) + ); + + $listener->handle($event); + } +} From 460a2b7c6f14c355c10088389bf56296abb3e913 Mon Sep 17 00:00:00 2001 From: ildyria Date: Mon, 5 Jan 2026 12:33:24 +0100 Subject: [PATCH 3/3] fix documentation --- docs/specs/2-how-to/sql-timeout-logging.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/specs/2-how-to/sql-timeout-logging.md b/docs/specs/2-how-to/sql-timeout-logging.md index 414d7619acb..4cceec091f0 100644 --- a/docs/specs/2-how-to/sql-timeout-logging.md +++ b/docs/specs/2-how-to/sql-timeout-logging.md @@ -71,8 +71,8 @@ A shutdown function that catches when PHP times out entirely, logging: Logs are written to different files based on severity: -- `storage/logs/errors.log` - Critical/slow queries (>80% timeout) -- `storage/logs/warning.log` - Slow queries (>70% timeout or >1s) +- `storage/logs/errors.log` - Critical/slow queries (>90% timeout) +- `storage/logs/warning.log` - Slow queries (>80% timeout or >1s) - `storage/logs/daily.log` - All SQL queries (when DB_LOG_SQL=true) ## Example Log Entries