Adding time for the request

Author: Nyholm

CHANGELOG.md

@@ -1,6 +1,10 @@
 # Change Log
 
 
+## 1.1.0 - 2018-03-29
+
+- Start measuring the time it took to do the request. 
+
 ## 1.0.0 - 2016-05-05
 
 - Initial release

spec/LoggerPluginSpec.php

@@ -34,13 +34,14 @@ function it_logs_request_and_response(
         LoggerInterface $logger,
         Formatter $formatter,
         RequestInterface $request,
-        ResponseInterface $response
+        ResponseInterface $response,
+        $milliseconds
     ) {
         $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", ['request' => $request, 'response' => $response])->shouldBeCalled();
+        $logger->info("Received response:\n200 OK 1.1\n\nfor request:\nGET / 1.1", ['request' => $request, 'response' => $response, 'milliseconds' => $milliseconds])->shouldBeCalled();
 
         $next = function () use ($response) {
             return new FulfilledPromise($response->getWrappedObject());
@@ -49,14 +50,14 @@ function it_logs_request_and_response(
         $this->handleRequest($request, $next, function () {});
     }
 
-    function it_logs_exception(LoggerInterface $logger, Formatter $formatter, RequestInterface $request)
+    function it_logs_exception(LoggerInterface $logger, Formatter $formatter, RequestInterface $request, $milliseconds)
     {
         $formatter->formatRequest($request)->willReturn('GET / 1.1');
 
         $exception = new NetworkException('Cannot connect', $request->getWrappedObject());
 
         $logger->info("Sending request:\nGET / 1.1", ['request' => $request])->shouldBeCalled();
-        $logger->error("Error:\nCannot connect\nwhen sending request:\nGET / 1.1", ['request' => $request, 'exception' => $exception])->shouldBeCalled();
+        $logger->error("Error:\nCannot connect\nwhen sending request:\nGET / 1.1", ['request' => $request, 'exception' => $exception, 'milliseconds' => $milliseconds])->shouldBeCalled();
 
         $next = function () use ($exception) {
             return new RejectedPromise($exception);
@@ -69,7 +70,8 @@ function it_logs_response_within_exception(
         LoggerInterface $logger,
         Formatter $formatter,
         RequestInterface $request,
-        ResponseInterface $response
+        ResponseInterface $response,
+        $milliseconds
     ) {
         $formatter->formatRequest($request)->willReturn('GET / 1.1');
         $formatter->formatResponse($response)->willReturn('403 Forbidden 1.1');
@@ -78,9 +80,10 @@ function it_logs_response_within_exception(
 
         $logger->info("Sending request:\nGET / 1.1", ['request' => $request])->shouldBeCalled();
         $logger->error("Error:\nForbidden\nwith response:\n403 Forbidden 1.1\n\nwhen sending request:\nGET / 1.1", [
-            'request'   => $request,
-            'response'  => $response,
-            'exception' => $exception
+            'request'      => $request,
+            'response'     => $response,
+            'exception'    => $exception,
+            'milliseconds' => $milliseconds
         ])->shouldBeCalled();
 
         $next = function () use ($exception) {

src/LoggerPlugin.php

@@ -32,26 +32,31 @@ public function __construct(LoggerInterface $logger, Formatter $formatter = null
      */
     public function handleRequest(RequestInterface $request, callable $next, callable $first)
     {
+        $start = microtime();
         $this->logger->info(sprintf("Sending request:\n%s", $this->formatter->formatRequest($request)), ['request' => $request]);
 
-        return $next($request)->then(function (ResponseInterface $response) use ($request) {
+        return $next($request)->then(function (ResponseInterface $response) use ($request, $start) {
+            $milliseconds = round(microtime() - $start / 1000);
             $this->logger->info(
                 sprintf("Received response:\n%s\n\nfor request:\n%s", $this->formatter->formatResponse($response), $this->formatter->formatRequest($request)),
                 [
                     'request' => $request,
                     'response' => $response,
+                    'milliseconds' => $milliseconds,
                 ]
             );
 
             return $response;
-        }, function (Exception $exception) use ($request) {
+        }, function (Exception $exception) use ($request, $start) {
+            $milliseconds = round(microtime() - $start / 1000);
             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)),
                     [
                         'request' => $request,
                         'response' => $exception->getResponse(),
                         'exception' => $exception,
+                        'milliseconds' => $milliseconds,
                     ]
                 );
             } else {
@@ -60,6 +65,7 @@ public function handleRequest(RequestInterface $request, callable $next, callabl
                     [
                         'request' => $request,
                         'exception' => $exception,
+                        'milliseconds' => $milliseconds,
                     ]
                 );
             }