Merge pull request #2918 from murgatroid99/grpc-js_backoff_trace

grpc-js: Add backoff timer trace logging

packages/grpc-js-xds/interop/test-client.Dockerfile

@@ -42,7 +42,7 @@ COPY --from=build /node/src/grpc-node/packages/grpc-js ./packages/grpc-js/
 COPY --from=build /node/src/grpc-node/packages/grpc-js-xds ./packages/grpc-js-xds/
 
 ENV GRPC_VERBOSITY="DEBUG"
-ENV GRPC_TRACE=xds_client,xds_resolver,xds_cluster_manager,cds_balancer,xds_cluster_resolver,xds_cluster_impl,priority,weighted_target,round_robin,resolving_load_balancer,subchannel,keepalive,dns_resolver,fault_injection,http_filter,csds,outlier_detection,server,server_call,ring_hash,transport,certificate_provider,xds_channel_credentials
+ENV GRPC_TRACE=xds_client,xds_resolver,xds_cluster_manager,cds_balancer,xds_cluster_resolver,xds_cluster_impl,priority,weighted_target,round_robin,resolving_load_balancer,subchannel,keepalive,dns_resolver,fault_injection,http_filter,csds,outlier_detection,server,server_call,ring_hash,transport,certificate_provider,xds_channel_credentials,backoff
 ENV NODE_XDS_INTEROP_VERBOSITY=1
 
 ENTRYPOINT [ "/nodejs/bin/node", "/node/src/grpc-node/packages/grpc-js-xds/build/interop/xds-interop-client" ]

packages/grpc-js/src/backoff-timeout.ts

@@ -15,6 +15,11 @@
  *
  */
 
+import { LogVerbosity } from './constants';
+import * as logging from './logging';
+
+const TRACER_NAME = 'backoff';
+
 const INITIAL_BACKOFF_MS = 1000;
 const BACKOFF_MULTIPLIER = 1.6;
 const MAX_BACKOFF_MS = 120000;
@@ -84,7 +89,12 @@ export class BackoffTimeout {
    */
   private endTime: Date = new Date();
 
+  private id: number;
+
+  private static nextId = 0;
+
   constructor(private callback: () => void, options?: BackoffOptions) {
+    this.id = BackoffTimeout.getNextId();
     if (options) {
       if (options.initialDelay) {
         this.initialDelay = options.initialDelay;
@@ -99,18 +109,29 @@ export class BackoffTimeout {
         this.maxDelay = options.maxDelay;
       }
     }
+    this.trace('constructed initialDelay=' + this.initialDelay + ' multiplier=' + this.multiplier + ' jitter=' + this.jitter + ' maxDelay=' + this.maxDelay);
     this.nextDelay = this.initialDelay;
     this.timerId = setTimeout(() => {}, 0);
     clearTimeout(this.timerId);
   }
 
+  private static getNextId() {
+    return this.nextId++;
+  }
+
+  private trace(text: string) {
+    logging.trace(LogVerbosity.DEBUG, TRACER_NAME, '{' + this.id + '} ' + text);
+  }
+
   private runTimer(delay: number) {
+    this.trace('runTimer(delay=' + delay + ')');
     this.endTime = this.startTime;
     this.endTime.setMilliseconds(
       this.endTime.getMilliseconds() + delay
     );
     clearTimeout(this.timerId);
     this.timerId = setTimeout(() => {
+      this.trace('timer fired');
       this.callback();
       this.running = false;
     }, delay);
@@ -123,6 +144,7 @@ export class BackoffTimeout {
    * Call the callback after the current amount of delay time
    */
   runOnce() {
+    this.trace('runOnce()');
     this.running = true;
     this.startTime = new Date();
     this.runTimer(this.nextDelay);
@@ -140,6 +162,7 @@ export class BackoffTimeout {
    * again.
    */
   stop() {
+    this.trace('stop()');
     clearTimeout(this.timerId);
     this.running = false;
   }
@@ -149,6 +172,7 @@ export class BackoffTimeout {
    * retroactively apply that reset to the current timer.
    */
   reset() {
+    this.trace('reset() running=' + this.running);
     this.nextDelay = this.initialDelay;
     if (this.running) {
       const now = new Date();