logtool.inc 22 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804
  1. <?php
  2. namespace FPM;
  3. class LogTool
  4. {
  5. const P_TIME = '\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d(?:\.\d+)?\]';
  6. const P_DEBUG = '(?:pid \d+, (?:\w+|\(null\))\(\), line \d+: )?';
  7. const P_PREFIX = '\[pool unconfined\] child \d+ said into stderr: ';
  8. const P_PREFIX_STDOUT = '\[pool unconfined\] child \d+ said into stdout: ';
  9. const FINAL_SUFFIX = ', pipe is closed';
  10. const DEBUG = 'DEBUG';
  11. const NOTICE = 'NOTICE';
  12. const WARNING = 'WARNING';
  13. const ERROR = 'ERROR';
  14. const ALERT = 'ALERT';
  15. /**
  16. * @var bool
  17. */
  18. private bool $debug;
  19. /**
  20. * @var LogReader
  21. */
  22. private LogReader $logReader;
  23. /**
  24. * @var string
  25. */
  26. private string $message;
  27. /**
  28. * @var string|null
  29. */
  30. private ?string $level = null;
  31. /**
  32. * @var int
  33. */
  34. private int $position;
  35. /**
  36. * @var int
  37. */
  38. private int $suffixPosition = 0;
  39. /**
  40. * @var int
  41. */
  42. private int $limit;
  43. /**
  44. * @var string|null
  45. */
  46. private ?string $pattern;
  47. /**
  48. * @var string|null
  49. */
  50. private ?string $error = null;
  51. /**
  52. * @var bool
  53. */
  54. private bool $pipeClosed = false;
  55. /**
  56. * Log tool constructor.
  57. *
  58. * @param LogReader $logReader
  59. * @param bool $debug
  60. */
  61. public function __construct(LogReader $logReader, bool $debug = false)
  62. {
  63. $this->logReader = $logReader;
  64. $this->debug = $debug;
  65. }
  66. /**
  67. * Set expected message for output logging.
  68. *
  69. * @param string $message
  70. * @param int $limit
  71. * @param int $repeat
  72. */
  73. public function setExpectedMessage(string $message, int $limit, int $repeat = 0)
  74. {
  75. $this->message = ($repeat > 0) ? str_repeat($message, $repeat) : $message;
  76. $this->limit = $limit;
  77. $this->position = 0;
  78. }
  79. /**
  80. * Set the expected logging level.
  81. *
  82. * @param string $level
  83. *
  84. * @return string
  85. */
  86. public function setExpectedLevel(string $level): string
  87. {
  88. return $this->level = $level;
  89. }
  90. /**
  91. * Get the expected logging level.
  92. *
  93. * @return string
  94. */
  95. public function getExpectedLevel(): string
  96. {
  97. return $this->level ?: 'WARNING';
  98. }
  99. /**
  100. * Set whether pipe closed error is shown.
  101. *
  102. * @param bool $pipeClosed
  103. */
  104. public function setPipeClosed(bool $pipeClosed): void
  105. {
  106. $this->pipeClosed = $pipeClosed;
  107. }
  108. /**
  109. * Match the matcher checking the log lines using the callback.
  110. *
  111. * @param callable $matcher Callback checking whether the log line matches the expected message.
  112. * @param string $notFoundMessage Error message to show if the message is not found.
  113. *
  114. * @return bool
  115. * @throws \Exception
  116. */
  117. private function match(callable $matcher, string $notFoundMessage): bool
  118. {
  119. if ($this->getError()) {
  120. return false;
  121. }
  122. if ($this->logReader->readUntil($matcher, $notFoundMessage)) {
  123. $this->popError();
  124. return true;
  125. }
  126. echo $this->popError();
  127. return false;
  128. }
  129. /**
  130. * @param string|null $line Log line to check against.
  131. *
  132. * @return bool
  133. * @throws \Exception
  134. */
  135. public function checkTruncatedMessage(string $line = null): bool
  136. {
  137. if ($this->message === null) {
  138. throw new \LogicException('The message has not been set');
  139. }
  140. $matcher = function (string $line) {
  141. $lineLen = strlen($line);
  142. if ( ! $this->checkLineLength($line)) {
  143. return false;
  144. }
  145. $this->pattern = '/^PHP message: (.*?)(\.\.\.)?$/';
  146. if (preg_match($this->pattern, $line, $matches) === 0) {
  147. return $this->error("Unexpected truncated message: {$line}");
  148. }
  149. if ($lineLen === $this->limit - strlen('NOTICE: ') - 1) {
  150. if ( ! isset($matches[2])) {
  151. return $this->error("The truncated line is not ended with '...'");
  152. }
  153. if ( ! $this->checkMessage($matches[1])) {
  154. return false;
  155. }
  156. } else {
  157. if (isset($matches[2])) {
  158. // this is expecting that the expected message does not end with '...'
  159. // which should not be an issue for the test purpose.
  160. return $this->error("The line is complete and should not end with '...'");
  161. }
  162. if ( ! $this->checkMessage($matches[1], -1)) {
  163. return false;
  164. }
  165. }
  166. return true;
  167. };
  168. if ($line !== null) {
  169. return $matcher($line);
  170. } else {
  171. return $this->match($matcher, 'Truncated message not found');
  172. }
  173. }
  174. /**
  175. * Check wrapped message.
  176. *
  177. * @param bool $terminated Whether to check termination lines.
  178. * @param bool $decorated Whether the output is decorated with prefix and suffix.
  179. * @param bool $isStdErr Whether the message is written to stderr.
  180. *
  181. * @return bool
  182. * @throws \Exception
  183. */
  184. public function checkWrappedMessage(
  185. bool $terminated = true,
  186. bool $decorated = true,
  187. bool $isStdErr = true,
  188. ): bool {
  189. if ($this->message === null) {
  190. throw new \LogicException('The message has not been set');
  191. }
  192. if ($decorated) {
  193. $this->pattern = sprintf(
  194. '/^(%s %s: %s%s)"([^"]*)"(.*)?$/',
  195. self::P_TIME,
  196. $this->getExpectedLevel(),
  197. self::P_DEBUG,
  198. $isStdErr ? self::P_PREFIX : self::P_PREFIX_STDOUT
  199. );
  200. } else {
  201. $this->pattern = null;
  202. }
  203. $matcher = fn(string $line) => $this->checkLine($line);
  204. while (strlen($this->message) !== $this->position) {
  205. if ( ! $this->match($matcher, 'Output message not found')) {
  206. return false;
  207. }
  208. }
  209. if ($this->suffixPosition > 0) {
  210. $suffixMatcher = function ($line) use ($isStdErr) {
  211. $suffixPattern = sprintf(
  212. '/^%s %s: %s%s(.*)$/',
  213. self::P_TIME,
  214. $this->getExpectedLevel(),
  215. self::P_DEBUG,
  216. $isStdErr ? self::P_PREFIX : self::P_PREFIX_STDOUT
  217. );
  218. if (preg_match($suffixPattern, $line, $matches) === 0) {
  219. return $this->error("Unexpected line: $line");
  220. }
  221. if ($matches[1] !== substr(self::FINAL_SUFFIX, $this->suffixPosition)) {
  222. return $this->error(
  223. "The suffix has not been finished from position $this->suffixPosition in line: $line"
  224. );
  225. }
  226. return true;
  227. };
  228. if ( ! $this->match($suffixMatcher, 'Suffix message not found')) {
  229. return false;
  230. }
  231. $this->suffixPosition = 0;
  232. }
  233. if ($terminated) {
  234. return $this->expectTerminatorLines();
  235. }
  236. return true;
  237. }
  238. /**
  239. * Check workers output line.
  240. *
  241. * @param string $line Log output line.
  242. *
  243. * @return bool
  244. */
  245. private function checkLine(string $line): bool
  246. {
  247. $useLine = $this->pattern === null;
  248. if ($useLine) {
  249. // plain (not decorated) output
  250. $out = rtrim($line);
  251. $finalSuffix = null;
  252. } elseif (preg_match($this->pattern, $line, $matches) > 0) {
  253. $out = $matches[2];
  254. $finalSuffix = $matches[3] ?? false;
  255. } else {
  256. return $this->error("Unexpected line: $line", $line);
  257. }
  258. $rem = strlen($this->message) - $this->position;
  259. $lineLen = strlen($line);
  260. if ( ! $this->checkLineLength($line, $lineLen)) {
  261. return false;
  262. }
  263. if ( ! $this->checkMessage($out, $this->position, $useLine)) {
  264. return false;
  265. }
  266. $outLen = strlen($out);
  267. $this->position += $outLen;
  268. if ($rem > $outLen) { // continuous line
  269. if ($lineLen !== $this->limit) {
  270. if ($lineLen + ($rem - $outLen) < $this->limit) {
  271. return $this->error("Printed less than the message len");
  272. }
  273. return $this->error(
  274. "The continuous line length is $lineLen but it should equal to limit $this->limit"
  275. );
  276. }
  277. return true;
  278. }
  279. if ($rem !== $outLen) {
  280. return $this->error("Printed more than the message len");
  281. }
  282. if ( ! $this->pipeClosed || $finalSuffix === null) {
  283. return true;
  284. }
  285. if ($finalSuffix === false) {
  286. return $this->error("No final suffix");
  287. }
  288. if (empty($finalSuffix) || ! str_contains(self::FINAL_SUFFIX, $finalSuffix)) {
  289. return $this->error("The final suffix has to be equal to ', pipe is closed'");
  290. }
  291. if (self::FINAL_SUFFIX !== $finalSuffix) {
  292. $this->suffixPosition = strlen($finalSuffix);
  293. }
  294. return true;
  295. }
  296. /**
  297. * Check the message line length - specifically if it's behind the limit.
  298. *
  299. * @param string $line Log output line.
  300. * @param int|null $lineLen Line length.
  301. *
  302. * @return bool
  303. */
  304. private function checkLineLength(string $line, int $lineLen = null): bool
  305. {
  306. $lineLen = $lineLen ?: strlen($line);
  307. if ($lineLen > $this->limit) {
  308. return $this->error(
  309. "The line length is $lineLen which is higher than limit $this->limit",
  310. $line
  311. );
  312. }
  313. return true;
  314. }
  315. /**
  316. * Check whether matched message part matches the expected message.
  317. *
  318. * @param string $matchedMessage The output message or part of it (match).
  319. * @param int $expectedMessageStart Message position.
  320. * @param bool $isLine Whether the whole log line is provided as a matched message.
  321. *
  322. * @return bool
  323. */
  324. private function checkMessage(
  325. string $matchedMessage,
  326. int $expectedMessageStart = 0,
  327. bool $isLine = false
  328. ): bool {
  329. if ($expectedMessageStart < 0) {
  330. $expectedMessage = $this->message;
  331. } else {
  332. $expectedMessage = substr($this->message, $expectedMessageStart, strlen($matchedMessage));
  333. }
  334. if ($expectedMessage !== $matchedMessage) {
  335. return $this->error(
  336. $this->getMatchDebugMessage(
  337. sprintf(
  338. "The actual string(%d) does not match expected string(%d):\n",
  339. strlen($matchedMessage),
  340. strlen($expectedMessage)
  341. ),
  342. expectedMessage: $expectedMessage,
  343. actualMessage: "'$matchedMessage'",
  344. ),
  345. $isLine ? $matchedMessage : null
  346. );
  347. }
  348. $this->traceMatch(
  349. "Message matched",
  350. expectedMessage: $expectedMessage,
  351. actualMessage: "'$matchedMessage'",
  352. );
  353. return true;
  354. }
  355. /**
  356. * Expect log entries for daemon reloading.
  357. *
  358. * @param int $expectedNumberOfSockets
  359. * @param bool $expectInitialProgressMessage
  360. * @param bool $expectReloadingMessage
  361. *
  362. * @return bool
  363. * @throws \Exception
  364. */
  365. public function expectReloadingLines(
  366. int $expectedNumberOfSockets,
  367. bool $expectInitialProgressMessage = true,
  368. bool $expectReloadingMessage = true
  369. ): bool {
  370. if ($expectInitialProgressMessage && ! $this->expectNotice('Reloading in progress ...')) {
  371. return false;
  372. }
  373. if ($expectReloadingMessage && ! $this->expectNotice('reloading: .*')) {
  374. return false;
  375. }
  376. for ($i = 0; $i < $expectedNumberOfSockets; $i++) {
  377. if ( ! $this->expectNotice('using inherited socket fd=\d+, "[^"]+"')) {
  378. return false;
  379. }
  380. }
  381. return $this->expectStartingLines();
  382. }
  383. /**
  384. * Expect log entries for reloading logs.
  385. *
  386. * @return bool
  387. * @throws \Exception
  388. */
  389. public function expectReloadingLogsLines(): bool {
  390. return (
  391. $this->expectNotice('error log file re-opened') &&
  392. $this->expectNotice('access log file re-opened')
  393. );
  394. }
  395. /**
  396. * Expect starting lines when FPM starts.
  397. *
  398. * @return bool
  399. * @throws \Exception
  400. */
  401. public function expectStartingLines(): bool
  402. {
  403. if ($this->getError()) {
  404. return false;
  405. }
  406. return (
  407. $this->expectNotice('fpm is running, pid \d+') &&
  408. $this->expectNotice('ready to handle connections')
  409. );
  410. }
  411. /**
  412. * Expect termination lines when FPM terminates.
  413. *
  414. * @return bool
  415. * @throws \Exception
  416. */
  417. public function expectTerminatorLines(): bool
  418. {
  419. if ($this->getError()) {
  420. return false;
  421. }
  422. return (
  423. $this->expectNotice('Terminating ...') &&
  424. $this->expectNotice('exiting, bye-bye!')
  425. );
  426. }
  427. /**
  428. * Get log entry matcher.
  429. *
  430. * @param string $type Entry type like NOTICE, WARNING, DEBUG and so on.
  431. * @param string $expectedMessage Message to search for
  432. * @param string $pool Pool that is used and prefixes the message.
  433. * @param string $ignoreErrorFor Ignore error for supplied string in the message.
  434. *
  435. * @return callable
  436. */
  437. private function getEntryMatcher(
  438. string $type,
  439. string $expectedMessage,
  440. ?string $pool,
  441. string $ignoreErrorFor
  442. ): callable {
  443. if ($pool !== null) {
  444. $expectedMessage = '\[pool ' . $pool . '\] ' . $expectedMessage;
  445. }
  446. $this->trace("Matching EXPECTED: $expectedMessage");
  447. $pattern = sprintf('/^(?:%s )?%s: %s(%s)$/', self::P_TIME, $type, self::P_DEBUG, $expectedMessage);
  448. $this->trace("PATTERN: $pattern");
  449. return function ($line) use ($expectedMessage, $pattern, $type, $ignoreErrorFor) {
  450. $line = rtrim($line);
  451. if (preg_match($pattern, $line, $matches) === 0) {
  452. if ($this->getError()) { // quick bail out to save some CPU
  453. return false;
  454. }
  455. // get actual message
  456. $types = implode('|', [self::NOTICE, self::WARNING, self::ERROR, self::ALERT]);
  457. $errorPattern = sprintf('/^(?:%s )?(%s): %s(.*)$/', self::P_TIME, $types, self::P_DEBUG);
  458. if (preg_match($errorPattern, $line, $matches) === 0) {
  459. $actualMessage = null;
  460. } else {
  461. $expectedMessage = $type . ' - ' . $expectedMessage;
  462. $actualMessage = $matches[1] . ' - ' . $matches[2];
  463. }
  464. return $this->error(
  465. $this->getMatchDebugMessage(
  466. 'Most likely invalid match for entry',
  467. $pattern,
  468. $line,
  469. $expectedMessage,
  470. $actualMessage
  471. ),
  472. $line,
  473. $ignoreErrorFor
  474. );
  475. }
  476. $this->trace("Matched ACTUAL: " . $matches[1]);
  477. return true;
  478. };
  479. }
  480. /**
  481. * Read all log entries until timeout.
  482. *
  483. * @param string $type Entry type like NOTICE, WARNING, DEBUG and so on.
  484. * @param string $expectedMessage Message to search for
  485. * @param string|null $pool Pool that is used and prefixes the message.
  486. * @param string $ignoreErrorFor Ignore error for supplied string in the message.
  487. *
  488. * @return bool
  489. * @throws \Exception
  490. */
  491. public function readAllEntries(
  492. string $type,
  493. string $expectedMessage,
  494. string $pool = null,
  495. string $ignoreErrorFor = self::DEBUG
  496. ): bool {
  497. if ($this->getError()) {
  498. return false;
  499. }
  500. $matcher = $this->getEntryMatcher($type, $expectedMessage, $pool, $ignoreErrorFor);
  501. while ($this->logReader->readUntil($matcher)) {
  502. $this->popError();
  503. }
  504. $this->popError();
  505. return true;
  506. }
  507. /**
  508. * Expect log entry.
  509. *
  510. * @param string $type Entry type like NOTICE, WARNING, DEBUG and so on.
  511. * @param string $expectedMessage Message to search for
  512. * @param string|null $pool Pool that is used and prefixes the message.
  513. * @param string $ignoreErrorFor Ignore error for supplied string in the message.
  514. *
  515. * @return bool
  516. * @throws \Exception
  517. */
  518. public function expectEntry(
  519. string $type,
  520. string $expectedMessage,
  521. string $pool = null,
  522. string $ignoreErrorFor = self::DEBUG
  523. ): bool {
  524. if ($this->getError()) {
  525. return false;
  526. }
  527. return $this->match(
  528. $this->getEntryMatcher($type, $expectedMessage, $pool, $ignoreErrorFor),
  529. "The $type does not match expected message"
  530. );
  531. }
  532. /**
  533. * Expect debug log entry.
  534. *
  535. * @param string $expectedMessage
  536. * @param string|null $pool
  537. *
  538. * @return bool
  539. * @throws \Exception
  540. */
  541. public function expectDebug(string $expectedMessage, string $pool = null): bool
  542. {
  543. return $this->expectEntry(self::DEBUG, $expectedMessage, $pool, self::ERROR);
  544. }
  545. /**
  546. * Expect notice log entry.
  547. *
  548. * @param string $expectedMessage
  549. * @param string|null $pool
  550. *
  551. * @return bool
  552. * @throws \Exception
  553. */
  554. public function expectNotice(string $expectedMessage, string $pool = null): bool
  555. {
  556. return $this->expectEntry(self::NOTICE, $expectedMessage, $pool);
  557. }
  558. /**
  559. * Expect warning log entry.
  560. *
  561. * @param string $expectedMessage
  562. * @param string|null $pool
  563. *
  564. * @return bool
  565. * @throws \Exception
  566. */
  567. public function expectWarning(string $expectedMessage, string $pool = null): bool
  568. {
  569. return $this->expectEntry(self::WARNING, $expectedMessage, $pool);
  570. }
  571. /**
  572. * Expect error log entry.
  573. *
  574. * @param string $expectedMessage
  575. * @param string|null $pool
  576. *
  577. * @return bool
  578. * @throws \Exception
  579. */
  580. public function expectError(string $expectedMessage, string $pool = null): bool
  581. {
  582. return $this->expectEntry(self::ERROR, $expectedMessage, $pool);
  583. }
  584. /**
  585. * Expect alert log entry.
  586. *
  587. * @param string $expectedMessage
  588. * @param string|null $pool
  589. *
  590. * @return bool
  591. * @throws \Exception
  592. */
  593. public function expectAlert(string $expectedMessage, string $pool = null): bool
  594. {
  595. return $this->expectEntry(self::ALERT, $expectedMessage, $pool);
  596. }
  597. /**
  598. * Expect pattern in the log line.
  599. *
  600. * @param string $pattern
  601. *
  602. * @return bool
  603. * @throws \Exception
  604. */
  605. public function expectPattern(string $pattern): bool
  606. {
  607. return $this->match(
  608. function ($line) use ($pattern) {
  609. if (preg_match($pattern, $line) === 1) {
  610. $this->traceMatch("Pattern expectation", $pattern, $line);
  611. return true;
  612. }
  613. return false;
  614. },
  615. 'The search pattern not found'
  616. );
  617. }
  618. /**
  619. * Get match debug message.
  620. *
  621. * @param string $title
  622. * @param string|null $pattern
  623. * @param string|null $line
  624. * @param string|null $expectedMessage
  625. * @param string|null $actualMessage
  626. *
  627. * @return string
  628. */
  629. private function getMatchDebugMessage(
  630. string $title,
  631. string $pattern = null,
  632. string $line = null,
  633. string $expectedMessage = null,
  634. string $actualMessage = null
  635. ): string {
  636. $msg = "$title:\n";
  637. if ($pattern !== null) {
  638. $msg .= "- PATTERN: $pattern\n";
  639. }
  640. if ($line !== null) {
  641. $msg .= "- LINE: $line\n";
  642. }
  643. if ($expectedMessage !== null) {
  644. $msg .= "- EXPECTED: $expectedMessage\n";
  645. }
  646. if ($actualMessage !== null) {
  647. $msg .= "- ACTUAL: $actualMessage\n";
  648. }
  649. return $msg;
  650. }
  651. /**
  652. * Print tracing of the match.
  653. *
  654. * @param string $title
  655. * @param string|null $pattern
  656. * @param string|null $line
  657. * @param string|null $expectedMessage
  658. * @param string|null $actualMessage
  659. */
  660. private function traceMatch(
  661. string $title,
  662. string $pattern = null,
  663. string $line = null,
  664. string $expectedMessage = null,
  665. string $actualMessage = null
  666. ): void {
  667. if ($this->debug) {
  668. echo "LogTool - " . $this->getMatchDebugMessage($title, $pattern, $line, $expectedMessage, $actualMessage);
  669. }
  670. }
  671. /**
  672. * Print tracing message - only in debug .
  673. *
  674. * @param string $msg Message to print.
  675. */
  676. private function trace(string $msg): void
  677. {
  678. if ($this->debug) {
  679. print "LogTool - $msg\n";
  680. }
  681. }
  682. /**
  683. * Save error message if the line does not contain ignored string.
  684. *
  685. * @param string $msg
  686. * @param string|null $line
  687. * @param string $ignoreFor
  688. *
  689. * @return false
  690. */
  691. private function error(string $msg, string $line = null, string $ignoreFor = self::DEBUG): bool
  692. {
  693. if ($this->error === null && ($line === null || ! str_contains($line, $ignoreFor))) {
  694. $this->trace("Setting error: $msg");
  695. $this->error = $msg;
  696. }
  697. return false;
  698. }
  699. /**
  700. * Get saved error.
  701. *
  702. * @return string|null
  703. */
  704. public function getError(): ?string
  705. {
  706. return $this->error;
  707. }
  708. /**
  709. * Get saved error and clear it.
  710. *
  711. * @return string|null
  712. */
  713. public function popError(): ?string
  714. {
  715. $error = $this->error;
  716. $this->error = null;
  717. if ($error !== null) {
  718. $this->trace("Clearing error: $error");
  719. }
  720. return $error;
  721. }
  722. }