php-8.0.30-src/sapi/fpm/tests/logtool.inc

805 lines
22 KiB
PHP

<?php
namespace FPM;
class LogTool
{
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';
const DEBUG = 'DEBUG';
const NOTICE = 'NOTICE';
const WARNING = 'WARNING';
const ERROR = 'ERROR';
const ALERT = 'ALERT';
/**
* @var bool
*/
private bool $debug;
/**
* @var LogReader
*/
private LogReader $logReader;
/**
* @var string
*/
private string $message;
/**
* @var string|null
*/
private ?string $level = null;
/**
* @var int
*/
private int $position;
/**
* @var int
*/
private int $suffixPosition = 0;
/**
* @var int
*/
private int $limit;
/**
* @var string|null
*/
private ?string $pattern;
/**
* @var string|null
*/
private ?string $error = null;
/**
* @var bool
*/
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
*/
public function setExpectedMessage(string $message, int $limit, int $repeat = 0)
{
$this->message = ($repeat > 0) ? str_repeat($message, $repeat) : $message;
$this->limit = $limit;
$this->position = 0;
}
/**
* Set the expected logging level.
*
* @param string $level
*
* @return string
*/
public function setExpectedLevel(string $level): string
{
return $this->level = $level;
}
/**
* Get the expected logging level.
*
* @return string
*/
public function getExpectedLevel(): string
{
return $this->level ?: 'WARNING';
}
/**
* Set whether pipe closed error is shown.
*
* @param bool $pipeClosed
*/
public function setPipeClosed(bool $pipeClosed): void
{
$this->pipeClosed = $pipeClosed;
}
/**
* 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
*/
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');
}
$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 {
return $this->match($matcher, 'Truncated message not found');
}
}
/**
* 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(
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)"([^"]*)"(.*)?$/',
self::P_TIME,
$this->getExpectedLevel(),
self::P_DEBUG,
$isStdErr ? self::P_PREFIX : self::P_PREFIX_STDOUT
);
} else {
$this->pattern = null;
}
$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) {
$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();
}
return true;
}
/**
* Check workers output line.
*
* @param string $line Log output line.
*
* @return bool
*/
private function checkLine(string $line): bool
{
$useLine = $this->pattern === null;
if ($useLine) {
// plain (not decorated) output
$out = rtrim($line);
$finalSuffix = null;
} elseif (preg_match($this->pattern, $line, $matches) > 0) {
$out = $matches[2];
$finalSuffix = $matches[3] ?? false;
} else {
return $this->error("Unexpected line: $line", $line);
}
$rem = strlen($this->message) - $this->position;
$lineLen = strlen($line);
if ( ! $this->checkLineLength($line, $lineLen)) {
return false;
}
if ( ! $this->checkMessage($out, $this->position, $useLine)) {
return false;
}
$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"
);
}
return true;
}
if ($rem !== $outLen) {
return $this->error("Printed more than the message len");
}
if ( ! $this->pipeClosed || $finalSuffix === null) {
return true;
}
if ($finalSuffix === false) {
return $this->error("No final suffix");
}
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);
}
return true;
}
/**
* 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, 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",
$line
);
}
return true;
}
/**
* 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,
bool $isLine = false
): bool {
if ($expectedMessageStart < 0) {
$expectedMessage = $this->message;
} else {
$expectedMessage = substr($this->message, $expectedMessageStart, strlen($matchedMessage));
}
if ($expectedMessage !== $matchedMessage) {
return $this->error(
$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;
}
/**
* Expect log entries for daemon reloading.
*
* @param int $expectedNumberOfSockets
* @param bool $expectInitialProgressMessage
* @param bool $expectReloadingMessage
*
* @return bool
* @throws \Exception
*/
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 = 0; $i < $expectedNumberOfSockets; $i++) {
if ( ! $this->expectNotice('using inherited socket fd=\d+, "[^"]+"')) {
return false;
}
}
return $this->expectStartingLines();
}
/**
* Expect log entries for reloading logs.
*
* @return bool
* @throws \Exception
*/
public function expectReloadingLogsLines(): bool {
return (
$this->expectNotice('error log file re-opened') &&
$this->expectNotice('access log file re-opened')
);
}
/**
* Expect starting lines when FPM starts.
*
* @return bool
* @throws \Exception
*/
public function expectStartingLines(): bool
{
if ($this->getError()) {
return false;
}
return (
$this->expectNotice('fpm is running, pid \d+') &&
$this->expectNotice('ready to handle connections')
);
}
/**
* Expect termination lines when FPM terminates.
*
* @return bool
* @throws \Exception
*/
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");
$pattern = sprintf('/^(?:%s )?%s: %s(%s)$/', self::P_TIME, $type, self::P_DEBUG, $expectedMessage);
$this->trace("PATTERN: $pattern");
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;
}
/**
* 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 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"
);
}
/**
* Expect debug log entry.
*
* @param string $expectedMessage
* @param string|null $pool
*
* @return bool
* @throws \Exception
*/
public function expectDebug(string $expectedMessage, string $pool = null): bool
{
return $this->expectEntry(self::DEBUG, $expectedMessage, $pool, self::ERROR);
}
/**
* Expect notice log entry.
*
* @param string $expectedMessage
* @param string|null $pool
*
* @return bool
* @throws \Exception
*/
public function expectNotice(string $expectedMessage, string $pool = null): bool
{
return $this->expectEntry(self::NOTICE, $expectedMessage, $pool);
}
/**
* Expect warning log entry.
*
* @param string $expectedMessage
* @param string|null $pool
*
* @return bool
* @throws \Exception
*/
public function expectWarning(string $expectedMessage, string $pool = null): bool
{
return $this->expectEntry(self::WARNING, $expectedMessage, $pool);
}
/**
* Expect error log entry.
*
* @param string $expectedMessage
* @param string|null $pool
*
* @return bool
* @throws \Exception
*/
public function expectError(string $expectedMessage, string $pool = null): bool
{
return $this->expectEntry(self::ERROR, $expectedMessage, $pool);
}
/**
* Expect alert log entry.
*
* @param string $expectedMessage
* @param string|null $pool
*
* @return bool
* @throws \Exception
*/
public function expectAlert(string $expectedMessage, string $pool = null): bool
{
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;
}
/**
* Get saved error.
*
* @return string|null
*/
public function getError(): ?string
{
return $this->error;
}
/**
* 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;
}
}