Skip to content

Commit 1e8fa66

Browse files
bukkabukka
committed
Rework FPM tests logging for better debugging
1 parent 3477499 commit 1e8fa66

11 files changed

+1356
-698
lines changed

‎sapi/fpm/tests/bug74083-concurrent-reload.phpt‎

Lines changed: 3 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -50,17 +50,11 @@ for ($interval = 0; $interval < $max_interval; $interval += $step) {
5050
usleep($interval);
5151
}
5252
echo "Reached interval $interval us with $step us steps\n";
53-
$tester->expectLogNotice('Reloading in progress ...');
54-
/* Consume mix of 'Reloading in progress ...' and 'reloading: .*' */
55-
$tester->getLogLines(2000);
53+
$tester->readAllLogNotices('Reloading in progress ...');
5654

57-
$tester->signal('USR2');
58-
$tester->expectLogNotice('Reloading in progress ...');
59-
$tester->expectLogNotice('reloading: .*');
60-
$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
61-
$tester->expectLogStartNotices();
55+
$tester->reload();
56+
$tester->expectLogReloadingNotices();
6257
$tester->ping('{{ADDR}}');
63-
6458
$tester->terminate();
6559
$tester->expectLogTerminatingNotices();
6660
$tester->close();

‎sapi/fpm/tests/bug76601-reload-child-signals.phpt‎

