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|null $notFoundMessage Error message to show if the message is not found. * @param bool $checkAllLogs Whether to also check past logs. * @param int|null $timeoutSeconds Timeout in seconds for reading of all messages. * @param int|null $timeoutMicroseconds Additional timeout in microseconds for reading of all messages. * * @return bool * @throws \Exception */ private function match( callable $matcher, ?string $notFoundMessage = null, bool $checkAllLogs = false, ?int $timeoutSeconds = null, ?int $timeoutMicroseconds = null ): bool { if ($this->getError()) { return false; } if ($this->logReader->readUntil( $matcher, $notFoundMessage, $checkAllLogs, $timeoutSeconds, $timeoutMicroseconds )) { $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"); // Allow expected message to contain %s and %s for any string or number as in run-tests.php $expectRe = str_replace('%s', '[^\r\n]+', $expectedMessage); $expectRe = str_replace('%d', '\d+', $expectRe); $pattern = sprintf('/^(?:%s )?%s: %s(%s)$/', self::P_TIME, $type, self::P_DEBUG, $expectRe); $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. * @param bool $checkAllLogs Whether to also check past logs. * @param bool $invert Whether the log entry is not expected rather than expected. * @param int|null $timeoutSeconds Timeout in seconds for reading of all messages. * @param int|null $timeoutMicroseconds Additional timeout in microseconds for reading of all messages. * * @return bool * @throws \Exception */ public function expectEntry( string $type, string $expectedMessage, ?string $pool = null, string $ignoreErrorFor = self::DEBUG, bool $checkAllLogs = false, bool $invert = false, ?int $timeoutSeconds = null, ?int $timeoutMicroseconds = null ): bool { if ($this->getError()) { return false; } $matchResult = $this->match( $this->getEntryMatcher($type, $expectedMessage, $pool, $ignoreErrorFor), $invert ? null : "The $type does not match expected message", $checkAllLogs, $timeoutSeconds, $timeoutMicroseconds ); if ($matchResult && $invert) { return $this->error("The $type matches unexpected message"); } return $matchResult; } /** * 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 Pattern to use. * @param bool $invert Whether to expect pattern not to match. * @param bool $checkAllLogs Whether to also check past logs. * @param int|null $timeoutSeconds Timeout in seconds for reading of all messages. * @param int|null $timeoutMicroseconds Additional timeout in microseconds for reading of all messages. * * @return bool * @throws \Exception */ public function expectPattern( string $pattern, bool $invert = false, bool $checkAllLogs = false, ?int $timeoutSeconds = null, ?int $timeoutMicroseconds = null, ): bool { $matchResult = $this->match( function ($line) use ($pattern) { if (preg_match($pattern, $line) === 1) { $this->traceMatch("Pattern expectation", $pattern, $line); return true; } return false; }, $invert ? null : 'The search pattern not found', $checkAllLogs, $timeoutSeconds, $timeoutMicroseconds ); if ($invert && $matchResult) { return $this->logReader->printError('The search pattern found - PATTERN: ' . $pattern); } return $matchResult; } /** * 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; } }