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