FFM-12353 Reduce excessive logs (#122)

Author: erdirowlands

Diff for: package-lock.json

@@ -1,6 +1,6 @@
 {
   "name": "@harnessio/ff-nodejs-server-sdk",
-  "version": "1.8.3",
+  "version": "1.8.4",
   "description": "Feature flags SDK for NodeJS environments",
   "main": "dist/cjs/index.js",
   "module": "dist/esm/index.mjs",

Diff for: package.json

@@ -39,8 +39,7 @@ describe('SDK Codes', () => {
     ['warnFailedInitAuthError', [logger]],
     ['warnAuthFailedExceedRetries', [logger]],
     ['warnAuthRetrying', [1, 'dummy error', logger]],
-    ['warnStreamDisconnected', ['dummy reason', logger]],
-    ['warnStreamRetrying', [4, logger]],
+    ['warnStreamDisconnectedWithRetry', ['dummy reason', 1, logger]],
     ['warnPostMetricsFailed', ['dummy error', logger]],
     [
       'warnDefaultVariationServed',

Diff for: src/__tests__/sdk_codes.test.ts

@@ -139,11 +139,32 @@ export default class Client {
       this.initialize(Processor.STREAM);
     });
 
+    // Track if we've already logged the streaming error since the last successful connection
+    let streamingErrorLogged = false;
+
+    // Reset the error logging flag when we connect successfully
+    this.eventBus.on(StreamEvent.CONNECTED, () => {
+      // Reset the streaming error logged state when we successfully connect
+      streamingErrorLogged = false;
+      this.pollProcessor.stop();
+    });
+
+    // Handle stream retry events
     this.eventBus.on(StreamEvent.RETRYING, () => {
       this.failure = true;
-      this.log.error(
-        'Issue with streaming: falling back to polling while the SDK attempts to reconnect',
-      );
+
+      // Only log the error message if it's the first time since the last successful connection
+      if (!streamingErrorLogged) {
+        this.log.error(
+          'Issue with streaming: falling back to polling while the SDK attempts to reconnect',
+        );
+        streamingErrorLogged = true;
+      } else {
+        // Log at debug level for subsequent retries until a successful reconnection
+        this.log.debug(
+          'Still trying to reconnect stream, staying on polling for now',
+        );
+      }
 
       if (!this.closing) {
         this.pollProcessor.start();
@@ -172,10 +193,6 @@ export default class Client {
       this.eventBus.emit(Event.FAILED);
     });
 
-    this.eventBus.on(StreamEvent.CONNECTED, () => {
-      this.pollProcessor.stop();
-    });
-
     this.eventBus.on(StreamEvent.DISCONNECTED, () => {
       if (!this.closing) {
         this.pollProcessor.start();

Diff for: src/client.ts

@@ -348,7 +348,7 @@ export class Evaluator {
     target: Target,
   ): Promise<boolean> {
     if (parent.prerequisites) {
-      this.log.info(
+      this.log.debug(
         'Checking pre requisites %s of parent feature %s',
         parent.prerequisites,
         parent.feature,

Diff for: src/evaluator.ts

@@ -131,7 +131,7 @@ export class PollingProcessor {
 
   start(): void {
     if (!this.stopped) {
-      this.log.info('PollingProcessor already started');
+      this.log.debug('PollingProcessor already started');
       return;
     }
     this.log.info(

Diff for: src/polling.ts

@@ -20,7 +20,7 @@ const sdkCodes: Record<number, string> = {
   4001: 'Polling stopped',
   // SDK_STREAM_5xxx
   5000: 'SSE stream successfully connected',
-  5001: 'SSE stream disconnected, reason:',
+  5001: 'SSE stream disconnected, reason:',  // When used with retrying, will combine with 5003
   5002: 'SSE event received',
   5003: 'SSE retrying to connect in',
   5004: 'SSE stopped',
@@ -158,14 +158,54 @@ export function warnAuthRetrying(
   );
 }
 
-export function warnStreamDisconnected(reason: string, logger: Logger): void {
-  logger.warn(getSdkErrMsg(5001, reason));
+// Track disconnect attempts for throttling warning logs
+let disconnectAttempts = 0;
+let lastConnectionSuccess = Date.now(); // Initialize with current time to avoid huge numbers
+
+// Restart disconnect counter when connection succeeds
+export function restartDisconnectCounter(): void {
+  disconnectAttempts = 0;
+  lastConnectionSuccess = Date.now();
 }
 
-export function warnStreamRetrying(seconds: number, logger: Logger): void {
-  logger.warn(getSdkErrMsg(5003, `${seconds}`));
+// Reset disconnect counter
+export function resetDisconnectCounter(): void {
+  disconnectAttempts = 0;
+  lastConnectionSuccess = Date.now();
 }
 
+
+// Combined warning function for both disconnect and retry in a single message
+export function warnStreamDisconnectedWithRetry(reason: string, ms: number, logger: Logger): void {
+  disconnectAttempts++;
+
+  // First disconnect after a successful connection - always warn
+  // Combine both codes to create a message with both disconnect reason and retry info
+  const combinedMessage = `${getSdkErrMsg(5001)} ${reason} - ${getSdkErrMsg(5003)} ${ms}ms`;
+
+  if (disconnectAttempts === 1) {
+    logger.warn(`${combinedMessage} (subsequent logs until 10th attempt will be at DEBUG level to reduce noise)`);
+  }
+  else if (disconnectAttempts === 10) {
+    const timeSince = Date.now() - lastConnectionSuccess;
+    const timeSinceConnection = Math.floor(timeSince/1000);
+    logger.warn(`${combinedMessage} (10th attempt, connection unstable for ${timeSinceConnection} seconds, subsequent logs will be at DEBUG level except every 50th attempt)`);
+  }
+
+  else if (disconnectAttempts > 10 && disconnectAttempts % 50 === 0) {
+    const timeSince = Date.now() - lastConnectionSuccess;
+    const timeSinceConnection = Math.floor(timeSince/1000);
+    const nextWarnAt = disconnectAttempts + 50;
+    logger.warn(`${combinedMessage} (${disconnectAttempts}th attempt, connection unstable for ${timeSinceConnection} seconds, next warning at ${nextWarnAt}th attempt)`);
+  }
+
+  // All other disconnect attempts - log at debug level
+  else {
+    logger.debug(`${combinedMessage} (attempt ${disconnectAttempts}, logging at debug level to reduce noise)`);
+  }
+}
+
+
 export function warnPostMetricsFailed(reason: string, logger: Logger): void {
   logger.warn(getSdkErrMsg(7002, reason));
 }

Diff for: src/sdk_codes.ts

@@ -10,9 +10,9 @@ import http, { ClientRequest } from 'http';
 import {
   debugStreamEventReceived,
   infoStreamStopped,
-  warnStreamDisconnected,
-  warnStreamRetrying,
-} from './sdk_codes';
+  warnStreamDisconnectedWithRetry,
+  resetDisconnectCounter, restartDisconnectCounter
+} from "./sdk_codes";
 
 type FetchFunction = (
   identifier: string,
@@ -101,6 +101,10 @@ export class StreamProcessor {
 
     const onConnected = () => {
       this.log.info(`SSE stream connected OK: ${url}`);
+
+      // Reset disconnect counter when connection succeeds
+      restartDisconnectCounter();
+
       this.retryAttempt = 0;
       this.readyState = StreamProcessor.CONNECTED;
       this.eventBus.emit(StreamEvent.CONNECTED);
@@ -111,13 +115,11 @@ export class StreamProcessor {
         this.retryAttempt += 1;
 
         const delayMs = this.getRandomRetryDelayMs();
-        warnStreamDisconnected(msg, this.log);
-        warnStreamRetrying(delayMs, this.log);
+        warnStreamDisconnectedWithRetry(msg, delayMs, this.log);
         this.readyState = StreamProcessor.RETRYING;
         this.eventBus.emit(StreamEvent.RETRYING);
 
         setTimeout(() => {
-          this.log.info('SSE retrying to connect');
           this.connect(url, options, onConnected, onFailed);
         }, delayMs);
       }
@@ -257,6 +259,7 @@ export class StreamProcessor {
     this.readyState = StreamProcessor.CLOSED;
     this.log.info('Closing StreamProcessor');
 
+    resetDisconnectCounter()
     this.request.destroy();
     this.request = undefined;
 

Diff for: src/streaming.ts

@@ -1 +1 @@
-export const VERSION = '1.8.3';
+export const VERSION = '1.8.4';