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\]'; 8 const P_PREFIX = '\[pool unconfined\] child \d+ said into stderr: '; 9 const P_PREFIX_STDOUT = '\[pool unconfined\] child \d+ said into stdout: '; 10 const FINAL_SUFFIX = ', pipe is closed'; 11 12 const DEBUG = 'DEBUG'; 13 const NOTICE = 'NOTICE'; 14 const WARNING = 'WARNING'; 15 const ERROR = 'ERROR'; 16 const ALERT = 'ALERT'; 17 18 /** 19 * @var string 20 */ 21 private $message; 22 23 /** 24 * @var string 25 */ 26 private $level; 27 28 /** 29 * @var int 30 */ 31 private $position; 32 33 /** 34 * @var int 35 */ 36 private $suffixPosition; 37 38 /** 39 * @var int 40 */ 41 private $limit; 42 43 /** 44 * @var string 45 */ 46 private $pattern; 47 48 /** 49 * @var string 50 */ 51 private $error; 52 53 /** 54 * @var bool 55 */ 56 private $pipeClosed = false; 57 58 /** 59 * @param string $message 60 * @param int $limit 61 * @param int $repeat 62 */ 63 public function setExpectedMessage(string $message, int $limit, int $repeat = 0) 64 { 65 $this->message = ($repeat > 0) ? str_repeat($message, $repeat) : $message; 66 $this->limit = $limit; 67 $this->position = 0; 68 } 69 70 /** 71 * @param string $level 72 * @return int 73 */ 74 public function setExpectedLevel(string $level) 75 { 76 return $this->level = $level; 77 } 78 79 /** 80 * @return string 81 */ 82 public function getExpectedLevel(): string 83 { 84 return $this->level ?: 'WARNING'; 85 } 86 87 /** 88 * @param bool $pipeClosed 89 */ 90 public function setPipeClosed(bool $pipeClosed) 91 { 92 $this->pipeClosed = $pipeClosed; 93 } 94 95 /** 96 * @param string $line 97 * @return bool 98 */ 99 public function checkTruncatedMessage(string $line) 100 { 101 if ($this->message === null) { 102 throw new \LogicException('The message has not been set'); 103 } 104 $lineLen = strlen($line); 105 if (!$this->checkLineLength($line)) { 106 return false; 107 } 108 $this->pattern = '/^PHP message: (.*?)(\.\.\.)?$/'; 109 if (preg_match($this->pattern, $line, $matches) === 0) { 110 return $this->error("Unexpected truncated message: {$line}"); 111 } 112 113 if ($lineLen === $this->limit - strlen('NOTICE: ') - 1) { 114 if (!isset($matches[2])) { 115 return $this->error("The truncated line is not ended with '...'"); 116 } 117 if (!$this->checkMessage($matches[1])) { 118 return false; 119 } 120 } else { 121 if (isset($matches[2])) { 122 // this is expecting that the expected message does not end with '...' 123 // which should not be an issue for the test purpose. 124 return $this->error("The line is complete and should not end with '...'"); 125 } 126 if (!$this->checkMessage($matches[1], -1)) { 127 return false; 128 } 129 } 130 131 return true; 132 } 133 134 /** 135 * @param array $lines 136 * @param bool $terminated 137 * @param bool $decorated 138 * @return bool 139 */ 140 public function checkWrappedMessage(array $lines, bool $terminated = true, bool $decorated = true, bool $is_stderr = true) 141 { 142 if ($this->message === null) { 143 throw new \LogicException('The message has not been set'); 144 } 145 if ($decorated) { 146 $this->pattern = sprintf( 147 '/^(%s %s: %s)"([^"]*)"(.*)?$/', 148 self::P_TIME, 149 $this->getExpectedLevel(), 150 $is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT 151 ); 152 } else { 153 $this->pattern = null; 154 } 155 156 $idx = 0; 157 foreach ($lines as $idx => $line) { 158 if (!$this->checkLine($line)) { 159 break; 160 } 161 } 162 163 if ($this->suffixPosition > 0) { 164 $suffixPattern = sprintf( 165 '/^%s %s: %s(.*)$/', 166 self::P_TIME, $this->getExpectedLevel(), 167 $is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT 168 ); 169 $line = $lines[++$idx]; 170 if (preg_match($suffixPattern, $line, $matches) === 0) { 171 return $this->error("Unexpected line: $line"); 172 } 173 if ($matches[1] !== substr(self::FINAL_SUFFIX, $this->suffixPosition)) { 174 return $this->error( 175 "The suffix has not been finished from position $this->suffixPosition in line: $line" 176 ); 177 } 178 } 179 180 if ($terminated) { 181 return $this->expectTerminatorLines($lines, $idx); 182 } 183 184 return true; 185 } 186 187 /** 188 * @param string $line 189 * @return bool 190 */ 191 private function checkLine(string $line) 192 { 193 if ($this->pattern === null) { 194 // plain (not decorated) output 195 $out = rtrim($line); 196 $finalSuffix = null; 197 } elseif (($res = preg_match($this->pattern, $line, $matches)) > 0) { 198 $out = $matches[2]; 199 $finalSuffix = $matches[3] ?? false; 200 } else { 201 return $this->error("Unexpected line: $line"); 202 } 203 204 $rem = strlen($this->message) - $this->position; 205 $lineLen = strlen($line); 206 if (!$this->checkLineLength($line, $lineLen)) { 207 return false; 208 } 209 if (!$this->checkMessage($out, $this->position)) { 210 return false; 211 } 212 $outLen = strlen($out); 213 if ($rem > $outLen) { // continuous line 214 if ($lineLen !== $this->limit) { 215 if ($lineLen + ($rem - $outLen) < $this->limit) { 216 return $this->error("Printed less than the message len"); 217 } 218 return $this->error( 219 "The continuous line length is $lineLen but it should equal to limit $this->limit" 220 ); 221 } 222 $this->position += $outLen; 223 return true; 224 } 225 if ($rem !== $outLen) { 226 return $this->error("Printed more than the message len"); 227 } 228 if (!$this->pipeClosed || $finalSuffix === null) { 229 return false; 230 } 231 if ($finalSuffix === false) { 232 return $this->error("No final suffix"); 233 } 234 if (empty($finalSuffix) || strpos(self::FINAL_SUFFIX, $finalSuffix) === false) { 235 return $this->error("The final suffix has to be equal to ', pipe is closed'"); 236 } 237 if (self::FINAL_SUFFIX !== $finalSuffix) { 238 $this->suffixPosition = strlen($finalSuffix); 239 } 240 // complete final suffix printed 241 return false; 242 } 243 244 /** 245 * @param string $line 246 * @param int $lineLen 247 * @return bool 248 */ 249 private function checkLineLength(string $line, $lineLen = null) { 250 $lineLen = $lineLen ?: strlen($line); 251 if ($lineLen > $this->limit) { 252 return $this->error( 253 "The line length is $lineLen which is higher than limit $this->limit" 254 ); 255 } 256 257 return true; 258 } 259 260 /** 261 * @param string $matchedMessage 262 * @param int $expectedMessageStart 263 * @return bool 264 */ 265 private function checkMessage(string $matchedMessage, int $expectedMessageStart = 0) 266 { 267 if ($expectedMessageStart < 0) { 268 $expectedMessage = $this->message; 269 } else { 270 $expectedMessage = substr($this->message, $expectedMessageStart, strlen($matchedMessage)); 271 } 272 if ($expectedMessage !== $matchedMessage) { 273 return $this->error( 274 sprintf( 275 "The actual string(%d) does not match expected string(%d):\n", 276 strlen($matchedMessage), 277 strlen($expectedMessage) 278 ) . 279 "- EXPECT: '$expectedMessage'\n" . 280 "- ACTUAL: '$matchedMessage'" 281 ); 282 } 283 284 return true; 285 } 286 287 /** 288 * @param array $lines 289 * @return bool 290 */ 291 public function expectReloadingLines(array $lines) 292 { 293 if ( 294 !$this->expectNotice($lines[0], 'Reloading in progress ...') || 295 !$this->expectNotice($lines[1], 'reloading: .*') 296 ) { 297 return false; 298 } 299 300 for ($i = 2; $i < count($lines) - 2; $i++) { 301 if (!$this->expectNotice($lines[$i], 'using inherited socket fd=\d+, "[^"]+"')) { 302 return false; 303 } 304 } 305 306 return $this->expectStartingLines(array_splice($lines, $i)); 307 } 308 309 /** 310 * @param array $lines 311 * @return bool 312 */ 313 public function expectStartingLines(array $lines) 314 { 315 if ($this->getError()) { 316 return false; 317 } 318 319 if (count($lines) < 2) { 320 return $this->error("No starting lines"); 321 } 322 323 return ( 324 $this->expectNotice($lines[0], 'fpm is running, pid \d+') && 325 $this->expectNotice($lines[1], 'ready to handle connections') 326 ); 327 } 328 329 /** 330 * @param array $lines 331 * @param int $idx 332 * @return bool 333 */ 334 public function expectTerminatorLines(array $lines, int $idx = -1) 335 { 336 if ($this->getError()) { 337 return false; 338 } 339 340 if (count($lines) - $idx < 3) { 341 return $this->error("No terminating lines"); 342 } 343 344 return ( 345 $this->expectNotice($lines[++$idx], 'Terminating ...') && 346 $this->expectNotice($lines[++$idx], 'exiting, bye-bye!') 347 ); 348 } 349 350 /** 351 * @param string $type 352 * @param string $line 353 * @param string $expectedMessage 354 * @param string|null $pool 355 * @return bool 356 */ 357 public function expectEntry(string $type, string $line, string $expectedMessage, $pool = null) 358 { 359 if ($this->getError()) { 360 return false; 361 } 362 if ($pool !== null) { 363 $expectedMessage = '\[pool ' . $pool . '\] ' . $expectedMessage; 364 } 365 366 $line = rtrim($line); 367 $pattern = sprintf('/^%s %s: %s$/', self::P_TIME, $type, $expectedMessage); 368 369 if (preg_match($pattern, $line, $matches) === 0) { 370 return $this->error( 371 "The $type does not match expected message:\n" . 372 "- PATTERN: $pattern\n" . 373 "- MESSAGE: $line\n" . 374 "- EXPECT: '$expectedMessage'\n" . 375 "- ACTUAL: '" . substr($line, strpos($line, $type) + strlen($type) + 2) . "'" 376 ); 377 } 378 379 return true; 380 } 381 382 /** 383 * @param string $line 384 * @param string $expectedMessage 385 * @param string|null $pool 386 * @return bool 387 */ 388 public function expectDebug(string $line, string $expectedMessage, $pool = null) 389 { 390 return $this->expectEntry(self::DEBUG, $line, $expectedMessage, $pool); 391 } 392 393 /** 394 * @param string $line 395 * @param string $expectedMessage 396 * @param string|null $pool 397 * @return bool 398 */ 399 public function expectNotice(string $line, string $expectedMessage, $pool = null) 400 { 401 return $this->expectEntry(self::NOTICE, $line, $expectedMessage, $pool); 402 } 403 404 /** 405 * @param string $line 406 * @param string $expectedMessage 407 * @param string|null $pool 408 * @return bool 409 */ 410 public function expectWarning(string $line, string $expectedMessage, $pool = null) 411 { 412 return $this->expectEntry(self::WARNING, $line, $expectedMessage, $pool); 413 } 414 415 /** 416 * @param string $line 417 * @param string $expectedMessage 418 * @param string|null $pool 419 * @return bool 420 */ 421 public function expectError(string $line, string $expectedMessage, $pool = null) 422 { 423 return $this->expectEntry(self::ERROR, $line, $expectedMessage, $pool); 424 } 425 426 /** 427 * @param string $line 428 * @param string $expectedMessage 429 * @param string|null $pool 430 * @return bool 431 */ 432 public function expectAlert(string $line, string $expectedMessage, $pool = null) 433 { 434 return $this->expectEntry(self::ALERT, $line, $expectedMessage, $pool); 435 } 436 437 /** 438 * @param string $msg 439 * @return bool 440 */ 441 private function error(string $msg) 442 { 443 $this->error = $msg; 444 echo "ERROR: $msg\n"; 445 return false; 446 } 447 448 /** 449 * @return string 450 */ 451 public function getError() 452 { 453 return $this->error; 454 } 455} 456 457if (isset($argv[1]) && $argv[1] === 'logtool-selftest') { 458 $cases = [ 459 [ 460 'limit' => 1050, 461 'lines' => [ 462 '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . 463 str_repeat('a', 968) . '"', 464 '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . 465 str_repeat('a', 968) . '"', 466 '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . 467 str_repeat('a', 112) . '", pipe is closed', 468 '[08-Oct-2017 19:53:55] NOTICE: Terminating ...', 469 '[08-Oct-2017 19:53:55] NOTICE: exiting, bye-bye!', 470 ], 471 'message' => str_repeat('a', 2048), 472 'type' => 'stdio', 473 ], 474 [ 475 'limit' => 1050, 476 'lines' => [ 477 '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . 478 str_repeat('a', 968) . '"', 479 '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . 480 str_repeat('a', 968) . '"', 481 '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: "' . 482 str_repeat('a', 964) . '", pi', 483 '[08-Oct-2017 19:53:50] WARNING: [pool unconfined] child 23183 said into stderr: pe is closed', 484 '[08-Oct-2017 19:53:55] NOTICE: Terminating ...', 485 '[08-Oct-2017 19:53:55] NOTICE: exiting, bye-bye!', 486 ], 487 'message' => str_repeat('a', 2900), 488 'type' => 'stdio', 489 ], 490 [ 491 'limit' => 1024, 492 'line' => '[08-Oct-2017 19:53:50] WARNING: ' . str_repeat('a',989) . '...', 493 'message' => str_repeat('a', 2900), 494 'type' => 'message', 495 ], 496 [ 497 'limit' => 1024, 498 'line' => '[08-Oct-2017 19:53:50] WARNING: ' . str_repeat('a',20), 499 'message' => str_repeat('a', 20), 500 'type' => 'message', 501 ], 502 ]; 503 foreach ($cases as $case) { 504 printf("Test message with len %d and limit %d: ", strlen($case['message']), $case['limit']); 505 $logTool = new LogTool(); 506 $logTool->setExpectedMessage($case['message'], $case['limit']); 507 if ($case['type'] === 'stdio') { 508 $logTool->checkWrappedMessage($case['lines']); 509 } else { 510 $logTool->checkTruncatedMessage($case['line']); 511 } 512 if (!$logTool->getError()) { 513 echo "OK\n"; 514 } 515 } 516 echo "Done\n"; 517} 518
