log UID for request and response rather than duplicating request log

when logging response

Author: ro0NL

CHANGELOG.md

@@ -1,5 +1,13 @@
 # Change Log
 
+## 1.3.0 - unreleased
+
+- Do not log request when loggin response again, but use UID to identify request
+  that belongs to response.
+  If you use a logger that does not log `info` severity and want the request
+  logged when an error happened, use a Fingerscrossed log handler to also log
+  info if any error is logged.
+
 ## 1.2.2 - 2021-07-26
 
 - Allow installation with psr/log version 2 and 3

spec/LoggerPluginSpec.php

@@ -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'])
                     ;
                 }
             )
@@ -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'])
                     ;
                 }
             )
@@ -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'])
                     ;
                 }
             )

src/LoggerPlugin.php

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