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
Posted by at
Labels: , ,