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