Add query logging (#3934)

ildyria · web-flow · commit 61ad72ab06ab · 2026-01-05T13:27:23.000+01:00
diff --git a/app/Listeners/LogQueryTimeout.php b/app/Listeners/LogQueryTimeout.php
@@ -0,0 +1,60 @@
+<?php
+
+/**
+ * SPDX-License-Identifier: MIT
+ * Copyright (c) 2017-2018 Tobias Reich
+ * Copyright (c) 2018-2026 LycheeOrg.
+ */
+
+namespace App\Listeners;
+
+use Illuminate\Database\Events\QueryExecuted;
+use Illuminate\Support\Facades\Log;
+
+/**
+ * Tracks long-running SQL queries that may timeout.
+ *
+ * This listener works by storing query start information in cache
+ * and checking execution time after completion.
+ */
+class LogQueryTimeout
+{
+	/**
+	 * Handle the event when a query is executed.
+	 *
+	 * @param QueryExecuted $event
+	 *
+	 * @return void
+	 */
+	public function handle(QueryExecuted $event): void
+	{
+		$max_execution_time = config('octane.max_execution_time', 30) * 1000; // convert to ms
+		$critical_threshold = $max_execution_time * 0.9; // 90% of timeout
+		$warning_threshold = $max_execution_time * 0.7; // 70% of timeout
+
+		// 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
@@ -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,52 @@ private function registerLoggerAccess(): void
 		});
 	}
 
+	/**
+	 * @codeCoverageIgnore
+	 */
+	private function logSQLStart(string $sql, array $bindings, string $connection): void
+	{
+		$uri = request()?->getRequestUri() ?? '';
+		// Quick exit
+		if (
+			Str::contains($uri, '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
@@ -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,13 @@ 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
+		// @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');
 		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
@@ -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 (>90% 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 (>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
+
+### 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 <container_name>`
+
+## Additional Notes
+
+- Timeout detection works best with FrankenPHP, Swoole, or RoadRunner
+- Traditional PHP-FPM may not trigger all timeout handlers consistently
diff --git a/tests/Unit/Listeners/LogQueryTimeoutTest.php b/tests/Unit/Listeners/LogQueryTimeoutTest.php
@@ -0,0 +1,82 @@
+<?php
+
+/**
+ * SPDX-License-Identifier: MIT
+ * Copyright (c) 2017-2018 Tobias Reich
+ * Copyright (c) 2018-2026 LycheeOrg.
+ */
+
+/**
+ * We don't care for unhandled exceptions in tests.
+ * It is the nature of a test to throw an exception.
+ * Without this suppression we had 100+ Linter warning in this file which
+ * don't help anything.
+ *
+ * @noinspection PhpDocMissingThrowsInspection
+ * @noinspection PhpUnhandledExceptionInspection
+ */
+
+namespace Tests\Unit\Listeners;
+
+use App\Listeners\LogQueryTimeout;
+use Illuminate\Database\Events\QueryExecuted;
+use Illuminate\Support\Facades\Config;
+use Illuminate\Support\Facades\Log;
+use Tests\AbstractTestCase;
+
+class LogQueryTimeoutTest extends AbstractTestCase
+{
+	public function testQueryBelowWarningThreshold(): void
+	{
+		Log::shouldReceive('error')->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);
+	}
+}
