diff --git a/app/AbstractRequest.php b/app/AbstractRequest.php index cfeb09c..dc9c22f 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,21 @@ 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 * @@ -438,10 +456,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..26ff37d 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,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( + <<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');