Friday 25 November 2016

PHP: decorating async GuzzleHttp calls - more methods

G'day:
Here's yet another article about decorating an async GuzzleHttp adapter. So far in the series I've got this lot:
To date my adapter has only had the one method to decorate: the get method. I also need to add more methods like post and put, which have their own considerations when doing decoration. Let's have a look.

Firstly I need some end points to test against. I decided I'd better shuffle-on from those CFML based ones I had, and use PHP instead. So I've rejigged them all as follows:

data.php

class Person{
    public $id;
    public $firstName;
    public $lastName;

    function __construct($id, $firstName, $lastName){
        $this->id = $id;
        $this->firstName = $firstName;
        $this->lastName = $lastName;
    }
}

$people = [
    new Person(1, "Donald", "Duck"),
    new Person(2, "Donald", "Cameron"),
    new Person(3, "Donald", "Trump"),
    new Person(4, "Donald", "Wearsyatroosas")
];

getById.php

$id = $_GET["id"];

require __DIR__ . "/data.php";

$filteredPeople = array_filter($people, function($person) use ($id) {
    return $person->id == $id;
});
$person = array_shift($filteredPeople);

$result = (array) $person;

sleep(5);
$result["retrieved"] = (new DateTime())->format("Y-m-d H:i:s");

header("type:application/json");
echo json_encode($result);

create.php

require __DIR__ . "/data.php";

$newPerson = new Person(
    uniqid(),
    $_POST['firstName'],
    $_POST['lastName']
);

$result = (array) $newPerson;

$result["retrieved"] = (new DateTime())->format("Y-m-d H:i:s");

header("type:application/json");
echo json_encode($result);

update.php

$id = $_GET["id"];
parse_str(file_get_contents("php://input"),$put_vars);

require __DIR__ . "/data.php";

$filteredPeople = array_filter($people, function($person) use ($id) {
    return $person->id == $id;
});

if (empty($filteredPeople)){
    http_response_code(400);
    throw new InvalidArgumentException("No Person with ID $id found");
}

$person = array_shift($filteredPeople);

$newPerson = new Person(
    $person->id,
    $put_vars['firstName'],
    $put_vars['lastName']
);

$result = [
    'before' => (array) $person,
    'after' => (array) $newPerson,
    'updated' => (new DateTime())->format("Y-m-d H:i:s")
];

header("type:application/json");
echo json_encode($result);

That lot is all pretty perfunctory. There was a coupla PHP things I didn't know about before hand, namely:
  • how to extract the body for a put request. I was initially expecting them to be in the $_POST array for some reason, but that makes no sense.
  • how to set the HTTP status. I'd never had to do that before with PHP (we use Silex / Symfony, and we just use API methods to do same).

