Merge pull request #11 from carsdotcom/log-in-cache

bbene · web-flow · commit 827b0ce828ba · 2024-08-07T09:24:43.000-05:00
feat: On cache hit, the request class has access to the log file when the cache was written
diff --git a/app/AbstractRequest.php b/app/AbstractRequest.php
@@ -323,12 +323,15 @@ protected function writeResponseToCache(): void
         Cache::tags($this->cacheTags)->put(
             $this->cacheKey(),
             [
-                // matches the argument order for Response constructor
-                $this->response->getStatusCode(),
-                $this->response->getHeaders(),
-                (string) $this->response->getBody(),
-                $this->response->getProtocolVersion(),
-                $this->response->getReasonPhrase(),
+                'logs' => $this->sentLogs,
+                'response' => [
+                    // matches the argument order for Response constructor
+                    $this->response->getStatusCode(),
+                    $this->response->getHeaders(),
+                    (string) $this->response->getBody(),
+                    $this->response->getProtocolVersion(),
+                    $this->response->getReasonPhrase(),
+                ]
             ],
             $this->cacheExpiresTime(),
         );
@@ -341,7 +344,38 @@ protected function responseFromCache(): ?Response
         }
 
         $fromCache = Cache::tags($this->cacheTags)->get($this->cacheKey());
-        return $fromCache ? new Response(...$fromCache) : null;
+        if ($fromCache) {
+            $this->sentLogs = $fromCache['logs'];
+            return new Response(...$fromCache['response']);
+        }
+        return null;
+    }
+
+    /**
+     * Return cache key string based on this class, URL, and request body
+     * @return string
+     */
+    public function cacheKey(): string
+    {
+        return hash(
+            'sha256',
+            json_encode([
+                self::class,
+                $this->getURL(),
+                $this->encodeBody(),
+                config('api-request.cache_key_seed', 'v2024.8.6'),
+            ]),
+        );
+    }
+
+    public function canBeFulfilledByCache(): bool
+    {
+        return Cache::tags($this->cacheTags)->has($this->cacheKey());
+    }
+
+    public function isFromCache(): bool
+    {
+        return $this->responseIsFromCache;
     }
 
     /**
@@ -387,11 +421,21 @@ public function log($outcome): void
      * @throws DomainException if this instance has never logged (could mean never run, or $shouldLog is false)
      */
     public function getLastLogContents(): string
