Skip to content

fix: relocate log() so parse/validation failures are captured (#35) #36

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
jwadhams merged 3 commits into from
Aug 15, 2026
Merged

fix: relocate log() so parse/validation failures are captured (#35) #36

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
010c2af
fix: relocate log() so parse/validation failures are captured (#35)
jwadhams Aug 13, 2026
acd726f
docs: correct testPostProcessFailureIsLogged comment
jwadhams Aug 14, 2026
21d51ff
docs: slim down the log() override example
jwadhams Aug 14, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
57 changes: 48 additions & 9 deletions app/AbstractRequest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -282,15 +282,13 @@ public function async(): PromiseInterface
$this->response = $cached;
$promise = new FulfilledPromise($cached);
} else {
$this->responseIsFromCache = false;
$promise = $this->getGuzzleClient()
->sendAsync($this->toGuzzle(), $this->guzzleOptions)
->then(function (Response $response) {
$this->responseIsFromCache = false;
$this->log($response);
return $this->response = $response;
})
->otherwise(function ($exception) {
$this->log($exception);
if ($exception instanceof BadResponseException) {
$this->response = $exception->getResponse();
}
Expand All @@ -301,10 +299,18 @@ public function async(): PromiseInterface
return $promise
->then($this->parseResponseBody(...))
->then($this->postProcess(...))
// Don't cache unless parse and postprocess were *both* successful
->then(function ($postProcessed) {
// Log a success only once parsing and postprocessing have both had a chance to throw,
// so a response that *looks* fine but fails validation isn't logged as a plain success.
$this->log($this->response);
// Don't cache unless parse and postprocess were *both* successful
$this->writeResponseToCache();
return $postProcessed;
})
->otherwise(function ($exception) {
// Covers transfer failures, parse failures, and postprocess failures alike
$this->log($exception);
return new RejectedPromise($exception);
});
})
->otherwise($this->otherwise(...));
Expand Down Expand Up @@ -428,20 +434,53 @@ public function cacheExpiresTime(): ?Carbon
}

/**
* Log this request and outcome to the folder returned by getLogFolder
* Note, this *may* be overridden by children that don't want to use LogFile
* (e.g., AbstractShiftLeadRequest uses LeadLog instead)
* Decide whether $outcome is worth logging, then log() it to the folder returned by getLogFolder.
*
* By default, cache hits are not logged at all -- the original request already has its own log entry,
* and $sentLogs already points back to it (see responseFromCache).
* Children that want different behavior on a cache hit (e.g., a short log that links back to the
* original, since some storage disks don't support symlinks) can override this method, and call
* writeLog() directly to bypass this guard, e.g.:
*
* public function log($outcome): void
* {
* if ($this->responseIsFromCache && $this->shouldLog) {
* $this->writeLog('Cache hit, previous log was ' . $this->getLastLogFile());
* }
* parent::log($outcome); // no-op on a cache hit, parent::log() already guards on that
* }
*
* @param mixed $outcome typically a Response, can also be an Exception
*
* @return void
*/
public function log($outcome): void
{
if (!$this->shouldLog) {
if (!$this->shouldLog || $this->responseIsFromCache) {
return;
}
$logged = $this->getLogFileHelper()::put($this->getLogFolder(), [$this->toGuzzle(), $outcome, $this->requestStats]);
$this->writeLog($outcome);
}

/**
* Unconditionally write $outcome to LogFile -- no $shouldLog or $responseIsFromCache guard.
* log() decides *whether* (and *what*) to log, then calls this to actually do it.
* Override this (instead of log()) if you want everything logged the same way, but to a different
* destination/format (e.g., AbstractShiftLeadRequest uses LeadLog instead of LogFile).
*/
protected function writeLog($outcome): void
{
// Always include the actual response (when we have one), even when $outcome is an Exception
// thrown later, e.g. by parseResponseBody or postProcess. Otherwise, a response that *looks*
// successful (e.g., HTTP 200) but fails schema validation would log as if nothing went wrong.
$contents = [$this->toGuzzle()];
if ($this->response && $this->response !== $outcome) {
$contents[] = $this->response;
}
$contents[] = $outcome;
$contents[] = $this->requestStats;

$logged = $this->getLogFileHelper()::put($this->getLogFolder(), $contents);
if ($logged) {
$this->sentLogs[] = Str::finish($this->getLogFolder(), '/') . $logged;
}
Expand Down
189 changes: 189 additions & 0 deletions tests/Feature/AbstractRequestTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,8 @@
use Carsdotcom\ApiRequest\Traits\EncodeRequestJSON;
use Carsdotcom\ApiRequest\Traits\ParseResponseJSON;
use Carsdotcom\ApiRequest\Traits\ParseResponseJSONOrThrow;
use Carsdotcom\ApiRequest\Traits\ParseResponseJSONSchemaOrThrow;
use Carsdotcom\JsonSchemaValidation\Exceptions\JsonSchemaValidationException;
use GuzzleHttp\Client;
use GuzzleHttp\Exception\ClientException;
use GuzzleHttp\Exception\ConnectException;
Expand Down Expand Up @@ -682,6 +684,193 @@ public function testResponseIsFromCachePreventsWritesToCache(): void
self::assertSame(42, $request->sync());
}

// https://github.com/carsdotcom/php-request-class/issues/35
// A response that looks fine (e.g. HTTP 200) but fails parsing should NOT be logged as a plain success.
public function testParseFailureIsLogged(): void
{
Storage::fake('api-logs');
$request = new class extends ConcreteRequest {
use ParseResponseJSONOrThrow;
protected bool $shouldLog = true;
public function getLogFolder(): string
{
return 'parse-failures';
}
};
$this->mockGuzzleWithTapper()->addMatchBody('POST', '/awesome/', '{"bogus', 200);

try {
$request->sync();
self::fail('Should have thrown UpstreamException');
} catch (UpstreamException) {
$contents = $request->getLastLogContents();
// The actual (apparently fine) response is still visible in the log...
self::assertStringContainsString('Response Status Code 200', $contents);
self::assertStringContainsString('{"bogus', $contents);
// ...alongside the exception that explains why it wasn't actually usable
self::assertStringContainsString('response was unreadable', $contents);
}
}

// https://github.com/carsdotcom/php-request-class/issues/35
// This is the exact scenario from the ticket: a 200 response that reads as valid JSON but doesn't
// match RESPONSE_SCHEMA. The log must show it failed, and must include the schema errors -- not just
// log the response as if it were a plain, unremarkable success.
public function testSchemaValidationFailureIsLoggedWithExtendedExceptionData(): void
{
Storage::fake('api-logs');
// carsdotcom/laravel-json-schema doesn't merge its own config defaults (only publishes them),
// so tests that never ran `vendor:publish` need to set this themselves.
config([
'json-schema.base_url' => 'file://localhost',
'json-schema.local_base_prefix' => sys_get_temp_dir(),
'json-schema.local_base_prefix_tests' => sys_get_temp_dir(),
]);
$request = new class extends ConcreteRequest {
use ParseResponseJSONSchemaOrThrow;
const RESPONSE_SCHEMA = '{"type":"object","required":["zipRegion"],"properties":{"zipRegion":{"type":"string"}}}';
protected bool $shouldLog = true;
public function getLogFolder(): string
{
return 'schema-failures';
}
};
// zipRegion is present but null, not a string -- fails RESPONSE_SCHEMA
$this->mockGuzzleWithTapper()->addMatchBody(
'POST',
'/awesome/',
'{"zipRegion":null,"filters":null,"offers":null}',
200,
);

try {
$request->sync();
self::fail('Should have thrown JsonSchemaValidationException');
} catch (JsonSchemaValidationException) {
// Full-content match (transfer time is the only non-deterministic part, hence %s):
// the apparently-fine response is still visible, but so is the exception, including its
// structured errors (HasExtendedExceptionData::getExtendedData / ->errors()).
self::assertStringMatchesFormat(
<<<LOG
POST https://awesome-api.com/url

Response Status Code 200

{
"zipRegion": null,
"filters": null,
"offers": null
}

Exception thrown: Carsdotcom\JsonSchemaValidation\Exceptions\JsonSchemaValidationException
Unexpected problem with Anonymous Descendent of Concrete Request call: Response does not match expected schema
{
"errors": {
"zipRegion": [
"The data (null) must match the type: string"
]
}
}


Transfer time: %ss

LOG,
$request->getLastLogContents(),
);
}
}

// Before this change, a cache-miss request always logged once, right after the Guzzle transfer
// completed -- before postProcess() ever ran. So a postProcess() failure didn't go unlogged, it
// logged as a false success: the entry was already written before the failure happened.
// Now that single log entry is deferred until postProcess() has had its chance to run, so it
// reflects the real, final outcome -- consistent with it also being excluded from the cache
// (see testDontCachePostprocessFailures).
public function testPostProcessFailureIsLogged(): void
{
Storage::fake('api-logs');
$request = new class extends ConcreteRequest {
use ParseResponseJSONOrThrow;
protected bool $shouldLog = true;
public function getLogFolder(): string
{
return 'postprocess-failures';
}
public function postProcess($parsed)
{
return new RejectedPromise(new \Exception("Cannot process {$parsed}"));
}
};
$this->mockGuzzleWithTapper()->addMatch('POST', '/awesome/', new Response(200, [], '"bogus"'));

try {
$request->sync();
self::fail('Should have thrown Exception');
} catch (\Exception) {
self::assertStringContainsString('Cannot process bogus', $request->getLastLogContents());
}
}

/**
* Cache hits are not logged by default (log() returns early when responseIsFromCache).
* Children can override log() to handle that case explicitly -- e.g. to write a short log
* that points back at the original request's log -- by calling writeLog() directly,
* which bypasses that guard.
*/
public function testLogCanBeOverriddenToHandleCacheHits(): void
{
Storage::fake('api-logs');
$this->mockGuzzleWithTapper()->addMatchBody('POST', '/awesome/', '{"awesome":"sauce"}');

$makeRequest = fn() => new class extends ConcreteRequest {
use ParseResponseJSON;
protected bool $shouldLog = true;
public array $logCalls = [];
public function getLogFolder(): string
{
return 'one/two';
}
public function log($outcome): void
{
$this->logCalls[] = $this->responseIsFromCache ? 'cache-hit' : 'fresh';
if ($this->responseIsFromCache && $this->shouldLog) {
$this->writeLog('Cache hit, previous log was ' . $this->getLastLogFile());
}
parent::log($outcome); // no-op on a cache hit, parent::log() already guards on that
}
};

Carbon::setTestNow('2018-01-01T00:00:00.000000+00:00');
$first = $makeRequest();
$first->sync();
self::assertSame(['fresh'], $first->logCalls);
self::assertCount(1, Storage::disk('api-logs')->allFiles());
$firstLogFile = $first->getLastLogFile();

// Second instance, same cache key: a cache hit. Freeze time to a different instant than the
// first request, so the two log files get distinct, differentiable names.
Carbon::setTestNow('2018-01-01T00:00:01.000000+00:00');
$second = $makeRequest();
$second->sync();
self::assertSame(['cache-hit'], $second->logCalls);

// The override still logged -- it just wrote a *second*, distinct file rather than reusing
// (or skipping) the first, and that file points back at the original.
self::assertCount(2, Storage::disk('api-logs')->allFiles());
$secondLogFile = $second->getLastLogFile();
self::assertNotSame($firstLogFile, $secondLogFile);
self::assertNotSame(
Storage::disk('api-logs')->get($firstLogFile),
Storage::disk('api-logs')->get($secondLogFile),
'Cache-hit log content should differ from the original log it references',
);
self::assertStringContainsString(
"Cache hit, previous log was {$firstLogFile}",
$second->getLastLogContents(),
);
}

public function testRequestLogHasTransferTime(): void
{
Storage::fake('api-logs');
Expand Down