feat: improve observability for the app registration flow by adding structured logs

composer.json

@@ -28,6 +28,7 @@
     "psr/http-factory": "^1.0",
     "psr/http-factory-implementation": "*",
     "psr/http-message": "^1.0 || ^2.0",
+    "psr/log": "^1.0 || ^2.0 || ^3.0",
     "psr/simple-cache": "^3.0",
     "strobotti/php-jwk": "^1.4"
   },

src/Authentication/DualSignatureRequestVerifier.php

@@ -8,6 +8,8 @@
 use Lcobucci\JWT\Validation\RequiredConstraintsViolated;
 use Psr\Clock\ClockInterface;
 use Psr\Http\Message\RequestInterface;
+use Psr\Log\LoggerInterface;
+use Psr\Log\NullLogger;
 use Shopware\App\SDK\AppConfiguration;
 use Shopware\App\SDK\Exception\SignatureInvalidException;
 use Shopware\App\SDK\Exception\SignatureNotFoundException;
@@ -21,8 +23,11 @@
 
     private readonly ClockInterface $clock;
 
-    public function __construct(private readonly RequestVerifier $primaryVerifier = new RequestVerifier(), ?ClockInterface $clock = null)
-    {
+    public function __construct(
+        private readonly RequestVerifier $primaryVerifier = new RequestVerifier(),
+        ?ClockInterface $clock = null,
+        private readonly LoggerInterface $logger = new NullLogger()
+    ) {
         $this->clock = $clock ?? new SystemClock(new \DateTimeZone('UTC'));
     }
 
@@ -35,7 +40,7 @@
         try {
             $this->primaryVerifier->authenticatePostRequest($request, $shop->getShopSecret());
         } catch (SignatureInvalidException $exception) {
-            $this->authenticateWithPreviousSecret($request, $shop, $exception, function (RequestInterface $request, string $secret) {
+            $this->authenticateWithPreviousSecret($request, $shop, $exception, function (RequestInterface $request, string $secret): void {
                 $this->primaryVerifier->authenticatePostRequest($request, $secret);
             });
         }
@@ -50,7 +55,7 @@
         try {
             $this->primaryVerifier->authenticateGetRequest($request, $shop->getShopSecret());
         } catch (SignatureInvalidException $exception) {
-            $this->authenticateWithPreviousSecret($request, $shop, $exception, function (RequestInterface $request, string $secret) {
+            $this->authenticateWithPreviousSecret($request, $shop, $exception, function (RequestInterface $request, string $secret): void {
                 $this->primaryVerifier->authenticateGetRequest($request, $secret);
             });
         }
@@ -59,23 +64,27 @@
     /**
      * @throws SignatureInvalidException
      * @throws SignatureNotFoundException
+     * @throws RequiredConstraintsViolated thrown by JWT validation on the signed storefront URL
      */
     public function authenticateStorefrontRequest(RequestInterface $request, string $shopId, ShopInterface $shop): void
     {
         try {
             $this->primaryVerifier->authenticateStorefrontRequest($request, $shopId, $shop->getShopSecret());
         } catch (RequiredConstraintsViolated $exception) {
-            $this->authenticateWithPreviousSecret($request, $shop, $exception, function (RequestInterface $request, string $secret) use ($shopId) {
+            $this->authenticateWithPreviousSecret($request, $shop, $exception, function (RequestInterface $request, string $secret) use ($shopId): void {
                 $this->primaryVerifier->authenticateStorefrontRequest($request, $shopId, $secret);
             });
         }
     }
 
     /**
-     * Helper method to authenticate with the previous secret during rotation window
+     * Authenticate with the previous secret during the rotation window. Past the allowance the request is
+     * rejected; but if the rotated-out secret still matches, we log how late it arrived so the allowance —
+     * a heuristic — can be tuned against real traffic.
      *
      * @param callable(RequestInterface, string): void $authenticator
      * @throws SignatureInvalidException
+     * @throws RequiredConstraintsViolated when the rethrown $exception originates from JWT validation
      */
     private function authenticateWithPreviousSecret(
         RequestInterface $request,
@@ -86,22 +95,49 @@
         $rotatedAt = $shop->getSecretsRotatedAt();
         $previousSecret = $shop->getPreviousShopSecret();
 
-        // No previous secret or rotation timestamp available
         if ($previousSecret === null || $rotatedAt === null) {
             throw $exception;
         }
 
-        // Check if we're still within the inflight allowance window
-        $allowanceEnd = $rotatedAt->modify(sprintf("+%d seconds", self::INFLIGHT_ALLOWANCE));
+        $allowanceEnd = $rotatedAt->modify(sprintf('+%d seconds', self::INFLIGHT_ALLOWANCE));
+        $now = $this->clock->now();
+
+        if ($now >= $allowanceEnd) {
+            // The HMAC is cheap, so we still check: a match is a valid request that arrived late. Log how far
+            // past the window it is (to tune the allowance), then reject. A non-match throws and stays silent.
+            $authenticator($request, $previousSecret);
+
+            $this->logger->info('Request signed with the rotated-out secret arrived after the in-flight allowance', [
+                'shop-id' => $shop->getShopId(),
+                'secrets-rotated-at' => $rotatedAt->format(\DateTimeInterface::ATOM),
+                'inflight-allowance-seconds' => self::INFLIGHT_ALLOWANCE,
+                'seconds-after-rotation' => $now->getTimestamp() - $rotatedAt->getTimestamp(),
+                'shopware-version' => self::incomingShopwareVersion($request),
+            ]);
 
-        if ($this->clock->now() >= $allowanceEnd) {
             throw $exception;
         }
 
-        // Try authenticating with the previous secret
         $authenticator($request, $previousSecret);
     }
 
+    /**
+     * The Shopware version that sent the request — the `sw-version` header on webhook (POST) requests,
+     * or the `sw-version` query parameter on signed GET requests. Null when absent.
+     */
+    private static function incomingShopwareVersion(RequestInterface $request): ?string
+    {
+        $header = $request->getHeaderLine('sw-version');
+        if ($header !== '') {
+            return $header;
+        }
+
+        \parse_str($request->getUri()->getQuery(), $query);
+        $version = $query['sw-version'] ?? null;
+
+        return \is_string($version) && $version !== '' ? $version : null;
+    }
+
     /**
      * Authenticate registration confirmation request
      *
@@ -116,18 +152,19 @@
         $pendingSecret = $shop->getPendingShopSecret();
         // Missing registration step, during registration confirmation the pending secret must be set.
         if ($pendingSecret === null) {
-            throw new SignatureInvalidException($request);
+            throw new SignatureInvalidException($request, verificationStage: 'missing-pending-secret');
         }
 
         // New registration: that is not yet confirmed from shop, verify with secret shared during registration handshake is sufficient.
-        $this->primaryVerifier->authenticatePostRequest($request, $pendingSecret);
+        $this->verifyLeg('pending-secret', fn () => $this->primaryVerifier->authenticatePostRequest($request, $pendingSecret));
+
         if (! $shop->isRegistrationConfirmed()) {
             return;
         }
 
         // OLD SHOP RE-REGISTRATION: If double signature is enforced, also verify with OLD current secret (the secret that the shop is actively using).
         if ($this->shouldEnforceDoubleSignatureForRegisterConfirm($appConfiguration, $shop, $request)) {
-            $this->primaryVerifier->authenticatePostRequest($request, $shop->getShopSecret(), self::SHOPWARE_SHOP_SIGNATURE_PREVIOUS_HEADER);
+            $this->verifyLeg('previous-signature', fn () => $this->primaryVerifier->authenticatePostRequest($request, $shop->getShopSecret(), self::SHOPWARE_SHOP_SIGNATURE_PREVIOUS_HEADER));
         }
     }
 
@@ -146,11 +183,28 @@
         ?ShopInterface $shop = null
     ): void {
         // Always verify app signature first
-        $this->primaryVerifier->authenticateRegistrationRequest($request, $appConfiguration->getAppSecret());
+        $this->verifyLeg('app-signature', fn () => $this->primaryVerifier->authenticateRegistrationRequest($request, $appConfiguration->getAppSecret()));
 
         // If there's a confirmed registration and double signature is enforced, also verify with shop's current secret
         if ($shop?->isRegistrationConfirmed() === true && $this->shouldEnforceDoubleSignatureForRegister($appConfiguration, $shop, $request)) {
-            $this->primaryVerifier->authenticateRegistrationRequestWithShopSignature($request, $shop->getShopSecret());
+            $this->verifyLeg('shop-signature', fn () => $this->primaryVerifier->authenticateRegistrationRequestWithShopSignature($request, $shop->getShopSecret()));
+        }
+    }
+
+    /**
+     * Run one verification leg; on failure, re-tag the exception with the leg that produced it (a non-secret
+     * label for the registration log), keeping the original as `previous`.
+     *
+     * @param callable(): void $leg
+     */
+    private function verifyLeg(string $stage, callable $leg): void
+    {
+        try {
+            $leg();
+        } catch (SignatureInvalidException|SignatureNotFoundException $e) {
+            throw $e instanceof SignatureNotFoundException
+                ? new SignatureNotFoundException($e->getRequest(), $e, $stage)
+                : new SignatureInvalidException($e->getRequest(), $e, $stage);
         }
     }
 

src/Exception/SignatureInvalidException.php

@@ -10,9 +10,18 @@ class SignatureInvalidException extends \Exception
 {
     public function __construct(
         private readonly RequestInterface $request,
-        ?\Throwable $previous = null
+        ?\Throwable $previous = null,
+        /**
+         * Which verification leg failed (e.g. app-signature, shop-signature), or null when not tagged.
+         */
+        public readonly ?string $verificationStage = null
     ) {
-        parent::__construct('Signature could not be verified', 0, $previous);
+        $message = 'Signature could not be verified';
+        if ($verificationStage !== null) {
+            $message = \sprintf('%s (verification stage: %s)', $message, $verificationStage);
+        }
+
+        parent::__construct($message, 0, $previous);
     }
 
     public function getRequest(): RequestInterface

src/Exception/SignatureNotFoundException.php

@@ -8,9 +8,20 @@
 
 class SignatureNotFoundException extends \RuntimeException
 {
-    public function __construct(private readonly RequestInterface $request, ?\Throwable $previous = null)
-    {
-        parent::__construct('Signature is not present in request', 0, $previous);
+    public function __construct(
+        private readonly RequestInterface $request,
+        ?\Throwable $previous = null,
+        /**
+         * Which verification leg failed (e.g. app-signature, shop-signature), or null when not tagged.
+         */
+        public readonly ?string $verificationStage = null
+    ) {
+        $message = 'Signature is not present in request';
+        if ($verificationStage !== null) {
+            $message = \sprintf('%s (verification stage: %s)', $message, $verificationStage);
+        }
+
+        parent::__construct($message, 0, $previous);
     }
 
     public function getRequest(): RequestInterface

src/Registration/RegistrationService.php

@@ -49,18 +49,33 @@
     {
         \parse_str($request->getUri()->getQuery(), $queries);
 
         if (!isset($queries['shop-id'], $queries['shop-url']) || !is_string($queries['shop-id']) || !is_string($queries['shop-url']) || empty($queries['shop-id']) || empty($queries['shop-url'])) {
             throw new MissingShopParameterException();
         }
 
         $shop = $this->shopRepository->getShopFromId($queries['shop-id']);
 
-        $this->dualSignatureVerifier->authenticateRegistrationRequest(
-            $request,
-            $this->appConfiguration,
-            $shop
+        $this->logger->info(
+            'Shop registration started',
+            $this->registrationLogContext($request, $queries['shop-id'], $queries['shop-url'], $shop)
         );
 
+        try {
+            $this->dualSignatureVerifier->authenticateRegistrationRequest(
+                $request,
+                $this->appConfiguration,
+                $shop
+            );
+        } catch (SignatureInvalidException|SignatureNotFoundException $e) {
+            $this->logger->warning(
+                'Shop registration signature verification failed',
+                $this->registrationLogContext($request, $queries['shop-id'], $queries['shop-url'], $shop)
+                    + ['exception' => $e::class, 'verification-stage' => $e->verificationStage]
+            );
+
+            throw $e;
+        }
+
         $secret = $this->shopSecretGeneratorInterface->generate();
 
         $proofParameters = [
@@ -93,6 +108,14 @@
         $this->logger->info('Shop registration request received', [
             'shop-id' => $shop->getShopId(),
             'shop-url' => $shop->getShopUrl(),
+            // Raw URL as signed into the proof; differs from the sanitized shop-url when the path is normalized.
+            'signed-shop-url' => $proofParameters['shop-url'],
+            'shopware-version' => self::incomingShopwareVersion($request),
+            'signature-payload' => implode('', [
+                $proofParameters['shop-id'],
+                $proofParameters['shop-url'],
+                $this->appConfiguration->getAppName(),
+            ]),
         ]);
 
         $psrFactory = new Psr17Factory();
@@ -138,10 +161,25 @@
             throw new ShopNotFoundException($requestContent['shopId']);
         }
 
+        $this->logger->info(
+            'Shop registration confirmation started',
+            $this->registrationLogContext($request, $requestContent['shopId'], $shop->getShopUrl(), $shop)
+        );
+
         $request->getBody()->rewind();
 
         // Use dual signature verifier for registration confirmation
-        $this->dualSignatureVerifier->authenticateRegistrationConfirmation($request, $shop, $this->appConfiguration);
+        try {
+            $this->dualSignatureVerifier->authenticateRegistrationConfirmation($request, $shop, $this->appConfiguration);
+        } catch (SignatureInvalidException|SignatureNotFoundException $e) {
+            $this->logger->warning(
+                'Shop registration confirmation signature verification failed',
+                $this->registrationLogContext($request, $shop->getShopId(), $shop->getShopUrl(), $shop)
+                    + ['exception' => $e::class, 'verification-stage' => $e->verificationStage]
+            );
+
+            throw $e;
+        }
 
         $this->eventDispatcher?->dispatch(new BeforeRegistrationCompletedEvent($shop, $request, $requestContent));
         $pendingSecret = $shop->getPendingShopSecret();
@@ -151,6 +189,11 @@
             $shop->setPreviousShopSecret($shop->getShopSecret())
                 ->setShopSecret($pendingSecret)
                 ->setSecretsRotatedAt(new \DateTimeImmutable());
+
+            $this->logger->info(
+                'Shop secret rotated during registration confirmation',
+                $this->registrationLogContext($request, $shop->getShopId(), $shop->getShopUrl(), $shop)
+            );
         }
 
         $pendingUrl = $shop->getPendingShopUrl();
@@ -166,6 +209,7 @@
         $this->logger->info('Shop registration confirmed', [
             'shop-id' => $shop->getShopId(),
             'shop-url' => $shop->getShopUrl(),
+            'shopware-version' => self::incomingShopwareVersion($request),
         ]);
 
         $this->eventDispatcher?->dispatch(new RegistrationCompletedEvent($request, $shop));
@@ -187,6 +231,35 @@
         return $shop->setShopUrl($this->sanitizeShopUrl($shop->getShopUrl()));
     }
 
+    /**
+     * @return array<string, bool|string|null>
+     */
+    private function registrationLogContext(RequestInterface $request, string $shopId, string $shopUrl, ?ShopInterface $shop = null): array
+    {
+        return [
+            'shop-id' => $shopId,
+            'shop-url' => $shopUrl,
+            'shop-exists' => $shop !== null,
+            'registration-confirmed' => $shop?->isRegistrationConfirmed(),
+            'has-pending-secret' => $shop !== null ? $shop->getPendingShopSecret() !== null : null,
+            'has-previous-secret' => $shop !== null ? $shop->getPreviousShopSecret() !== null : null,
+            'enforce-double-signature' => $this->appConfiguration->enforceDoubleSignature(),
+            'has-verified-with-double-signature' => $shop?->hasVerifiedWithDoubleSignature(),
+            'shopware-version' => self::incomingShopwareVersion($request),
+        ];
+    }
+
+    /**
+     * The Shopware version that sent the registration request, read from the `sw-version` header
+     * (Shopware sends it as a header on the register and confirm calls). Null when absent.
+     */
+    private static function incomingShopwareVersion(RequestInterface $request): ?string
+    {
+        $version = $request->getHeaderLine('sw-version');
+
+        return $version !== '' ? $version : null;
+    }
+
     /**
      * @deprecated tag:v6.0.0 - Will be removed. Double signature verification will always be enforced.
      */