diff --git a/src/AccessLogHandler.php b/src/AccessLogHandler.php index 30a86b8..672594a 100644 --- a/src/AccessLogHandler.php +++ b/src/AccessLogHandler.php @@ -15,9 +15,13 @@ class AccessLogHandler /** @var SapiHandler */ private $sapi; + /** @var bool */ + private $hasHighResolution; + public function __construct() { $this->sapi = new SapiHandler(); + $this->hasHighResolution = \function_exists('hrtime'); // PHP 7.3+ } /** @@ -25,21 +29,22 @@ public function __construct() */ public function __invoke(ServerRequestInterface $request, callable $next) { + $now = $this->now(); $response = $next($request); if ($response instanceof PromiseInterface) { - return $response->then(function (ResponseInterface $response) use ($request) { - $this->logWhenClosed($request, $response); + return $response->then(function (ResponseInterface $response) use ($request, $now) { + $this->logWhenClosed($request, $response, $now); return $response; }); } elseif ($response instanceof \Generator) { - return (function (\Generator $generator) use ($request) { + return (function (\Generator $generator) use ($request, $now) { $response = yield from $generator; - $this->logWhenClosed($request, $response); + $this->logWhenClosed($request, $response, $now); return $response; })($response); } else { - $this->logWhenClosed($request, $response); + $this->logWhenClosed($request, $response, $now); return $response; } } @@ -47,7 +52,7 @@ public function __invoke(ServerRequestInterface $request, callable $next) /** * checks if response body is closed (not streaming) before writing log message for response */ - private function logWhenClosed(ServerRequestInterface $request, ResponseInterface $response): void + private function logWhenClosed(ServerRequestInterface $request, ResponseInterface $response, float $start): void { $body = $response->getBody(); @@ -57,23 +62,23 @@ private function logWhenClosed(ServerRequestInterface $request, ResponseInterfac $size += strlen($chunk); }); - $body->on('close', function () use (&$size, $request, $response) { - $this->log($request, $response, $size); + $body->on('close', function () use (&$size, $request, $response, $start) { + $this->log($request, $response, $size, $this->now() - $start); }); } else { - $this->log($request, $response, $body->getSize() ?? strlen((string) $body)); + $this->log($request, $response, $body->getSize() ?? strlen((string) $body), $this->now() - $start); } } /** * writes log message for response after response body is closed (not streaming anymore) */ - private function log(ServerRequestInterface $request, ResponseInterface $response, int $responseSize): void + private function log(ServerRequestInterface $request, ResponseInterface $response, int $responseSize, float $time): void { $this->sapi->log( ($request->getServerParams()['REMOTE_ADDR'] ?? '-') . ' ' . '"' . $this->escape($request->getMethod()) . ' ' . $this->escape($request->getRequestTarget()) . ' HTTP/' . $request->getProtocolVersion() . '" ' . - $response->getStatusCode() . ' ' . $responseSize + $response->getStatusCode() . ' ' . $responseSize . ' ' . sprintf('%.3F', $time < 0 ? 0 : $time) ); } @@ -83,4 +88,9 @@ private function escape(string $s): string return str_replace('%', '\x', rawurlencode($m[0])); }, $s); } + + private function now(): float + { + return $this->hasHighResolution ? hrtime(true) * 1e-9 : microtime(true); + } } diff --git a/tests/AccessLogHandlerTest.php b/tests/AccessLogHandlerTest.php index 69ae0f6..b53c6d2 100644 --- a/tests/AccessLogHandlerTest.php +++ b/tests/AccessLogHandlerTest.php @@ -18,8 +18,8 @@ public function testInvokePrintsRequestLogWithCurrentDateAndTime() $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\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" . PHP_EOL . "$/"); + // 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 . "$/"); $handler($request, function () use ($response) { return $response; }); } @@ -30,8 +30,8 @@ public function testInvokePrintsRequestWithQueryParametersLogWithCurrentDateAndT $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\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" . PHP_EOL . "$/"); + // 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 . "$/"); $handler($request, function () use ($response) { return $response; }); } @@ -43,8 +43,8 @@ public function testInvokePrintsRequestWithEscapedSpecialCharactersInRequestMeth $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\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" . PHP_EOL . "$/"); + // 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 . "$/"); $handler($request, function () use ($response) { return $response; }); } @@ -56,8 +56,8 @@ public function testInvokePrintsPlainProxyRequestLogWithCurrentDateAndTime() $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\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" . PHP_EOL . "$#"); + // 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 . "$#"); $handler($request, function () use ($response) { return $response; }); } @@ -69,8 +69,8 @@ public function testInvokePrintsConnectProxyRequestLogWithCurrentDateAndTime() $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\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" . PHP_EOL . "$#"); + // 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 . "$#"); $handler($request, function () use ($response) { return $response; }); } @@ -82,8 +82,8 @@ public function testInvokePrintsOptionsAsteriskLogWithCurrentDateAndTime() $request = $request->withRequestTarget('*'); $response = new Response(400, [], ""); - // 2021-01-29 12:22:01.717 127.0.0.1 "OPTIONS * HTTP/1.1" 400 0\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" . PHP_EOL . "$#"); + // 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 . "$#"); $handler($request, function () use ($response) { return $response; }); } @@ -94,8 +94,8 @@ public function testInvokeWithDeferredNextPrintsRequestLogWithCurrentDateAndTime $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\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" . PHP_EOL . "$/"); + // 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 . "$/"); $handler($request, function () use ($response) { return resolve($response); }); } @@ -116,8 +116,8 @@ public function testInvokeWithCoroutineNextPrintsRequestLogWithCurrentDateAndTim /** @var \Generator $generator */ $this->assertInstanceOf(\Generator::class, $generator); - // 2021-01-29 12:22:01.717 127.0.0.1 "GET /users HTTP/1.1" 200 6\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" . PHP_EOL . "$/"); + // 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 . "$/"); $generator->next(); } @@ -129,13 +129,29 @@ public function testInvokeWithStreamingResponsePrintsRequestLogWithCurrentDateAn $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\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" . PHP_EOL . "$/"); + // 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 . "$/"); $handler($request, function () use ($response) { return $response; }); $stream->write('hello'); $stream->end('world'); } + public function testInvokeWithStreamingResponseThatClosesAfterSomeTimePrintsRequestLogWithCurrentDateAndTime() + { + $handler = new AccessLogHandler(); + + $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 . "$/"); + $handler($request, function () use ($response) { return $response; }); + + usleep(110000); // 100ms + 10ms to account for inaccurate clocks + $stream->end(); + } + public function testInvokeWithClosedStreamingResponsePrintsRequestLogWithCurrentDateAndTime() { $handler = new AccessLogHandler(); @@ -145,8 +161,8 @@ public function testInvokeWithClosedStreamingResponsePrintsRequestLogWithCurrent $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\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" . PHP_EOL . "$/"); + // 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 . "$/"); $handler($request, function () use ($response) { return $response; }); } @@ -170,8 +186,8 @@ public function testInvokeWithoutRemoteAddressPrintsRequestLogWithDashAsPlacehol $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\n - $this->expectOutputRegex("/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} - \"GET \/users HTTP\/1\.1\" 200 6" . PHP_EOL . "$/"); + // 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 . "$/"); $handler($request, function () use ($response) { return $response; }); } }