Skip to content

Commit 1326621

Browse files
paulbalandanpaulbalandan
authored
feat: uniform rendering of stack trace from failed DB operations (#9677)
* Add `render_backtrace()` function * Add structured trace for all DB drivers * Add changelog
1 parent e6dcf5b commit 1326621

File tree

13 files changed

+187
-75
lines changed

13 files changed

+187
-75
lines changed

‎system/Common.php‎

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -941,6 +941,57 @@ function remove_invisible_characters(string $str, bool $urlEncoded = true): stri
941941
}
942942
}
943943

944+
if (! function_exists('render_backtrace')) {
945+
/**
946+
* Renders a backtrace in a nice string format.
947+
*
948+
* @param list<array{
949+
* file?: string,
950+
* line?: int,
951+
* class?: string,
952+
* type?: string,
953+
* function: string,
954+
* args?: list<mixed>
955+
* }> $backtrace
956+
*/
957+
function render_backtrace(array $backtrace): string
958+
{
959+
$backtraces = [];
960+
961+
foreach ($backtrace as $index => $trace) {
962+
$frame = $trace + ['file' => '[internal function]', 'line' => 0, 'class' => '', 'type' => '', 'args' => []];
963+
964+
if ($frame['file'] !== '[internal function]') {
965+
$frame['file'] = sprintf('%s(%s)', $frame['file'], $frame['line']);
966+
}
967+
968+
unset($frame['line']);
969+
$idx = $index;
970+
$idx = str_pad((string) ++$idx, 2, ' ', STR_PAD_LEFT);
971+
972+
$args = implode(', ', array_map(static fn ($value): string => match (true) {
973+
is_object($value) => sprintf('Object(%s)', $value::class),
974+
is_array($value) => $value !== [] ? '[...]' : '[]',
975+
$value === null => 'null',
976+
is_resource($value) => sprintf('resource (%s)', get_resource_type($value)),
977+
default => var_export($value, true),
978+
}, $frame['args']));
979+
980+
$backtraces[] = sprintf(
981+
'%s %s: %s%s%s(%s)',
982+
$idx,
983+
clean_path($frame['file']),
984+
$frame['class'],
985+
$frame['type'],
986+
$frame['function'],
987+
$args,
988+
);
989+
}
990+
991+
return implode("\n", $backtraces);
992+
}
993+
}
994+
944995
if (! function_exists('request')) {
945996
/**
946997
* Returns the shared Request.

‎system/Database/MySQLi/Connection.php‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -326,7 +326,12 @@ protected function execute(string $sql)
326326
try {
327327
return $this->connID->query($this->prepQuery($sql), $this->resultMode);
328328
} catch (mysqli_sql_exception $e) {
329-
log_message('error', (string) $e);
329+
log_message('error', "{message}\nin {exFile} on line {exLine}.\n{trace}", [
330+
'message' => $e->getMessage(),
331+
'exFile' => clean_path($e->getFile()),
332+
'exLine' => $e->getLine(),
333+
'trace' => render_backtrace($e->getTrace()),
334+
]);
330335

331336
if ($this->DBDebug) {
332337
throw new DatabaseException($e->getMessage(), $e->getCode(), $e);

‎system/Database/OCI8/Connection.php‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -231,7 +231,14 @@ protected function execute(string $sql)
231231

232232
return $result;
233233
} catch (ErrorException $e) {
234-
log_message('error', (string) $e);
234+
$trace = array_slice($e->getTrace(), 2); // remove call to error handler
235+
236+
log_message('error', "{message}\nin {exFile} on line {exLine}.\n{trace}", [
237+
'message' => $e->getMessage(),
238+
'exFile' => clean_path($e->getFile()),
239+
'exLine' => $e->getLine(),
240+
'trace' => render_backtrace($trace),
241+
]);
235242

236243
if ($this->DBDebug) {
237244
throw new DatabaseException($e->getMessage(), $e->getCode(), $e);

‎system/Database/Postgre/Connection.php‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -205,7 +205,14 @@ protected function execute(string $sql)
205205
try {
206206
return pg_query($this->connID, $sql);
207207
} catch (ErrorException $e) {
208-
log_message('error', (string) $e);
208+
$trace = array_slice($e->getTrace(), 2); // remove the call to error handler
209+
210+
log_message('error', "{message}\nin {exFile} on line {exLine}.\n{trace}", [
211+
'message' => $e->getMessage(),
212+
'exFile' => clean_path($e->getFile()),
213+
'exLine' => $e->getLine(),
214+
'trace' => render_backtrace($trace),
215+
]);
209216

210217
if ($this->DBDebug) {
211218
throw new DatabaseException($e->getMessage(), $e->getCode(), $e);

‎system/Database/SQLSRV/Connection.php‎

Lines changed: 18 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -155,8 +155,12 @@ public function getAllErrorMessages(): string
155155
$errors = [];
156156

157157
foreach (sqlsrv_errors() as $error) {
158-
$errors[] = $error['message']
159-
. ' SQLSTATE: ' . $error['SQLSTATE'] . ', code: ' . $error['code'];
158+
$errors[] = sprintf(
159+
'%s SQLSTATE: %s, code: %s',
160+
$error['message'],
161+
$error['SQLSTATE'],
162+
$error['code'],
163+
);
160164
}
161165

162166
return implode("\n", $errors);
@@ -522,17 +526,23 @@ public function setDatabase(?string $databaseName = null)
522526
*/
523527
protected function execute(string $sql)
524528
{
525-
$stmt = ($this->scrollable === false || $this->isWriteType($sql)) ?
526-
sqlsrv_query($this->connID, $sql) :
527-
sqlsrv_query($this->connID, $sql, [], ['Scrollable' => $this->scrollable]);
529+
$stmt = ($this->scrollable === false || $this->isWriteType($sql))
530+
? sqlsrv_query($this->connID, $sql)
531+
: sqlsrv_query($this->connID, $sql, [], ['Scrollable' => $this->scrollable]);
528532

529533
if ($stmt === false) {
530-
$error = $this->error();
534+
$trace = debug_backtrace();
535+
$first = array_shift($trace);
531536

532-
log_message('error', $error['message']);
537+
log_message('error', "{message}\nin {exFile} on line {exLine}.\n{trace}", [
538+
'message' => $this->getAllErrorMessages(),
539+
'exFile' => clean_path($first['file']),
540+
'exLine' => $first['line'],
541+
'trace' => render_backtrace($trace),
542+
]);
533543

534544
if ($this->DBDebug) {
535-
throw new DatabaseException($error['message']);
545+
throw new DatabaseException($this->getAllErrorMessages());
536546
}
537547
}
538548

‎system/Database/SQLite3/Connection.php‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -175,7 +175,12 @@ protected function execute(string $sql)
175175
? $this->connID->exec($sql)
176176
: $this->connID->query($sql);
177177
} catch (Exception $e) {
178-
log_message('error', (string) $e);
178+
log_message('error', "{message}\nin {exFile} on line {exLine}.\n{trace}", [
179+
'message' => $e->getMessage(),
180+
'exFile' => clean_path($e->getFile()),
181+
'exLine' => $e->getLine(),
182+
'trace' => render_backtrace($e->getTrace()),
183+
]);
179184

180185
if ($this->DBDebug) {
181186
throw new DatabaseException($e->getMessage(), $e->getCode(), $e);

‎system/Debug/Exceptions.php‎

Lines changed: 3 additions & 40 deletions
Original file line numberDiff line numberDiff line change
@@ -136,7 +136,7 @@ public function exceptionHandler(Throwable $exception)
136136
'routeInfo' => $routeInfo,
137137
'exFile' => clean_path($exception->getFile()), // {file} refers to THIS file
138138
'exLine' => $exception->getLine(), // {line} refers to THIS line
139-
'trace' => self::renderBacktrace($exception->getTrace()),
139+
'trace' => render_backtrace($exception->getTrace()),
140140
]);
141141

142142
// Get the first exception.
@@ -149,7 +149,7 @@ public function exceptionHandler(Throwable $exception)
149149
'message' => $prevException->getMessage(),
150150
'exFile' => clean_path($prevException->getFile()), // {file} refers to THIS file
151151
'exLine' => $prevException->getLine(), // {line} refers to THIS line
152-
'trace' => self::renderBacktrace($prevException->getTrace()),
152+
'trace' => render_backtrace($prevException->getTrace()),
153153
]);
154154
}
155155
}
@@ -527,7 +527,7 @@ private function handleDeprecationError(string $message, ?string $file = null, ?
527527
'message' => $message,
528528
'errFile' => clean_path($file ?? ''),
529529
'errLine' => $line ?? 0,
530-
'trace' => self::renderBacktrace($trace),
530+
'trace' => render_backtrace($trace),
531531
],
532532
);
533533

