Merge pull request #332 from fredden/issue-245

[Feature] Improve API deprecation logging
Shopify · Apr 16, 2024 · 43d7cbf · 43d7cbf
2 parents 0365e3f + 4518c05
commit 43d7cbf
Show file tree

Hide file tree

Showing 7 changed files with 102 additions and 35 deletions.
diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml
@@ -4,7 +4,7 @@ jobs:
   CI:
     runs-on: ubuntu-latest
     env:
-      PHP_INI_VALUES: assert.exception=1, zend.assertions=1
+      PHP_INI_VALUES: assert.exception=1, zend.assertions=1, apc.enable_cli=1
     strategy:
       fail-fast: false
       matrix:
@@ -21,6 +21,7 @@ jobs:
           tools: composer:v2, phpcs
           coverage: xdebug
           ini-values: ${{ env.PHP_INI_VALUES }}
+          extensions: apcu
 
       - name: Install dependencies with composer
         run: composer update --no-ansi --no-interaction --no-progress

diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -7,6 +7,8 @@ and adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html).
 
 ## Unreleased
 
+- [#332](https://github.com/Shopify/shopify-api-php/pull/332) [Patch] Avoid writing to system temporary directory when an API deprecation is encountered
+
 ## v5.4.0 - 2024-04-08
 
 - [#333](https://github.com/Shopify/shopify-api-php/pull/333) [Minor] Adding support for 2024-04 API version

diff --git a/composer-require-checker.json b/composer-require-checker.json
@@ -0,0 +1,7 @@
+{
+  "symbol-whitelist" : [
+    "apcu_enabled",
+    "apcu_fetch",
+    "apcu_store"
+  ]
+}
diff --git a/composer.json b/composer.json
@@ -36,12 +36,16 @@
         "ramsey/uuid": "^4.1"
     },
     "require-dev": {
+        "ext-apcu": "*",
         "ergebnis/composer-normalize": "^2.30",
         "maglnet/composer-require-checker": "^3.0 || ^4.0",
         "mikey179/vfsstream": "^1.6",
         "phpunit/phpunit": "^9",
         "squizlabs/php_codesniffer": "^3.6"
     },
+    "suggest": {
+        "ext-apcu": "Log fewer API deprecation warnings"
+    },
     "autoload": {
         "psr-4": {
             "Shopify\\": "src/"

diff --git a/composer.lock b/composer.lock
diff --git a/src/Clients/Http.php b/src/Clients/Http.php
@@ -21,11 +21,13 @@ class Http
     public const DATA_TYPE_GRAPHQL = 'application/graphql';
 
     private const RETRIABLE_STATUS_CODES = [429, 500];
-    private const DEPRECATION_ALERT_SECONDS = 60;
+    private const DEPRECATION_ALERT_SECONDS = 3600;
 
     /** @var string */
     private $domain;
 
+    private int $lastApiDeprecationWarning = 0;
+
     public function __construct(string $domain)
     {
         $this->domain = $domain;
@@ -274,27 +276,35 @@ private function logApiDeprecation(string $url, string $reason): void
      */
     private function shouldLogApiDeprecation(): bool
     {
-        $warningFilePath = $this->getApiDeprecationTimestampFilePath();
+        if (function_exists('apcu_enabled') && apcu_enabled()) {
+            $apcuKey = 'shopify/shopify-api/last-api-deprecation-warning';
+        } else {
+            $apcuKey = null;
+        }
 
-        $lastWarning = null;
-        if (file_exists($warningFilePath)) {
-            $lastWarning = (int)(file_get_contents($warningFilePath));
+        if ($this->lastApiDeprecationWarning === 0 && $apcuKey) {
+            $this->lastApiDeprecationWarning = (int) apcu_fetch($apcuKey);
         }
 
-        if (time() - $lastWarning < self::DEPRECATION_ALERT_SECONDS) {
-            $result = false;
-        } else {
-            $result = true;
-            file_put_contents($warningFilePath, time());
+        $secondsSinceLastAlert = time() - $this->lastApiDeprecationWarning;
+        if ($secondsSinceLastAlert < self::DEPRECATION_ALERT_SECONDS) {
+            return false;
+        }
+
+        $this->lastApiDeprecationWarning = time();
+
+        if ($apcuKey) {
+            apcu_store($apcuKey, $this->lastApiDeprecationWarning, self::DEPRECATION_ALERT_SECONDS);
         }
 
-        return $result;
+        return true;
     }
 
     /**
      * Fetches the path to the file holding the timestamp of the last API deprecation warning we logged.
      *
      * @codeCoverageIgnore This is mocked in tests so we don't use real files
+     * @deprecated 5.4.1 This method is no longer used internally.
      */
     public function getApiDeprecationTimestampFilePath(): string
     {

diff --git a/tests/Clients/HttpTest.php b/tests/Clients/HttpTest.php
@@ -7,6 +7,7 @@
 use org\bovigo\vfs\vfsStream;
 use PHPUnit\Framework\MockObject\MockObject;
 use Psr\Log\LogLevel;
+use ReflectionProperty;
 use Shopify\Clients\Http;
 use Shopify\Context;
 use ShopifyTest\BaseTestCase;
@@ -442,20 +443,19 @@ public function testRetryStopsOnNonRetriableError()
 
     public function testDeprecatedRequestsAreLoggedWithinLimit()
     {
-        $vfsRoot = vfsStream::setup('test');
-
         /** @var MockObject|Http */
         $mockedClient = $this->getMockBuilder(Http::class)
             ->setConstructorArgs([$this->domain])
-            ->onlyMethods(['getApiDeprecationTimestampFilePath'])
+            ->onlyMethods([])
             ->getMock();
-        $mockedClient->expects($this->exactly(2))
-            ->method('getApiDeprecationTimestampFilePath')
-            ->willReturn(vfsStream::url('test/timestamp_file'));
 
         $testLogger = new LogMock();
         Context::$LOGGER = $testLogger;
 
+        if (function_exists('apcu_enabled') && apcu_enabled()) {
+            apcu_delete('shopify/shopify-api/last-api-deprecation-warning');
+        }
+
         $this->mockTransportRequests([
             new MockRequest(
                 $this->buildMockHttpResponse(200, null, ['X-Shopify-API-Deprecated-Reason' => 'Test reason']),
@@ -469,35 +469,61 @@ public function testDeprecatedRequestsAreLoggedWithinLimit()
             )
         ]);
 
-        $this->assertFalse($vfsRoot->hasChild('timestamp_file'));
+        $reflector = new ReflectionProperty(Http::class, 'lastApiDeprecationWarning');
+
+        $this->assertEquals(
+            0,
+            $reflector->getValue($mockedClient),
+            'Last API deprecation warning time starts out unset'
+        );
+
         $mockedClient->get('test/path');
 
-        $this->assertTrue($vfsRoot->hasChild('timestamp_file'));
-        $this->assertTrue($testLogger->hasWarningThatContains('API Deprecation notice'));
-        $this->assertCount(1, $testLogger->recordsByLevel[LogLevel::WARNING]);
+        $this->assertTrue(
+            $testLogger->hasWarningThatContains('API Deprecation notice'),
+            'Logger has API deprecation message'
+        );
+        $this->assertCount(
+            1,
+            $testLogger->recordsByLevel[LogLevel::WARNING],
+            'Logger has exactly one warning'
+        );
+        $this->assertGreaterThan(
+            0,
+            $reflector->getValue($mockedClient),
+            'Last API deprecation warning time is set'
+        );
 
+        $lastApiDeprecationWarning = $reflector->getValue($mockedClient);
         $mockedClient->get('test/path');
 
-        $this->assertTrue($vfsRoot->hasChild('timestamp_file'));
-        $this->assertCount(1, $testLogger->recordsByLevel[LogLevel::WARNING]);
+        $this->assertEquals(
+            $lastApiDeprecationWarning,
+            $reflector->getValue($mockedClient),
+            'Last API deprecation warning time is unchanged'
+        );
+        $this->assertCount(
+            1,
+            $testLogger->recordsByLevel[LogLevel::WARNING],
+            'Logger still has exactly one warning'
+        );
     }
 
     public function testDeprecationLogBackoffPeriod()
     {
-        vfsStream::setup('test');
-
         /** @var MockObject|Http */
         $mockedClient = $this->getMockBuilder(Http::class)
             ->setConstructorArgs([$this->domain])
-            ->onlyMethods(['getApiDeprecationTimestampFilePath'])
+            ->onlyMethods([])
             ->getMock();
-        $mockedClient->expects($this->exactly(3))
-            ->method('getApiDeprecationTimestampFilePath')
-            ->willReturn(vfsStream::url('test/timestamp_file'));
 
         $testLogger = new LogMock();
         Context::$LOGGER = $testLogger;
 
+        if (function_exists('apcu_enabled') && apcu_enabled()) {
+            apcu_delete('shopify/shopify-api/last-api-deprecation-warning');
+        }
+
         $this->mockTransportRequests([
             new MockRequest(
                 $this->buildMockHttpResponse(200, null, ['X-Shopify-API-Deprecated-Reason' => 'Test reason']),
@@ -514,6 +540,11 @@ public function testDeprecationLogBackoffPeriod()
                 "https://$this->domain/test/path",
                 "GET",
             ),
+            new MockRequest(
+                $this->buildMockHttpResponse(200, null, ['X-Shopify-API-Deprecated-Reason' => 'Test reason']),
+                "https://$this->domain/test/path",
+                "GET",
+            ),
         ]);
 
         $this->assertCount(0, $testLogger->records);
@@ -524,9 +555,19 @@ public function testDeprecationLogBackoffPeriod()
         $mockedClient->get('test/path');
         $this->assertCount(1, $testLogger->records);
 
-        // We only log once every minute, so simulate more time than having elapsed
-        file_put_contents(vfsStream::url('test/timestamp_file'), time() - 70);
+        // We only log once every hour, so simulate more time than having elapsed
+        $reflector = new ReflectionProperty(Http::class, 'lastApiDeprecationWarning');
+        $reflector->setValue($mockedClient, time() - 7200);
+
+        $mockedClient->get('test/path');
+        $this->assertCount(2, $testLogger->records);
+
+        if (!function_exists('apcu_enabled') || !apcu_enabled()) {
+            $this->markTestSkipped('APCu is not enabled and is required for the correct testing of this feature.');
+        }
 
+        // Set the internal value back to its initial state. The class should read the stored value from APCu.
+        $reflector->setValue($mockedClient, 0);
         $mockedClient->get('test/path');
         $this->assertCount(2, $testLogger->records);
     }