Skip to content
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

Jump to bottom

Show actual response size in access log for streaming response body #48

Merged
merged 1 commit into from
Nov 4, 2021
Merged

Show actual response size in access log for streaming response body #48

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
35 changes: 30 additions & 5 deletions src/AccessLogHandler.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
use Psr\Http\Message\ResponseInterface;
use Psr\Http\Message\ServerRequestInterface;
use React\Promise\PromiseInterface;
use React\Stream\ReadableStreamInterface;

/**
* @internal
Expand All @@ -28,27 +29,51 @@ public function __invoke(ServerRequestInterface $request, callable $next)

if ($response instanceof PromiseInterface) {
return $response->then(function (ResponseInterface $response) use ($request) {
$this->log($request, $response);
$this->logWhenClosed($request, $response);
return $response;
});
} elseif ($response instanceof \Generator) {
return (function (\Generator $generator) use ($request) {
$response = yield from $generator;
$this->log($request, $response);
$this->logWhenClosed($request, $response);
return $response;
})($response);
} else {
$this->log($request, $response);
$this->logWhenClosed($request, $response);
return $response;
}
}

private function log(ServerRequestInterface $request, ResponseInterface $response): void
/**
* checks if response body is closed (not streaming) before writing log message for response
*/
private function logWhenClosed(ServerRequestInterface $request, ResponseInterface $response): void
{
$body = $response->getBody();

if ($body instanceof ReadableStreamInterface && $body->isReadable()) {
$size = 0;
$body->on('data', function (string $chunk) use (&$size) {
$size += strlen($chunk);
});

$body->on('close', function () use (&$size, $request, $response) {
$this->log($request, $response, $size);
});
} else {
$this->log($request, $response, $body->getSize() ?? strlen((string) $body));
}
}

/**
* writes log message for response after response body is closed (not streaming anymore)
*/
private function log(ServerRequestInterface $request, ResponseInterface $response, int $responseSize): void
{
$this->sapi->log(
($request->getServerParams()['REMOTE_ADDR'] ?? '-') . ' ' .
'"' . $this->escape($request->getMethod()) . ' ' . $this->escape($request->getRequestTarget()) . ' HTTP/' . $request->getProtocolVersion() . '" ' .
$response->getStatusCode() . ' ' . $response->getBody()->getSize()
$response->getStatusCode() . ' ' . $responseSize
);
}

Expand Down
43 changes: 43 additions & 0 deletions tests/AccessLogHandlerTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
use PHPUnit\Framework\TestCase;
use React\Http\Message\Response;
use React\Http\Message\ServerRequest;
use React\Stream\ThroughStream;
use function React\Promise\resolve;

class AccessLogHandlerTest extends TestCase
Expand Down Expand Up @@ -120,6 +121,48 @@ public function testInvokeWithCoroutineNextPrintsRequestLogWithCurrentDateAndTim
$generator->next();
}

public function testInvokeWithStreamingResponsePrintsRequestLogWithCurrentDateAndTime()
{
$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 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 . "$/");
$handler($request, function () use ($response) { return $response; });
$stream->write('hello');
$stream->end('world');
}

public function testInvokeWithClosedStreamingResponsePrintsRequestLogWithCurrentDateAndTime()
{
$handler = new AccessLogHandler();

$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 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 . "$/");
$handler($request, function () use ($response) { return $response; });
}

public function testInvokeWithStreamingResponsePrintsNothingIfStreamIsPending()
{
$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);

$this->expectOutputString('');
$handler($request, function () use ($response) { return $response; });
$stream->write('hello');
}

public function testInvokeWithoutRemoteAddressPrintsRequestLogWithDashAsPlaceholder()
{
$handler = new AccessLogHandler();
Expand Down