Lines changed: 3 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -63,18 +63,10 @@ for ($interval = 0; $interval < $max_interval; $interval += $step) {
6363
echo "Reached interval $interval us with $step us steps\n";
6464
$tester->expectLogNotice('Reloading in progress ...');
6565
/* Consume mix of 'Reloading in progress ...' and 'reloading: .*' */
66-
$skipped = $tester->getLogLines(2000);
66+
$tester->readAllLogNotices('Reloading in progress ...');
6767

68-
$tester->signal('USR2');
69-
$tester->expectLogNotice('Reloading in progress ...');
70-
/* When a child ignores SIGQUIT, the following expectation fails due to timeout. */
71-
if (!$tester->expectLogNotice('reloading: .*')) {
72-
/* for troubleshooting */
73-
echo "Skipped messages\n";
74-
echo implode('', $skipped);
75-
}
76-
$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
77-
$tester->expectLogStartNotices();
68+
$tester->reload();
69+
$tester->expectLogReloadingNotices();
7870

7971
$tester->terminate();
8072
$tester->expectLogTerminatingNotices();

‎sapi/fpm/tests/gh8885-stderr-fd-reload-usr1.phpt‎

Lines changed: 18 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
--TEST--
2-
FPM: GH-8885 - access.log with stderr begins to write logs to error_log after daemon reload
2+
FPM: GH-8885 - access.log with stderr begins to write logs to error_log after reloading logs
33
--SKIPIF--
44
<?php
55
include "skipif.inc";
@@ -26,60 +26,25 @@ pm.min_spare_servers = 1
2626
pm.max_spare_servers = 3
2727
EOT;
2828

29-
// php-fpm must not be launched with --force-stderr option
30-
$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
31-
// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
32-
$errorLogFile = $tester->getPrefixedFile('err.log');
33-
34-
$tester->start();
35-
$tester->expectNoLogMessages();
36-
37-
$content = file_get_contents($errorLogFile);
38-
assert($content !== false && strlen($content) > 0, 'File must not be empty');
39-
40-
$errorLogLines = explode("\n", $content);
41-
array_pop($errorLogLines);
42-
43-
assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
44-
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
45-
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
46-
47-
$tester->ping('{{ADDR}}');
48-
$stderrLines = $tester->getLogLines(-1);
49-
assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
50-
$stderrLine = $stderrLines[0];
51-
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
52-
53-
$tester->signal('USR1');
29+
$tester = new FPM\Tester($cfg);
30+
$tester->start(forceStderr: false);
5431
$tester->expectNoLogMessages();
55-
56-
$content = file_get_contents($errorLogFile);
57-
assert($content !== false && strlen($content) > 0, 'File must not be empty');
58-
$errorLogLines = explode("\n", $content);
59-
array_pop($errorLogLines);
60-
61-
assert(count($errorLogLines) >= 4, 'Expected at least 4 records in the error_log file');
62-
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
63-
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
64-
assert(strpos($errorLogLines[2], 'NOTICE: error log file re-opened'));
65-
assert(strpos($errorLogLines[3], 'NOTICE: access log file re-opened'));
66-
67-
68-
$tester->ping('{{ADDR}}');
69-
$stderrLines = $tester->getLogLines(-1);
70-
assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
71-
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
72-
32+
$tester->switchLogSource('{{FILE:LOG}}');
33+
$tester->expectLogStartNotices();
34+
$tester->ping();
35+
$tester->switchLogSource('{{MASTER:OUT}}');
36+
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
37+
$tester->reloadLogs();
38+
$tester->switchLogSource('{{FILE:LOG}}');
39+
$tester->expectLogReloadingLogsNotices();
40+
$tester->ping();
41+
$tester->switchLogSource('{{MASTER:OUT}}');
42+
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
43+
$tester->switchLogSource('{{FILE:LOG}}');
7344
$tester->terminate();
74-
$stderrLines = $tester->expectNoLogMessages();
75-
76-
$content = file_get_contents($errorLogFile);
77-
assert($content !== false && strlen($content) > 0, 'File must not be empty');
78-
$errorLogLines = explode("\n", $content);
79-
array_pop($errorLogLines);
80-
$errorLogLastLine = array_pop($errorLogLines);
81-
assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
82-
45+
$tester->expectLogTerminatingNotices();
46+
$tester->switchLogSource('{{MASTER:OUT}}');
47+
$tester->expectNoLogMessages();
8348
$tester->close();
8449
?>
8550
Done

‎sapi/fpm/tests/gh8885-stderr-fd-reload-usr2.phpt‎

Lines changed: 17 additions & 52 deletions
Original file line numberDiff line numberDiff line change
@@ -26,60 +26,25 @@ pm.min_spare_servers = 1
2626
pm.max_spare_servers = 3
2727
EOT;
2828

29-
// php-fpm must not be launched with --force-stderr option
30-
$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
31-
// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
32-
$errorLogFile = $tester->getPrefixedFile('err.log');
33-
34-
$tester->start();
29+
$tester = new FPM\Tester($cfg);
30+
$tester->start(forceStderr: false);
3531
$tester->expectNoLogMessages();
36-
37-
$content = file_get_contents($errorLogFile);
38-
assert($content !== false && strlen($content) > 0, 'File must not be empty');
39-
40-
$errorLogLines = explode("\n", $content);
41-
array_pop($errorLogLines);
42-
43-
assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
44-
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
45-
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
46-
47-
$tester->ping('{{ADDR}}');
48-
$stderrLines = $tester->getLogLines(-1);
49-
assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
50-
$stderrLine = $stderrLines[0];
51-
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
52-
53-
$tester->signal('USR2');
54-
$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
55-
56-
$content = file_get_contents($errorLogFile);
57-
assert($content !== false && strlen($content) > 0, 'File must not be empty');
58-
$errorLogLines = explode("\n", $content);
59-
array_pop($errorLogLines);
60-
61-
assert(count($errorLogLines) >= 5, 'Expected at least 5 records in the error_log file');
62-
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
63-
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
64-
assert(strpos($errorLogLines[2], 'NOTICE: Reloading in progress'));
65-
assert(strpos($errorLogLines[3], 'NOTICE: reloading: execvp'));
66-
assert(strpos($errorLogLines[4], 'NOTICE: using inherited socket'));
67-
68-
$tester->ping('{{ADDR}}');
69-
$stderrLines = $tester->getLogLines(-1);
70-
assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
71-
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
72-
32+
$tester->switchLogSource('{{FILE:LOG}}');
33+
$tester->expectLogStartNotices();
34+
$tester->ping();
35+
$tester->switchLogSource('{{MASTER:OUT}}');
36+
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
37+
$tester->reload();
38+
$tester->switchLogSource('{{FILE:LOG}}');
39+
$tester->expectLogReloadingNotices();
40+
$tester->ping();
41+
$tester->switchLogSource('{{MASTER:OUT}}');
42+
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
43+
$tester->switchLogSource('{{FILE:LOG}}');
7344
$tester->terminate();
74-
$stderrLines = $tester->expectNoLogMessages();
75-
76-
$content = file_get_contents($errorLogFile);
77-
assert($content !== false && strlen($content) > 0, 'File must not be empty');
78-
$errorLogLines = explode("\n", $content);
79-
array_pop($errorLogLines);
80-
$errorLogLastLine = array_pop($errorLogLines);
81-
assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
82-
45+
$tester->expectLogTerminatingNotices();
46+
$tester->switchLogSource('{{MASTER:OUT}}');
47+
$tester->expectNoLogMessages();
8348
$tester->close();
8449
?>
8550
Done

‎sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt‎

Lines changed: 2 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -30,18 +30,15 @@ $tester = new FPM\Tester($cfg, $code);
3030
$tester->start();
3131
$tester->expectLogStartNotices();
3232
$tester->request()->expectEmptyBody();
33-
$lines = $tester->getLogLines(2);
34-
var_dump($lines[0] === str_repeat('a', 1021) . "\0f\n");
35-
var_dump($lines[1] === "abc\n");
33+
$tester->expectLogLine(str_repeat('a', 1021) . "\0f", decorated: false);
34+
$tester->expectLogLine("abc", decorated: false);
3635
$tester->terminate();
3736
$tester->expectLogTerminatingNotices();
3837
$tester->close();
3938

4039
?>
4140
Done
4241
--EXPECT--
43-
bool(true)
44-
bool(true)
4542
Done
4643
--CLEAN--
4744
<?php

‎sapi/fpm/tests/log-bwp-msg-flush-split-real.phpt‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,13 +31,12 @@ $tester->start();
3131
$tester->expectLogStartNotices();
3232
$tester->request()->expectEmptyBody();
3333
$tester->terminate();
34-
var_dump($tester->getLastLogLine() === str_repeat('a', 1022) . "\n");
34+
$tester->expectLogLine(str_repeat('a', 1022), decorated: false);
3535
$tester->close();
3636

3737
?>
3838
Done
3939
--EXPECT--
40-
bool(true)
4140
Done
4241
--CLEAN--
4342
<?php

‎sapi/fpm/tests/log-bwp-realloc-buffer.phpt‎

Lines changed: 3 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -33,17 +33,14 @@ $tester->start();
3333
$tester->expectLogStartNotices();
3434
$tester->request()->expectEmptyBody();
3535
$tester->terminate();
36-
var_dump($tester->getLastLogLine() === str_repeat('a', 100) . str_repeat('b', 923) . "\n");
37-
var_dump($tester->getLastLogLine() === str_repeat('b', 1023) . "\n");
38-
var_dump($tester->getLastLogLine() === str_repeat('b', 554) . "\n");
36+
$tester->expectLogLine(str_repeat('a', 100) . str_repeat('b', 923), decorated: false);
37+
$tester->expectLogLine(str_repeat('b', 1023), decorated: false);
38+
$tester->expectLogLine(str_repeat('b', 554), decorated: false);
3939
$tester->close();
4040

4141
?>
4242
Done
4343
--EXPECT--
44-
bool(true)
45-
bool(true)
46-
bool(true)
4744
Done
4845
--CLEAN--
4946
<?php

0 commit comments

Comments
 (0)