123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804 |
- <?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;
- }
- }
|