@@ -646,41 +646,4 @@ public static function highlightFile(string $file, int $lineNumber, int $lines =
646646

647647
return '<pre><code>' . $out . '</code></pre>';
648648
}
649-
650-
private static function renderBacktrace(array $backtrace): string
651-
{
652-
$backtraces = [];
653-
654-
foreach ($backtrace as $index => $trace) {
655-
$frame = $trace + ['file' => '[internal function]', 'line' => '', 'class' => '', 'type' => '', 'args' => []];
656-
657-
if ($frame['file'] !== '[internal function]') {
658-
$frame['file'] = sprintf('%s(%s)', $frame['file'], $frame['line']);
659-
}
660-
661-
unset($frame['line']);
662-
$idx = $index;
663-
$idx = str_pad((string) ++$idx, 2, ' ', STR_PAD_LEFT);
664-
665-
$args = implode(', ', array_map(static fn ($value): string => match (true) {
666-
is_object($value) => sprintf('Object(%s)', $value::class),
667-
is_array($value) => $value !== [] ? '[...]' : '[]',
668-
$value === null => 'null',
669-
is_resource($value) => sprintf('resource (%s)', get_resource_type($value)),
670-
default => var_export($value, true),
671-
}, $frame['args']));
672-
673-
$backtraces[] = sprintf(
674-
'%s %s: %s%s%s(%s)',
675-
$idx,
676-
clean_path($frame['file']),
677-
$frame['class'],
678-
$frame['type'],
679-
$frame['function'],
680-
$args,
681-
);
682-
}
683-
684-
return implode("\n", $backtraces);
685-
}
686649
}

