Skip to content

Show time spent in request handler in access log #49

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Nov 4, 2021
Merged

Show time spent in request handler in access log #49

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 21 additions & 11 deletions src/AccessLogHandler.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,39 +15,44 @@ 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+
}

/**
* @return ResponseInterface|PromiseInterface<ResponseInterface>|\Generator
*/
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;
}
}

/**
* 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();

Expand All @@ -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)
);
}

Expand All @@ -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);
}
}
60 changes: 38 additions & 22 deletions tests/AccessLogHandlerTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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; });
}

Expand All @@ -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; });
}

Expand All @@ -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; });
}

Expand All @@ -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; });
}

Expand All @@ -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; });
}

Expand All @@ -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; });
}

Expand All @@ -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); });
}

Expand All @@ -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();
}

Expand All @@ -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();
Expand All @@ -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; });
}

Expand All @@ -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; });
}
}