diff --git a/sapi/fpm/tests/bug74083-concurrent-reload.phpt b/sapi/fpm/tests/bug74083-concurrent-reload.phpt index 8b4b690e962..ad5d560abae 100644 --- a/sapi/fpm/tests/bug74083-concurrent-reload.phpt +++ b/sapi/fpm/tests/bug74083-concurrent-reload.phpt @@ -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(); diff --git a/sapi/fpm/tests/bug76601-reload-child-signals.phpt b/sapi/fpm/tests/bug76601-reload-child-signals.phpt index f095ed667ca..1a3e6d2b74f 100644 --- a/sapi/fpm/tests/bug76601-reload-child-signals.phpt +++ b/sapi/fpm/tests/bug76601-reload-child-signals.phpt @@ -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(); diff --git a/sapi/fpm/tests/gh8885-stderr-fd-reload-usr1.phpt b/sapi/fpm/tests/gh8885-stderr-fd-reload-usr1.phpt index 4ff8d066093..fcdaccf40d8 100644 --- a/sapi/fpm/tests/gh8885-stderr-fd-reload-usr1.phpt +++ b/sapi/fpm/tests/gh8885-stderr-fd-reload-usr1.phpt @@ -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-- 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 diff --git a/sapi/fpm/tests/gh8885-stderr-fd-reload-usr2.phpt b/sapi/fpm/tests/gh8885-stderr-fd-reload-usr2.phpt index 68d9f6fa68b..e4531d56186 100644 --- a/sapi/fpm/tests/gh8885-stderr-fd-reload-usr2.phpt +++ b/sapi/fpm/tests/gh8885-stderr-fd-reload-usr2.phpt @@ -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 diff --git a/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt b/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt index 01b00d44853..5d996ddaece 100644 --- a/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt +++ b/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt @@ -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-- 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-- 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-- 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); + } +} diff --git a/sapi/fpm/tests/logtool.inc b/sapi/fpm/tests/logtool.inc index e085ae291be..b1c9009f6f8 100644 --- a/sapi/fpm/tests/logtool.inc +++ b/sapi/fpm/tests/logtool.inc @@ -4,7 +4,8 @@ namespace FPM; class LogTool { - const P_TIME = '\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d\]'; + const P_TIME = '\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d(?:\.\d+)?\]'; + const P_DEBUG = '(?:pid \d+, (?:\w+|\(null\))\(\), line \d+: )?'; const P_PREFIX = '\[pool unconfined\] child \d+ said into stderr: '; const P_PREFIX_STDOUT = '\[pool unconfined\] child \d+ said into stdout: '; const FINAL_SUFFIX = ', pipe is closed'; @@ -16,67 +17,96 @@ class LogTool const ALERT = 'ALERT'; /** - * @var string + * @var bool */ - private $message; + private bool $debug; + + /** + * @var LogReader + */ + private LogReader $logReader; /** * @var string */ - private $level; + private string $message; + + /** + * @var string|null + */ + private ?string $level = null; /** * @var int */ - private $position; + private int $position; /** * @var int */ - private $suffixPosition; + private int $suffixPosition = 0; /** * @var int */ - private $limit; + private int $limit; /** - * @var string + * @var string|null */ - private $pattern; + private ?string $pattern; /** - * @var string + * @var string|null */ - private $error; + private ?string $error = null; /** * @var bool */ - private $pipeClosed = false; + private bool $pipeClosed = false; /** + * Log tool constructor. + * + * @param LogReader $logReader + * @param bool $debug + */ + public function __construct(LogReader $logReader, bool $debug = false) + { + $this->logReader = $logReader; + $this->debug = $debug; + } + + /** + * Set expected message for output logging. + * * @param string $message - * @param int $limit - * @param int $repeat + * @param int $limit + * @param int $repeat */ public function setExpectedMessage(string $message, int $limit, int $repeat = 0) { - $this->message = ($repeat > 0) ? str_repeat($message, $repeat) : $message; - $this->limit = $limit; + $this->message = ($repeat > 0) ? str_repeat($message, $repeat) : $message; + $this->limit = $limit; $this->position = 0; } /** + * Set the expected logging level. + * * @param string $level - * @return int + * + * @return string */ - public function setExpectedLevel(string $level) + public function setExpectedLevel(string $level): string { return $this->level = $level; } /** + * Get the expected logging level. + * * @return string */ public function getExpectedLevel(): string @@ -85,172 +115,239 @@ class LogTool } /** + * Set whether pipe closed error is shown. + * * @param bool $pipeClosed */ - public function setPipeClosed(bool $pipeClosed) + public function setPipeClosed(bool $pipeClosed): void { $this->pipeClosed = $pipeClosed; } /** - * @param string $line + * Match the matcher checking the log lines using the callback. + * + * @param callable $matcher Callback checking whether the log line matches the expected message. + * @param string $notFoundMessage Error message to show if the message is not found. + * * @return bool + * @throws \Exception */ - public function checkTruncatedMessage(string $line) + private function match(callable $matcher, string $notFoundMessage): bool + { + if ($this->getError()) { + return false; + } + + if ($this->logReader->readUntil($matcher, $notFoundMessage)) { + $this->popError(); + + return true; + } + echo $this->popError(); + + return false; + } + + /** + * @param string|null $line Log line to check against. + * + * @return bool + * @throws \Exception + */ + public function checkTruncatedMessage(string $line = null): bool { if ($this->message === null) { throw new \LogicException('The message has not been set'); } - $lineLen = strlen($line); - if (!$this->checkLineLength($line)) { - return false; - } - $this->pattern = '/^PHP message: (.*?)(\.\.\.)?$/'; - if (preg_match($this->pattern, $line, $matches) === 0) { - return $this->error("Unexpected truncated message: {$line}"); - } - if ($lineLen === $this->limit - strlen('NOTICE: ') - 1) { - if (!isset($matches[2])) { - return $this->error("The truncated line is not ended with '...'"); - } - if (!$this->checkMessage($matches[1])) { + $matcher = function (string $line) { + $lineLen = strlen($line); + if ( ! $this->checkLineLength($line)) { return false; } + $this->pattern = '/^PHP message: (.*?)(\.\.\.)?$/'; + if (preg_match($this->pattern, $line, $matches) === 0) { + return $this->error("Unexpected truncated message: {$line}"); + } + + if ($lineLen === $this->limit - strlen('NOTICE: ') - 1) { + if ( ! isset($matches[2])) { + return $this->error("The truncated line is not ended with '...'"); + } + if ( ! $this->checkMessage($matches[1])) { + return false; + } + } else { + if (isset($matches[2])) { + // this is expecting that the expected message does not end with '...' + // which should not be an issue for the test purpose. + return $this->error("The line is complete and should not end with '...'"); + } + if ( ! $this->checkMessage($matches[1], -1)) { + return false; + } + } + + return true; + }; + + if ($line !== null) { + return $matcher($line); } else { - if (isset($matches[2])) { - // this is expecting that the expected message does not end with '...' - // which should not be an issue for the test purpose. - return $this->error("The line is complete and should not end with '...'"); - } - if (!$this->checkMessage($matches[1], -1)) { - return false; - } + return $this->match($matcher, 'Truncated message not found'); } - - return true; } /** - * @param array $lines - * @param bool $terminated - * @param bool $decorated + * Check wrapped message. + * + * @param bool $terminated Whether to check termination lines. + * @param bool $decorated Whether the output is decorated with prefix and suffix. + * @param bool $isStdErr Whether the message is written to stderr. + * * @return bool + * @throws \Exception */ - public function checkWrappedMessage(array $lines, bool $terminated = true, bool $decorated = true, bool $is_stderr = true) - { + public function checkWrappedMessage( + bool $terminated = true, + bool $decorated = true, + bool $isStdErr = true, + ): bool { if ($this->message === null) { throw new \LogicException('The message has not been set'); } if ($decorated) { $this->pattern = sprintf( - '/^(%s %s: %s)"([^"]*)"(.*)?$/', + '/^(%s %s: %s%s)"([^"]*)"(.*)?$/', self::P_TIME, $this->getExpectedLevel(), - $is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT + self::P_DEBUG, + $isStdErr ? self::P_PREFIX : self::P_PREFIX_STDOUT ); } else { $this->pattern = null; } - $idx = 0; - foreach ($lines as $idx => $line) { - if (!$this->checkLine($line)) { - break; + $matcher = fn(string $line) => $this->checkLine($line); + + while (strlen($this->message) !== $this->position) { + if ( ! $this->match($matcher, 'Output message not found')) { + return false; } } if ($this->suffixPosition > 0) { - $suffixPattern = sprintf( - '/^%s %s: %s(.*)$/', - self::P_TIME, $this->getExpectedLevel(), - $is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT - ); - $line = $lines[++$idx]; - if (preg_match($suffixPattern, $line, $matches) === 0) { - return $this->error("Unexpected line: $line"); - } - if ($matches[1] !== substr(self::FINAL_SUFFIX, $this->suffixPosition)) { - return $this->error( - "The suffix has not been finished from position $this->suffixPosition in line: $line" + $suffixMatcher = function ($line) use ($isStdErr) { + $suffixPattern = sprintf( + '/^%s %s: %s%s(.*)$/', + self::P_TIME, + $this->getExpectedLevel(), + self::P_DEBUG, + $isStdErr ? self::P_PREFIX : self::P_PREFIX_STDOUT ); + if (preg_match($suffixPattern, $line, $matches) === 0) { + return $this->error("Unexpected line: $line"); + } + if ($matches[1] !== substr(self::FINAL_SUFFIX, $this->suffixPosition)) { + return $this->error( + "The suffix has not been finished from position $this->suffixPosition in line: $line" + ); + } + + return true; + }; + if ( ! $this->match($suffixMatcher, 'Suffix message not found')) { + return false; } + $this->suffixPosition = 0; } if ($terminated) { - return $this->expectTerminatorLines($lines, $idx); + return $this->expectTerminatorLines(); } return true; } /** - * @param string $line + * Check workers output line. + * + * @param string $line Log output line. + * * @return bool */ - private function checkLine(string $line) + private function checkLine(string $line): bool { - if ($this->pattern === null) { + $useLine = $this->pattern === null; + if ($useLine) { // plain (not decorated) output - $out = rtrim($line); + $out = rtrim($line); $finalSuffix = null; - } elseif (($res = preg_match($this->pattern, $line, $matches)) > 0) { - $out = $matches[2]; + } elseif (preg_match($this->pattern, $line, $matches) > 0) { + $out = $matches[2]; $finalSuffix = $matches[3] ?? false; } else { - return $this->error("Unexpected line: $line"); + return $this->error("Unexpected line: $line", $line); } - $rem = strlen($this->message) - $this->position; + $rem = strlen($this->message) - $this->position; $lineLen = strlen($line); - if (!$this->checkLineLength($line, $lineLen)) { + if ( ! $this->checkLineLength($line, $lineLen)) { return false; } - if (!$this->checkMessage($out, $this->position)) { + if ( ! $this->checkMessage($out, $this->position, $useLine)) { return false; } - $outLen = strlen($out); + $outLen = strlen($out); + $this->position += $outLen; if ($rem > $outLen) { // continuous line if ($lineLen !== $this->limit) { if ($lineLen + ($rem - $outLen) < $this->limit) { return $this->error("Printed less than the message len"); } + return $this->error( "The continuous line length is $lineLen but it should equal to limit $this->limit" ); } - $this->position += $outLen; + return true; } - if ($rem !== $outLen) { + if ($rem !== $outLen) { return $this->error("Printed more than the message len"); } - if (!$this->pipeClosed || $finalSuffix === null) { - return false; + if ( ! $this->pipeClosed || $finalSuffix === null) { + return true; } if ($finalSuffix === false) { return $this->error("No final suffix"); } - if (empty($finalSuffix) || strpos(self::FINAL_SUFFIX, $finalSuffix) === false) { + if (empty($finalSuffix) || ! str_contains(self::FINAL_SUFFIX, $finalSuffix)) { return $this->error("The final suffix has to be equal to ', pipe is closed'"); } if (self::FINAL_SUFFIX !== $finalSuffix) { $this->suffixPosition = strlen($finalSuffix); } - // complete final suffix printed - return false; + + return true; } /** - * @param string $line - * @param int $lineLen + * Check the message line length - specifically if it's behind the limit. + * + * @param string $line Log output line. + * @param int|null $lineLen Line length. + * * @return bool */ - private function checkLineLength(string $line, $lineLen = null) { + private function checkLineLength(string $line, int $lineLen = null): bool + { $lineLen = $lineLen ?: strlen($line); if ($lineLen > $this->limit) { return $this->error( - "The line length is $lineLen which is higher than limit $this->limit" + "The line length is $lineLen which is higher than limit $this->limit", + $line ); } @@ -258,12 +355,19 @@ class LogTool } /** - * @param string $matchedMessage - * @param int $expectedMessageStart + * Check whether matched message part matches the expected message. + * + * @param string $matchedMessage The output message or part of it (match). + * @param int $expectedMessageStart Message position. + * @param bool $isLine Whether the whole log line is provided as a matched message. + * * @return bool */ - private function checkMessage(string $matchedMessage, int $expectedMessageStart = 0) - { + private function checkMessage( + string $matchedMessage, + int $expectedMessageStart = 0, + bool $isLine = false + ): bool { if ($expectedMessageStart < 0) { $expectedMessage = $this->message; } else { @@ -271,247 +375,430 @@ class LogTool } if ($expectedMessage !== $matchedMessage) { return $this->error( - sprintf( - "The actual string(%d) does not match expected string(%d):\n", - strlen($matchedMessage), - strlen($expectedMessage) - ) . - "- EXPECT: '$expectedMessage'\n" . - "- ACTUAL: '$matchedMessage'" + $this->getMatchDebugMessage( + sprintf( + "The actual string(%d) does not match expected string(%d):\n", + strlen($matchedMessage), + strlen($expectedMessage) + ), + expectedMessage: $expectedMessage, + actualMessage: "'$matchedMessage'", + ), + $isLine ? $matchedMessage : null ); } + $this->traceMatch( + "Message matched", + expectedMessage: $expectedMessage, + actualMessage: "'$matchedMessage'", + ); + return true; } /** - * @param array $lines + * Expect log entries for daemon reloading. + * + * @param int $expectedNumberOfSockets + * @param bool $expectInitialProgressMessage + * @param bool $expectReloadingMessage + * * @return bool + * @throws \Exception */ - public function expectReloadingLines(array $lines) - { - if ( - !$this->expectNotice($lines[0], 'Reloading in progress ...') || - !$this->expectNotice($lines[1], 'reloading: .*') - ) { + public function expectReloadingLines( + int $expectedNumberOfSockets, + bool $expectInitialProgressMessage = true, + bool $expectReloadingMessage = true + ): bool { + if ($expectInitialProgressMessage && ! $this->expectNotice('Reloading in progress ...')) { + return false; + } + if ($expectReloadingMessage && ! $this->expectNotice('reloading: .*')) { return false; } - for ($i = 2; $i < count($lines) - 2; $i++) { - if (!$this->expectNotice($lines[$i], 'using inherited socket fd=\d+, "[^"]+"')) { + for ($i = 0; $i < $expectedNumberOfSockets; $i++) { + if ( ! $this->expectNotice('using inherited socket fd=\d+, "[^"]+"')) { return false; } } - return $this->expectStartingLines(array_splice($lines, $i)); + return $this->expectStartingLines(); } /** - * @param array $lines + * Expect log entries for reloading logs. + * * @return bool + * @throws \Exception */ - public function expectStartingLines(array $lines) - { - if ($this->getError()) { - return false; - } - - if (count($lines) < 2) { - return $this->error("No starting lines"); - } - + public function expectReloadingLogsLines(): bool { return ( - $this->expectNotice($lines[0], 'fpm is running, pid \d+') && - $this->expectNotice($lines[1], 'ready to handle connections') + $this->expectNotice('error log file re-opened') && + $this->expectNotice('access log file re-opened') ); } /** - * @param array $lines - * @param int $idx + * Expect starting lines when FPM starts. + * * @return bool + * @throws \Exception */ - public function expectTerminatorLines(array $lines, int $idx = -1) + public function expectStartingLines(): bool { if ($this->getError()) { return false; } - if (count($lines) - $idx < 3) { - return $this->error("No terminating lines"); - } - return ( - $this->expectNotice($lines[++$idx], 'Terminating ...') && - $this->expectNotice($lines[++$idx], 'exiting, bye-bye!') + $this->expectNotice('fpm is running, pid \d+') && + $this->expectNotice('ready to handle connections') ); } /** - * @param string $type - * @param string $line - * @param string $expectedMessage - * @param string|null $pool + * Expect termination lines when FPM terminates. + * * @return bool + * @throws \Exception */ - public function expectEntry(string $type, string $line, string $expectedMessage, $pool = null) + public function expectTerminatorLines(): bool { if ($this->getError()) { return false; } + + return ( + $this->expectNotice('Terminating ...') && + $this->expectNotice('exiting, bye-bye!') + ); + } + + /** + * Get log entry matcher. + * + * @param string $type Entry type like NOTICE, WARNING, DEBUG and so on. + * @param string $expectedMessage Message to search for + * @param string $pool Pool that is used and prefixes the message. + * @param string $ignoreErrorFor Ignore error for supplied string in the message. + * + * @return callable + */ + private function getEntryMatcher( + string $type, + string $expectedMessage, + ?string $pool, + string $ignoreErrorFor + ): callable { if ($pool !== null) { $expectedMessage = '\[pool ' . $pool . '\] ' . $expectedMessage; } + $this->trace("Matching EXPECTED: $expectedMessage"); - $line = rtrim($line); - $pattern = sprintf('/^(%s )?%s: %s$/', self::P_TIME, $type, $expectedMessage); + $pattern = sprintf('/^(?:%s )?%s: %s(%s)$/', self::P_TIME, $type, self::P_DEBUG, $expectedMessage); + $this->trace("PATTERN: $pattern"); - if (preg_match($pattern, $line, $matches) === 0) { - return $this->error( - "The $type does not match expected message:\n" . - "- PATTERN: $pattern\n" . - "- MESSAGE: $line\n" . - "- EXPECT: '$expectedMessage'\n" . - "- ACTUAL: '" . substr($line, strpos($line, $type) + strlen($type) + 2) . "'" - ); + return function ($line) use ($expectedMessage, $pattern, $type, $ignoreErrorFor) { + $line = rtrim($line); + if (preg_match($pattern, $line, $matches) === 0) { + if ($this->getError()) { // quick bail out to save some CPU + return false; + } + + // get actual message + $types = implode('|', [self::NOTICE, self::WARNING, self::ERROR, self::ALERT]); + $errorPattern = sprintf('/^(?:%s )?(%s): %s(.*)$/', self::P_TIME, $types, self::P_DEBUG); + if (preg_match($errorPattern, $line, $matches) === 0) { + $actualMessage = null; + } else { + $expectedMessage = $type . ' - ' . $expectedMessage; + $actualMessage = $matches[1] . ' - ' . $matches[2]; + } + + return $this->error( + $this->getMatchDebugMessage( + 'Most likely invalid match for entry', + $pattern, + $line, + $expectedMessage, + $actualMessage + ), + $line, + $ignoreErrorFor + ); + } + $this->trace("Matched ACTUAL: " . $matches[1]); + + return true; + }; + } + + /** + * Read all log entries until timeout. + * + * @param string $type Entry type like NOTICE, WARNING, DEBUG and so on. + * @param string $expectedMessage Message to search for + * @param string|null $pool Pool that is used and prefixes the message. + * @param string $ignoreErrorFor Ignore error for supplied string in the message. + * + * @return bool + * @throws \Exception + */ + public function readAllEntries( + string $type, + string $expectedMessage, + string $pool = null, + string $ignoreErrorFor = self::DEBUG + ): bool { + if ($this->getError()) { + return false; } + $matcher = $this->getEntryMatcher($type, $expectedMessage, $pool, $ignoreErrorFor); + + while ($this->logReader->readUntil($matcher)) { + $this->popError(); + } + $this->popError(); + return true; } /** - * @param string $line - * @param string $expectedMessage - * @param string|null $pool + * Expect log entry. + * + * @param string $type Entry type like NOTICE, WARNING, DEBUG and so on. + * @param string $expectedMessage Message to search for + * @param string|null $pool Pool that is used and prefixes the message. + * @param string $ignoreErrorFor Ignore error for supplied string in the message. + * * @return bool + * @throws \Exception */ - public function expectDebug(string $line, string $expectedMessage, $pool = null) - { - return $this->expectEntry(self::DEBUG, $line, $expectedMessage, $pool); + public function expectEntry( + string $type, + string $expectedMessage, + string $pool = null, + string $ignoreErrorFor = self::DEBUG + ): bool { + if ($this->getError()) { + return false; + } + + return $this->match( + $this->getEntryMatcher($type, $expectedMessage, $pool, $ignoreErrorFor), + "The $type does not match expected message" + ); } /** - * @param string $line - * @param string $expectedMessage + * Expect debug log entry. + * + * @param string $expectedMessage * @param string|null $pool + * * @return bool + * @throws \Exception */ - public function expectNotice(string $line, string $expectedMessage, $pool = null) + public function expectDebug(string $expectedMessage, string $pool = null): bool { - return $this->expectEntry(self::NOTICE, $line, $expectedMessage, $pool); + return $this->expectEntry(self::DEBUG, $expectedMessage, $pool, self::ERROR); } /** - * @param string $line - * @param string $expectedMessage + * Expect notice log entry. + * + * @param string $expectedMessage * @param string|null $pool + * * @return bool + * @throws \Exception */ - public function expectWarning(string $line, string $expectedMessage, $pool = null) + public function expectNotice(string $expectedMessage, string $pool = null): bool { - return $this->expectEntry(self::WARNING, $line, $expectedMessage, $pool); + return $this->expectEntry(self::NOTICE, $expectedMessage, $pool); } /** - * @param string $line - * @param string $expectedMessage + * Expect warning log entry. + * + * @param string $expectedMessage * @param string|null $pool + * * @return bool + * @throws \Exception */ - public function expectError(string $line, string $expectedMessage, $pool = null) + public function expectWarning(string $expectedMessage, string $pool = null): bool { - return $this->expectEntry(self::ERROR, $line, $expectedMessage, $pool); + return $this->expectEntry(self::WARNING, $expectedMessage, $pool); } /** - * @param string $line - * @param string $expectedMessage + * Expect error log entry. + * + * @param string $expectedMessage * @param string|null $pool + * * @return bool + * @throws \Exception */ - public function expectAlert(string $line, string $expectedMessage, $pool = null) + public function expectError(string $expectedMessage, string $pool = null): bool { - return $this->expectEntry(self::ALERT, $line, $expectedMessage, $pool); + return $this->expectEntry(self::ERROR, $expectedMessage, $pool); } /** - * @param string $msg + * Expect alert log entry. + * + * @param string $expectedMessage + * @param string|null $pool + * * @return bool + * @throws \Exception */ - private function error(string $msg) + public function expectAlert(string $expectedMessage, string $pool = null): bool { - $this->error = $msg; - echo "ERROR: $msg\n"; + return $this->expectEntry(self::ALERT, $expectedMessage, $pool); + } + + /** + * Expect pattern in the log line. + * + * @param string $pattern + * + * @return bool + * @throws \Exception + */ + public function expectPattern(string $pattern): bool + { + return $this->match( + function ($line) use ($pattern) { + if (preg_match($pattern, $line) === 1) { + $this->traceMatch("Pattern expectation", $pattern, $line); + + return true; + } + + return false; + }, + 'The search pattern not found' + ); + } + + /** + * Get match debug message. + * + * @param string $title + * @param string|null $pattern + * @param string|null $line + * @param string|null $expectedMessage + * @param string|null $actualMessage + * + * @return string + */ + private function getMatchDebugMessage( + string $title, + string $pattern = null, + string $line = null, + string $expectedMessage = null, + string $actualMessage = null + ): string { + $msg = "$title:\n"; + if ($pattern !== null) { + $msg .= "- PATTERN: $pattern\n"; + } + if ($line !== null) { + $msg .= "- LINE: $line\n"; + } + if ($expectedMessage !== null) { + $msg .= "- EXPECTED: $expectedMessage\n"; + } + if ($actualMessage !== null) { + $msg .= "- ACTUAL: $actualMessage\n"; + } + + return $msg; + } + + /** + * Print tracing of the match. + * + * @param string $title + * @param string|null $pattern + * @param string|null $line + * @param string|null $expectedMessage + * @param string|null $actualMessage + */ + private function traceMatch( + string $title, + string $pattern = null, + string $line = null, + string $expectedMessage = null, + string $actualMessage = null + ): void { + if ($this->debug) { + echo "LogTool - " . $this->getMatchDebugMessage($title, $pattern, $line, $expectedMessage, $actualMessage); + } + } + + /** + * Print tracing message - only in debug . + * + * @param string $msg Message to print. + */ + private function trace(string $msg): void + { + if ($this->debug) { + print "LogTool - $msg\n"; + } + } + + + /** + * Save error message if the line does not contain ignored string. + * + * @param string $msg + * @param string|null $line + * @param string $ignoreFor + * + * @return false + */ + private function error(string $msg, string $line = null, string $ignoreFor = self::DEBUG): bool + { + if ($this->error === null && ($line === null || ! str_contains($line, $ignoreFor))) { + $this->trace("Setting error: $msg"); + $this->error = $msg; + } + return false; } /** - * @return string + * Get saved error. + * + * @return string|null */ - public function getError() + public function getError(): ?string { return $this->error; } -} -if (isset($argv[1]) && $argv[1] === 'logtool-selftest') { - $cases = [ - [ - 'limit' => 1050, - 'lines' => [ - '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . - str_repeat('a', 968) . '"', - '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . - str_repeat('a', 968) . '"', - '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . - str_repeat('a', 112) . '", pipe is closed', - '[08-Oct-2017 19:53:55] NOTICE: Terminating ...', - '[08-Oct-2017 19:53:55] NOTICE: exiting, bye-bye!', - ], - 'message' => str_repeat('a', 2048), - 'type' => 'stdio', - ], - [ - 'limit' => 1050, - 'lines' => [ - '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . - str_repeat('a', 968) . '"', - '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . - str_repeat('a', 968) . '"', - '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . - str_repeat('a', 964) . '", pi', - '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: pe is closed', - '[08-Oct-2017 19:53:55] NOTICE: Terminating ...', - '[08-Oct-2017 19:53:55] NOTICE: exiting, bye-bye!', - ], - 'message' => str_repeat('a', 2900), - 'type' => 'stdio', - ], - [ - 'limit' => 1024, - 'line' => '[08-Oct-2017 19:53:50] WARNING: ' . str_repeat('a',989) . '...', - 'message' => str_repeat('a', 2900), - 'type' => 'message', - ], - [ - 'limit' => 1024, - 'line' => '[08-Oct-2017 19:53:50] WARNING: ' . str_repeat('a',20), - 'message' => str_repeat('a', 20), - 'type' => 'message', - ], - ]; - foreach ($cases as $case) { - printf("Test message with len %d and limit %d: ", strlen($case['message']), $case['limit']); - $logTool = new LogTool(); - $logTool->setExpectedMessage($case['message'], $case['limit']); - if ($case['type'] === 'stdio') { - $logTool->checkWrappedMessage($case['lines']); - } else { - $logTool->checkTruncatedMessage($case['line']); - } - if (!$logTool->getError()) { - echo "OK\n"; + /** + * Get saved error and clear it. + * + * @return string|null + */ + public function popError(): ?string + { + $error = $this->error; + $this->error = null; + if ($error !== null) { + $this->trace("Clearing error: $error"); } + + return $error; } - echo "Done\n"; } diff --git a/sapi/fpm/tests/response.inc b/sapi/fpm/tests/response.inc index 1d0783b66ec..991e272b2ff 100644 --- a/sapi/fpm/tests/response.inc +++ b/sapi/fpm/tests/response.inc @@ -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"; } diff --git a/sapi/fpm/tests/tester.inc b/sapi/fpm/tests/tester.inc index dce81bfeb76..78e22854138 100644 --- a/sapi/fpm/tests/tester.inc +++ b/sapi/fpm/tests/tester.inc @@ -5,6 +5,7 @@ namespace FPM; use Adoy\FastCGI\Client; require_once 'fcgi.inc'; +require_once 'logreader.inc'; require_once 'logtool.inc'; require_once 'response.inc'; @@ -35,15 +36,10 @@ class Tester */ const FILE_EXT_PID = 'pid'; - /** - * Name for the option to manage php-fpm --force-stderr flag - */ - const PHP_FPM_DISABLE_FORCE_STDERR = 'disable-force-stderr'; - /** * @var array */ - static private $supportedFiles = [ + static private array $supportedFiles = [ self::FILE_EXT_LOG_ACC, self::FILE_EXT_LOG_ERR, self::FILE_EXT_LOG_SLOW, @@ -57,46 +53,51 @@ class Tester /** * @var array */ - static private $filesToClean = ['.user.ini']; + static private array $filesToClean = ['.user.ini']; /** * @var bool */ - private $debug; + private bool $debug; /** * @var array */ - private $clients; + private array $clients = []; + + /** + * @var LogReader + */ + private LogReader $logReader; /** * @var LogTool */ - private $logTool; + private LogTool $logTool; /** * Configuration template * * @var string|array */ - private $configTemplate; + private string|array $configTemplate; /** * The PHP code to execute * * @var string */ - private $code; + private string $code; /** * @var array */ - private $options; + private array $options; /** * @var string */ - private $fileName; + private string $fileName; /** * @var resource @@ -111,19 +112,19 @@ class Tester /** * @var array */ - private $ports = []; + private array $ports = []; /** - * @var string + * @var string|null */ - private $error; + private ?string $error = null; /** * The last response for the request call * - * @var Response + * @var Response|null */ - private $response; + private ?Response $response; /** * Clean all the created files up @@ -133,19 +134,19 @@ class Tester static public function clean($backTraceIndex = 1) { $filePrefix = self::getCallerFileName($backTraceIndex); - if (substr($filePrefix, -6) === 'clean.') { + if (str_ends_with($filePrefix, 'clean.')) { $filePrefix = substr($filePrefix, 0, -6); } $filesToClean = array_merge( array_map( - function($fileExtension) use ($filePrefix) { + function ($fileExtension) use ($filePrefix) { return $filePrefix . $fileExtension; }, self::$supportedFiles ), array_map( - function($fileExtension) { + function ($fileExtension) { return __DIR__ . '/' . $fileExtension; }, self::$filesToClean @@ -164,9 +165,10 @@ class Tester /** * Clean config files */ - static public function cleanConfigFiles() { + static public function cleanConfigFiles() + { if (is_dir(self::CONF_DIR)) { - foreach(glob(self::CONF_DIR . '/*.conf') as $name) { + foreach (glob(self::CONF_DIR . '/*.conf') as $name) { unlink($name); } rmdir(self::CONF_DIR); @@ -175,9 +177,10 @@ class Tester /** * @param int $backTraceIndex + * * @return string */ - static private function getCallerFileName($backTraceIndex = 1) + static private function getCallerFileName(int $backTraceIndex = 1): string { $backtrace = debug_backtrace(); if (isset($backtrace[$backTraceIndex]['file'])) { @@ -192,7 +195,7 @@ class Tester /** * @return bool|string */ - static public function findExecutable() + static public function findExecutable(): bool|string { $phpPath = getenv("TEST_PHP_EXECUTABLE"); for ($i = 0; $i < 2; $i++) { @@ -205,11 +208,11 @@ class Tester } if ($phpPath && is_dir($phpPath)) { - if (file_exists($phpPath."/fpm/php-fpm") && is_executable($phpPath."/fpm/php-fpm")) { + if (file_exists($phpPath . "/fpm/php-fpm") && is_executable($phpPath . "/fpm/php-fpm")) { /* gotcha */ - return $phpPath."/fpm/php-fpm"; + return $phpPath . "/fpm/php-fpm"; } - $phpSbinFpmi = $phpPath."/sbin/php-fpm"; + $phpSbinFpmi = $phpPath . "/sbin/php-fpm"; if (file_exists($phpSbinFpmi) && is_executable($phpSbinFpmi)) { return $phpSbinFpmi; } @@ -231,11 +234,11 @@ class Tester */ static public function skipIfAnyFileDoesNotExist($files) { - if (!is_array($files)) { + if ( ! is_array($files)) { $files = array($files); } foreach ($files as $file) { - if (!file_exists($file)) { + if ( ! file_exists($file)) { die("skip File $file does not exist"); } } @@ -245,11 +248,12 @@ class Tester * Skip test if config file is invalid. * * @param string $configTemplate + * * @throws \Exception */ static public function skipIfConfigFails(string $configTemplate) { - $tester = new self($configTemplate, '', [], self::getCallerFileName()); + $tester = new self($configTemplate, '', [], self::getCallerFileName()); $testResult = $tester->testConfig(); if ($testResult !== null) { self::clean(2); @@ -305,7 +309,7 @@ class Tester */ static public function skipIfPosixNotLoaded() { - if (!extension_loaded('posix')) { + if ( ! extension_loaded('posix')) { die('skip posix extension not loaded'); } } @@ -314,22 +318,25 @@ class Tester * Tester constructor. * * @param string|array $configTemplate - * @param string $code - * @param array $options - * @param string $fileName + * @param string $code + * @param array $options + * @param string|null $fileName + * @param bool|null $debug */ public function __construct( - $configTemplate, + string|array $configTemplate, string $code = '', array $options = [], - $fileName = null + string $fileName = null, + bool $debug = null ) { $this->configTemplate = $configTemplate; - $this->code = $code; - $this->options = $options; - $this->fileName = $fileName ?: self::getCallerFileName(); - $this->logTool = new LogTool(); - $this->debug = (bool) getenv('TEST_FPM_DEBUG'); + $this->code = $code; + $this->options = $options; + $this->fileName = $fileName ?: self::getCallerFileName(); + $this->debug = $debug !== null ? $debug : (bool)getenv('TEST_FPM_DEBUG'); + $this->logReader = new LogReader($this->debug); + $this->logTool = new LogTool($this->logReader, $this->debug); } /** @@ -338,6 +345,7 @@ class Tester public function setUserIni(string $ini) { $iniFile = __DIR__ . '/.user.ini'; + $this->trace('Setting .user.ini file', $ini, isFile: true); file_put_contents($iniFile, $ini); } @@ -350,7 +358,8 @@ class Tester public function testConfig() { $configFile = $this->createConfig(); - $cmd = self::findExecutable() . ' -t -y ' . $configFile . ' 2>&1'; + $cmd = self::findExecutable() . ' -t -y ' . $configFile . ' 2>&1'; + $this->trace('Testing config using command', $cmd, true); exec($cmd, $output, $code); if ($code) { return preg_replace("/\[.+?\]/", "", $output[0]); @@ -362,20 +371,20 @@ class Tester /** * Start PHP-FPM master process * - * @param array $extraArgs + * @param array $extraArgs Command extra arguments. + * @param bool $forceStderr Whether to output to stderr so error log is used. + * * @return bool * @throws \Exception */ - public function start(array $extraArgs = []) + public function start(array $extraArgs = [], bool $forceStderr = true) { $configFile = $this->createConfig(); - $desc = $this->outDesc ? [] : [1 => array('pipe', 'w'), 2 => array('redirect', 1)]; + $desc = $this->outDesc ? [] : [1 => array('pipe', 'w'), 2 => array('redirect', 1)]; $cmd = [self::findExecutable(), '-F', '-y', $configFile]; - if (!(isset($this->options[self::PHP_FPM_DISABLE_FORCE_STDERR]) && - $this->options[self::PHP_FPM_DISABLE_FORCE_STDERR] === true) - ) { + if ($forceStderr) { $cmd[] = '-O'; } @@ -383,10 +392,11 @@ class Tester $cmd[] = '--allow-to-run-as-root'; } $cmd = array_merge($cmd, $extraArgs); + $this->trace('Starting FPM using command:', $cmd, true); $this->masterProcess = proc_open($cmd, $desc, $pipes); register_shutdown_function( - function($masterProcess) use($configFile) { + function ($masterProcess) use ($configFile) { @unlink($configFile); if (is_resource($masterProcess)) { @proc_terminate($masterProcess); @@ -397,8 +407,9 @@ class Tester }, $this->masterProcess ); - if (!$this->outDesc !== false) { + if ( ! $this->outDesc !== false) { $this->outDesc = $pipes[1]; + $this->logReader->setStreamSource('{{MASTER:OUT}}', $this->outDesc); } return true; @@ -407,49 +418,35 @@ class Tester /** * Run until needle is found in the log. * - * @param string $needle - * @param int $max + * @param string $pattern Search pattern to find. + * * @return bool * @throws \Exception */ - public function runTill(string $needle, $max = 10) + public function runTill(string $pattern) { $this->start(); - $found = false; - for ($i = 0; $i < $max; $i++) { - $line = $this->getLogLine(); - if (is_null($line)) { - break; - } - if (preg_match($needle, $line) === 1) { - $found = true; - break; - } - } + $found = $this->logTool->expectPattern($pattern); $this->close(true); - if (!$found) { - return $this->error("The search pattern not found"); - } - - return true; + return $found; } /** * Check if connection works. * - * @param string $host - * @param null|string $successMessage - * @param null|string $errorMessage - * @param int $attempts - * @param int $delay + * @param string $host + * @param string|null $successMessage + * @param string|null $errorMessage + * @param int $attempts + * @param int $delay */ public function checkConnection( - $host = '127.0.0.1', - $successMessage = null, - $errorMessage = 'Connection failed', - $attempts = 20, - $delay = 50000 + string $host = '127.0.0.1', + string $successMessage = null, + ?string $errorMessage = 'Connection failed', + int $attempts = 20, + int $delay = 50000 ) { $i = 0; do { @@ -457,9 +454,10 @@ class Tester usleep($delay); } $fp = @fsockopen($host, $this->getPort()); - } while ((++$i < $attempts) && !$fp); + } while ((++$i < $attempts) && ! $fp); if ($fp) { + $this->trace('Checking connection successful'); $this->message($successMessage); fclose($fp); } else { @@ -471,22 +469,23 @@ class Tester /** * Execute request with parameters ordered for better checking. * - * @param string $address + * @param string $address * @param string|null $successMessage * @param string|null $errorMessage - * @param string $uri - * @param string $query - * @param array $headers + * @param string $uri + * @param string $query + * @param array $headers + * * @return Response */ public function checkRequest( string $address, string $successMessage = null, string $errorMessage = null, - $uri = '/ping', - $query = '', - $headers = [] - ) { + string $uri = '/ping', + string $query = '', + array $headers = [] + ): Response { return $this->request($query, $headers, $uri, $address, $successMessage, $errorMessage); } @@ -509,10 +508,11 @@ class Tester /** * Execute and check status request(s). * - * @param array $expectedFields + * @param array $expectedFields * @param string|null $address - * @param string $statusPath - * @param mixed $formats + * @param string $statusPath + * @param mixed $formats + * * @throws \Exception */ public function status( @@ -521,14 +521,14 @@ class Tester string $statusPath = '/status', $formats = ['plain', 'html', 'xml', 'json'] ) { - if (!is_array($formats)) { + if ( ! is_array($formats)) { $formats = [$formats]; } require_once "status.inc"; $status = new Status(); foreach ($formats as $format) { - $query = $format === 'plain' ? '' : $format; + $query = $format === 'plain' ? '' : $format; $response = $this->request($query, [], $statusPath, $address); $status->checkStatus($response, $expectedFields, $format); } @@ -537,20 +537,17 @@ class Tester /** * Get request params array. * - * @param string $query - * @param array $headers + * @param string $query + * @param array $headers * @param string|null $uri - * @param string|null $address - * @param string|null $successMessage - * @param string|null $errorMessage - * @param bool $connKeepAlive + * * @return array */ private function getRequestParams( string $query = '', array $headers = [], string $uri = null - ) { + ): array { if (is_null($uri)) { $uri = $this->makeSourceFile(); } @@ -562,7 +559,7 @@ class Tester 'SCRIPT_FILENAME' => $uri, 'SCRIPT_NAME' => $uri, 'QUERY_STRING' => $query, - 'REQUEST_URI' => $uri . ($query ? '?'.$query : ""), + 'REQUEST_URI' => $uri . ($query ? '?' . $query : ""), 'DOCUMENT_URI' => $uri, 'SERVER_SOFTWARE' => 'php/fcgiclient', 'REMOTE_ADDR' => '127.0.0.1', @@ -578,23 +575,24 @@ class Tester $headers ); - return array_filter($params, function($value) { - return !is_null($value); + return array_filter($params, function ($value) { + return ! is_null($value); }); } /** * Execute request. * - * @param string $query - * @param array $headers + * @param string $query + * @param array $headers * @param string|null $uri * @param string|null $address * @param string|null $successMessage * @param string|null $errorMessage - * @param bool $connKeepAlive - * @param bool $expectError - * @param int $readLimit + * @param bool $connKeepAlive + * @param bool $expectError + * @param int $readLimit + * * @return Response */ public function request( @@ -607,12 +605,13 @@ class Tester bool $connKeepAlive = false, bool $expectError = false, int $readLimit = -1, - ) { + ): Response { if ($this->hasError()) { return new Response(null, true); } $params = $this->getRequestParams($query, $headers, $uri); + $this->trace('Request params', $params); try { $this->response = new Response( @@ -636,37 +635,37 @@ class Tester if ($this->debug) { $this->response->debugOutput(); } + return $this->response; } /** * Execute multiple requests in parallel. * - * @param array|int $requests + * @param int|array $requests * @param string|null $address * @param string|null $successMessage * @param string|null $errorMessage - * @param bool $connKeepAlive - * @param int $readTimeout + * @param bool $connKeepAlive + * @param int $readTimeout + * * @return Response[] * @throws \Exception */ public function multiRequest( - $requests, + int|array $requests, string $address = null, string $successMessage = null, string $errorMessage = null, bool $connKeepAlive = false, int $readTimeout = 0 ) { - if ($this->hasError()) { - return new Response(null, true); - } - if (is_numeric($requests)) { $requests = array_fill(0, $requests, []); - } elseif (!is_array($requests)) { - throw new \Exception('Requests can be either numeric or array'); + } + + if ($this->hasError()) { + return array_map(fn($request) => new Response(null, true), $requests); } try { @@ -677,8 +676,9 @@ class Tester $requestData['headers'] ?? [], $requestData['uri'] ?? null ); + return [ - 'client' => $client, + 'client' => $client, 'requestId' => $client->async_request($params, false), ]; }, $requests); @@ -688,9 +688,11 @@ class Tester if ($this->debug) { $response->debugOutput(); } + return $response; }, $connections); $this->message($successMessage); + return $responses; } catch (\Exception $exception) { if ($errorMessage === null) { @@ -698,6 +700,8 @@ class Tester } else { $this->message($errorMessage); } + + return array_map(fn($request) => new Response(null, true), $requests); } } @@ -705,10 +709,11 @@ class Tester * Get client. * * @param string $address - * @param bool $keepAlive + * @param bool $keepAlive + * * @return Client */ - private function getClient(string $address = null, $keepAlive = false) + private function getClient(string $address = null, $keepAlive = false): Client { $address = $address ? $this->processTemplate($address) : $this->getAddr(); if ($address[0] === '/') { // uds @@ -716,7 +721,7 @@ class Tester $port = -1; } elseif ($address[0] === '[') { // ipv6 $addressParts = explode(']:', $address); - $host = $addressParts[0]; + $host = $addressParts[0]; if (isset($addressParts[1])) { $host .= ']'; $port = $addressParts[1]; @@ -725,15 +730,15 @@ class Tester } } else { // ipv4 $addressParts = explode(':', $address); - $host = $addressParts[0]; - $port = $addressParts[1] ?? $this->getPort(); + $host = $addressParts[0]; + $port = $addressParts[1] ?? $this->getPort(); } - if (!$keepAlive) { + if ( ! $keepAlive) { return new Client($host, $port); } - if (!isset($this->clients[$host][$port])) { + if ( ! isset($this->clients[$host][$port])) { $client = new Client($host, $port); $client->setKeepAlive(true); $this->clients[$host][$port] = $client; @@ -742,83 +747,6 @@ class Tester return $this->clients[$host][$port]; } - /** - * Display logs - * - * @param int $number - * @param string $ignore - */ - public function displayLog(int $number = 1, string $ignore = 'systemd') - { - /* Read $number lines or until EOF */ - while ($number > 0 || ($number < 0 && !feof($this->outDesc))) { - $a = fgets($this->outDesc); - if (empty($ignore) || !strpos($a, $ignore)) { - echo $a; - $number--; - } - } - } - - /** - * Get a single log line - * - * @return null|string - */ - private function getLogLine() - { - $read = [$this->outDesc]; - $write = null; - $except = null; - if (stream_select($read, $write, $except, $timeout=3)) { - return fgets($this->outDesc); - } else { - return null; - } - } - - /** - * Get log lines - * - * @param int $number - * @param bool $skipBlank - * @param string $ignore - * @return array - */ - public function getLogLines(int $number = 1, bool $skipBlank = false, string $ignore = 'systemd') - { - $lines = []; - /* Read $n lines or until EOF */ - while ($number > 0 || ($number < 0 && !feof($this->outDesc))) { - $line = $this->getLogLine(); - if (is_null($line)) { - break; - } - if ((empty($ignore) || !strpos($line, $ignore)) && (!$skipBlank || strlen(trim($line)) > 0)) { - $lines[] = $line; - $number--; - } - } - - if ($this->debug) { - foreach ($lines as $line) { - echo "LOG LINE: " . $line; - } - } - - return $lines; - } - - /** - * @return mixed|string - */ - public function getLastLogLine() - { - $lines = $this->getLogLines(); - - return $lines[0] ?? ''; - } - /** * @return string */ @@ -855,12 +783,13 @@ class Tester * Reload FPM by sending USR2 signal and optionally change config before that. * * @param string|array $configTemplate + * * @return string * @throws \Exception */ public function reload($configTemplate = null) { - if (!is_null($configTemplate)) { + if ( ! is_null($configTemplate)) { self::cleanConfigFiles(); $this->configTemplate = $configTemplate; $this->createConfig(); @@ -869,11 +798,23 @@ class Tester return $this->signal('USR2'); } + /** + * Reload FPM logs by sending USR1 signal. + * + * @return string + * @throws \Exception + */ + public function reloadLogs(): string + { + return $this->signal('USR1'); + } + /** * Send signal to the supplied PID or the server PID. * - * @param string $signal + * @param string $signal * @param int|null $pid + * * @return string */ public function signal($signal, int $pid = null) @@ -881,6 +822,8 @@ class Tester if (is_null($pid)) { $pid = $this->getPid(); } + $cmd = "kill -$signal $pid"; + $this->trace('Sending signal using command', $cmd, true); return exec("kill -$signal $pid"); } @@ -903,7 +846,6 @@ class Tester if ($terminate) { $this->terminate(); } - fclose($this->outDesc); proc_close($this->masterProcess); } @@ -911,6 +853,7 @@ class Tester * Create a config file. * * @param string $extension + * * @return string * @throws \Exception */ @@ -918,11 +861,11 @@ class Tester { if (is_array($this->configTemplate)) { $configTemplates = $this->configTemplate; - if (!isset($configTemplates['main'])) { + if ( ! isset($configTemplates['main'])) { throw new \Exception('The config template array has to have main config'); } $mainTemplate = $configTemplates['main']; - if (!is_dir(self::CONF_DIR)) { + if ( ! is_dir(self::CONF_DIR)) { mkdir(self::CONF_DIR); } foreach ($this->createPoolConfigs($configTemplates) as $name => $poolConfig) { @@ -944,29 +887,32 @@ class Tester * Create pool config templates. * * @param array $configTemplates + * * @return array * @throws \Exception */ private function createPoolConfigs(array $configTemplates) { - if (!isset($configTemplates['poolTemplate'])) { + if ( ! isset($configTemplates['poolTemplate'])) { unset($configTemplates['main']); + return $configTemplates; } $poolTemplate = $configTemplates['poolTemplate']; - $configs = []; + $configs = []; if (isset($configTemplates['count'])) { $start = $configTemplates['start'] ?? 1; - for ($i = $start; $i < $start + $configTemplates['count']; $i++) { + for ($i = $start; $i < $start + $configTemplates['count']; $i++) { $configs[$i] = str_replace('%index%', $i, $poolTemplate); } } elseif (isset($configTemplates['names'])) { - foreach($configTemplates['names'] as $name) { + foreach ($configTemplates['names'] as $name) { $configs[$name] = str_replace('%name%', $name, $poolTemplate); } } else { throw new \Exception('The config template requires count or names if poolTemplate set'); } + return $configs; } @@ -974,33 +920,37 @@ class Tester * Process template string. * * @param string $template + * * @return string */ private function processTemplate(string $template) { - $vars = [ - 'FILE:LOG:ACC' => ['getAbsoluteFile', self::FILE_EXT_LOG_ACC], - 'FILE:LOG:ERR' => ['getAbsoluteFile', self::FILE_EXT_LOG_ERR], - 'FILE:LOG:SLOW' => ['getAbsoluteFile', self::FILE_EXT_LOG_SLOW], - 'FILE:PID' => ['getAbsoluteFile', self::FILE_EXT_PID], - 'RFILE:LOG:ACC' => ['getRelativeFile', self::FILE_EXT_LOG_ACC], - 'RFILE:LOG:ERR' => ['getRelativeFile', self::FILE_EXT_LOG_ERR], + $vars = [ + 'FILE:LOG:ACC' => ['getAbsoluteFile', self::FILE_EXT_LOG_ACC], + 'FILE:LOG:ERR' => ['getAbsoluteFile', self::FILE_EXT_LOG_ERR], + 'FILE:LOG:SLOW' => ['getAbsoluteFile', self::FILE_EXT_LOG_SLOW], + 'FILE:PID' => ['getAbsoluteFile', self::FILE_EXT_PID], + 'RFILE:LOG:ACC' => ['getRelativeFile', self::FILE_EXT_LOG_ACC], + 'RFILE:LOG:ERR' => ['getRelativeFile', self::FILE_EXT_LOG_ERR], 'RFILE:LOG:SLOW' => ['getRelativeFile', self::FILE_EXT_LOG_SLOW], - 'RFILE:PID' => ['getRelativeFile', self::FILE_EXT_PID], - 'ADDR:IPv4' => ['getAddr', 'ipv4'], - 'ADDR:IPv4:ANY' => ['getAddr', 'ipv4-any'], - 'ADDR:IPv6' => ['getAddr', 'ipv6'], - 'ADDR:IPv6:ANY' => ['getAddr', 'ipv6-any'], - 'ADDR:UDS' => ['getAddr', 'uds'], - 'PORT' => ['getPort', 'ip'], - 'INCLUDE:CONF' => self::CONF_DIR . '/*.conf', - 'USER' => ['getUser'], - 'GROUP' => ['getGroup'], - 'UID' => ['getUid'], - 'GID' => ['getGid'], + 'RFILE:PID' => ['getRelativeFile', self::FILE_EXT_PID], + 'ADDR:IPv4' => ['getAddr', 'ipv4'], + 'ADDR:IPv4:ANY' => ['getAddr', 'ipv4-any'], + 'ADDR:IPv6' => ['getAddr', 'ipv6'], + 'ADDR:IPv6:ANY' => ['getAddr', 'ipv6-any'], + 'ADDR:UDS' => ['getAddr', 'uds'], + 'PORT' => ['getPort', 'ip'], + 'INCLUDE:CONF' => self::CONF_DIR . '/*.conf', + 'USER' => ['getUser'], + 'GROUP' => ['getGroup'], + 'UID' => ['getUid'], + 'GID' => ['getGid'], + 'MASTER:OUT' => 'pipe:1', + 'STDERR' => '/dev/stderr', + 'STDOUT' => '/dev/stdout', ]; $aliases = [ - 'ADDR' => 'ADDR:IPv4', + 'ADDR' => 'ADDR:IPv4', 'FILE:LOG' => 'FILE:LOG:ERR', ]; foreach ($aliases as $aliasName => $aliasValue) { @@ -1011,17 +961,19 @@ class Tester '/{{([a-zA-Z0-9:]+)(\[\w+\])?}}/', function ($matches) use ($vars) { $varName = $matches[1]; - if (!isset($vars[$varName])) { + if ( ! isset($vars[$varName])) { $this->error("Invalid config variable $varName"); + return 'INVALID'; } - $pool = $matches[2] ?? 'default'; + $pool = $matches[2] ?? 'default'; $varValue = $vars[$varName]; if (is_string($varValue)) { return $varValue; } $functionName = array_shift($varValue); - $varValue[] = $pool; + $varValue[] = $pool; + return call_user_func_array([$this, $functionName], $varValue); }, $template @@ -1031,6 +983,7 @@ class Tester /** * @param string $type * @param string $pool + * * @return string */ public function getAddr(string $type = 'ipv4', $pool = 'default') @@ -1045,9 +998,9 @@ class Tester return $address; } - return sys_get_temp_dir().'/'. - hash('crc32', dirname($address)).'-'. - basename($address); + return sys_get_temp_dir() . '/' . + hash('crc32', dirname($address)) . '-' . + basename($address); } return $this->getHost($type) . ':' . $port; @@ -1056,19 +1009,20 @@ class Tester /** * @param string $type * @param string $pool - * @param bool $useAsId + * @param bool $useAsId + * * @return int */ public function getPort(string $type = 'ip', $pool = 'default', $useAsId = false) { - if ($type === 'uds' && !$useAsId) { + if ($type === 'uds' && ! $useAsId) { return -1; } if (isset($this->ports['values'][$pool])) { return $this->ports['values'][$pool]; } - $port = ($this->ports['last'] ?? 9000 + PHP_INT_SIZE - 1) + 1; + $port = ($this->ports['last'] ?? 9000 + PHP_INT_SIZE - 1) + 1; $this->ports['values'][$pool] = $this->ports['last'] = $port; return $port; @@ -1076,6 +1030,7 @@ class Tester /** * @param string $type + * * @return string */ public function getHost(string $type = 'ipv4') @@ -1096,6 +1051,7 @@ class Tester * Get listen address. * * @param string|null $template + * * @return string */ public function getListen($template = null) @@ -1111,45 +1067,55 @@ class Tester public function getPid() { $pidFile = $this->getFile('pid'); - if (!is_file($pidFile)) { - return (int) $this->error("PID file has not been created"); + if ( ! is_file($pidFile)) { + return (int)$this->error("PID file has not been created"); } $pidContent = file_get_contents($pidFile); - if (!is_numeric($pidContent)) { - return (int) $this->error("PID content '$pidContent' is not integer"); + if ( ! is_numeric($pidContent)) { + return (int)$this->error("PID content '$pidContent' is not integer"); } + $this->trace('PID found', $pidContent); - return (int) $pidContent; + return (int)$pidContent; } /** - * @param string $extension + * Get file path for resource file. + * + * @param string $extension * @param string|null $dir * @param string|null $name + * * @return string */ - private function getFile(string $extension, $dir = null, $name = null) + private function getFile(string $extension, string $dir = null, string $name = null): string { $fileName = (is_null($name) ? $this->fileName : $name . '.') . $extension; - return is_null($dir) ? $fileName : $dir . '/' . $fileName; + return is_null($dir) ? $fileName : $dir . '/' . $fileName; } /** + * Get absolute file path for the resource file used by templates. + * * @param string $extension + * * @return string */ - private function getAbsoluteFile(string $extension) + private function getAbsoluteFile(string $extension): string { return $this->getFile($extension); } /** + * Get relative file name for resource file used by templates. + * * @param string $extension + * * @return string */ - private function getRelativeFile(string $extension) + private function getRelativeFile(string $extension): string { $fileName = rtrim(basename($this->fileName), '.'); @@ -1157,14 +1123,17 @@ class Tester } /** - * @param string $extension - * @param string $prefix + * Get prefixed file. + * + * @param string $extension + * @param string|null $prefix + * * @return string */ - public function getPrefixedFile(string $extension, string $prefix = null) + public function getPrefixedFile(string $extension, string $prefix = null): string { $fileName = rtrim($this->fileName, '.'); - if (!is_null($prefix)) { + if ( ! is_null($prefix)) { $fileName = $prefix . '/' . basename($fileName); } @@ -1172,26 +1141,40 @@ class Tester } /** - * @param string $extension - * @param string $content + * Create a resource file. + * + * @param string $extension + * @param string $content * @param string|null $dir * @param string|null $name + * * @return string */ - private function makeFile(string $extension, string $content = '', $dir = null, $name = null) - { + private function makeFile( + string $extension, + string $content = '', + string $dir = null, + string $name = null, + bool $overwrite = true + ): string { $filePath = $this->getFile($extension, $dir, $name); + if ( ! $overwrite && is_file($filePath)) { + return $filePath; + } file_put_contents($filePath, $content); + $this->trace('Created file: ' . $filePath, $content, isFile: true); return $filePath; } /** + * Create a source code file. + * * @return string */ - public function makeSourceFile() + public function makeSourceFile(): string { - return $this->makeFile('src.php', $this->code); + return $this->makeFile('src.php', $this->code, overwrite: false); } /** @@ -1205,26 +1188,34 @@ class Tester } /** - * @param string $msg + * Display error. + * + * @param string $msg * @param \Exception|null $exception + * + * @return false */ - private function error($msg, \Exception $exception = null) + private function error($msg, \Exception $exception = null): bool { - $this->error = 'ERROR: ' . $msg; + $this->error = 'ERROR: ' . $msg; if ($exception) { $this->error .= '; EXCEPTION: ' . $exception->getMessage(); } $this->error .= "\n"; echo $this->error; + + return false; } /** + * Check whether any error was set. + * * @return bool */ private function hasError() { - return !is_null($this->error) || !is_null($this->logTool->getError()); + return ! is_null($this->error) || ! is_null($this->logTool->getError()); } /** @@ -1232,14 +1223,16 @@ class Tester * * @param string $extension * @param string $prefix + * * @return bool */ public function expectFile(string $extension, $prefix = null) { $filePath = $this->getPrefixedFile($extension, $prefix); - if (!file_exists($filePath)) { + if ( ! file_exists($filePath)) { return $this->error("The file $filePath does not exist"); } + $this->trace('File path exists as expected', $filePath); return true; } @@ -1249,6 +1242,7 @@ class Tester * * @param string $extension * @param string $prefix + * * @return bool */ public function expectNoFile(string $extension, $prefix = null) @@ -1257,6 +1251,7 @@ class Tester if (file_exists($filePath)) { return $this->error("The file $filePath exists"); } + $this->trace('File path does not exist as expected', $filePath); return true; } @@ -1265,8 +1260,8 @@ class Tester * Expect message to be written to FastCGI error stream. * * @param string $message - * @param int $limit - * @param int $repeat + * @param int $limit + * @param int $repeat */ public function expectFastCGIErrorMessage( string $message, @@ -1280,37 +1275,74 @@ class Tester /** * Expect reloading lines to be logged. * - * @param int $socketCount + * @param int $socketCount + * @param bool $expectInitialProgressMessage + * @param bool $expectReloadingMessage + * + * @throws \Exception */ - public function expectLogReloadingNotices($socketCount = 1) + public function expectLogReloadingNotices( + int $socketCount = 1, + bool $expectInitialProgressMessage = true, + bool $expectReloadingMessage = true + ) { + $this->logTool->expectReloadingLines( + $socketCount, + $expectInitialProgressMessage, + $expectReloadingMessage + ); + } + + /** + * Expect reloading lines to be logged. + * + * @throws \Exception + */ + public function expectLogReloadingLogsNotices() { - $this->logTool->expectReloadingLines($this->getLogLines($socketCount + 4)); + $this->logTool->expectReloadingLogsLines(); } /** * Expect starting lines to be logged. + * @throws \Exception */ public function expectLogStartNotices() { - $this->logTool->expectStartingLines($this->getLogLines(2)); + $this->logTool->expectStartingLines(); } /** * Expect terminating lines to be logged. + * @throws \Exception */ public function expectLogTerminatingNotices() { - $this->logTool->expectTerminatorLines($this->getLogLines(-1)); + $this->logTool->expectTerminatorLines(); + } + + /** + * Expect log pattern in logs. + * + * @param string $pattern Log pattern + * + * @throws \Exception + */ + public function expectLogPattern(string $pattern) + { + $this->logTool->expectPattern($pattern); } /** * Expect log message that can span multiple lines. * * @param string $message - * @param int $limit - * @param int $repeat - * @param bool $decorated - * @param bool $wrapped + * @param int $limit + * @param int $repeat + * @param bool $decorated + * @param bool $wrapped + * + * @throws \Exception */ public function expectLogMessage( string $message, @@ -1321,66 +1353,71 @@ class Tester ) { $this->logTool->setExpectedMessage($message, $limit, $repeat); if ($wrapped) { - $logLines = $this->getLogLines(-1, true); - $this->logTool->checkWrappedMessage($logLines, true, $decorated); + $this->logTool->checkWrappedMessage(true, $decorated); } else { - $logLines = $this->getLogLines(1, true); - $this->logTool->checkTruncatedMessage($logLines[0] ?? ''); - } - if ($this->debug) { - $this->message("-------------- LOG LINES: -------------"); - var_dump($logLines); - $this->message("---------------------------------------\n"); + $this->logTool->checkTruncatedMessage(); } } /** * Expect a single log line. * - * @param string $message + * @param string $message The expected message. + * @param bool $isStdErr Whether it is logged to stderr. + * @param bool $decorated Whether the log lines are decorated. + * * @return bool + * @throws \Exception */ - public function expectLogLine(string $message, bool $is_stderr = true) - { + public function expectLogLine( + string $message, + bool $isStdErr = true, + bool $decorated = true + ): bool { $messageLen = strlen($message); - $limit = $messageLen > 1024 ? $messageLen + 16 : 1024; + $limit = $messageLen > 1024 ? $messageLen + 16 : 1024; $this->logTool->setExpectedMessage($message, $limit); - $logLines = $this->getLogLines(1, true); - if ($this->debug) { - $this->message("LOG LINE: " . ($logLines[0] ?? '')); - } - return $this->logTool->checkWrappedMessage($logLines, false, true, $is_stderr); + return $this->logTool->checkWrappedMessage(false, $decorated, $isStdErr); } /** * Expect log entry. * - * @param string $type The log type - * @param string $message The expected message - * @param string|null $pool The pool for pool prefixed log entry - * @param int $count The number of items + * @param string $type The log type + * @param string $message The expected message + * @param string|null $pool The pool for pool prefixed log entry + * @param int $count The number of items + * * @return bool + * @throws \Exception */ - private function expectLogEntry(string $type, string $message, $pool = null, $count = 1) - { + private function expectLogEntry( + string $type, + string $message, + string $pool = null, + int $count = 1 + ): bool { for ($i = 0; $i < $count; $i++) { - if (!$this->logTool->expectEntry($type, $this->getLastLogLine(), $message, $pool)) { + if ( ! $this->logTool->expectEntry($type, $message, $pool)) { return false; } } + return true; } /** * Expect a log debug message. * - * @param string $message + * @param string $message * @param string|null $pool - * @param int $count + * @param int $count + * * @return bool + * @throws \Exception */ - public function expectLogDebug(string $message, $pool = null, $count = 1) + public function expectLogDebug(string $message, string $pool = null, int $count = 1): bool { return $this->expectLogEntry(LogTool::DEBUG, $message, $pool, $count); } @@ -1388,12 +1425,14 @@ class Tester /** * Expect a log notice. * - * @param string $message + * @param string $message * @param string|null $pool - * @param int $count + * @param int $count + * * @return bool + * @throws \Exception */ - public function expectLogNotice(string $message, $pool = null, $count = 1) + public function expectLogNotice(string $message, string $pool = null, int $count = 1): bool { return $this->expectLogEntry(LogTool::NOTICE, $message, $pool, $count); } @@ -1401,12 +1440,14 @@ class Tester /** * Expect a log warning. * - * @param string $message + * @param string $message * @param string|null $pool - * @param int $count + * @param int $count + * * @return bool + * @throws \Exception */ - public function expectLogWarning(string $message, $pool = null, $count = 1) + public function expectLogWarning(string $message, string $pool = null, int $count = 1): bool { return $this->expectLogEntry(LogTool::WARNING, $message, $pool, $count); } @@ -1414,12 +1455,14 @@ class Tester /** * Expect a log error. * - * @param string $message + * @param string $message * @param string|null $pool - * @param int $count + * @param int $count + * * @return bool + * @throws \Exception */ - public function expectLogError(string $message, $pool = null, $count = 1) + public function expectLogError(string $message, string $pool = null, int $count = 1): bool { return $this->expectLogEntry(LogTool::ERROR, $message, $pool, $count); } @@ -1427,12 +1470,14 @@ class Tester /** * Expect a log alert. * - * @param string $message + * @param string $message * @param string|null $pool - * @param int $count + * @param int $count + * * @return bool + * @throws \Exception */ - public function expectLogAlert(string $message, $pool = null, $count = 1) + public function expectLogAlert(string $message, string $pool = null, int $count = 1): bool { return $this->expectLogEntry(LogTool::ALERT, $message, $pool, $count); } @@ -1441,15 +1486,20 @@ class Tester * Expect no log lines to be logged. * * @return bool + * @throws \Exception */ - public function expectNoLogMessages() + public function expectNoLogMessages(): bool { - $logLines = $this->getLogLines(-1, true); - if (!empty($logLines)) { + $logLine = $this->logReader->getLine(timeoutSeconds: 0, timeoutMicroseconds: 1000); + if ($logLine === "") { + $logLine = $this->logReader->getLine(timeoutSeconds: 0, timeoutMicroseconds: 1000); + } + if ($logLine !== null) { return $this->error( - "Expected no log lines but following lines logged:\n" . implode("\n", $logLines) + "Expected no log lines but following line logged: $logLine" ); } + $this->trace('No log message received as expected'); return true; } @@ -1464,4 +1514,80 @@ class Tester print file_get_contents($accessLog); } } + + /** + * Read all log entries. + * + * @param string $type The log type + * @param string $message The expected message + * @param string|null $pool The pool for pool prefixed log entry + * + * @return bool + * @throws \Exception + */ + public function readAllLogEntries(string $type, string $message, string $pool = null): bool + { + return $this->logTool->readAllEntries($type, $message, $pool); + } + + /** + * Read all log entries. + * + * @param string $message The expected message + * @param string|null $pool The pool for pool prefixed log entry + * + * @return bool + * @throws \Exception + */ + public function readAllLogNotices(string $message, string $pool = null): bool + { + return $this->readAllLogEntries(LogTool::NOTICE, $message, $pool); + } + + /** + * Switch the logs source. + * + * @param string $source The source file path or name if log is a pipe. + * + * @throws \Exception + */ + public function switchLogSource(string $source) + { + $this->trace('Switching log descriptor to:', $source); + $this->logReader->setFileSource($source, $this->processTemplate($source)); + } + + /** + * Trace execution by printing supplied message only in debug mode. + * + * @param string $title Trace title to print if supplied. + * @param string|array|null $message Message to print. + * @param bool $isCommand Whether message is a command array. + */ + private function trace( + string $title, + string|array $message = null, + bool $isCommand = false, + bool $isFile = false + ): void { + if ($this->debug) { + echo "\n"; + echo ">>> $title\n"; + if (is_array($message)) { + if ($isCommand) { + echo implode(' ', $message) . "\n"; + } else { + print_r($message); + } + } elseif ($message !== null) { + if ($isFile) { + $this->logReader->printSeparator(); + } + echo $message . "\n"; + if ($isFile) { + $this->logReader->printSeparator(); + } + } + } + } }