Retrying and Logging Requests with Guzzle
When consuming 3d party API, you may want to do two things:
- Retrying. Usually you can retry your requests on 500 responses received from server.
- Logging. It is considered a good practice to log requests you send and responses you get back.
In this article we will look at how to implement the above features using Guzzle, a popular PHP library for making API calls.
Let us scaffold our app
composer init
composer require guzzlehttp/guzzle:~6.0
composer require monolog/monolog
composer require –dev phpunit/phpunit:^8
We will be using PHPUnit to run our code. PHPUnit 9 requires PHP7.3. Since I have PHP7.2, I will stick with PHPUnit 8. We also need to create phpunit.xml file in the root of our project:
<?xml version="1.0" encoding="UTF-8"?>
<phpunit backupGlobals="false"
backupStaticAttributes="false"
bootstrap="vendor/autoload.php"
colors="true"
convertErrorsToExceptions="true"
convertNoticesToExceptions="true"
convertWarningsToExceptions="true"
processIsolation="false"
stopOnFailure="false">
<testsuites>
<testsuite name="Unit">
<directory suffix="Test.php">./tests</directory>
</testsuite>
</testsuites>
<filter>
<whitelist processUncoveredFilesFromWhitelist="true">
<directory suffix=".php">./app</directory>
</whitelist>
</filter>
<php>
<env name="APP_ENV" value="testing"/>
</php>
</phpunit>
Let us also define PSR-4 autoloading in composer.json file. Complete composer.json file should look something like this.
{
"name": "apr/retrying-and-logging",
"description": "Retrying and logging Guzzle requests",
"authors": [
{
"name": "Alex Rusin",
"email": "alex@email.com"
}
],
"require": {
"guzzlehttp/guzzle": "~6.0",
"monolog/monolog": "^2.0"
},
"require-dev": {
"phpunit/phpunit": "^8"
},
"autoload": {
"psr-4": {
"App\\": "src/"
}
},
"autoload-dev": {
"psr-4": {
"Tests\\": "tests/"
}
}
}
Don’t forget to run composer dump-autoload
Now we are ready to start creating our code. In src/Api folder we are going to create Api.php file containing Api class.
<?php
namespace App\Api;
use GuzzleHttp\Client;
use GuzzleHttp\HandlerStack;
use GuzzleHttp\Middleware;
use GuzzleHttp\MessageFormatter;
use GuzzleHttp\Psr7\Request;
use GuzzleHttp\Psr7\Response;
use GuzzleHttp\Exception\ConnectException;
use GuzzleHttp\Exception\RequestException;
use Psr\Log\LoggerInterface;
abstract class Api
{
protected $logger;
protected $client;
const MAX_RETRIES = 3;
public function __construct(LoggerInterface $logger)
{
$this->logger = $logger;
$this->client = new Client([
'base_uri' => $this->baseUri,
'handler' => $this->createHandlerStack(),
'timeout' => 30.0,
'headers' => [
'Accept' => 'application/json',
],
'verify' => false
]);
}
protected function createHandlerStack()
{
$stack = HandlerStack::create();
$stack->push(Middleware::retry($this->retryDecider(), $this->retryDelay()));
return $this->createLoggingHandlerStack($stack);
}
protected function createLoggingHandlerStack(HandlerStack $stack)
{
$messageFormats = [
'{method} {uri} HTTP/{version}',
'HEADERS: {req_headers}',
'BODY: {req_body}',
'RESPONSE: {code} - {res_body}',
];
foreach ($messageFormats as $messageFormat) {
// We'll use unshift instead of push, to add the middleware to the bottom of the stack, not the top
$stack->unshift(
$this->createGuzzleLoggingMiddleware($messageFormat)
);
}
return $stack;
}
protected function createGuzzleLoggingMiddleware(string $messageFormat)
{
return Middleware::log(
$this->logger,
new MessageFormatter($messageFormat)
);
}
protected function retryDecider()
{
return function (
$retries,
Request $request,
Response $response = null,
RequestException $exception = null
) {
// Limit the number of retries to MAX_RETRIES
if ($retries >= self::MAX_RETRIES) {
return false;
}
// Retry connection exceptions
if ($exception instanceof ConnectException) {
$this->logger->info('Timeout encountered, retrying');
return true;
}
if ($response) {
// Retry on server errors
if ($response->getStatusCode() >= 500) {
$this->logger->info('Server 5xx error encountered, retrying...');
return true;
}
}
return false;
};
}
/**
* delay 1s 2s 3s 4s 5s ...
*
* @return callable
*/
protected function retryDelay()
{
return function ($numberOfRetries) {
return 1000 * $numberOfRetries;
};
}
}
The logging and retrying logic is defined in the class above. We use handler stack to incorporate this logic. Since this is a demo code, I also turned off ssl verification ‘verify’ => false. This is not a good practice to use in production.
Now let’s create our class that will actually be used to make calls. We will be using mocky.io. In src/Api create MockyApi class that will extend abstract Api.
<?php
namespace App\Api;
class MockyApi extends Api
{
protected $baseUri = 'https://www.mocky.io/v2/';
public function getTasks()
{
$response = $this->client->get('5eb81e152d00003e2b357c06');
$response->getBody()->rewind();
return $response;
}
public function createTask()
{
$response = $this->client->post('5eb81ee82d00005800357c07', [
'json' => [
'description' => 'Write a blog post'
]
]);
$response->getBody()->rewind();
return $response;
}
public function failedGetTasks()
{
$response = $this->client->get('5eb829d42d00003e2b357c26');
$response->getBody()->rewind();
return $response;
}
}
Since we are using the logger in Guzzle stack it will read the body of the response. Response body is a stream (PSR-7). Unfortunately, it does not get rewound back after it is logged. We need to make sure we rewind it before returning response.
Using mocky.io, we created mock responses for getting tasks, creating a task and for failing to get tasks We used generated routes in the class above for getTasks(), createTask(), and failedGetTasks() functions.
Now let’s abstract logger creation. In app/Factories folder create LoggerFactory.php:
<?php
namespace App\Factories;
use DateTime;
use DateTimeZone;
use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Formatter\LineFormatter;
class LoggerFactory
{
public function create(string $channel = 'testing', string $fileNameHandle = 'app_log')
{
$logger = new Logger($channel);
$dateFormat = "n/j/Y, g:i a";
$formatter = new LineFormatter(null, $dateFormat, false, true);
$now = (new DateTime("now"))->format('m_d_Y');
$handler = new StreamHandler(__DIR__ . "/../logs/{$fileNameHandle}_{$now}.log", Logger::INFO);
$handler->setFormatter($formatter);
$logger->pushHandler($handler);
$logger->setTimezone(new DateTimeZone('America/Los_Angeles'));
return $logger;
}
}
The logger factory creates an instance of PSR-3 complient logger, sets date formats, files to write to, and time zone.
It is time to try out our code. In tests folder create MockyApiTest.php. We create tests for each of our MockyApi methods. Note, that here I am using PHPUnit not to test my code, but to run it because PHPUnit provides a cli environment. Normally, you would not want to hit your API endpoint when running tests.
<?php
namespace Tests;
use App\Api\MockyApi;
use App\Factories\LoggerFactory;
use GuzzleHttp\Exception\RequestException;
use PHPUnit\Framework\TestCase as PhpUnitTestCase;
class MockyApiTest extends PhpUnitTestCase
{
private $logger;
public function setUp(): void
{
$this->logger = (new LoggerFactory)->create('retries-and-logging');
}
/** @test */
public function it_gets_tasks()
{
$api = new MockyApi($this->logger);
$response = $api->getTasks();
$contents = $response->getBody()->getContents();
$this->assertCount(2, json_decode($contents));
}
/** @test */
public function it_creates_a_task()
{
$api = new MockyApi($this->logger);
$response = $api->createTask();
$contents = $response->getBody()->getContents();
$description = json_decode($contents)->description;
$this->assertEquals('Write a blog post', $description);
}
/** @test */
public function it_fails_to_get_tasks()
{
$api = new MockyApi($this->logger);
$this->expectException(RequestException::class);
$api->failedGetTasks();
}
}
composer dump-autoload
.vendor/bin/phpunit
And in your log file you should see something like this:
[5/10/2020, 9:30 am] retries-and-logging.INFO: GET https://www.mocky.io/v2/5eb81e152d00003e2b357c06 HTTP/1.1
[5/10/2020, 9:30 am] retries-and-logging.INFO: HEADERS: GET /v2/5eb81e152d00003e2b357c06 HTTP/1.1 Accept: application/json User-Agent: GuzzleHttp/6.5.3 curl/7.64.0 PHP/7.2.17 Host: www.mocky.io
[5/10/2020, 9:30 am] retries-and-logging.INFO: BODY:
[5/10/2020, 9:30 am] retries-and-logging.INFO: RESPONSE: 200 - [ {"description":"Get groceries","completed":true}, {"description":"Clean the room","completed":false} ]
[5/10/2020, 9:30 am] retries-and-logging.INFO: POST https://www.mocky.io/v2/5eb81ee82d00005800357c07 HTTP/1.1
[5/10/2020, 9:30 am] retries-and-logging.INFO: HEADERS: POST /v2/5eb81ee82d00005800357c07 HTTP/1.1 Accept: application/json User-Agent: GuzzleHttp/6.5.3 curl/7.64.0 PHP/7.2.17 Content-Type: application/json Host: www.mocky.io
[5/10/2020, 9:30 am] retries-and-logging.INFO: BODY: {"description":"Write a blog post"}
[5/10/2020, 9:30 am] retries-and-logging.INFO: RESPONSE: 201 - {"description":"Write a blog post","completed":true}
[5/10/2020, 9:30 am] retries-and-logging.INFO: Server 5xx error encountered, retrying...
[5/10/2020, 9:30 am] retries-and-logging.INFO: Server 5xx error encountered, retrying...
[5/10/2020, 9:31 am] retries-and-logging.INFO: Server 5xx error encountered, retrying...
[5/10/2020, 9:31 am] retries-and-logging.NOTICE: GET https://www.mocky.io/v2/5eb829d42d00003e2b357c26 HTTP/1.1
[5/10/2020, 9:31 am] retries-and-logging.NOTICE: HEADERS: GET /v2/5eb829d42d00003e2b357c26 HTTP/1.1 Accept: application/json User-Agent: GuzzleHttp/6.5.3 curl/7.64.0 PHP/7.2.17 Host: www.mocky.io
[5/10/2020, 9:31 am] retries-and-logging.NOTICE: BODY:
[5/10/2020, 9:31 am] retries-and-logging.NOTICE: RESPONSE: 500 -