logtool.inc 14 KB

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