+    {
+        return LogFile::disk()->get($this->getLastLogFile());
+    }
+
+    /**
+     * Get the filename for the last run of this instance of this request.
+     * If the last sync or async was a cache hit, this will return the original log of the request that was cached
+     * @throws DomainException if this instance has never logged (could mean never run, or $shouldLog is false)
+     */
+    public function getLastLogFile(): string
     {
         if (!$this->sentLogs) {
             throw new DomainException('No log files have been saved by this instance.');
         }
-        return LogFile::disk()->get($this->getLastLogFile());
+        return Str::finish($this->getLogFolder(), '/') . Arr::last($this->sentLogs);
     }
 
     /**
@@ -438,36 +482,6 @@ public function getResponse(): ?Response
         return $this->response;
     }
 
-    /**
-     * Return cache key string based on this class, URL, and request body
-     * @return string
-     */
-    public function cacheKey(): string
-    {
-        return hash(
-            'sha256',
-            json_encode([
-                self::class,
-                $this->getURL(),
-                $this->encodeBody(),
-                config('api-request.cache_key_seed', 'v2022.4.12.0'),
-            ]),
-        );
-    }
-
-    public function canBeFulfilledByCache(): bool
-    {
-        return Cache::tags($this->cacheTags)->has($this->cacheKey());
-    }
-
-    /**
-     * @return string
-     */
-    public function getLastLogFile(): string
-    {
-        return Str::finish($this->getLogFolder(), '/') . Arr::last($this->sentLogs);
-    }
-
     /**
      * Change the timeout of this request. This is the preferred way to override the default,
      * even in the constructor of a custom class I think this is much more expressive than a numeric constant
@@ -477,4 +491,5 @@ public function setTimeout(CarbonInterval $interval): void
     {
         $this->guzzleOptions[RequestOptions::TIMEOUT] = $interval->totalSeconds;
     }
+
 }
diff --git a/tests/BaseTestCase.php b/tests/BaseTestCase.php
@@ -39,7 +39,7 @@ protected static function mockRequestCachedResponse(
         array $headers = [],
     ) {
         $tags = getProperty($request, 'cacheTags');
-        Cache::tags($tags)->put($request->cacheKey(), [$status, $headers, $body]);
+        Cache::tags($tags)->put($request->cacheKey(), ['logs' => [], 'response' => [$status, $headers, $body]]);
     }
 
     /**
@@ -54,4 +54,4 @@ protected static function requestCacheBodyContains(
         self::assertNotNull($cached, 'Cache should not be empty for request.');
         self::assertStringContainsString($substring, (string) $cached->getBody(), $message);
     }
-}
+}
diff --git a/tests/Feature/AbstractRequestTest.php b/tests/Feature/AbstractRequestTest.php
@@ -31,37 +31,36 @@ class AbstractRequestTest extends BaseTestCase
 {
     use MocksGuzzleInstance;
 
+    protected function setUp(): void
+    {
+        parent::setUp();
+        Storage::fake('api-logs');
+    }
+
     protected function mockRequestWithLog()
     {
         return new class extends ConcreteRequest {
             use ParseResponseJSON;
 
             protected bool $shouldLog = true;
 
-            public $logged;
-            public function log($outcome): void
-            {
-                $this->logged = $outcome;
-            }
-
-            public function isFromCache(): bool
+            public function getLogFolder(): string
             {
-                return $this->responseIsFromCache;
+                return 'one/two';
             }
         };
     }
 
     public function testCacheMissUsesGuzzle(): void
     {
         $this->mockGuzzleWithTapper();
-        $expectedResponse = new Response(200, [], '{"awesome":"sauce"}');
-        $this->tapper->addMatch('POST', '/.*?/', $expectedResponse);
+        $this->tapper->addMatchBody('POST', '/.*?/', '{"awesome":"sauce"}');
 
         $requestClass = $this->mockRequestWithLog();
 
         $result = $requestClass->sync();
 
-        self::assertSame($expectedResponse, $requestClass->logged);
+        self::assertStringContainsString('"sauce"', $requestClass->getLastLogContents());
         $this->expectTotalRequestCount(1);
         $this->assertTapperRequestLike('POST', '/.*?/', 1);
 
@@ -103,6 +102,38 @@ public function testCacheHitAfterFirstRequest(): void
         self::assertTrue($secondRequest->canBeFulfilledByCache());
     }
 
+    public function testCacheHitHasAccessToOriginalLog(): void
+    {
+        Storage::fake('api-logs');
+        $tapper = $this->mockGuzzleWithTapper();
+        $tapper->addMatchBody('POST', '/awesome/', '{"awesome":"sauce"}');
+
+        $firstLogTime = '2018-01-01T00:00:00.000000+00:00';
+        Carbon::setTestNow($firstLogTime);
+        $firstRequest = $this->mockRequestWithLog();
+        $firstRequest->sync();
+        self::assertTrue($firstRequest->canBeFulfilledByCache());
+        self::assertSame($firstRequest->getLastLogFile(), "one/two/{$firstLogTime}");
+        self::assertSame(1, $tapper->getCountLike('POST', '/awesome/'));
+
+        // Regenerate the request
+        $secondLogTime = '2018-01-01T00:02:02.000000+00:00';
+        Carbon::setTestNow($secondLogTime);
+        $secondRequest = $this->mockRequestWithLog();
+        self::assertTrue($secondRequest->canBeFulfilledByCache());
+        // Both requests have same key
+        self::assertSame($firstRequest->cacheKey(), $secondRequest->cacheKey());
+
+        $secondRequest->sync();
+        self::assertSame(1, $tapper->getCountLike('POST', '/awesome/'));
+        // Result was in cache
+        self::assertTrue($secondRequest->isFromCache());
+        // Second request can retrieve log from original time
+        self::assertSame($secondRequest->getLastLogFile(), "one/two/{$firstLogTime}");
+        // Second request did not log to disk, only the first request
+        self::assertSame(["one/two/{$firstLogTime}"], Storage::disk('api-logs')->files('one/two'));
+    }
+
     public function testDontCacheErrorStatus(): void
     {
         $firstRequest = $this->mockRequestWithPostProcessor();
@@ -320,6 +351,7 @@ public function testMissingGetLogFolderImplementation(): void
         $tapper->addMatchBody('POST', '/awesome/', 'true');
 
         $this->expectException(ToDoException::class);
+        $this->expectExceptionMessageMatches('/To enable request logging, .+ will have to implement the method getLogFolder/');
         $request->sync();
     }
 
@@ -366,6 +398,12 @@ public function getLogFolder(): string
         } catch (\DomainException $exception) {
             self::assertSame('No log files have been saved by this instance.', $exception->getMessage());
         }
+        try {
+            $request->getLastLogFile();
+            self::fail('Should have thrown');
+        } catch (\DomainException $exception) {
+            self::assertSame('No log files have been saved by this instance.', $exception->getMessage());
+        }
 
         $tapper = $this->mockGuzzleWithTapper();
         $tapper->addMatchBody('POST', '/awesome/', 'true');
@@ -374,6 +412,7 @@ public function getLogFolder(): string
         Carbon::setTestNow($firstLogTime);
         $request->sync();
         Storage::disk('api-logs')->assertExists("one/two/{$firstLogTime}");
+        self::assertSame($request->getLastLogFile(), "one/two/{$firstLogTime}");
         self::assertSame($request->getLastLogContents(), Storage::disk('api-logs')->get("one/two/{$firstLogTime}"));
 
         // Make a second log, see that it's now returned
@@ -383,6 +422,7 @@ public function getLogFolder(): string
         Carbon::setTestNow($secondLogTime);
         $request->sync();
         Storage::disk('api-logs')->assertExists("one/two/{$secondLogTime}");
+        self::assertSame($request->getLastLogFile(), "one/two/{$secondLogTime}");
         self::assertSame($request->getLastLogContents(), Storage::disk('api-logs')->get("one/two/{$secondLogTime}"));
     }
 
@@ -553,7 +593,7 @@ public function testResponseIsFromCachePreventsWritesToCache(): void
         Cache::shouldReceive('get')
             ->once()
             ->with($request->cacheKey())
-            ->andReturn([200, [], '42']);
+            ->andReturn(['logs' => [], 'response' => [200, [], '42']]);
         // It is NOT written back to cache
         Cache::shouldReceive('put')->never();
 

Original file line number	Diff line number	Diff line change
`@@ -39,7 +39,7 @@ protected static function mockRequestCachedResponse(`
`39`	`39`	`array $headers = [],`
`40`	`40`	`) {`
`41`	`41`	`$tags = getProperty($request, 'cacheTags');`
`42`		`- Cache::tags($tags)->put($request->cacheKey(), [$status, $headers, $body]);`
	`42`	`+ Cache::tags($tags)->put($request->cacheKey(), ['logs' => [], 'response' => [$status, $headers, $body]]);`
`43`	`43`	`}`
`44`	`44`
`45`	`45`	`/**`
`@@ -54,4 +54,4 @@ protected static function requestCacheBodyContains(`
`54`	`54`	`self::assertNotNull($cached, 'Cache should not be empty for request.');`
`55`	`55`	`self::assertStringContainsString($substring, (string) $cached->getBody(), $message);`
`56`	`56`	`}`
`57`		`-}`
	`57`	`+}`