‎tests/system/CommonFunctionsTest.php‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -805,4 +805,14 @@ public function testIsWindowsUsingMock(): void
805805
$this->assertSame(str_contains(php_uname(), 'Windows'), is_windows());
806806
$this->assertSame(defined('PHP_WINDOWS_VERSION_MAJOR'), is_windows());
807807
}
808+
809+
public function testRenderBacktrace(): void
810+
{
811+
$trace = (new RuntimeException('Test exception'))->getTrace();
812+
$renders = explode("\n", render_backtrace($trace));
813+
814+
foreach ($renders as $render) {
815+
$this->assertMatchesRegularExpression('/^\s*\d* .+(?:\(\d+\))?: \S+(?:(?:\->|::)\S+)?\(.*\)$/', $render);
816+
}
817+
}
808818
}

‎tests/system/Database/Live/ExecuteLogMessageFormatTest.php‎

Lines changed: 73 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,73 @@
1+
<?php
2+
3+
declare(strict_types=1);
4+
5+
/**
6+
* This file is part of CodeIgniter 4 framework.
7+
*
8+
* (c) CodeIgniter Foundation <admin@codeigniter.com>
9+
*
10+
* For the full copyright and license information, please view
11+
* the LICENSE file that was distributed with this source code.
12+
*/
13+
14+
namespace CodeIgniter\Database\Live;
15+
16+
use CodeIgniter\Test\CIUnitTestCase;
17+
use CodeIgniter\Test\TestLogger;
18+
use Config\Database;
19+
use PHPUnit\Framework\Attributes\Group;
20+
21+
/**
22+
* @internal
23+
*/
24+
#[Group('DatabaseLive')]
25+
final class ExecuteLogMessageFormatTest extends CIUnitTestCase
26+
{
27+
protected function setUp(): void
28+
{
29+
parent::setUp();
30+
31+
self::setPrivateProperty(TestLogger::class, 'op_logs', []);
32+
}
33+
34+
protected function tearDown(): void
35+
{
36+
parent::tearDown();
37+
38+
self::setPrivateProperty(TestLogger::class, 'op_logs', []);
39+
}
40+
41+
public function testLogMessageWhenExecuteFailsShowFullStructuredBacktrace(): void
42+
{
43+
$db = Database::connect('tests', false);
44+
self::setPrivateProperty($db, 'DBDebug', false);
45+
46+
$sql = 'SELECT * FROM some_table WHERE id = ? AND status = ? AND author = ?';
47+
$db->query($sql, [3, 'live', 'Rick']);
48+
49+
$pattern = match ($db->DBDriver) {
50+
'MySQLi' => '/Table \'test\.some_table\' doesn\'t exist/',
51+
'Postgre' => '/pg_query\(\): Query failed: ERROR: relation "some_table" does not exist/',
52+
'SQLite3' => '/Unable to prepare statement:\s(\d+,\s)?no such table: some_table/',
53+
'OCI8' => '/oci_execute\(\): ORA-00942: table or view does not exist/',
54+
'SQLSRV' => '/\[Microsoft\]\[ODBC Driver \d+ for SQL Server\]\[SQL Server\]Invalid object name \'some_table\'/',
55+
default => '/Unknown DB error/',
56+
};
57+
$messageFromLogs = explode("\n", self::getPrivateProperty(TestLogger::class, 'op_logs')[0]['message']);
58+
59+
$this->assertMatchesRegularExpression($pattern, array_shift($messageFromLogs));
60+
61+
if ($db->DBDriver === 'Postgre') {
62+
$messageFromLogs = array_slice($messageFromLogs, 2);
63+
} elseif ($db->DBDriver === 'OCI8') {
64+
$messageFromLogs = array_slice($messageFromLogs, 1);
65+
}
66+
67+
$this->assertMatchesRegularExpression('/^in \S+ on line \d+\.$/', array_shift($messageFromLogs));
68+
69+
foreach ($messageFromLogs as $line) {
70+
$this->assertMatchesRegularExpression('/^\s*\d* .+(?:\(\d+\))?: \S+(?:(?:\->|::)\S+)?\(.*\)$/', $line);
71+
}
72+
}
73+
}

‎tests/system/Debug/ExceptionsTest.php‎

Lines changed: 0 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -128,22 +128,6 @@ public function testDetermineCodes(): void
128128
$this->assertSame([500, EXIT_DATABASE], $determineCodes(new DatabaseException('This.')));
129129
}
130130

131-
public function testRenderBacktrace(): void
132-
{
133-
$renderer = self::getPrivateMethodInvoker(Exceptions::class, 'renderBacktrace');
134-
$exception = new RuntimeException('This.');
135-
136-
$renderedBacktrace = $renderer($exception->getTrace());
137-
$renderedBacktrace = explode("\n", $renderedBacktrace);
138-
139-
foreach ($renderedBacktrace as $trace) {
140-
$this->assertMatchesRegularExpression(
141-
'/^\s*\d* .+(?:\(\d+\))?: \S+(?:(?:\->|::)\S+)?\(.*\)$/',
142-
$trace,
143-
);
144-
}
145-
}
146-
147131
public function testMaskSensitiveData(): void
148132
{
149133
$maskSensitiveData = self::getPrivateMethodInvoker($this->exception, 'maskSensitiveData');

0 commit comments

Comments
 (0)