(readers need to remember I'm fairly new to PHP ;-)

The next update is to the Adapter interface:

namespace me\adamcameron\testApp\adapter;

use GuzzleHttp\Promise\Promise;

interface Adapter {
    public function get($url, $parameters) : Promise;
    public function post($url, $body) : Promise;
    public function put($url, $body, $parameters) : Promise;
}

I've added the two new methods there. This now breaks all my Adapter implementations.

First I need to add the actual method implementations to the base adapter: the ones that actually makes the calls:

namespace me\adamcameron\testApp\adapter;

use GuzzleHttp\Client;
use GuzzleHttp\Promise\Promise;

class GuzzleAdapter implements Adapter {

    private $client;

    public function __construct() {
        $this->client = new Client();
    }

    public function get($url, $parameters) : Promise {
        $fullUrl = sprintf("%s?%s", $url, http_build_query($parameters));

        $response = $this->client->requestAsync("get", $fullUrl);

        return $response;
    }

    public function post($url, $body) : Promise {
        $options = ['form_params' => $body];

        $response = $this->client->requestAsync("post", $url, $options);

        return $response;
    }

    public function put($url, $body, $parameters) : Promise {
        $fullUrl = sprintf("%s?%s", $url, http_build_query($parameters));
        $options = ['form_params' => $body];

        $response = $this->client->requestAsync("put", $fullUrl, $options);

        return $response;
    }
}

Nothing surprising there. Note that each of the new methods have different argument requirements. This becomes relevant later.

Now I need to add equivalent methods to the decorators. I'll start with the caching one as that's easy: we have no caching requirements for POST or PUT requests, so the methods just pass through to the underlying adapter:

public function post($url, $body) : Promise {
    return $this->adapter->post($url, $body);
}

public function put($url, $body, $parameters) : Promise {
    return $this->adapter->put($url, $body, $parameters);
}


See: easy.

The logging adapter was more of a challenge. The first pass of the implementation looked like this sort of thing:

public function get($url, $parameters) : Promise {
    $encodedParameters = json_encode($parameters);
    $this->logger->logMessage(sprintf("%s: Requesting for %s", $this->thisFile, $encodedParameters));

    $response = $this->adapter->get($url, $parameters);

    $response->then(function($response) use ($encodedParameters) {
        $body = $response->getBody();
        $this->logger->logMessage(sprintf("%s: Response for %s: %s", $this->thisFile, $encodedParameters, $body));
        $body->rewind();
    });

    return $response;
}

public function post($url, $body) : Promise {
    $logDetails = json_encode($body);
    $this->logger->logMessage(sprintf("%s: Requesting for %s", $this->thisFile, $logDetails));

    $response = $this->adapter->post($url, $body);

    $response->then(function($response) use ($logDetails) {
        $body = $response->getBody();
        $this->logger->logMessage(sprintf("%s: Response for %s: %s", $this->thisFile, $logDetails, $body));
        $body->rewind();
    });

    return $response;
}

public function post($url, $body, $parameters) : Promise {
    $logDetails = json_encode([
        'parameters' => $parameters,
        'body' => $body
    ]);
    $this->logger->logMessage(sprintf("%s: Requesting for %s", $this->thisFile, $logDetails));

    $response = $this->adapter->put($url, $body, $parameters);

    $response->then(function($response) use ($logDetails) {
        $body = $response->getBody();
        $this->logger->logMessage(sprintf("%s: Response for %s: %s", $this->thisFile, $logDetails, $body));
        $body->rewind();
    });

    return $response;
}

That's fine, but look at how much similarity there is in there:
  • We log some stuff
  • We peform a request to a method
  • We have a resolution handler
What we log is different for all three methods, but the handling after that is the same. So I figured there was a refactoring opportunity there. One slight challenge is that which I mentioned above: each method passes different arguments. That'll be tricky to refactor into one method. Well so I thought. Enter PHP's variadic functions. These allow me to specify a method signature that has a concrete argument list, then one last argument that captures any other arguments passed into the function when it's called.

This way I have three congruent parts:
  • capture some stuff to log. The composition of what to log is method-specific, but that's fine
  • call a method
  • with some arguments

I was able to factor-out this commonality into a helper method:

private function performLoggedRequest($method, $logDetails, ...$requestArgs) : Promise {
    $this->logger->logMessage(sprintf("%s: Requesting for %s", $this->thisFile,  $logDetails));

    $response = call_user_func_array([$this->adapter, $method], $requestArgs);

    $response->then(function($response) use ($logDetails) {
        $body = $response->getBody();
        $this->logger->logMessage(sprintf("%s: Response for %s: %s", $this->thisFile, $logDetails, $body));
        $body->rewind();
    });

    return $response;
}

From there, it's just a matter of refactoring all three public methods to call this helper method:

public function get($url, $parameters) : Promise {
    $logDetails = json_encode($parameters);

    return $this->performLoggedRequest(__FUNCTION__, $logDetails, $url, $parameters);
}

public function post($url, $body) : Promise {
    $logDetails = json_encode($body);

    return $this->performLoggedRequest(__FUNCTION__, $logDetails, $url, $body);
}

public function put($url, $body, $parameters) : Promise {
    $logDetails = json_encode([
        'parameters' => $parameters,
        'body' => $body
    ]);

    return $this->performLoggedRequest(__FUNCTION__, $logDetails, $url, $body, $parameters);
}

For each call to performLoggedRequest, all the passed-in arguments after $logDetails end up in a single array, as $requestArgs All because of the ... in the method signature. Cool.

This enables use to call call_user_func_array. with both a dynamic method name, and a dynamic number of arguments in that array.

I then needed to do much the same with the StatusToExceptionAdapter:

public function get($url, $parameters) : Promise {
    return $this->request(__FUNCTION__, $url, $parameters);
}

public function post($url, $body) : Promise {
    return $this->request(__FUNCTION__, $url, $body);
}

public function put($url, $parameters, $body) : Promise {
    return $this->request(__FUNCTION__, $url, $parameters, $body);
}

private function request($method, ...$args) : Promise {
    return call_user_func_array([$this->adapter, $method], $args)
        ->then(function (Response $response) {
            return $this->handleThen($response);
        })
        ->otherwise(function ($exception) {
            $this->handleOtherwise($exception);
        });
}

Easy!

Finally a test. I used the same basic test rig as last time, so I'll just focus on the individual tests here. I also ran the equivalent test of getById as before: no change there so I'll not bother reproducing it.

The test for post was as follows:

function testCreate(PersonRepository $personRepository, LoggingService $loggingService) {
    $personDetails = [
        'firstName' => 'Donald',
        'lastName' => 'McLean'
    ];

    $loggingService->logMessage(sprintf("Test: calling create(%s)", json_encode($personDetails)));

    $response = $personRepository->create($personDetails);
    $body = (string) $response->wait()->getBody();

    $loggingService->logMessage(sprintf("Test: called create(): [%s]", $body));
}

That's all obvious. The log output for this was:

[2016-11-24 20:04:11] testPost.INFO: Test: calling create({"firstName":"Donald","lastName":"McLean"}) [] []
[2016-11-24 20:04:11] testPost.INFO: LoggingAdapter: Requesting for {"firstName":"Donald","lastName":"McLean"} [] []
[2016-11-24 20:04:11] testPost.INFO: LoggingAdapter: Response for {"firstName":"Donald","lastName":"McLean"}: {"id":"583747bb1a6d9","firstName":"Donald","lastName":"McLean","retrieved":"2016-11-24 20:04:11"} [] []
[2016-11-24 20:04:11] testPost.INFO: StatusToExceptionAdapter: non-exception status encountered: 200 [] []
[2016-11-24 20:04:11] testPost.INFO: Test: called create(): [{"id":"583747bb1a6d9","firstName":"Donald","lastName":"McLean","retrieved":"2016-11-24 20:04:11"}] [] []

We can see no caching was called (good), but the approrpiate logging and StatusToException checks were made. And we got a new record ID back after the insert. Excellent.

The test of the update had two things to do: doing an update of an existing record (happy path) then trying to update a non-existent record (which should yield an exception):

function testUpdate(PersonRepository $personRepository, LoggingService $loggingService) {
    testUpdateByPhase("Valid ID", 3, $personRepository, $loggingService);
    testUpdateByPhase("Invalid ID", -1, $personRepository, $loggingService);
}

function testUpdateByPhase($phase, $id, PersonRepository $personRepository, LoggingService $loggingService) {
    $personDetails = [
        'firstName' => 'Donald',
        'lastName' => 'Corleone'
    ];

    $logDetails = [
        'id' => $id,
        'details' => $personDetails
    ];

    $loggingService->logMessage(sprintf("Test (phase: %s): calling update(%s)", $phase, json_encode($logDetails)));

    $response = $personRepository->update($id, $personDetails);
    try {
        $body = (string) $response->wait()->getBody();
        $loggingService->logMessage(sprintf("Test (phase %s): called update(): [%s]", $phase, $body));
    } catch (Exception $e) {
        $previous = $e->getPrevious();
        $loggingService->logMessage(
            sprintf(
                "Test (phase %s): call to update failed: "
                . "Class: %s; "
                . "Code: %s; "
                . "Message: %s"
                . "Previous class: %s"
                . "Previous message: %s"
                , $phase, get_class($e), $e->getCode(), $e->getMessage()
                , get_class($previous), $previous->getMessage()
            )
        );
    } finally {
        $loggingService->logMessage(sprintf("Test (phase %s): complete", $phase));
    }
}

That's more code, but most of it is error handling, and there's nothing noteworthy. The log shows the outcome. First the valid update:

[2016-11-24 20:04:11] testPost.INFO: Test (phase: Valid ID): calling update({"id":3,"details":{"firstName":"Donald","lastName":"Corleone"}}) [] []
[2016-11-24 20:04:11] testPost.INFO: LoggingAdapter: Requesting for {"parameters":{"id":3},"body":{"firstName":"Donald","lastName":"Corleone"}} [] []
[2016-11-24 20:04:11] testPost.INFO: LoggingAdapter: Response for {"parameters":{"id":3},"body":{"firstName":"Donald","lastName":"Corleone"}}: {"before":{"id":3,"firstName":"Donald","lastName":"Trump"},"after":{"id":3,"firstName":"Donald","lastName":"Corleone"},"updated":"2016-11-24 20:04:11"} [] []
[2016-11-24 20:04:11] testPost.INFO: StatusToExceptionAdapter: non-exception status encountered: 200 [] []
[2016-11-24 20:04:11] testPost.INFO: Test (phase Valid ID): called update(): [{"before":{"id":3,"firstName":"Donald","lastName":"Trump"},"after":{"id":3,"firstName":"Donald","lastName":"Corleone"},"updated":"2016-11-24 20:04:11"}] [] []
[2016-11-24 20:04:11] testPost.INFO: Test (phase Valid ID): complete [] []

Success!

And the invalid ID:

[2016-11-24 20:04:11] testPost.INFO: LoggingAdapter: Requesting for {"parameters":{"id":-1},"body":{"firstName":"Donald","lastName":"Corleone"}} [] []
[2016-11-24 20:04:11] testPost.INFO: StatusToExceptionAdapter: remapped status encountered: 400 [] []
[2016-11-24 20:04:11] testPost.INFO: Test (phase Invalid ID): call to update failed: Class: me\adamcameron\testApp\exception\BadRequestException; Code: 400; Message: A response of 400 was received from the service Previous class: GuzzleHttp\Exception\ClientExceptionPrevious message: Client error: `PUT http://php.local:8070/experiment/guzzle/update.php?id=-1` resulted in a `400 Bad Request` response: <br /> <font size='1'><table class='xdebug-error xe-uncaught-exception' dir='ltr' border='1' cellspacing='0' cellpadding (truncated...)  [] []
[2016-11-24 20:04:11] testPost.INFO: Test (phase Invalid ID): complete [] []


That worked as expected too. Although I now note I should have returned a 404 there, not a 400. Oops. But it's doing what I told it to do, anyhow. And pleasingly, the StatusToExceptionAdapter did its job.

And that's about it. I learned a few new things whilst investigating this one, which is good.

That's the end of my foray into decorating GuzzleHttp adapters. I'll get onto something different next.

Righto.

--
Adam

Wednesday 23 November 2016

PHP: decorating async GuzzleHttp calls - multiple decorators

G'day:
Here's yet another article about decorating an async GuzzleHttp adapter. So far in the series I've got this lot:

Over the course of those articles, I've created three decorators:

  • logging - wraps the async call in "before" and "after" logging;
  • exception handling - remapping GuzzleHttp's default exceptions to HTTP-response-status-specific exceptions;
  • caching - caching successful responses so future calls for the same info won't need to hit the underlying  web service.

These all mirror real-world requirements I have.

I've tested them all separately, but the theory with decoration is that one should be able to further-decorate an already-decorated object. I've decided to give this a go.

Firstly I've revised my approach somewhat. Previously I was baking my endpoint into the adapter as that was convenient for how i was demonstrating the code. This isn't a good approach as the adapter should just focus on making the calls and handling them, not having a position on the destination of the calls. So I've removed the endpoint from the basic adapter:

use GuzzleHttp\Client;
use GuzzleHttp\Promise\Promise;

class GuzzleAdapter implements Adapter {

    private $client;

    public function __construct() {
        $this->client = new Client();
    }

    public function get($url, $parameters) : Promise {
        $fullUrl = sprintf("%s?%s", $url, http_build_query($parameters));

        $response = $this->client->requestAsync("get", $fullUrl);

        return $response;
    }
}

Now I pass the URL into the call to get, and append the passed-in parameters to make a complete URL. In real life I'd probably also be optionally passing in some headers, and perhaps some GuzzleHttp options, but that's just noise for the purposes of what I'm doing here.

Also note I've gone all PHP7 for a change, and added in some stricter typing. To that end, I'm also enforcing an interface on these classes now:

use GuzzleHttp\Promise\Promise;

interface Adapter {
    public function get($url, $parameters) : Promise;
}

In dynamic languages like PHP and CFML I generally try to shy away from being to forceful about type checking as it doesn't really add much, and sometimes gets in the way. But I think in this situation it makes some sense. And I also want to start getting into the swing of things of writing PHP 7 code too.

I've also changed my approach to calling the adapter somewhat. Now that the endpoint has been moved out of the adapter, I need it to go somewhere else. I don't want to be passing it in with every get call. We use the Repository Pattern at work to wrap up details of external service implementation, so I've run with that here.

use GuzzleHttp\Promise\Promise;
use me\adamcameron\testApp\adapter\Adapter;

class PersonRepository {

    private $adapter;

    private static $baseUrl = "http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/";
    private static $getByIdUrl = "getById.cfm";
    private static $getByNameUrl = "getByName.cfm";
    private static $returnStatusCodeUrl = "returnStatusCode.cfm";

    public function __construct(Adapter $adapter)
    {
        $this->adapter = $adapter;
    }

    public function getById($id) : Promise {
        $response = $this->adapter->get(
            self::$baseUrl . self::$getByIdUrl,
            ["id" => $id]
        );

        return $response;
    }

    public function getByName($firstName, $lastName) : Promise {
        $response = $this->adapter->get(
            self::$baseUrl . self::$getByNameUrl,
            [
                "firstName" => $firstName,
                "lastName" => $lastName
            ]
        );

        return $response;
    }

    public function returnStatusCode($statusCode) : Promise {
        $response = $this->adapter->get(
            self::$baseUrl . self::$returnStatusCodeUrl,
            ["statusCode" => $statusCode]
        );

        return $response;
    }
}

Notes on this one:

  • The repo knows about the endpoints it calls. Usually we'd probably have the base URL as a constructor param so we can easily change version of the web service, but that's just noise here, so I've "hard-coded" it.
  • I've added a new method - getByName - that I've not used before. I just wanted to have a second method which had a different method signature from the others I'd previously used. This was mostly for an experiment that I was gonna do but decided against for this article, but left the method in anyhow.
For the sake of completeness, here's the revised endpoint code:

getById.cfm

<cfscript>
cfcontent(type="application/json");

writeLog(file="testApp", text="[ID: #URL.id#] request received");

sleep(5000);
include "./data.cfm";

record = queryExecute(
    "SELECT id, firstName, lastName FROM people WHERE id = :id",
    {id=URL.id},
    {dbtype="query", query="people", maxrows=1}
);

result = structNew("ordered");
result["id"] = record.id;
result["firstName"] = record.firstName;
result["lastName"] = record.lastName;
result["retrieved"] = now().dateTimeFormat("HH:nn:ss.lll");

writeOutput(serializeJson(result));
writeLog(file="testApp", text="[ID: #URL.id#] response returned");
</cfscript>


getByName.cfm

<cfscript>
cfcontent(type="application/json");

writeLog(file="testApp", text="[firstName: #URL.firstName#][lastName: #URL.lastName#] request received");

sleep(2500);
include "./data.cfm";

record = queryExecute(
    "SELECT id, firstName, lastName FROM people WHERE firstName = :firstName AND lastName = :lastName",
    {firstName=URL.firstName, lastName=URL.lastName},
    {dbtype="query", query="people", maxrows=1}
);

result = structNew("ordered");
result["id"] = record.id;
result["firstName"] = record.firstName;
result["lastName"] = record.lastName;
result["retrieved"] = now().dateTimeFormat("HH:nn:ss.lll");

sleep(2500);

writeOutput(serializeJson(result));
writeLog(file="testApp", text="[firstName: #URL.firstName#][lastName: #URL.lastName#] response returned");
</cfscript>

data.cfm

<cfscript>
people = queryNew("id,firstName,lastName", "integer,varchar,varchar", [
    {id=1, firstName="Donald", lastName="Duck"},
    {id=2, firstName="Donald", lastName="Cameron"},
    {id=3, firstName="Donald", lastName="Trump"},
    {id=4, firstName="Donald", lastName="Wearsyatroosas"}
]);
</cfscript>

returnStatusCode.cfm

Remains unchanged:

<cfset sleep(2000)>
<cfheader statusCode="#URL.statusCode#">
<cfoutput>The request resulted in a #URL.statusCode# status code @ #now().dateTimeFormat("HH:nn:ss.lll")#</cfoutput>

The only thing to note really is that these endpoints are kinda data-driven now.

And I have a test of all this. It's long-winded, so I'll go through it section by section, before presenting it again in its entirety.

Firstly - and the only really important bit for the purposes of this article - is setting our test objects:

$loggingService = getLoggingService();
$personRepository = getPersonRepository($loggingService);

// ...


function getLoggingService() : LoggingService {
    $ts = (new DateTime())->format("His");
    $loggingService = new LoggingService("all_$ts");

    return $loggingService;
}

function getPersonRepository(LoggingService $loggingService) : PersonRepository {
    $guzzleAdapter = getGuzzleAdapter();
    $loggingAdapter = getLoggingAdapter($guzzleAdapter, $loggingService);
    $statusToExceptionAdapter = getStatusToExceptionAdapter($loggingAdapter, $loggingService);
    $cachingAdapter = getCachingAdapter($statusToExceptionAdapter, $loggingService);

    $personRepository = new PersonRepository($cachingAdapter);

    return $personRepository;
}

function getGuzzleAdapter() : GuzzleAdapter {
    $guzzleAdapter = new GuzzleAdapter();

    return $guzzleAdapter;
}

function getLoggingAdapter(Adapter $adapter, LoggingService $loggingService) : LoggingAdapter {
    $loggingAdapter = new LoggingAdapter($adapter, $loggingService);

    return $loggingAdapter;
}

function getStatusToExceptionAdapter(Adapter $adapter, LoggingService $loggingService) : StatusToExceptionAdapter {
    $exceptionMap = [
        400 => '\me\adamcameron\testApp\exception\BadRequestException',
        503 => '\me\adamcameron\testApp\exception\ServerException'
    ];

    $statusToExceptionAdapter = new StatusToExceptionAdapter($adapter, $exceptionMap, $loggingService);

    return $statusToExceptionAdapter;
}

function getCachingAdapter(Adapter $adapter, LoggingService $loggingService) : CachingAdapter {
    $cachingService = new CachingService($loggingService);
    $cachingAdapter = new CachingAdapter($adapter, $cachingService);

    return $cachingAdapter;
}

That looks like a chunk of code (well: it is), but it's mostly just compartmentalising some calls. Notes:

  • we need a LoggingService and a PersonRepository for our tests.
  • The PersonRepository needs an Adapter.
  • For our purposes we are decorating the baseline GuzzleAdapter with:
    • a LoggingAdapter. We only want to log calls made to the service, so we put this closest to the baseline Adapter.
    • a StatusToExceptionAdapter. We only want to cache successful calls, and intrinsically previously successful calls will not need the logic in this adapter, so put this next.
    • a CachingAdapter. This goes closest to the calling code so that there's a minimum of complexity if a successful call has been previously made.

The order that the decorations are layers is important, as hopefully I've explained above. The ordering needs to be considered on a case-by-case basis, determined by the purpose of each decorator, and how one decorator might interrupt the execution of other ones; eg: if the StatusToExceptionAdapter throws an exception, the CachingAdapter never does its work. And depending on what those two do, the GuzzleAdapter itself might not be needed, so the LoggingAdapter is skipped too.

From there I test each of the three endpoints again, in much the same way I did before, but noting how the decorators combine where appropriate.

makeRequestsToGetById($personRepository, $loggingService);
logTestSeparator($loggingService);

makeRequestsToGetByName($personRepository, $loggingService);
logTestSeparator($loggingService);

makeRequestsToReturnStatusCode($personRepository, $loggingService);
logTestSeparator($loggingService);

Testing getById I just check the caching still works:

function makeRequestsToGetById(PersonRepository $personRepository, LoggingService $loggingService){
    $id = 4;

    makeRequestToGetById($id, "Uncached", $personRepository, $loggingService);
    pause(5, $loggingService);
    makeRequestToGetById($id, "Cached", $personRepository, $loggingService);
}

function makeRequestToGetById($id, $phase, PersonRepository $personRepository, LoggingService $loggingService){
    $startTime = time();

    $loggingService->logMessage("Test (phase: $phase): calling getById($id)");
    $response = $personRepository->getById($id);
    $loggingService->logMessage("Test (phase: $phase): call to getById complete");
    $body = (string) $response->wait()->getBody();
    $loggingService->logMessage("Test (phase: $phase): Body: $body");

    $duration = time() - $startTime;
    $loggingService->logMessage("Test (phase: $phase): Process duration: {$duration}sec");
}


Sample output:

[2016-11-22 20:39:21] all_203921.INFO: Test: Getting not-yet cached results [] []
[2016-11-22 20:39:21] all_203921.INFO: Test (phase: Uncached): calling getById(4) [] []
[2016-11-22 20:39:21] all_203921.INFO: LoggingAdapter: Requesting for {"id":4} [] []
[2016-11-22 20:39:21] all_203921.INFO: Test (phase: Uncached): call to getById complete [] []
[2016-11-22 20:39:26] all_203921.INFO: LoggingAdapter: Response for {"id":4}: {"id":4,"firstName":"Donald","lastName":"Wearsyatroosas","retrieved":"20:39:26.161"} [] []
[2016-11-22 20:39:26] all_203921.INFO: StatusToExceptionAdapter: non-exception status encountered: 200 [] []
[2016-11-22 20:39:26] all_203921.INFO: CachingService: put called with cd51039fde58b80cf261c3f1a99da3ef [] []
[2016-11-22 20:39:26] all_203921.INFO: Test (phase: Uncached): Body: {"id":4,"firstName":"Donald","lastName":"Wearsyatroosas","retrieved":"20:39:26.161"} [] []
[2016-11-22 20:39:26] all_203921.INFO: Test (phase: Uncached): Process duration: 5sec [] []
[2016-11-22 20:39:26] all_203921.INFO: Test: waiting 5sec [] []
[2016-11-22 20:39:31] all_203921.INFO: Test: waited 5sec [] []
[2016-11-22 20:39:31] all_203921.INFO: Test (phase: Cached): calling getById(4) [] []
no log entry here, because the LoggingAdapter was never hit: the CachingAdapter took care of it
[2016-11-22 20:39:31] all_203921.INFO: Test (phase: Cached): call to getById complete [] []
[2016-11-22 20:39:31] all_203921.INFO: CachingService: get called with cd51039fde58b80cf261c3f1a99da3ef [] []
[2016-11-22 20:39:31] all_203921.INFO: Test (phase: Cached): Body: {"id":4,"firstName":"Donald","lastName":"Wearsyatroosas","retrieved":"20:39:26.161"} [] []
[2016-11-22 20:39:31] all_203921.INFO: Test (phase: Cached): Process duration: 0sec [] []

Also note this demonstrates the LoggingAdapter at work too. Specifically note that there's only a log entry for the request when the web service is actually being called, not when it's coming from cache, further down.

Next I test getByName. It's exactly the same test as the getById one, so I won't bore you with it. It demonstrates the same thing.

Lastly I test returnStatusCode:

function makeRequestsToReturnStatusCode(PersonRepository $personRepository, LoggingService $loggingService) {
    makeRequestToReturnStatusCode200("First", $personRepository, $loggingService);
    pause(2, $loggingService);
    makeRequestToReturnStatusCode200("Second", $personRepository, $loggingService);
    logTestSeparator($loggingService);
    makeRequestToMappedStatusCode("First", $personRepository, $loggingService);
    $loggingService->logMessage("Test: Repeating an erroring call will not touch cache");
    makeRequestToMappedStatusCode("Second", $personRepository, $loggingService);
}

The test here is twofold. First I test that requests that are not intercepted and don't error are logged and cached correctly:

function makeRequestToReturnStatusCode200($phase, PersonRepository $personRepository, LoggingService $loggingService){
    $statusCode = 200;
    $loggingService->logMessage("Test (phase: $phase): calling returnStatusCode($statusCode)");
    $response = $personRepository->returnStatusCode($statusCode);
    $loggingService->logMessage("Test (phase: $phase): call to returnStatusCode complete");
    $body = (string) $response->wait()->getBody();
    $loggingService->logMessage("Test (phase: $phase): Body: $body");
}

Sample log output:

[2016-11-22 20:39:41] all_203921.INFO: Test (phase: First): calling returnStatusCode(200) [] []
[2016-11-22 20:39:41] all_203921.INFO: LoggingAdapter: Requesting for {"statusCode":200} [] []
[2016-11-22 20:39:41] all_203921.INFO: Test (phase: First): call to returnStatusCode complete [] []
[2016-11-22 20:39:43] all_203921.INFO: LoggingAdapter: Response for {"statusCode":200}: The request resulted in a 200 status code @ 20:39:43.319 [] []
[2016-11-22 20:39:43] all_203921.INFO: StatusToExceptionAdapter: non-exception status encountered: 200 [] []
[2016-11-22 20:39:43] all_203921.INFO: CachingService: put called with 8670b5e29a709e36ae186bce7715de68 [] []
[2016-11-22 20:39:43] all_203921.INFO: Test (phase: First): Body: The request resulted in a 200 status code @ 20:39:43.319 [] []
[2016-11-22 20:39:43] all_203921.INFO: Test: waiting 2sec [] []
[2016-11-22 20:39:45] all_203921.INFO: Test: waited 2sec [] []
[2016-11-22 20:39:45] all_203921.INFO: Test (phase: Second): calling returnStatusCode(200) [] []
[2016-11-22 20:39:45] all_203921.INFO: Test (phase: Second): call to returnStatusCode complete [] []
[2016-11-22 20:39:45] all_203921.INFO: CachingService: get called with 8670b5e29a709e36ae186bce7715de68 [] []
[2016-11-22 20:39:45] all_203921.INFO: Test (phase: Second): Body: The request resulted in a 200 status code @ 20:39:43.319 [] []

The second test of returnStatusCode test a remapped status to make sure it works to spec:

function makeRequestToMappedStatusCode($phase, PersonRepository $personRepository, LoggingService $loggingService) {
    $statusCode = 400;
    $loggingService->logMessage("Test (phase: $phase): calling returnStatusCode($statusCode)");
    $response = $personRepository->returnStatusCode($statusCode);
    $loggingService->logMessage("Test (phase: $phase): call to returnStatusCode complete");
    try {
        $response->wait();
        $loggingService->logMessage("Test (phase: $phase): failed to throw expected exception");
    } catch (Exception $e){
        logException($e, $loggingService);
    }
}

Sample logging:

[2016-11-22 20:39:45] all_203921.INFO: Test (phase: First): calling returnStatusCode(400) [] []
[2016-11-22 20:39:45] all_203921.INFO: LoggingAdapter: Requesting for {"statusCode":400} [] []
[2016-11-22 20:39:45] all_203921.INFO: Test (phase: First): call to returnStatusCode complete [] []
[2016-11-22 20:39:47] all_203921.INFO: StatusToExceptionAdapter: remapped status encountered: 400 [] []
[2016-11-22 20:39:47] all_203921.INFO: Test: Request errored with 400  [] []
[2016-11-22 20:39:47] all_203921.INFO: Test: Class: me\adamcameron\testApp\exception\BadRequestException  [] []
[2016-11-22 20:39:47] all_203921.INFO: Test: Message A response of 400 was received from the service  [] []
[2016-11-22 20:39:47] all_203921.INFO: Test: Previous class GuzzleHttp\Exception\ClientException  [] []
[2016-11-22 20:39:47] all_203921.INFO: Test: Previous code 400  [] []
[2016-11-22 20:39:47] all_203921.INFO: Test: Previous message Client error: `GET http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/returnStatusCode.cfm?statusCode=400` resulted in a `400 Bad Request` response: The request resulted in a 400 status code @ 20:39:47.359   [] []
[2016-11-22 20:39:47] all_203921.INFO: Test: Repeating an erroring call will not touch cache [] []
[2016-11-22 20:39:47] all_203921.INFO: Test (phase: Second): calling returnStatusCode(400) [] []
[2016-11-22 20:39:47] all_203921.INFO: LoggingAdapter: Requesting for {"statusCode":400} [] []
[2016-11-22 20:39:47] all_203921.INFO: Test (phase: Second): call to returnStatusCode complete [] []
[2016-11-22 20:39:49] all_203921.INFO: StatusToExceptionAdapter: remapped status encountered: 400 [] []
[2016-11-22 20:39:49] all_203921.INFO: Test: Request errored with 400  [] []
[2016-11-22 20:39:49] all_203921.INFO: Test: Class: me\adamcameron\testApp\exception\BadRequestException  [] []
[2016-11-22 20:39:49] all_203921.INFO: Test: Message A response of 400 was received from the service  [] []
[2016-11-22 20:39:49] all_203921.INFO: Test: Previous class GuzzleHttp\Exception\ClientException  [] []
[2016-11-22 20:39:49] all_203921.INFO: Test: Previous code 400  [] []
[2016-11-22 20:39:49] all_203921.INFO: Test: Previous message Client error: `GET http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/returnStatusCode.cfm?statusCode=400` resulted in a `400 Bad Request` response: The request resulted in a 400 status code @ 20:39:49.392   [] []

So:
  • The status code is converted to the correct exception.
  • The initial log entry is made for the request, but not the one for the response (see the log extract from the getById tests for that one.
  • Nothing is cached or attempted to be fetched from cache at any point because the appropriate handlers are never invoked.

That'sit really. I'm happy with that.

Oh, I use a coupla other helper functions in that lot. For completeness here they are:

function logException(Exception $e, LoggingService $loggingService) {
    $previous = $e->getPrevious();
    $loggingService->logMessage(sprintf("Test: Request errored with %s%s", $e->getCode(), PHP_EOL));
    $loggingService->logMessage(sprintf("Test: Class: %s%s", get_class($e), PHP_EOL));
    $loggingService->logMessage(sprintf("Test: Message %s%s", $e->getMessage(), PHP_EOL));
    $loggingService->logMessage(sprintf("Test: Previous class %s%s", get_class($previous), PHP_EOL));
    $loggingService->logMessage(sprintf("Test: Previous code %s%s", $previous->getCode(), PHP_EOL));
    $loggingService->logMessage(sprintf("Test: Previous message %s%s", $previous->getMessage(), PHP_EOL));
}

function logTestSeparator(LoggingService $loggingService) {
    $loggingService->logMessage("==================================================================");
}

function pause($seconds, LoggingService $loggingService) {
    $loggingService->logMessage("Test: waiting {$seconds}sec");
    sleep($seconds);
    $loggingService->logMessage("Test: waited {$seconds}sec");
}

Indeed the code for everything here is up at GitHub, but I'm changing it with each article I write, so it gets out of date quickly. Here's the current commit, anyhow, and that's the code I've been using for this article.

I've got yet another article to write on this, but I haven't even worked out how I'm gonna write the code yet, so that might be a day or so still.

Righto.

--
Adam

Tuesday 22 November 2016

PHP: decorating async GuzzleHttp calls - caching

G'day:
This continues my series of exercise in decorating GuzzleHttp calls. Recap:

The last piece of the puzzle I need to deal with is caching. We need to decorate our web service adapter with a caching tier so that we don't continually pester it over the wire for info we have already asked for.

The treatment here is traditional:
  • we get a request for data  based on an ID;
  • we check the cache for data stored against that ID;
  • if we have it, we returned the cached version;
  • if not, we call the web service;
  • and before returning the result, we cache it for "next time".
I've implemented a stub caching service which simply sticks stuff in an array. This'll do for the purposes of testing:

class CachingService {

    public $cache;

    public function __construct(){
        $this->cache = [];
    }

    public function contains($id){
        return array_key_exists($id, $this->cache);
    }

    public function get($id){
        echo "Getting $id from cache" . PHP_EOL . PHP_EOL;
        return $this->cache[$id];
    }

    public function put($id, $value){
        echo "Putting $id into cache" . PHP_EOL . PHP_EOL;
        return $this->cache[$id] = $value;
    }
}

In reality we'd use redis or something like that, but it's the interface that matters here, not the implementation. Note I'm also outputing a message when the cache methods are hit, just so we can tell what's going on when the code is running.

Next I have a CachingGuzzleAdapter which is the decorator for a GuzzleAdapter. This has a chunk of code in it, so I'll break it down:

class CachingGuzzleAdapter {

    private $adapter;
    private $cache;

    public function __construct($adapter, $cache) {
        $this->adapter = $adapter;
        $this->cache = $cache;
    }

    // ...

}

No surprises here. The decorator takes the adapter it's decorating, as well as an instance of the cache service it'll be talking to. I probably shoulda called that $cachingService, now that I look at it. We're taking the same approach here as we did with the other decorators (in the earlier articles): all the guzzling is offloaded to the adapter here; this class only deals with the caching side of things.

To that end, our get method is very simple:

public function get($id){
    if ($this->cache->contains($id)) {
        return $this->returnResponseFromCache($id);
    }
    return $this->returnResponseFromWebService($id);
}

If it's in the cache: use that; if not: go get it. The details of how to get the thing from cache or how to get things from the adapter are hidden in helper functions.

Here's the tricky bit: getting the response back from cache:

private function returnResponseFromCache($id) {
    $p = new Promise(function() use (&$p, $id){
        echo "GETTING FROM CACHE" . PHP_EOL;
        $cachedResult = $this->cache->get($id);

        $newResponse = new Response(
            $cachedResult['status'],
            $cachedResult['headers'],
            $cachedResult['body']
        );

        $p->resolve($newResponse);
    });

    return $p;
}

Here we:

  • get some data from the cache. This method only gets called if the data is there, so we can dive straight in.
  • We create a new Guzzle Response object, and put the data back into it.
  • We resolve a promise with that as its value. We need to return a promise here because that's what the get method we're decorating returns.

I'm not entirely comfortable with the self-referential bit around $p, but that was from the docs as the recommended way of doing this. So be it.

If the stuff wasn't in cache, we need to make an actual web service call:

private function returnResponseFromWebService($id){
    $response = $this->adapter->get($id);

    $response->then(function(Response $response) use ($id) {
        echo "PUTTING IN CACHE" . PHP_EOL;

        $detailsToCache = [
            'status' => $response->getStatusCode(),
            'headers' => $response->getHeaders(),
            'body' => $response->getBody()->getContents()
        ];
        $this->cache->put($id, $detailsToCache);
    });

    return $response;
}

This is straight forward:

  • make the call;
  • in its resolution handler grab the data and bung it in the cache.
  • Note that I'm only caching the significant bits of the response, not the response itself. My original version of this cached the entire response object: because the cache is just an in-memory array I can do that; in reality I'd need to serialise it somehow, so I wanted to make a point of only caching the data here.

That's it!

Of course I need to test this, so I wrote a test rig, similar to the ones I've already done:

$endPoint  = "http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/getById.cfm?id=";

$guzzleAdapter = new GuzzleAdapter($endPoint);
$cache = new CachingService();
$adapter = new CachingGuzzleAdapter($guzzleAdapter, $cache);

printf("Getting not-yet cached results @ %s%s", (new DateTime())->format("H:i:s"), PHP_EOL . PHP_EOL);
makeRequests($adapter);

echo "===================================================" .PHP_EOL . PHP_EOL;

sleep(10);

printf("Getting results again (from cache) @ %s%s", (new DateTime())->format("H:i:s"), PHP_EOL . PHP_EOL);
makeRequests($adapter);


function makeRequests($adapter){
    $startTime = time();
    $ids = ["001", "002"];
    $responses = [];
    foreach ($ids as $id) {
        echo "Making requests" . PHP_EOL . PHP_EOL;
        echo "Requesting: $id" . PHP_EOL;
        $responses[] = $adapter->get($id);
        echo "Requests made" . PHP_EOL . PHP_EOL;
    }
    echo "Fetching responses" . PHP_EOL . PHP_EOL;
    foreach ($responses as $response){
        $body = (string) $response->wait()->getBody();
        echo "Body: $body" . PHP_EOL . PHP_EOL;
    }
    echo "Responses fetched" . PHP_EOL . PHP_EOL;
    $duration = time() - $startTime;
    echo "Process duration: {$duration}sec" . PHP_EOL . PHP_EOL;
}

This just:
  • calls the adapter for a coupla IDs,
  • waits 10sec
  • and gets the same data again.
The expectation is that the first call will take around 5sec as that's how long each web service call takes:

<cfscript>
cfcontent(type="application/json");

writeLog(file="testApp", text="[ID: #URL.id#] request received");

sleep(5000);

writeOutput(serializeJson({"id"=URL.id, "retrieved"=now().dateTimeFormat("HH:nn:ss.lll")}));
writeLog(file="testApp", text="[ID: #URL.id#] response returned");
</cfscript>

It'll only be 5sec in total not 10sec because the calls are being made asynchronously, remember?

The second round of calls should take no time at all because the adapter will be able to get the results from cache. In theory. Let's see:

>php testCachingAdapter.php
Getting not-yet cached results @ 09:24:25

Making requests

Requesting: 001
Requests made

Making requests

Requesting: 002
Requests made

Fetching responses

PUTTING IN CACHE
Putting 001 into cache

PUTTING IN CACHE
Putting 002 into cache

Body: {"retrieved":"09:24:30.453","id":"001"}

Body: {"retrieved":"09:24:30.457","id":"002"}

Responses fetched

Process duration: 5sec

===================================================

Getting results again (from cache) @ 09:24:40

Making requests

Requesting: 001
Requests made

Making requests

Requesting: 002
Requests made

Fetching responses

GETTING FROM CACHE
Getting 001 from cache

Body: {"retrieved":"09:24:30.453","id":"001"}

GETTING FROM CACHE
Getting 002 from cache

Body: {"retrieved":"09:24:30.457","id":"002"}

Responses fetched

Process duration: 0sec


>

Hurrah! As predicted the first call takes 5sec; the second takes 0sec. And the intermediary telemetry confirms that the cache is being used correctly. Also note the timestamps on the returned data reflect when the initial requests were made, not when the second round of calls were made.

That was pretty easy this time. It took me a while to find the code for returning a resolved promise with the Response value in it, but wiring everything up was simple.

As an exercise I'm now gonna wire up a CachedLoggedErrorMappedGuzzleAdapter. Or perhaps a LoggedErrorMappedCacheGuzzleAdapter. Not sure. But it's all a difference in wiring, and that's it really. I'll write that up next.

Righto.

--
Adam

Monday 21 November 2016

PHP: decorating async GuzzleHttp calls - handling exceptions a different way

G'day:
The previous article ("PHP: decorating async GuzzleHttp calls - handling exceptions") detailed how I've used a simple decorator to intercept 4xx & 5xx HTTP responses from my web service and remap Guzzle's default exceptions and use my own ones.  It was basically just this:

public function get($status){
    return $this->adapter
        ->get($status)
        ->otherwise(function($exception){
            $code = $exception->getCode();

            if (!array_key_exists($code, $this->exceptionMap)) {
                throw $exception;
            }
            throw new $this->exceptionMap[$code](
                "A response of $code was received from the service",
                $code,
                $exception
            );
        });
}


Notes:
  • get is a wrapper for a call to Guzzle, and it returns a GuzzleHttp\Promise
  • if the promise rejects (which it will on a 4xx or 5xx response), then I have a handler to check if it's a status that I'm interested in, and if so return (well: throw) a different exception.
  • If not, I just rethrow the original exception.
Simple enough and that works nicely. Read the article though, for more detail on this.

Along the way to that solution I ballsed something up in a way I still don't quite understand and I cannot replicate now, so abandoned that easy solution and approached things a different way. SO I've now got two ways of doing the same thing, and that seems liek a cheap win for me as far as blog content goes, so yer hearing about both of 'em ;-)

If I could not work out how to intercept Guzzle's own exception handling, I decided to replace it.

Reading through the docs I found one could switch off Guzzle's exception handling via the http_errors option. That was no use in itself (as it turns out), but looking at the matches for http_errors in the docs, I got down to the Middleware section, which detailed how the error handler (the one that pays attention to the http_errors setting) is one of the default middelware that Guzzle configures if no bespoke middleware is specified. It also details how one can set one's own middleware. Ergo: one can set one's own error handling middleware.

First things first, I took their own bespoke middleware example and modified it to handle my error remapping code (as per the previous article). As I was only really copying and pasting still into their example, I'll just present the final job:

private function handleHttpErrors($exceptionMap)
{
    return function (callable $handler) use ($exceptionMap) {
        return function ($request, array $options) use ($handler, $exceptionMap) {
            return $handler($request, $options)->then(
                function (ResponseInterface $response) use ($request, $handler, $exceptionMap) {
                    $code = $response->getStatusCode();

                    if ($code < 400) {
                        return $response;
                    }

                    if (array_key_exists($code, $exceptionMap)){
                        throw new $exceptionMap[$code](
                            (string)$response->getBody(),
                            $code
                        );
                    }
                    throw RequestException::create($request, $response);
                }
            );
        };
    };
}

Notes:
  • most of this is copy and paste from the docs and I have no idea why it is the way it is, so... erm... well there you go.
  • The rest just checks the response for an "error" situation;
  • if it's not just return it... the next middleware will continue with it.
  • If it is an exceptional situation: consult the exception map for how to handle it (which exception to throw);
  • or if there's no remapping consideration, just throw the same exception one would normally throw (this was pinched from a different part of the Guzzle source code: Middleware.php).
That's all lovely, but I still need to get it into the middleware stack. Remember this is just a decorator, and it doesn't itself have its own Guzzle client... that's hidden away in the base Guzzle Adapter. But I need to have access to its middleware stack.

Here I cheat slightly and add a method to the base GuzzleAdapter:

namespace me\adamcameron\testApp;

use GuzzleHttp\Client;

class GuzzleAdapter {

    private $client;
    private $endPoint;

    public function __construct($endPoint){
        $this->endPoint = $endPoint;
        $this->client = new Client();
    }

    public function get($id){
        $response = $this->client->requestAsync(
            "get",
            $this->endPoint . $id,
            ["http_errors" => true]
        );

        return $response;
    }

    public function getHandlerStack()
    {
        return $this->client->getConfig('handler');
    }

}

This means the ExceptionHandler decorator can call that method, and get a reference to the handler stack. One caveat with this is that all decorators now need a proxy for this method too. This kinda suggests to me I need to have a GuzzleAdapter interface which specifies which methods decorators need to implement, but I've not got around to that yet.

Now from the ExceptionHandler decorator, I can horse around slightly, replacing the default exception handling with my own version:

public function __construct($adapter, $exceptionMap) {
    $this->adapter = $adapter;
    $this->exceptionMap = $exceptionMap;

    $this->replaceClientErrorHandler($exceptionMap);
}

// ...

private function replaceClientErrorHandler($exceptionMap)
{
    $stack = $this->adapter->getHandlerStack();

    $stack->remove('http_errors');

    $stack->unshift($this->handleHttpErrors($exceptionMap));
}

The handler stack doesn't have a "set" method that works on a named handler like $stack->set('http_errors', $this->handleHttpErrors($exceptionMap)), hence having to remove the default and then stick my own back in. But that's OK I guess.

And that all works.

I have the same test code as I had in the previous article, and it outputs much the same results.

My question is now... which of these approaches is better?

  • The previous article's code is simpler, and easier to follow as one needs to know less about the inner workings of Guzzle.
  • However letting Guzzle handle exceptions in one way, then intercepting that and going "actually now I'll do it meself thanks" seems like doubling up on work a bit.

I think from the perspective of code maintenance, the previous approach is probably "better" in the long run. But I'll just give both options to the chief, and see what he reckons. As my lunch break is about to be over, I think he'll be reckoning "get back to work, Cameron", so I better do that.

Righto.

--
Adam

Sunday 20 November 2016

PHP: decorating async GuzzleHttp calls - handling exceptions

G'day:
This is a continuation from my earlier article - "PHP: decorating async GuzzleHttp calls". Hopefully it stands on its own merit, but perhaps y/day's one (ie: Thursday 17/11/2016) will offer some more context than I perhaps will repeat here. I do refer back to some of the code in that article. Go read it.

Speaking of context though, we're in the process of re-decorating (in the Decorator Pattern sense, not the shopping-at-Ikea sense) our GuzzleHttp calls, specifically when we're making async calls.  Yesterday I looked at how to do request & response logging on async calls. The next mission is to deal with exceptions in our own way.

GuzzleHttp calls will raise a ClientException when an HTTP response has a 400-series status code, and a ServerException when it's in the 500 range. See "Guzzle 6 docs / Quickstart / Exceptions". That's all cool as a default, but we need to be able to map response codes to different exceptions in our adapters for one reason or another. So I need to work out how to intercept those, handle them, and throw our own exceptions. I was fairly confident it was gonna be the same as with the logging example, except using rejection handlers instead of resolution ones.

For testing I set up another quick CFML-based endpoint, which would just let me return a specific HTTP response code:

<cfheader statusCode="#URL.statusCode#">
<cfoutput>The request resulted in a #URL.statusCode# status code</cfoutput>


So whatever code I pass on the URL, it uses that as the status code for the response, and also confirms that in the body.

I figured adapter on the PHP end of things would be along these lines:
namespace me\adamcameron\testApp;

class StatusToExceptionAdapter {

    private $adapter;
    private $exceptionMap;

    public function __construct($adapter, $exceptionMap) {
        $this->adapter = $adapter;
        $this->exceptionMap = $exceptionMap;
    }

    public function get($status){
        return $this->adapter
            ->get($status)
            ->otherwise(function($exception){
                $code = $exception->getCode();

                if (!array_key_exists($code, $this->exceptionMap)) {
                    throw $exception;
                }
                throw new $this->exceptionMap[$code](
                    "A response of $code was received from the service",
                    $code,
                    $exception
                );
            });
    }
}

Points:

  • Again this adapter just decorates the adapter that does the actual "guzzling" (code in previous article); 
  • the decoration being a passed-in exception map.
  • Where in the previous logging example I was using a resolution handler (a then call), here I'm using a rejection handler, via otherwise.
  • So if the call to get results in a rejected promise (ie: an error), I do the following:
    • check if the exception passed to the handler was one I have a mapping for
    • if not, just rethrow the original exception
    • otherwise I throw a new exception of the remapped exception type
    • and pass the original exception as its previous exception.
That's it. And... um... this all... works.

Here's a test rig:


use \me\adamcameron\testApp\GuzzleAdapter;
use \me\adamcameron\testApp\StatusToExceptionAdapterOld;

require_once __DIR__ . "/../../vendor/autoload.php";

$endPoint  = "http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/returnStatusCode.cfm?statusCode=";

$guzzleAdapter = new GuzzleAdapter($endPoint);

$exceptionMap = [
    400 => '\me\adamcameron\testApp\exception\BadRequestException',
    503 => '\me\adamcameron\testApp\exception\ServerException'
];

$adapter = new StatusToExceptionAdapter($guzzleAdapter, $exceptionMap);

$tests = [
    'non-error' => 200,
    'mapped client error' => 400,
    'mapped server error' => 503,
    'un-mapped client error' => 404,
    'un-mapped server error' => 500
];

foreach($tests as $test=>$value) {
    printf("%s (%s)%s", $test, $value, PHP_EOL . PHP_EOL);

    $response = $adapter->get($value);

    try {
        $resolvedResponse = $response->wait();

        printf(
            "Successful request returned: %s%s ",
            (string) $resolvedResponse->getBody()
        );
    } catch (Exception $e){
        printf("Request errored with %s%s", $e->getCode(), PHP_EOL);
        printf("Class: %s%s", get_class($e), PHP_EOL);
        printf("Message %s%s", $e->getMessage(), PHP_EOL);

        $previous = $e->getPrevious();
        if (is_null($previous)){
            continue;
        }

        printf("Previous class %s%s", get_class($previous), PHP_EOL);
        printf("Previous code %s%s", $previous->getCode(), PHP_EOL);
        printf("Previous message %s%s", $previous->getMessage(), PHP_EOL);
    }
    finally {
        echo PHP_EOL . "====================================================" . PHP_EOL . PHP_EOL;
    }
}


That looks like a lot of code, but it's simple:

  • initialise the Guzzle adapter
  • decorate it with the exception mapping one
  • I'm mapping for just a couple of response codes
  • I loop over a bunch of possibilities, including:
    • a 200-OK response (which is not impacted by any of this work, and should just filter through);
    • both exceptions I'm remapping;
    • another coupla "error" response codes I'm not remapping
  • I call the web service for each of these;
  • and output the results.
  • Which might or might not have a wrapped "previous" exception.
And the output of that test run shows it all working A-OK:


 C:\>php testExceptionMap.php

 non-error (200)

 Successful request returned: The request resulted in a 200 status code


 ====================================================

 mapped client error (400)

 Request errored with 400
 Class: me\adamcameron\testApp\exception\BadRequestException
 Message A response of 400 was received from the service
 Previous class GuzzleHttp\Exception\ClientException
 Previous code 400
 Previous message Client error: `GET http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/returnStatusCode.cfm?statusCode=400` resulted in a `400 Bad Request` response: The request resulted in a 400 status code

 ====================================================


 mapped server error (503)

 Request errored with 503
 Class: me\adamcameron\testApp\exception\ServerException
 Message A response of 503 was received from the service
 Previous class GuzzleHttp\Exception\ServerException
 Previous code 503
 Previous message Server error: `GET http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/returnStatusCode.cfm?statusCode=503` resulted in a `503 Service Unavailable` response: The request resulted in a 503 status code

 ====================================================

 un-mapped client error (404)

 Request errored with 404
 Class: GuzzleHttp\Exception\ClientException
 Message Client error: `GET http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/returnStatusCode.cfm?statusCode=404` resulted in a `404 Not Found` response: The request resulted in a 404 status code

 ====================================================

 un-mapped server error (500)

 Request errored with 500
 Class: GuzzleHttp\Exception\ServerException
 Message Server error: `GET http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/returnStatusCode.cfm?statusCode=500` resulted in a `500 Internal Server Error` response: The request resulted in a 500 status code

 ====================================================

 C:\>

So here we see, again:
  • the 200-OK response;
  • both exceptions I'm remapping;
  • A 404 and a 500 which I'm not remapping, so retain their Guzzle-specific exceptions

All good. But why did I sound hesitant before when I said "And... um... this all... works"? Because when I first wrote this code on Friday it didn't bloody work. No matter what I did could I stop the original Guzzle exceptions bubbling back. I started writing this up today, and hastily rewrote the code I was using on Fri for the article, and... now it bloody works! This is excellent as it's really easy, but I spent all Fri evening and Saturday working around not being able to get this working the way I wanted. Sigh. And now I can't - for the life of me - work out where I was going wrong before. Grrr.

One positive side of this though is that I did find another way of dealing with this, and it might be slightly more "semantically Guzzle", so I'll write that up tomorrow. -ish.

Anyway, I need to scarf this Guinness and go find my gate; which will hopefully have an aircraft at it, to take me back to London.

Righto.

--
Adam

Thursday 17 November 2016

PHP: decorating async GuzzleHttp calls

G'day:
A while back I looked at the decorator pattern in the context of some stuff we were doing:

That's all surprisingly straight forward and handy stuff.

We're revisiting some of this for a new implementation of our HTTP adapter library, which had everything baked into it before, and the decorating has had me scratching my head a bit as we're implementing an adapter for GuzzleHttp, and it does its requests asynchronously, and we want to leverage that.

Just to recap, previously we'd have this sort of thing:

namespace me\adamcameron\testApp;

use GuzzleHttp\Client;

class GuzzleAdapter {

    private $client;
    private $endPoint;

    public function __construct($endPoint){
        $this->endPoint = $endPoint;
        $this->client = new Client();
    }

    public function get($id){
        $response = $this->client->requestAsync(
            "get",
            $this->endPoint . $id
        );

        return $response;
    }

}

And say a logging decorator for that:

namespace me\adamcameron\testApp;

class LoggedGuzzleAdapter {

    private $adapter;
    private $logger;

    public function __construct($adapter, $logger) {
        $this->adapter = $adapter;
        $this->logger = $logger;
    }

    public function get($id){
        $this->logger->logMessage(sprintf("Requesting for %s", $id));

        $response = $this->adapter->get($id);

        $body = $response->getBody();
        $this->logger->logMessage(sprintf("Response for %s: %s", $id, $body));
        
        return $response;
    }

}


And we'd init our adapter thus:

$endPoint  = "http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/getById.cfm?id=";

$guzzleAdapter = new GuzzleAdapter($endPoint);
$logger = new LoggingService();
$adapter = new LoggedGuzzleAdapter($guzzleAdapter, $logger);


So the underlying GuzzleAdapter handles the Guzzle stuff, the LoggedGuzzleAdapter handles just the logging stuff, but defers to its GuzzleAdapter to do its part of the job, and keeps all the moving parts and bits of functionality sensibly separated.  And it's pretty simple. And as detailed in those earlier articles, we can keep layering decorators around an adapter to add caching or what-have-you in a similar way. Easy. Nice.

However this only works cos the call to Guzzle actually returns the result on the spot. And this is cos we were using it synchronously: we make a call to it, it blocks until it gets the answer back from the target and gives us the answer.

Now that we're using async calls, Guzzle doesn't give us the answer, it just gives us a Promise which will eventually resolve to be the answer. This is in theory good cos it means the calling code can make a bunch of HTTP calls, and not wait around for each of them to resolve in series: Guzzle will actually make them all in parallel. I have a look at this in article "PHP: async requests using Guzzle and request pools".

If we go back to our decorator we can see the problem:

public function get($id){
    $this->logger->logMessage(sprintf("Requesting for %s", $id));

    $response$promisedResponse = $this->adapter->get($id);

    $body = $response$promisedResponse->getBody();
    $this->logger->logMessage(sprintf("Response for %s: %s", $id, $body));
    
    return $response$promisedResponse;
}

At the point at which our decorator needs the body... we don't have it yet. All we have is a promise that at some point we'll have a body (or we'll have response object via the resolved promise, anyhow; and the response object will have the body).

To get the body we first need to wait for the promise to resolve... which is a blocking operation and kinda defeats the purpose of using the async approach in the first place. IE: we could do this sort of thing:

public function get($id){
    $this->logger->logMessage(sprintf("Requesting for %s", $id));

    $promisedResponse = $this->adapter->get($id);
    $response = $promisedResponse->wait();
    
    $body = $response->getBody();
    $this->logger->logMessage(sprintf("Response for %s: %s", $id, $body));
    
    return $response;
}

But doing the wait immediately defeats the purpose of making the call async in the first place. We want the wait call to... err... wait... until the calling code says "right I need to actually use that data now".

Our initial attempt to sort this out was to analyse the issue as being one of "well we don't have the data we need until we call wait, so then we need to do the logging then... which means we need to intercept the wait call... which means we need to return our own decorated version of the response from the call to the adapter with its own wait and have a LoggedResponse, and return that from the code above..." But... and I hope my colleague doesn't mind me saying... when I saw this code in code review I kinda went "there must be a better, more semantic way of doing this". I won't repeat the code as I cannot use our actual work code in my blog, and I am not in the office right now and can't remember the detail of the implementation anyhow. But it's not ideal, so I don't want to share it anyhow.

I've been off sick for the last coupla days, which gives me a lot of time to deliberate and mess around with stuff and google a lot more than I allow myself time for when I'm in the office. With a wee bit of "standing back and having another think about it", the solution became clear. We don't need to explicitly override the wait method before we call it... the promise builds that capability in! At the time we're making the call, we get to tell the Promise what happens when it gets resolved. So I've knocked together this proof of concept:

public function get($id){
    $this->logger->logMessage(sprintf("(%s) Requesting for %s", $this->thisFile, $id));

    $response = $this->adapter->get($id);

    $response->then(function($response) use ($id){
        $body = $response->getBody();
        $this->logger->logMessage(sprintf("(%s) Response for %s: %s", $this->thisFile, $id, $body));
        $body->rewind();
    });

    return $response;
}

This was a bit of a head-slap moment - in that it took me a while to work out what to do - the whole thing about Promises is that one's able to chain functionality onto their lifecycle. if we wanna run some code once the Promise resolves, we just sling a then handler onto it.

This is a good solution IMO as it keeps all the logging decoration in one place, doesn't require any blocking of the async part of the operation, and is still very clear what's going on, even if the inner workings of Promises are a bit opaque (which TBH, they still are for me. Every time I work with 'em I have to re-read the docs. Which in Guzzle's case are pretty bloody awful, if I'm to be unkindly frank).

I chucked all this into a test rig to demonstrate to myself it was sound.

First up I contrived an endpoint in CFML for the PHP code to hit. I wanted to do this outside of PHP so it didn't in any way interfere with the PHP code running. It's simple:

<cfscript>
cfcontent(type="application/json");

writeLog(file="testApp", text="[ID: #URL.id#] request received");

sleep(5000);

writeOutput(serializeJson({"id"=URL.id, "retrieved"=now().dateTimeFormat("HH:nn:ss.lll")}));
writeLog(file="testApp", text="[ID: #URL.id#] response returned");
</cfscript>


This just takes an ID parameter and waits 5sec then returns it in a JSON packet. I wait 5sec to make the async-ness of the PHP calls easier to see. I'm also logging some stuff here to compare when the requests got to CF compared to when they were sent by PHP.

On the PHP end of things, I've got this:

use \me\adamcameron\testApp\GuzzleAdapter;
use \me\adamcameron\testApp\LoggedGuzzleAdapter;
use \me\adamcameron\testApp\LoggingService;

require_once __DIR__ . "/../vendor/autoload.php";

$endPoint = "http://cf2016.local:8516/cfml/misc/guzzleTestEndpoints/getById.cfm?id=";

$guzzleAdapter = new GuzzleAdapter($endPoint);
$logger = new LoggingService();
$adapter = new LoggedGuzzleAdapter($guzzleAdapter, $logger);

$ids = ["001", "002", "003", "004"];

$thisFile = basename(__FILE__);

$logger->logMessage(sprintf("(%s) Making requests...", $thisFile));

$responses = [];
foreach ($ids as $id){
    $logger->logMessage(sprintf("(%s) Requesting for %s", $thisFile, $id));
    $responses[] = $adapter->get($id);
}
$logger->logMessage(sprintf("(%s) Requests made", $thisFile));

$logger->logMessage(sprintf("(%s) Getting bodies from requests...", $thisFile));
foreach ($responses as $response){
    $logger->logMessage(sprintf("(%s) before calling wait()", $thisFile));
    $body = $response->wait()->getBody()->getContents();
    $logger->logMessage(sprintf("(%s) Response Body: %s", $thisFile, $body));
}
$logger->logMessage("Done");

This does the following:
  • creates the GuzzleAdapter;
  • uses a LoggedGuzzleAdapter to decorate it with some logging (the LoggingService just wraps some Monolog stuff);
  • loops over four IDs;
  • and requests their bumpf;
  • we then loop over the responses we've accumulated;
  • wait for them to resolve (calling wait blocks until they are);
  • and outputs the result;
  • all the way along, writing to the log at key points.

The actual LoggedGuzzleAdapter I'm using here is:

class LoggedGuzzleAdapter {

    private $adapter;
    private $logger;
    private $thisFile;

    public function __construct($adapter, $logger) {
        $this->adapter = $adapter;
        $this->logger = $logger;
        $this->thisFile = basename(__FILE__);
    }

    public function get($id){
        $this->logger->logMessage(sprintf("(%s) Requesting for %s", $this->thisFile, $id));

        $response = $this->adapter->get($id);

        $response->then(function($response) use ($id){
            $body = $response->getBody();
            $this->logger->logMessage(sprintf("(%s) Response for %s: %s", $this->thisFile, $id, $body));
            $body->rewind();
        });

        return $response;
    }

}


And the underlying GuzzleAdapter:

use GuzzleHttp\Client;

class GuzzleAdapter {

    private $client;
    private $endPoint;

    public function __construct($endPoint){
        $this->endPoint = $endPoint;
        $this->client = new Client();
    }

    public function get($id){
        $response = $this->client->requestAsync(
            "get",
            $this->endPoint . $id,
            ["http_errors" => true]
        );

        return $response;
    }

    public function getHandlerStack()
    {
        return $this->client->getConfig('handler');
    }

}


The things to note here are:

  • I'm logging the file name the log entry was made from. This is just to make it clearer in the logs which code is doing what for a given entry.
  • Just note the complete separation of concerns between the two files. One does logging. One does... "Guzzling". And they each focus on the job at hand, and that's it.

Here's the result. This is what PHP logged. I've trimmed-out some repetition & clutter, but have not changed any context or ordering of what got logged:

[14:15:53](makeRequests.php) Making requests...
[14:15:53](LoggedGuzzleAdapter.php) Requesting for 001
[14:15:53](LoggedGuzzleAdapter.php) Requesting for 002
[14:15:53](LoggedGuzzleAdapter.php) Requesting for 003
[14:15:53](LoggedGuzzleAdapter.php) Requesting for 004
[14:15:53](makeRequests.php) Requests made
[14:15:53](makeRequests.php) Getting bodies from requests...
[14:15:53](makeRequests.php) before calling wait()
[14:15:58](LoggedGuzzleAdapter.php) Response for 003{"retrieved":"14:15:58.450","id":"003"}
[14:15:58](LoggedGuzzleAdapter.php) Response for 002{"retrieved":"14:15:58.450","id":"002"}
[14:15:58](LoggedGuzzleAdapter.php) Response for 004{"retrieved":"14:15:58.450","id":"004"}
[14:15:58](LoggedGuzzleAdapter.php) Response for 001{"retrieved":"14:15:58.450","id":"001"}
[14:15:58](makeRequests.php) Response Body {"retrieved":"14:15:58.450","id":"001"}
[14:15:58](makeRequests.php) before calling wait()
[14:15:58](makeRequests.php) Response Body {"retrieved":"14:15:58.450","id":"002"}
[14:15:58](makeRequests.php) before calling wait()
[14:15:58](makeRequests.php) Response Body {"retrieved":"14:15:58.450","id":"003"}
[14:15:58](makeRequests.php) before calling wait()
[14:15:58](makeRequests.php) Response Body {"retrieved":"14:15:58.450","id":"004"}

Things to note:

  • first and foremost: the PHP code is indeed making the HTTP requests asynchronously. Remember the CFML code pauses for 5sec for each response, which means if we do four requests that's a total of 20sec paused time. But the whole process for all four requests takes only 5sec (CF is intrinsically multi-threaded, so from its side of things, it'll process all four requests simultaneously).
  • PHP makes all four requests within the same first second of execution.
  • After 5sec, the responses start to come in.
  • The first wait call bears the brunt of this 5sec wait. Bear in mind this is a blocking operation so PHP is now waiting for the 5sec-long response from CF to come back. But after that, all the responses start to come in before their equivalent wait calls, so those promises are resolved before the code even calls wait for them.
  • most importantly: the correct logging is taking place at the correct time. So the code actually works as intended.
One interesting thing here. it doesn't seem like the act of making the request actually triggers the request. It's the act of waiting that causes the requests to be sent (albeit it: all of them).

I stuck a ten second wait in my PHP code, between making the requests and asking about their responses:

$logger->logMessage(sprintf("(%s) Requests made", $thisFile));

sleep(10);

$logger->logMessage(sprintf("(%s) Getting bodies from requests...", $thisFile));

And here's the log for that run:

[14:47:58] (makeRequests.php) Making requests...
[14:47:58] (LoggedGuzzleAdapter.php) Requesting for 001
[14:47:58] (LoggedGuzzleAdapter.php) Requesting for 002
[14:47:58] (LoggedGuzzleAdapter.php) Requesting for 003
[14:47:58] (LoggedGuzzleAdapter.php) Requesting for 004
[14:47:58] (makeRequests.php) Requests made
[14:48:08] (makeRequests.php) Getting bodies from requests...
[14:48:08] (makeRequests.php) before calling wait()
[14:48:13] (LoggedGuzzleAdapter.php) Response for 004: {"retrieved":"14:48:13.704","id":"004"}
[14:48:13] (LoggedGuzzleAdapter.php) Response for 001: {"retrieved":"14:48:13.719","id":"001"}
[14:48:13] (LoggedGuzzleAdapter.php) Response for 003: {"retrieved":"14:48:13.719","id":"003"}
[14:48:13] (LoggedGuzzleAdapter.php) Response for 002: {"retrieved":"14:48:13.704","id":"002"}
[14:48:13] (makeRequests.php) Response Bodies: {"retrieved":"14:48:13.719","id":"001"}
[14:48:13] (makeRequests.php) before calling wait()
[14:48:13] (makeRequests.php) Response Bodies: {"retrieved":"14:48:13.704","id":"002"}
[14:48:13] (makeRequests.php) before calling wait()
[14:48:13] (makeRequests.php) Response Bodies: {"retrieved":"14:48:13.719","id":"003"}
[14:48:13] (makeRequests.php) before calling wait()
[14:48:13] (makeRequests.php) Response Bodies: {"retrieved":"14:48:13.704","id":"004"}
[14:48:13] Done

Notes:

  • the requests are all made @ 58.
  • you can see the 10sec sleep here. If the requests had actually been made, then they'd've all come back in that 10sec window.
  • but we can tell from the values coming back from ColdFusion that the requests weren't actually even made until 08 (as the 5sec delay is indicated in 13 in the returned timestamp
  • so it's the first call to wait that actually triggers the requests to be sent.

I'm not too sure I like that. Guzzle should crack on with it, as soon as it's asked, surely? Not wait around for me to ask "are we there yet?" Still... I don't think this will adversely impact what we're doing very often. In reality we're making a single call and then waiting for it immediately, almost all the time (this is to the extent I have actually questioned why we are doing this work, and why we're arsing about with Guzzle when we could just be using curl. But... oh well).

So that's the end of my most recent adventure with Guzzle and Promises and async calls and the like. I'm pleased with the resulting code. Not so pleased with how Guzzle works.

I've another two articles that cover the next challenge I faced with this stuff still to come. I've got the code for the second one written... but the topic for the third one only came to mind whilst writing this. So perhaps tomorrow I'll document my adventures of howTF to coerce Guzzle into raising the exceptions I choose for it to raise when requests come back with 400-500 responses, not its generic ones; and after that, how to implement a caching decorator for all this stuff. I've been off work sick for yesterday and today, but will be back in the office tomorrow. So I suspect the second article won't be out until Saturday now. I've had enough of being awake today, and am heading back to bed now. it is 3pm, after all ;-)

Righto.

--
Adam