fix: reduce Pub/Sub recovery log noise and respect backoff delay

Log the subscription loop error only once until the condition changes
(successful run resets the flag). Pass retryDelay from attemptRecovery
to startLoop so it waits for the actual backoff period instead of
retrying every 3 seconds.

Author: andris9

lib/oauth/pubsub/google.js

@@ -19,6 +19,7 @@ class PubSubInstance {
         this.recoveryAttempts = 0;
         this.lastRecoveryAttempt = 0;
         this._hadPubSubFlag = true;
+        this._loopErrorLogged = false;
 
         this.checkSchemaVersions()
             .catch(err => {
@@ -37,19 +38,23 @@ class PubSubInstance {
         }
         this.run()
             .then(() => {
+                this._loopErrorLogged = false;
                 this.startLoop();
             })
             .catch(err => {
-                logger.error({ msg: 'Failed to process subscription loop', app: this.app, err });
-
-                this._hadPubSubFlag = true;
-                oauth2Apps.setMeta(this.app, {
-                    pubSubFlag: {
-                        message: `Failed to process subscription loop`,
-                        description: [err.message, err.reason, err.code].filter(val => val).join('; ')
-                    }
-                });
-                setTimeout(() => this.startLoop(), 3000);
+                if (!this._loopErrorLogged) {
+                    logger.error({ msg: 'Failed to process subscription loop', app: this.app, err });
+                    this._loopErrorLogged = true;
+
+                    this._hadPubSubFlag = true;
+                    oauth2Apps.setMeta(this.app, {
+                        pubSubFlag: {
+                            message: `Failed to process subscription loop`,
+                            description: [err.message, err.reason, err.code].filter(val => val).join('; ')
+                        }
+                    });
+                }
+                setTimeout(() => this.startLoop(), err.retryDelay || 3000);
             });
     }
 
@@ -251,14 +256,16 @@ class PubSubInstance {
         let now = Date.now();
         let backoffMs = Math.min(3000 * Math.pow(2, Math.min(this.recoveryAttempts, 20)), 5 * 60 * 1000);
         if (now - this.lastRecoveryAttempt < backoffMs) {
-            logger.warn({ msg: 'Skipping subscription recovery (backoff)', app: this.app, reason, recoveryAttempts: this.recoveryAttempts, backoffMs });
-            throw new Error(reason);
+            let remainingMs = backoffMs - (now - this.lastRecoveryAttempt);
+            let err = new Error(reason);
+            err.retryDelay = remainingMs;
+            throw err;
         }
 
         this.lastRecoveryAttempt = now;
         this.recoveryAttempts++;
 
-        logger.warn({ msg: 'Attempting subscription recovery', app: this.app, reason, recoveryAttempts: this.recoveryAttempts });
+        logger.info({ msg: 'Attempting subscription recovery', app: this.app, reason, recoveryAttempts: this.recoveryAttempts });
 
         try {
             await this.getApp(true);
@@ -269,7 +276,9 @@ class PubSubInstance {
             this.recoveryAttempts = 0;
             logger.info({ msg: 'Successfully recovered Pub/Sub subscription', app: this.app, reason });
         } catch (recoveryErr) {
-            logger.error({ msg: 'Failed to recover Pub/Sub subscription', app: this.app, reason, err: recoveryErr });
+            let nextBackoffMs = Math.min(3000 * Math.pow(2, Math.min(this.recoveryAttempts, 20)), 5 * 60 * 1000);
+            logger.warn({ msg: 'Subscription recovery failed', app: this.app, reason, err: recoveryErr, nextRetryMs: nextBackoffMs });
+            recoveryErr.retryDelay = nextBackoffMs;
             throw recoveryErr;
         }
     }

test/pubsub-recovery-test.js

@@ -331,8 +331,16 @@ test('Pub/Sub subscription recovery tests', async t => {
                 assert.strictEqual(instance.recoveryAttempts, 1);
                 assert.strictEqual(ensurePubsubCalls.length, 1);
 
-                // Second call immediately: should skip recovery due to backoff and throw
-                await assert.rejects(() => instance.run(), /Subscription not found/);
+                // Second call immediately: should skip recovery due to backoff and throw with retryDelay
+                let backoffErr;
+                try {
+                    await instance.run();
+                } catch (err) {
+                    backoffErr = err;
+                }
+                assert.ok(backoffErr, 'should throw during backoff');
+                assert.match(backoffErr.message, /Subscription not found/);
+                assert.ok(typeof backoffErr.retryDelay === 'number' && backoffErr.retryDelay > 0, 'backoff error should include retryDelay');
                 // ensurePubsub should NOT be called again (backoff not elapsed)
                 assert.strictEqual(ensurePubsubCalls.length, 1, 'ensurePubsub should not be called during backoff');
             }