Rework FPM tests logging for better debugging

This commit is contained in:
Jakub Zelenka 2022-09-04 18:53:15 +01:00
parent 3477499d26
commit 1e8fa6607d
No known key found for this signature in database
GPG Key ID: 1C0779DC5C0A9DE4
11 changed files with 1360 additions and 702 deletions

View File

@ -50,17 +50,11 @@ for ($interval = 0; $interval < $max_interval; $interval += $step) {
usleep($interval);
}
echo "Reached interval $interval us with $step us steps\n";
$tester->expectLogNotice('Reloading in progress ...');
/* Consume mix of 'Reloading in progress ...' and 'reloading: .*' */
$tester->getLogLines(2000);
$tester->readAllLogNotices('Reloading in progress ...');
$tester->signal('USR2');
$tester->expectLogNotice('Reloading in progress ...');
$tester->expectLogNotice('reloading: .*');
$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
$tester->expectLogStartNotices();
$tester->reload();
$tester->expectLogReloadingNotices();
$tester->ping('{{ADDR}}');
$tester->terminate();
$tester->expectLogTerminatingNotices();
$tester->close();

View File

@ -63,18 +63,10 @@ for ($interval = 0; $interval < $max_interval; $interval += $step) {
echo "Reached interval $interval us with $step us steps\n";
$tester->expectLogNotice('Reloading in progress ...');
/* Consume mix of 'Reloading in progress ...' and 'reloading: .*' */
$skipped = $tester->getLogLines(2000);
$tester->readAllLogNotices('Reloading in progress ...');
$tester->signal('USR2');
$tester->expectLogNotice('Reloading in progress ...');
/* When a child ignores SIGQUIT, the following expectation fails due to timeout. */
if (!$tester->expectLogNotice('reloading: .*')) {
/* for troubleshooting */
echo "Skipped messages\n";
echo implode('', $skipped);
}
$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
$tester->expectLogStartNotices();
$tester->reload();
$tester->expectLogReloadingNotices();
$tester->terminate();
$tester->expectLogTerminatingNotices();

View File

@ -1,5 +1,5 @@
--TEST--
FPM: GH-8885 - access.log with stderr begins to write logs to error_log after daemon reload
FPM: GH-8885 - access.log with stderr begins to write logs to error_log after reloading logs
--SKIPIF--
<?php
include "skipif.inc";
@ -26,60 +26,25 @@ pm.min_spare_servers = 1
pm.max_spare_servers = 3
EOT;
// php-fpm must not be launched with --force-stderr option
$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
$errorLogFile = $tester->getPrefixedFile('err.log');
$tester->start();
$tester = new FPM\Tester($cfg);
$tester->start(forceStderr: false);
$tester->expectNoLogMessages();
$content = file_get_contents($errorLogFile);
assert($content !== false && strlen($content) > 0, 'File must not be empty');
$errorLogLines = explode("\n", $content);
array_pop($errorLogLines);
assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
$tester->ping('{{ADDR}}');
$stderrLines = $tester->getLogLines(-1);
assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
$stderrLine = $stderrLines[0];
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
$tester->signal('USR1');
$tester->expectNoLogMessages();
$content = file_get_contents($errorLogFile);
assert($content !== false && strlen($content) > 0, 'File must not be empty');
$errorLogLines = explode("\n", $content);
array_pop($errorLogLines);
assert(count($errorLogLines) >= 4, 'Expected at least 4 records in the error_log file');
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
assert(strpos($errorLogLines[2], 'NOTICE: error log file re-opened'));
assert(strpos($errorLogLines[3], 'NOTICE: access log file re-opened'));
$tester->ping('{{ADDR}}');
$stderrLines = $tester->getLogLines(-1);
assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
$tester->switchLogSource('{{FILE:LOG}}');
$tester->expectLogStartNotices();
$tester->ping();
$tester->switchLogSource('{{MASTER:OUT}}');
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
$tester->reloadLogs();
$tester->switchLogSource('{{FILE:LOG}}');
$tester->expectLogReloadingLogsNotices();
$tester->ping();
$tester->switchLogSource('{{MASTER:OUT}}');
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
$tester->switchLogSource('{{FILE:LOG}}');
$tester->terminate();
$stderrLines = $tester->expectNoLogMessages();
$content = file_get_contents($errorLogFile);
assert($content !== false && strlen($content) > 0, 'File must not be empty');
$errorLogLines = explode("\n", $content);
array_pop($errorLogLines);
$errorLogLastLine = array_pop($errorLogLines);
assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
$tester->expectLogTerminatingNotices();
$tester->switchLogSource('{{MASTER:OUT}}');
$tester->expectNoLogMessages();
$tester->close();
?>
Done

View File

@ -26,60 +26,25 @@ pm.min_spare_servers = 1
pm.max_spare_servers = 3
EOT;
// php-fpm must not be launched with --force-stderr option
$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
$errorLogFile = $tester->getPrefixedFile('err.log');
$tester->start();
$tester = new FPM\Tester($cfg);
$tester->start(forceStderr: false);
$tester->expectNoLogMessages();
$content = file_get_contents($errorLogFile);
assert($content !== false && strlen($content) > 0, 'File must not be empty');
$errorLogLines = explode("\n", $content);
array_pop($errorLogLines);
assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
$tester->ping('{{ADDR}}');
$stderrLines = $tester->getLogLines(-1);
assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
$stderrLine = $stderrLines[0];
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
$tester->signal('USR2');
$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
$content = file_get_contents($errorLogFile);
assert($content !== false && strlen($content) > 0, 'File must not be empty');
$errorLogLines = explode("\n", $content);
array_pop($errorLogLines);
assert(count($errorLogLines) >= 5, 'Expected at least 5 records in the error_log file');
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
assert(strpos($errorLogLines[2], 'NOTICE: Reloading in progress'));
assert(strpos($errorLogLines[3], 'NOTICE: reloading: execvp'));
assert(strpos($errorLogLines[4], 'NOTICE: using inherited socket'));
$tester->ping('{{ADDR}}');
$stderrLines = $tester->getLogLines(-1);
assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
$tester->switchLogSource('{{FILE:LOG}}');
$tester->expectLogStartNotices();
$tester->ping();
$tester->switchLogSource('{{MASTER:OUT}}');
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
$tester->reload();
$tester->switchLogSource('{{FILE:LOG}}');
$tester->expectLogReloadingNotices();
$tester->ping();
$tester->switchLogSource('{{MASTER:OUT}}');
$tester->expectLogPattern('/127.0.0.1 .* "GET \/ping" 200/');
$tester->switchLogSource('{{FILE:LOG}}');
$tester->terminate();
$stderrLines = $tester->expectNoLogMessages();
$content = file_get_contents($errorLogFile);
assert($content !== false && strlen($content) > 0, 'File must not be empty');
$errorLogLines = explode("\n", $content);
array_pop($errorLogLines);
$errorLogLastLine = array_pop($errorLogLines);
assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
$tester->expectLogTerminatingNotices();
$tester->switchLogSource('{{MASTER:OUT}}');
$tester->expectNoLogMessages();
$tester->close();
?>
Done

View File

@ -30,9 +30,8 @@ $tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$lines = $tester->getLogLines(2);
var_dump($lines[0] === str_repeat('a', 1021) . "\0f\n");
var_dump($lines[1] === "abc\n");
$tester->expectLogLine(str_repeat('a', 1021) . "\0f", decorated: false);
$tester->expectLogLine("abc", decorated: false);
$tester->terminate();
$tester->expectLogTerminatingNotices();
$tester->close();
@ -40,8 +39,6 @@ $tester->close();
?>
Done
--EXPECT--
bool(true)
bool(true)
Done
--CLEAN--
<?php

View File

@ -31,13 +31,12 @@ $tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
var_dump($tester->getLastLogLine() === str_repeat('a', 1022) . "\n");
$tester->expectLogLine(str_repeat('a', 1022), decorated: false);
$tester->close();
?>
Done
--EXPECT--
bool(true)
Done
--CLEAN--
<?php

View File

@ -33,17 +33,14 @@ $tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
var_dump($tester->getLastLogLine() === str_repeat('a', 100) . str_repeat('b', 923) . "\n");
var_dump($tester->getLastLogLine() === str_repeat('b', 1023) . "\n");
var_dump($tester->getLastLogLine() === str_repeat('b', 554) . "\n");
$tester->expectLogLine(str_repeat('a', 100) . str_repeat('b', 923), decorated: false);
$tester->expectLogLine(str_repeat('b', 1023), decorated: false);
$tester->expectLogLine(str_repeat('b', 554), decorated: false);
$tester->close();
?>
Done
--EXPECT--
bool(true)
bool(true)
bool(true)
Done
--CLEAN--
<?php

View File

@ -0,0 +1,336 @@
<?php
namespace FPM;
class LogReader
{
/**
* Log debugging.
*
* @var bool
*/
private bool $debug;
/**
* Log descriptor.
*
* @var string|null
*/
private ?string $currentSourceName;
/**
* Log descriptors.
*
* @var LogSource[]
*/
private array $sources = [];
/**
* Log reader constructor.
*
* @param bool $debug
*/
public function __construct(bool $debug = false)
{
$this->debug = $debug;
}
/**
* Returns log descriptor source.
*
* @return LogSource
* @throws \Exception
*/
private function getSource(): LogSource
{
if ( ! $this->currentSourceName) {
throw new \Exception('Log descriptor is not set');
}
return $this->sources[$this->currentSourceName];
}
/**
* Set current stream source and create it if it does not exist.
*
* @param string $name Stream name.
* @param resource $stream The actual stream.
*/
public function setStreamSource(string $name, $stream)
{
$this->currentSourceName = $name;
if ( ! isset($this->sources[$name])) {
$this->sources[$name] = new LogStreamSource($stream);
}
}
/**
* Set file source as current and create it if it does not exist.
*
* @param string $name Source name.
* @param string $filePath Source file path.s
*/
public function setFileSource(string $name, string $filePath)
{
$this->currentSourceName = $name;
if ( ! isset($this->sources[$name])) {
$this->sources[$name] = new LogFileSource($filePath);
}
}
/**
* Get a single log line.
*
* @param int $timeoutSeconds
* @param int $timeoutMicroseconds
*
* @return null|string
* @throws \Exception
*/
public function getLine(int $timeoutSeconds = 3, int $timeoutMicroseconds = 0): ?string
{
$line = $this->getSource()->getLine($timeoutSeconds, $timeoutMicroseconds);
$this->trace(is_null($line) ? "LINE - null" : "LINE: $line");
return $line;
}
/**
* Print separation line.
*/
public function printSeparator(): void
{
echo str_repeat('-', 68) . "\n";
}
/**
* Print all logs.
*/
public function printLogs(): void
{
$hasMultipleDescriptors = count($this->sources) > 1;
echo "LOGS:\n";
foreach ($this->sources as $name => $source) {
if ($hasMultipleDescriptors) {
echo ">>> source: $name\n";
}
$this->printSeparator();
foreach ($source->getAllLines() as $line) {
echo $line;
}
$this->printSeparator();
}
}
/**
* Print error and logs.
*
* @param string|null $errorMessage Error message to print before the logs.
*
* @return false
*/
private function printError(?string $errorMessage): bool
{
if (is_null($errorMessage)) {
return false;
}
echo "ERROR: " . $errorMessage . "\n\n";
$this->printLogs();
echo "\n";
return false;
}
/**
* Read log until matcher matches the log message or there are no more logs.
*
* @param callable $matcher Callback to identify a match
* @param string|null $notFoundMessage Error message if matcher does not succeed.
* @param bool $checkAllLogs Whether to also check past logs.
* @param int $timeoutSeconds Timeout in seconds for reading of all messages.
* @param int $timeoutMicroseconds Additional timeout in microseconds for reading of all messages.
*
* @return bool
* @throws \Exception
*/
public function readUntil(
callable $matcher,
string $notFoundMessage = null,
bool $checkAllLogs = false,
int $timeoutSeconds = 3,
int $timeoutMicroseconds = 0
): bool {
$startTime = microtime(true);
$endTime = $startTime + $timeoutSeconds + ($timeoutMicroseconds / 1_000_000);
if ($checkAllLogs) {
foreach ($this->getSource()->getAllLines() as $line) {
if ($matcher($line)) {
return true;
}
}
}
do {
if (microtime(true) > $endTime) {
return $this->printError($notFoundMessage);
}
$line = $this->getLine($timeoutSeconds, $timeoutMicroseconds);
if ($line === null || microtime(true) > $endTime) {
return $this->printError($notFoundMessage);
}
} while ( ! $matcher($line));
return true;
}
/**
* Print tracing message - only in debug .
*
* @param string $msg Message to print.
*/
private function trace(string $msg): void
{
if ($this->debug) {
print "LogReader - $msg";
}
}
}
abstract class LogSource
{
/**
* Get single line from the source.
*
* @param int $timeoutSeconds Read timeout in seconds
* @param int $timeoutMicroseconds Read timeout in microseconds
*
* @return string|null
*/
public abstract function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string;
/**
* Get all lines that has been returned by getLine() method.
*
* @return string[]
*/
public abstract function getAllLines(): array;
}
class LogStreamSource extends LogSource
{
/**
* @var resource
*/
private $stream;
/**
* @var array
*/
private array $lines = [];
public function __construct($stream)
{
$this->stream = $stream;
}
/**
* Get single line from the stream.
*
* @param int $timeoutSeconds Read timeout in seconds
* @param int $timeoutMicroseconds Read timeout in microseconds
*
* @return string|null
*/
public function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string
{
if (feof($this->stream)) {
return null;
}
$read = [$this->stream];
$write = null;
$except = null;
if (stream_select($read, $write, $except, $timeoutSeconds, $timeoutMicroseconds)) {
$line = fgets($this->stream);
$this->lines[] = $line;
return $line;
} else {
return null;
}
}
/**
* Get all stream read lines.
*
* @return string[]
*/
public function getAllLines(): array
{
return $this->lines;
}
}
class LogFileSource extends LogSource
{
/**
* @var string
*/
private string $filePath;
/**
* @var int
*/
private int $position;
/**
* @var array
*/
private array $lines = [];
public function __construct(string $filePath)
{
$this->filePath = $filePath;
$this->position = 0;
}
/**
* Get single line from the file.
*
* @param int $timeoutSeconds Read timeout in seconds
* @param int $timeoutMicroseconds Read timeout in microseconds
*
* @return string|null
*/
public function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string
{
$endTime = microtime(true) + $timeoutSeconds + ($timeoutMicroseconds / 1_000_000);
while ($this->position >= count($this->lines)) {
if (is_file($this->filePath)) {
$lines = file($this->filePath);
if ($lines === false) {
return null;
}
$this->lines = $lines;
if ($this->position < count($lines)) {
break;
}
}
usleep(50_000);
if (microtime(true) > $endTime) {
return null;
}
}
return $this->lines[$this->position++];
}
/**
* Get all returned lines from the file.
*
* @return string[]
*/
public function getAllLines(): array
{
return array_slice($this->lines, 0, $this->position);
}
}

File diff suppressed because it is too large Load Diff

View File

@ -170,11 +170,11 @@ class Response
*/
public function debugOutput()
{
echo "-------------- RESPONSE: --------------\n";
echo "OUT:\n";
echo $this->data['out_response'];
echo "ERR:\n";
echo $this->data['err_response'];
echo ">>> Response\n";
echo "----------------- OUT -----------------\n";
echo $this->data['out_response'] . "\n";
echo "----------------- ERR -----------------\n";
echo $this->data['err_response'] . "\n";
echo "---------------------------------------\n\n";
}

File diff suppressed because it is too large Load Diff