Merge pull request #5 from php-http/time

Adding time for the request

Author: Nyholm

.travis.yml

@@ -13,7 +13,6 @@ php:
     - 7.0
     - 7.1
     - 7.2
-    - hhvm
 
 env:
     global:

CHANGELOG.md

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

spec/LoggerPluginSpec.php

@@ -7,6 +7,7 @@
 use Http\Promise\FulfilledPromise;
 use Http\Promise\RejectedPromise;
 use Http\Message\Formatter;
+use Prophecy\Argument;
 use Psr\Http\Message\RequestInterface;
 use Psr\Http\Message\ResponseInterface;
 use Psr\Http\Message\UriInterface;
@@ -40,7 +41,17 @@ function it_logs_request_and_response(
         $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",
+            Argument::that(
+                function(array $context) use ($request, $response) {
+                    return $context['request'] === $request->getWrappedObject()
+                        && $context['response'] === $response->getWrappedObject()
+                        && is_int($context['milliseconds'])
+                    ;
+                }
+            )
+        )->shouldBeCalled();
 
         $next = function () use ($response) {
             return new FulfilledPromise($response->getWrappedObject());
@@ -56,7 +67,17 @@ 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->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",
+            Argument::that(
+                function(array $context) use ($request, $exception) {
+                    return $context['request'] === $request->getWrappedObject()
+                        && $context['exception'] === $exception
+                        && is_int($context['milliseconds'])
+                    ;
+                }
+            )
+        )->shouldBeCalled();
 
         $next = function () use ($exception) {
             return new RejectedPromise($exception);
@@ -77,11 +98,18 @@ 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->error("Error:\nForbidden\nwith response:\n403 Forbidden 1.1\n\nwhen sending request:\nGET / 1.1", [
-            'request'   => $request,
-            'response'  => $response,
-            'exception' => $exception
-        ])->shouldBeCalled();
+        $logger->error(
+            "Error:\nForbidden\nwith response:\n403 Forbidden 1.1\n\nwhen sending request:\nGET / 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'])
+                        ;
+                }
+            )
+        )->shouldBeCalled();
 
         $next = function () use ($exception) {
             return new RejectedPromise($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(true);
         $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 = (int) round((microtime(true) - $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 = (int) round((microtime(true) - $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,
                     ]
                 );
             }