diff --git a/.travis.yml b/.travis.yml index 1c197f0..d112cdc 100644 --- a/.travis.yml +++ b/.travis.yml @@ -13,7 +13,6 @@ php: - 7.0 - 7.1 - 7.2 - - hhvm env: global: diff --git a/CHANGELOG.md b/CHANGELOG.md index 84dc0d1..43d1d0c 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/spec/LoggerPluginSpec.php b/spec/LoggerPluginSpec.php index 115ed27..07642ab 100644 --- a/spec/LoggerPluginSpec.php +++ b/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); diff --git a/src/LoggerPlugin.php b/src/LoggerPlugin.php index 4a0572d..1797d7f 100644 --- a/src/LoggerPlugin.php +++ b/src/LoggerPlugin.php @@ -32,19 +32,23 @@ 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)), @@ -52,6 +56,7 @@ public function handleRequest(RequestInterface $request, callable $next, callabl '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, ] ); }