logtool.inc 15 KB

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