diff --git a/src/AccessLogHandler.php b/src/AccessLogHandler.php index a8d6e80..74052c0 100644 --- a/src/AccessLogHandler.php +++ b/src/AccessLogHandler.php @@ -2,7 +2,7 @@ namespace FrameworkX; -use FrameworkX\Io\SapiHandler; +use FrameworkX\Io\LogStreamHandler; use Psr\Http\Message\ResponseInterface; use Psr\Http\Message\ServerRequestInterface; use React\Http\Message\Response; @@ -14,15 +14,17 @@ */ class AccessLogHandler { - /** @var SapiHandler */ - private $sapi; + /** @var LogStreamHandler */ + private $logger; /** @var bool */ private $hasHighResolution; + /** @throws void */ public function __construct() { - $this->sapi = new SapiHandler(); + /** @throws void because `fopen()` is known to always return a `resource` for built-in wrappers */ + $this->logger = new LogStreamHandler(\PHP_SAPI === 'cli' ? 'php://output' : 'php://stderr'); $this->hasHighResolution = \function_exists('hrtime'); // PHP 7.3+ } @@ -85,7 +87,7 @@ private function log(ServerRequestInterface $request, ResponseInterface $respons $responseSize = 0; } - $this->sapi->log( + $this->logger->log( ($request->getAttribute('remote_addr') ?? $request->getServerParams()['REMOTE_ADDR'] ?? '-') . ' ' . '"' . $this->escape($method) . ' ' . $this->escape($request->getRequestTarget()) . ' HTTP/' . $request->getProtocolVersion() . '" ' . $status . ' ' . $responseSize . ' ' . sprintf('%.3F', $time < 0 ? 0 : $time) diff --git a/src/App.php b/src/App.php index 9a03917..7f50a33 100644 --- a/src/App.php +++ b/src/App.php @@ -3,6 +3,7 @@ namespace FrameworkX; use FrameworkX\Io\FiberHandler; +use FrameworkX\Io\LogStreamHandler; use FrameworkX\Io\MiddlewareHandler; use FrameworkX\Io\RedirectHandler; use FrameworkX\Io\RouteHandler; @@ -24,9 +25,12 @@ class App /** @var RouteHandler */ private $router; - /** @var SapiHandler */ + /** @var ?SapiHandler */ private $sapi; + /** @var ?LogStreamHandler */ + private $logger; + /** @var Container */ private $container; @@ -115,7 +119,8 @@ public function __construct(...$middleware) $this->router = new RouteHandler($this->container); $handlers[] = $this->router; $this->handler = new MiddlewareHandler($handlers); - $this->sapi = new SapiHandler(); + $this->sapi = (\PHP_SAPI !== 'cli' ? new SapiHandler() : null); + $this->logger = (\PHP_SAPI === 'cli' ? new LogStreamHandler('php://output') : null); } /** @@ -231,6 +236,9 @@ public function run(): void private function runLoop(): void { + $logger = $this->logger; + assert($logger instanceof LogStreamHandler); + $http = new HttpServer(function (ServerRequestInterface $request) { return $this->handleRequest($request); }); @@ -240,31 +248,31 @@ private function runLoop(): void $socket = new SocketServer($listen); $http->listen($socket); - $this->sapi->log('Listening on ' . \str_replace('tcp:', 'http:', (string) $socket->getAddress())); + $logger->log('Listening on ' . \str_replace('tcp:', 'http:', (string) $socket->getAddress())); - $http->on('error', function (\Exception $e): void { - $this->sapi->log('HTTP error: ' . $e->getMessage()); + $http->on('error', static function (\Exception $e) use ($logger): void { + $logger->log('HTTP error: ' . $e->getMessage()); }); // @codeCoverageIgnoreStart try { - Loop::addSignal(\defined('SIGINT') ? \SIGINT : 2, $f1 = function () use ($socket) { + Loop::addSignal(\defined('SIGINT') ? \SIGINT : 2, $f1 = static function () use ($socket, $logger) { if (\PHP_VERSION_ID >= 70200 && \stream_isatty(\STDIN)) { echo "\r"; } - $this->sapi->log('Received SIGINT, stopping loop'); + $logger->log('Received SIGINT, stopping loop'); $socket->close(); Loop::stop(); }); - Loop::addSignal(\defined('SIGTERM') ? \SIGTERM : 15, $f2 = function () use ($socket) { - $this->sapi->log('Received SIGTERM, stopping loop'); + Loop::addSignal(\defined('SIGTERM') ? \SIGTERM : 15, $f2 = static function () use ($socket, $logger) { + $logger->log('Received SIGTERM, stopping loop'); $socket->close(); Loop::stop(); }); } catch (\BadMethodCallException $e) { - $this->sapi->log('Notice: No signal handler support, installing ext-ev or ext-pcntl recommended for production use.'); + $logger->log('Notice: No signal handler support, installing ext-ev or ext-pcntl recommended for production use.'); } // @codeCoverageIgnoreEnd @@ -273,7 +281,7 @@ private function runLoop(): void if ($socket->getAddress() !== null) { // Fiber compatibility mode for PHP < 8.1: Restart loop as long as socket is available - $this->sapi->log('Warning: Loop restarted. Upgrade to react/async v4 recommended for production use.'); + $logger->log('Warning: Loop restarted. Upgrade to react/async v4 recommended for production use.'); } else { break; } @@ -286,6 +294,7 @@ private function runLoop(): void private function runOnce(): void { + assert($this->sapi instanceof SapiHandler); $request = $this->sapi->requestFromGlobals(); $response = $this->handleRequest($request); @@ -294,6 +303,7 @@ private function runOnce(): void $this->sapi->sendResponse($response); } elseif ($response instanceof PromiseInterface) { $response->then(function (ResponseInterface $response) { + assert($this->sapi instanceof SapiHandler); $this->sapi->sendResponse($response); }); } diff --git a/src/Io/LogStreamHandler.php b/src/Io/LogStreamHandler.php new file mode 100644 index 0000000..5ef078b --- /dev/null +++ b/src/Io/LogStreamHandler.php @@ -0,0 +1,45 @@ +stream = $stream; + } + + public function log(string $message): void + { + $time = \microtime(true); + $prefix = \date('Y-m-d H:i:s', (int) $time) . \sprintf('.%03d ', (int) (($time - (int) $time) * 1e3)); + + $ret = \fwrite($this->stream, $prefix . $message . \PHP_EOL); + assert(\is_int($ret)); + } +} diff --git a/src/Io/SapiHandler.php b/src/Io/SapiHandler.php index ece6ee1..7170f89 100644 --- a/src/Io/SapiHandler.php +++ b/src/Io/SapiHandler.php @@ -13,15 +13,6 @@ */ class SapiHandler { - /** @var resource */ - private $logStream; - - public function __construct() - { - // @phpstan-ignore-next-line because `fopen()` is known to always return a `resource` for built-in wrappers - $this->logStream = PHP_SAPI === 'cli' ? \fopen('php://output', 'a') : (\defined('STDERR') ? \STDERR : \fopen('php://stderr', 'a')); - } - public function requestFromGlobals(): ServerRequestInterface { $host = null; @@ -140,12 +131,4 @@ public function sendResponse(ResponseInterface $response): void echo $body; } } - - public function log(string $message): void - { - $time = microtime(true); - $log = date('Y-m-d H:i:s', (int)$time) . sprintf('.%03d ', (int)(($time - (int)$time) * 1e3)) . $message . PHP_EOL; - - fwrite($this->logStream, $log); - } } diff --git a/tests/AccessLogHandlerTest.php b/tests/AccessLogHandlerTest.php index 56e45e2..338486e 100644 --- a/tests/AccessLogHandlerTest.php +++ b/tests/AccessLogHandlerTest.php @@ -3,6 +3,7 @@ namespace FrameworkX\Tests; use FrameworkX\AccessLogHandler; +use FrameworkX\Io\LogStreamHandler; use PHPUnit\Framework\TestCase; use React\Http\Message\Response; use React\Http\Message\ServerRequest; @@ -11,134 +12,200 @@ class AccessLogHandlerTest extends TestCase { - public function testInvokePrintsRequestLogWithCurrentDateAndTime(): void + public function testInvokeLogsRequest(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], "Hello\n"); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 200 6 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 200 6 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 200 6 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsRequestWithQueryParametersLogWithCurrentDateAndTime(): void + public function testInvokeLogsRequestWithEncodedQueryParameters(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/?a=1&b=hello wörld', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], "Hello\n"); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /?a=1&b=hello%20w%C3%B6rld HTTP/1.1" 200 6 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/\?a=1&b=hello%20w%C3%B6rld HTTP\/1\.1\" 200 6 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /\?a=1&b=hello%20w%C3%B6rld HTTP/1\.1" 200 6 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsRequestWithEscapedSpecialCharactersInRequestMethodAndTargetWithCurrentDateAndTime(): void + public function testInvokeLogsRequestWithEscapedSpecialCharactersInRequestMethodAndTarget(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GE"T', 'http://localhost:8080/wörld', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $request = $request->withRequestTarget('/wörld'); $response = new Response(200, [], "Hello\n"); // 2021-01-29 12:22:01.717 127.0.0.1 "GE\x22T /w\xC3\xB6rld HTTP/1.1" 200 6 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GE\\\\x22T \/w\\\\xC3\\\\xB6rld HTTP\/1\.1\" 200 6 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GE\\\\x22T /w\\\\xC3\\\\xB6rld HTTP/1\.1" 200 6 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsRequestLogForHeadRequestWithResponseSizeAsZero(): void + public function testInvokeLogsRequestForHeadRequestWithResponseSizeAsZero(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('HEAD', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], "HEAD\n"); // 2021-01-29 12:22:01.717 127.0.0.1 "HEAD /users HTTP/1.1" 200 0 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"HEAD \/users HTTP\/1\.1\" 200 0 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "HEAD /users HTTP/1\.1" 200 0 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsRequestLogForNoContentResponseWithResponseSizeAsZero(): void + public function testInvokeLogsRequestForNoContentResponseWithResponseSizeAsZero(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(204, [], "No Content\n"); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 204 0 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 204 0 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 204 0 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsRequestLogForNotModifiedResponseWithResponseSizeAsZero(): void + public function testInvokeLogsRequestForNotModifiedResponseWithResponseSizeAsZero(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(304, [], "Not Modified\n"); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 304 0 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 304 0 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 304 0 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsPlainProxyRequestLogWithCurrentDateAndTime(): void + public function testInvokeWithPlainProxyRequestLogsRequestWithRequestTargetInOriginForm(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $request = $request->withRequestTarget('http://localhost:8080/users'); $response = new Response(400, [], ""); // 2021-01-29 12:22:01.717 127.0.0.1 "GET http://localhost:8080/users HTTP/1.1" 400 0 0.000\n - $this->expectOutputRegex("#^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET http://localhost:8080/users HTTP/1\.1\" 400 0 0\.0\d\d" . PHP_EOL . "$#"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET http://localhost:8080/users HTTP/1\.1" 400 0 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsConnectProxyRequestLogWithCurrentDateAndTime(): void + public function testInvokeWithConnectProxyRequestLogsRequestWithRequestTargetInAuthorityForm(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('CONNECT', 'example.com:8080', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $request = $request->withRequestTarget('example.com:8080'); $response = new Response(400, [], ""); // 2021-01-29 12:22:01.717 127.0.0.1 "CONNECT example.com:8080 HTTP/1.1" 400 0 0.000\n - $this->expectOutputRegex("#^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"CONNECT example.com:8080 HTTP/1\.1\" 400 0 0\.0\d\d" . PHP_EOL . "$#"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "CONNECT example.com:8080 HTTP/1\.1" 400 0 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokePrintsOptionsAsteriskLogWithCurrentDateAndTime(): void + public function testInvokeWithOptionsAsteriskRequestLogsRequestWithRequestTargetAsteriskForm(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('OPTIONS', 'http://example.com:8080', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $request = $request->withRequestTarget('*'); $response = new Response(400, [], ""); // 2021-01-29 12:22:01.717 127.0.0.1 "OPTIONS * HTTP/1.1" 400 0 0.000\n - $this->expectOutputRegex("#^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"OPTIONS \* HTTP/1\.1\" 400 0 0\.0\d\d" . PHP_EOL . "$#"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "OPTIONS \* HTTP/1\.1" 400 0 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokeWithDeferredNextPrintsRequestLogWithCurrentDateAndTime(): void + public function testInvokeWithDeferredNextLogsRequest(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], "Hello\n"); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 200 6 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 200 6 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 200 6 0\.0\d\d$#')); $handler($request, function () use ($response) { return resolve($response); }); } - public function testInvokeWithCoroutineNextPrintsRequestLogWithCurrentDateAndTime(): void + public function testInvokeWithCoroutineNextLogsRequest(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], "Hello\n"); @@ -153,52 +220,70 @@ public function testInvokeWithCoroutineNextPrintsRequestLogWithCurrentDateAndTim $this->assertInstanceOf(\Generator::class, $generator); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 200 6 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 200 6 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 200 6 0\.0\d\d$#')); $generator->next(); } - public function testInvokeWithStreamingResponsePrintsRequestLogWithCurrentDateAndTime(): void + public function testInvokeWithStreamingResponseLogsRequest(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $stream = new ThroughStream(); $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], $stream); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 200 10 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 200 10 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 200 10 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); $stream->write('hello'); $stream->end('world'); } - public function testInvokeWithStreamingResponseThatClosesAfterSomeTimePrintsRequestLogWithCurrentDateAndTime(): void + public function testInvokeWithStreamingResponseThatClosesAfterSomeTimeLogsRequest(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $stream = new ThroughStream(); $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], $stream); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 200 0 0.100\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 200 0 0\.1\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 200 0 0\.1\d\d$#')); $handler($request, function () use ($response) { return $response; }); usleep(150000); // 100ms + 50ms to account for inaccurate clocks $stream->end(); } - public function testInvokeWithClosedStreamingResponsePrintsRequestLogWithCurrentDateAndTime(): void + public function testInvokeWithClosedStreamingResponseLogsRequest(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $stream = new ThroughStream(); $stream->close(); $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], $stream); // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 200 0 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 127\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 200 0 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^127\.0\.0\.1 "GET /users HTTP/1\.1" 200 0 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } @@ -206,6 +291,12 @@ public function testInvokeWithStreamingResponsePrintsNothingIfStreamIsPending(): { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $stream = new ThroughStream(); $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $response = new Response(200, [], $stream); @@ -215,28 +306,40 @@ public function testInvokeWithStreamingResponsePrintsNothingIfStreamIsPending(): $stream->write('hello'); } - public function testInvokeWithRemoteAddrAttributePrintsRequestLogWithIpFromAttribute(): void + public function testInvokeWithRemoteAddrAttributeLogsRequestWithIpFromAttribute(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users', [], '', '1.1', ['REMOTE_ADDR' => '127.0.0.1']); $request = $request->withAttribute('remote_addr', '10.0.0.1'); $response = new Response(200, [], "Hello\n"); // 2021-01-29 12:22:01.717 10.0.0.1 "GET /users HTTP/1.1" 200 6 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} 10\.0\.0\.1 \"GET \/users HTTP\/1\.1\" 200 6 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^10\.0\.0\.1 "GET /users HTTP/1\.1" 200 6 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } - public function testInvokeWithoutRemoteAddressPrintsRequestLogWithDashAsPlaceholder(): void + public function testInvokeWithoutRemoteAddressLogsRequestWithDashAsPlaceholder(): void { $handler = new AccessLogHandler(); + $logger = $this->createMock(LogStreamHandler::class); + // $handler->logger = $logger; + $ref = new \ReflectionProperty($handler, 'logger'); + $ref->setAccessible(true); + $ref->setValue($handler, $logger); + $request = new ServerRequest('GET', 'http://localhost:8080/users'); $response = new Response(200, [], "Hello\n"); // 2021-01-29 12:22:01.717 - "GET /users HTTP/1.1" 200 6 0.000\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} - \"GET \/users HTTP\/1\.1\" 200 6 0\.0\d\d" . PHP_EOL . "$/"); + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('#^- "GET /users HTTP/1\.1" 200 6 0\.0\d\d$#')); $handler($request, function () use ($response) { return $response; }); } } diff --git a/tests/AppTest.php b/tests/AppTest.php index bc20eba..8135255 100644 --- a/tests/AppTest.php +++ b/tests/AppTest.php @@ -37,6 +37,7 @@ use function React\Async\await; use function React\Promise\reject; use function React\Promise\resolve; +use FrameworkX\Io\LogStreamHandler; class AppTest extends TestCase { @@ -623,6 +624,14 @@ public function testRunWillReportListeningAddressAndRunLoopWithSocketServer(): v $app = new App(); + $logger = $this->createMock(LogStreamHandler::class); + $logger->expects($this->atLeastOnce())->method('log')->withConsecutive(['Listening on http://127.0.0.1:8080']); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); + // lovely: remove socket server on next tick to terminate loop Loop::futureTick(function () { $resources = get_resources(); @@ -635,7 +644,6 @@ public function testRunWillReportListeningAddressAndRunLoopWithSocketServer(): v Loop::stop(); }); - $this->expectOutputRegex('/' . preg_quote('Listening on http://127.0.0.1:8080' . PHP_EOL, '/') . '.*/'); $app->run(); } @@ -652,6 +660,14 @@ public function testRunWillReportListeningAddressFromContainerEnvironmentAndRunL $app = new App($container); + $logger = $this->createMock(LogStreamHandler::class); + $logger->expects($this->atLeastOnce())->method('log')->withConsecutive(['Listening on http://' . $addr]); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); + // lovely: remove socket server on next tick to terminate loop Loop::futureTick(function () { $resources = get_resources(); @@ -664,7 +680,6 @@ public function testRunWillReportListeningAddressFromContainerEnvironmentAndRunL Loop::stop(); }); - $this->expectOutputRegex('/' . preg_quote('Listening on http://' . $addr . PHP_EOL, '/') . '.*/'); $app->run(); } @@ -676,6 +691,14 @@ public function testRunWillReportListeningAddressFromContainerEnvironmentWithRan $app = new App($container); + $logger = $this->createMock(LogStreamHandler::class); + $logger->expects($this->atLeastOnce())->method('log')->withConsecutive([$this->matches('Listening on http://127.0.0.1:%d')]); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); + // lovely: remove socket server on next tick to terminate loop Loop::futureTick(function () { $resources = get_resources(); @@ -688,7 +711,6 @@ public function testRunWillReportListeningAddressFromContainerEnvironmentWithRan Loop::stop(); }); - $this->expectOutputRegex('/' . preg_quote('Listening on http://127.0.0.1:', '/') . '\d+' . PHP_EOL . '.*/'); $app->run(); } @@ -700,8 +722,15 @@ public function testRunWillRestartLoopUntilSocketIsClosed(): void $app = new App($container); + $logger = $this->createMock(LogStreamHandler::class); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); + // lovely: remove socket server on next tick to terminate loop - Loop::futureTick(function () { + Loop::futureTick(function () use ($logger) { $resources = get_resources(); $socket = end($resources); assert(is_resource($socket)); @@ -713,10 +742,10 @@ public function testRunWillRestartLoopUntilSocketIsClosed(): void Loop::stop(); }); + $logger->expects($this->once())->method('log')->with('Warning: Loop restarted. Upgrade to react/async v4 recommended for production use.'); Loop::stop(); }); - $this->expectOutputRegex('/' . preg_quote('Warning: Loop restarted. Upgrade to react/async v4 recommended for production use.' . PHP_EOL, '/') . '$/'); $app->run(); } @@ -732,7 +761,14 @@ public function testRunWillListenForHttpRequestAndSendBackHttpResponseOverSocket 'X_LISTEN' => $addr ]); - $app = new App($container); + $app = $this->createAppWithoutLogger($container); + + $logger = $this->createMock(LogStreamHandler::class); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); Loop::futureTick(function () use ($addr): void { $connector = new Connector(); @@ -759,7 +795,6 @@ public function testRunWillListenForHttpRequestAndSendBackHttpResponseOverSocket }); }); - $this->expectOutputRegex('/' . preg_quote('Listening on http://' . $addr . PHP_EOL, '/') . '.*/'); $app->run(); } @@ -777,9 +812,17 @@ public function testRunWillReportHttpErrorForInvalidClientRequest(): void $app = new App($container); - Loop::futureTick(function () use ($addr): void { + $logger = $this->createMock(LogStreamHandler::class); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); + + Loop::futureTick(function () use ($addr, $logger): void { $connector = new Connector(); - $connector->connect($addr)->then(function (ConnectionInterface $connection): void { + $connector->connect($addr)->then(function (ConnectionInterface $connection) use ($logger): void { + $logger->expects($this->once())->method('log')->with($this->matchesRegularExpression('/^HTTP error: .*$/')); $connection->write("not a valid HTTP request\r\n\r\n"); // lovely: remove socket server on client connection close to terminate loop @@ -798,7 +841,6 @@ public function testRunWillReportHttpErrorForInvalidClientRequest(): void }); }); - $this->expectOutputRegex('/HTTP error: .*' . PHP_EOL . '$/'); $app->run(); } @@ -814,13 +856,23 @@ public function testRunWillStopWhenReceivingSigint(): void $app = new App($container); - Loop::futureTick(function () { + $logger = $this->createMock(LogStreamHandler::class); + $logger->expects($this->exactly(2))->method('log'); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); + + Loop::futureTick(function () use ($logger) { + $logger->expects($this->once())->method('log')->with('Received SIGINT, stopping loop'); + $pid = getmypid(); assert(is_int($pid)); posix_kill($pid, defined('SIGINT') ? SIGINT : 2); }); - $this->expectOutputRegex('/' . preg_quote('Received SIGINT, stopping loop' . PHP_EOL, '/') . '$/'); + $this->expectOutputRegex("#^\r?$#"); $app->run(); } @@ -836,13 +888,21 @@ public function testRunWillStopWhenReceivingSigterm(): void $app = new App($container); - Loop::futureTick(function () { + $logger = $this->createMock(LogStreamHandler::class); + + // $app->logger = $logger; + $ref = new \ReflectionProperty($app, 'logger'); + $ref->setAccessible(true); + $ref->setValue($app, $logger); + + Loop::futureTick(function () use ($logger) { + $logger->expects($this->once())->method('log')->with('Received SIGTERM, stopping loop'); + $pid = getmypid(); assert(is_int($pid)); posix_kill($pid, defined('SIGTERM') ? SIGTERM : 15); }); - $this->expectOutputRegex('/' . preg_quote('Received SIGTERM, stopping loop' . PHP_EOL, '/') . '$/'); $app->run(); } @@ -854,7 +914,6 @@ public function testRunAppWithEmptyAddressThrows(): void $app = new App($container); - $this->expectException(\InvalidArgumentException::class); $app->run(); } @@ -2201,9 +2260,9 @@ public function testHandleRequestWithMatchingRouteReturnsInternalServerErrorResp $this->assertStringContainsString("

Expected request handler to return Psr\Http\Message\ResponseInterface but got null.

\n", (string) $response->getBody()); } - private function createAppWithoutLogger(): App + private function createAppWithoutLogger(callable ...$middleware): App { - $app = new App(); + $app = new App(...$middleware); $ref = new \ReflectionProperty($app, 'handler'); $ref->setAccessible(true); diff --git a/tests/Io/LogStreamHandlerTest.php b/tests/Io/LogStreamHandlerTest.php new file mode 100644 index 0000000..8bb6461 --- /dev/null +++ b/tests/Io/LogStreamHandlerTest.php @@ -0,0 +1,68 @@ +log('Hello'); + + $ref = new \ReflectionProperty($logger, 'stream'); + $ref->setAccessible(true); + $stream = $ref->getValue($logger); + assert(is_resource($stream)); + + rewind($stream); + $output = stream_get_contents($stream); + assert(is_string($output)); + + // 2021-01-29 12:22:01.717 Hello\n + if (method_exists($this, 'assertMatchesRegularExpression')) { + $this->assertMatchesRegularExpression("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} Hello" . PHP_EOL . "$/", $output); // @phpstan-ignore-line + } else { + // legacy PHPUnit < 9.1 + $this->assertRegExp("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} Hello" . PHP_EOL . "$/", $output); + } + } + + public function testLogWithOutputStreamPrintsMessageWithCurrentDateAndTime(): void + { + $logger = new LogStreamHandler('php://output'); + + // 2021-01-29 12:22:01.717 Hello\n + $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} Hello" . PHP_EOL . "$/"); + $logger->log('Hello'); + } + + public function testCtorWithDirectoryInsteadOfFileThrowsWithoutCallingGlobalErrorHandler(): void + { + $called = 0; + set_error_handler($new = function () use (&$called): bool { + ++$called; + return false; + }); + + try { + try { + new LogStreamHandler(__DIR__); + } finally { + $previous = set_error_handler(function (): bool { return false; }); + restore_error_handler(); + restore_error_handler(); + } + $this->fail(); + } catch (\RuntimeException $e) { + $errstr = DIRECTORY_SEPARATOR === '\\' ? 'Permission denied' : 'Is a directory'; + $this->assertEquals('Unable to open log file "' . __DIR__ . '": ' . $errstr, $e->getMessage()); + + $this->assertEquals(0, $called); + $this->assertSame($new, $previous ?? null); + } + } +} diff --git a/tests/Io/SapiHandlerTest.php b/tests/Io/SapiHandlerTest.php index 71a5f15..8603cce 100644 --- a/tests/Io/SapiHandlerTest.php +++ b/tests/Io/SapiHandlerTest.php @@ -379,13 +379,4 @@ public function testSendResponseSetsMultipleCookieHeaders(): void $this->assertEquals(['Content-Type:', 'Set-Cookie: 1=1', 'Set-Cookie: 2=2'], xdebug_get_headers()); } - - public function testLogPrintsMessageWithCurrentDateAndTime(): void - { - // 2021-01-29 12:22:01.717 Hello\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} Hello" . PHP_EOL . "$/"); - - $sapi = new SapiHandler(); - $sapi->log('Hello'); - } }