From 010c2af79581f245778f0a2c59c637b1cbcfa46b Mon Sep 17 00:00:00 2001 From: Jeremy Wadhams Date: Thu, 13 Aug 2026 18:37:43 -0500 Subject: [PATCH 1/3] fix: relocate log() so parse/validation failures are captured (#35) Previously, log() was only called right after the Guzzle send resolved or rejected. A response that looked fine over the wire (e.g. HTTP 200) but later failed json_decode or JSON Schema validation was logged as an apparent success, with the real failure invisible. log() is now called once, at the same point as writeResponseToCache(): after parseResponseBody() and postProcess() have both had a chance to run/throw. Both branches funnel through log(), so a single log() call now sees the real outcome, whether that's the postprocessed response or whatever exception was thrown along the way -- and it still includes the raw Response object it has on hand, so schema failures show both the response *and* the exception (with ->getExtendedData() errors). This also relocates the "don't log cache hits" decision from the call site into log() itself (log() now returns early when $this->responseIsFromCache is true). That was previously handled implicitly by simply never calling log() on a cache hit. log() is split into a guard (log()) and the actual write (writeLog()). Children that want different behavior on a cache hit -- e.g. writing a short log that points back at the original request instead of writing nothing at all -- can override log() and call writeLog() directly to bypass the default guard, without having to also override responseFromCache() just to get a chance to log. Tests added: - testParseFailureIsLogged / testSchemaValidationFailureIsLoggedWithExtendedExceptionData: reproduce the exact scenario from the ticket (a 200 response that reads as valid JSON but fails ParseResponseJSONSchemaOrThrow's schema check). testSchemaValidationFailureIsLoggedWithExtendedExceptionData does a full-content match (assertStringMatchesFormat) of the log, pinning down that the response body, the exception, and its HasExtendedExceptionData::getExtendedData() (->errors()) are all present in the exact expected shape. - testPostProcessFailureIsLogged: postProcess() rejections are now logged too. - testLogCanBeOverriddenToHandleCacheHits: demonstrates overriding log() to write a distinct, differentiable log on a cache hit that references the original. --- app/AbstractRequest.php | 61 +++++++-- tests/Feature/AbstractRequestTest.php | 187 ++++++++++++++++++++++++++ 2 files changed, 239 insertions(+), 9 deletions(-) diff --git a/app/AbstractRequest.php b/app/AbstractRequest.php index cfeb09c..821ec62 100644 --- a/app/AbstractRequest.php +++ b/app/AbstractRequest.php @@ -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(); } @@ -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(...)); @@ -428,9 +434,25 @@ 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) { + * parent::log($outcome); + * return; + * } + * if (!$this->shouldLog) { + * return; + * } + * $this->writeLog('Cache hit, previous log was ' . $this->getLastLogFile()); + * } * * @param mixed $outcome typically a Response, can also be an Exception * @@ -438,10 +460,31 @@ public function cacheExpiresTime(): ?Carbon */ 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; } diff --git a/tests/Feature/AbstractRequestTest.php b/tests/Feature/AbstractRequestTest.php index b2e63e3..7c48a10 100644 --- a/tests/Feature/AbstractRequestTest.php +++ b/tests/Feature/AbstractRequestTest.php @@ -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; @@ -682,6 +684,191 @@ 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( + <<getLastLogContents(), + ); + } + } + + // A postProcess() failure is a real outcome for this request and should be logged too, + // 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 + { + if (!$this->responseIsFromCache) { + parent::log($outcome); + $this->logCalls[] = 'fresh'; + return; + } + $this->logCalls[] = 'cache-hit'; + $this->writeLog('Cache hit, previous log was ' . $this->getLastLogFile()); + } + }; + + 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'); From acd726f4d638a95efc71883c8b3fa5f4eeca74a3 Mon Sep 17 00:00:00 2001 From: Jeremy Wadhams Date: Fri, 14 Aug 2026 15:00:49 -0500 Subject: [PATCH 2/3] docs: correct testPostProcessFailureIsLogged comment The old comment implied postProcess() failures weren't logged at all before this change. That's not quite right: for a cache miss, log() already ran immediately after the Guzzle transfer, before postProcess() ever got a chance to run -- so a postProcess() failure was already producing a log entry, it just froze on "transfer succeeded" before the real outcome was known. Clarify that this change defers that same entry rather than adding a new one. Co-Authored-By: Claude Sonnet 5 --- tests/Feature/AbstractRequestTest.php | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/tests/Feature/AbstractRequestTest.php b/tests/Feature/AbstractRequestTest.php index 7c48a10..671ec91 100644 --- a/tests/Feature/AbstractRequestTest.php +++ b/tests/Feature/AbstractRequestTest.php @@ -781,8 +781,12 @@ public function getLogFolder(): string } } - // A postProcess() failure is a real outcome for this request and should be logged too, - // consistent with it also being excluded from the cache (see testDontCachePostprocessFailures) + // 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'); From 21d51ffcc4234ed30050b7fd67503f98a3399e5c Mon Sep 17 00:00:00 2001 From: Jeremy Wadhams Date: Fri, 14 Aug 2026 15:19:03 -0500 Subject: [PATCH 3/3] docs: slim down the log() override example Reuse parent::log()'s existing responseIsFromCache guard instead of re-implementing the "not from cache" branch by hand -- calling parent::log() unconditionally at the end is already a no-op on a cache hit, so the example (and the matching test) collapses from two branches to one conditional plus a pass-through call. Co-Authored-By: Claude Sonnet 5 --- app/AbstractRequest.php | 10 +++------- tests/Feature/AbstractRequestTest.php | 10 ++++------ 2 files changed, 7 insertions(+), 13 deletions(-) diff --git a/app/AbstractRequest.php b/app/AbstractRequest.php index 821ec62..dc9c22f 100644 --- a/app/AbstractRequest.php +++ b/app/AbstractRequest.php @@ -444,14 +444,10 @@ public function cacheExpiresTime(): ?Carbon * * public function log($outcome): void * { - * if (!$this->responseIsFromCache) { - * parent::log($outcome); - * return; + * if ($this->responseIsFromCache && $this->shouldLog) { + * $this->writeLog('Cache hit, previous log was ' . $this->getLastLogFile()); * } - * if (!$this->shouldLog) { - * return; - * } - * $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 diff --git a/tests/Feature/AbstractRequestTest.php b/tests/Feature/AbstractRequestTest.php index 671ec91..26ff37d 100644 --- a/tests/Feature/AbstractRequestTest.php +++ b/tests/Feature/AbstractRequestTest.php @@ -833,13 +833,11 @@ public function getLogFolder(): string } public function log($outcome): void { - if (!$this->responseIsFromCache) { - parent::log($outcome); - $this->logCalls[] = 'fresh'; - return; + $this->logCalls[] = $this->responseIsFromCache ? 'cache-hit' : 'fresh'; + if ($this->responseIsFromCache && $this->shouldLog) { + $this->writeLog('Cache hit, previous log was ' . $this->getLastLogFile()); } - $this->logCalls[] = 'cache-hit'; - $this->writeLog('Cache hit, previous log was ' . $this->getLastLogFile()); + parent::log($outcome); // no-op on a cache hit, parent::log() already guards on that } };