Skip to content

Deduplicate request logs, couple request<>response by UID #19

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

Closed
wants to merge 4 commits into from
Closed

Deduplicate request logs, couple request<>response by UID #19

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
fa34df7
Update LoggerPlugin.php
ro0NL Feb 4, 2022
9ff7799
dedup
ro0NL Feb 4, 2022
b77bcef
pass
ro0NL Feb 7, 2022
b9e346a
clog
ro0NL Feb 7, 2022
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
5 changes: 5 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,10 @@
# Change Log

## 1.3.0 - tomorrow

- Deduplicate request log in response logs
- Link request log with response log by UID

## 1.2.2 - 2021-07-26

- Allow installation with psr/log version 2 and 3
Expand Down
40 changes: 35 additions & 5 deletions spec/LoggerPluginSpec.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -42,14 +42,24 @@ function it_logs_request_and_response(
$formatter->formatRequest($request)->willReturn('GET / 1.1');
$formatter->formatResponse($response)->willReturn('200 OK 1.1');

$logger->info("Sending request:\nGET / 1.1", ['request' => $request])->shouldBeCalled();
$logger->info(
"Received response:\n200 OK 1.1\n\nfor request:\nGET / 1.1",
"Sending request:\nGET / 1.1",
Argument::that(
function(array $context) use ($request) {
return $context['request'] === $request->getWrappedObject()
&& is_string($context['uid'])
;
}
)
)->shouldBeCalled();
$logger->info(
"Received response:\n200 OK 1.1",
Argument::that(
function(array $context) use ($request, $response) {
return $context['request'] === $request->getWrappedObject()
&& $context['response'] === $response->getWrappedObject()
&& is_int($context['milliseconds'])
&& is_string($context['uid'])
;
}
)
Expand All @@ -68,14 +78,24 @@ function it_logs_exception(LoggerInterface $logger, Formatter $formatter, Reques

$exception = new NetworkException('Cannot connect', $request->getWrappedObject());

$logger->info("Sending request:\nGET / 1.1", ['request' => $request])->shouldBeCalled();
$logger->info(
"Sending request:\nGET / 1.1",
Argument::that(
function(array $context) use ($request) {
return $context['request'] === $request->getWrappedObject()
&& is_string($context['uid'])
;
}
)
)->shouldBeCalled();
$logger->error(
"Error:\nCannot connect\nwhen sending request:\nGET / 1.1",
Argument::that(
function(array $context) use ($request, $exception) {
return $context['request'] === $request->getWrappedObject()
&& $context['exception'] === $exception
&& is_int($context['milliseconds'])
&& is_string($context['uid'])
;
}
)
Expand All @@ -99,15 +119,25 @@ function it_logs_response_within_exception(

$exception = new HttpException('Forbidden', $request->getWrappedObject(), $response->getWrappedObject());

$logger->info("Sending request:\nGET / 1.1", ['request' => $request])->shouldBeCalled();
$logger->info(
"Sending request:\nGET / 1.1",
Argument::that(
function(array $context) use ($request) {
return $context['request'] === $request->getWrappedObject()
&& is_string($context['uid'])
;
}
)
)->shouldBeCalled();
$logger->error(
"Error:\nForbidden\nwith response:\n403 Forbidden 1.1\n\nwhen sending request:\nGET / 1.1",
"Error:\nForbidden\nwith response:\n403 Forbidden 1.1",
Argument::that(
function(array $context) use ($request, $response, $exception) {
return $context['request'] === $request->getWrappedObject()
&& $context['response'] === $response->getWrappedObject()
&& $context['exception'] === $exception
&& is_int($context['milliseconds'])
&& is_string($context['uid'])
;
}
)
Expand Down
14 changes: 9 additions & 5 deletions src/LoggerPlugin.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,30 +32,33 @@ public function __construct(LoggerInterface $logger, Formatter $formatter = null
protected function doHandleRequest(RequestInterface $request, callable $next, callable $first)
{
$start = hrtime(true) / 1E6;
$this->logger->info(sprintf("Sending request:\n%s", $this->formatter->formatRequest($request)), ['request' => $request]);
$uid = uniqid('', true);
$this->logger->info(sprintf("Sending request:\n%s", $this->formatter->formatRequest($request)), ['request' => $request, 'uid' => $uid]);

return $next($request)->then(function (ResponseInterface $response) use ($request, $start) {
return $next($request)->then(function (ResponseInterface $response) use ($request, $start, $uid) {
$milliseconds = (int) round(hrtime(true) / 1E6 - $start);
$this->logger->info(
sprintf("Received response:\n%s\n\nfor request:\n%s", $this->formatter->formatResponse($response), $this->formatter->formatRequest($request)),
sprintf("Received response:\n%s", $this->formatter->formatResponse($response)),
[
'request' => $request,
'response' => $response,
'milliseconds' => $milliseconds,
'uid' => $uid,
]
);

return $response;
}, function (Exception $exception) use ($request, $start) {
}, function (Exception $exception) use ($request, $start, $uid) {
$milliseconds = (int) round((hrtime(true) / 1E6 - $start));
if ($exception instanceof Exception\HttpException) {
$this->logger->error(
sprintf("Error:\n%s\nwith response:\n%s\n\nwhen sending request:\n%s", $exception->getMessage(), $this->formatter->formatResponse($exception->getResponse()), $this->formatter->formatRequest($request)),
sprintf("Error:\n%s\nwith response:\n%s", $exception->getMessage(), $this->formatter->formatResponse($exception->getResponse())),
[
'request' => $request,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

you still specify the request in the context. is that on purpose?

Copy link
Contributor Author

@ro0NL ro0NL Feb 8, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes, i left other context entries untouched.

this is for #16 to solve, but in CLI it works well:

16:07:07 INFO      [app] Received response:
HTTP/1.1 200 OK

[
  "request" => GuzzleHttp\Psr7\Request {
    -method: "GET"

i wouldnt mind if these are dropped though :) if these objects become stringable/serializable one day, it starts leaking into prod logs.

Arguably, even in dev env it's just noise.

'response' => $exception->getResponse(),
'exception' => $exception,
'milliseconds' => $milliseconds,
'uid' => $uid,
]
);
} else {
Expand All @@ -65,6 +68,7 @@ protected function doHandleRequest(RequestInterface $request, callable $next, ca
'request' => $request,
'exception' => $exception,
'milliseconds' => $milliseconds,
'uid' => $uid,
]
);
}
Expand Down