Merge pull request #2692 from murgatroid99/grpc-js_deadline_info

grpc-js: Add more info to deadline exceeded errors

packages/grpc-js/src/call-interface.ts

@@ -171,3 +171,7 @@ export interface Call {
   getCallNumber(): number;
   setCredentials(credentials: CallCredentials): void;
 }
+
+export interface DeadlineInfoProvider {
+  getDeadlineInfo(): string[];
+}

packages/grpc-js/src/deadline.ts

@@ -93,3 +93,14 @@ export function deadlineToString(deadline: Deadline): string {
     }
   }
 }
+
+/**
+ * Calculate the difference between two dates as a number of seconds and format
+ * it as a string.
+ * @param startDate
+ * @param endDate
+ * @returns
+ */
+export function formatDateDifference(startDate: Date, endDate: Date): string {
+  return ((endDate.getTime() - startDate.getTime()) / 1000).toFixed(3) + 's';
+}

packages/grpc-js/src/internal-channel.ts

@@ -684,7 +684,7 @@ export class InternalChannel {
     host: string,
     credentials: CallCredentials,
     deadline: Deadline
-  ): Call {
+  ): LoadBalancingCall | RetryingCall {
     // Create a RetryingCall if retries are enabled
     if (this.options['grpc.enable_retries'] === 0) {
       return this.createLoadBalancingCall(

packages/grpc-js/src/load-balancing-call.ts

@@ -18,14 +18,15 @@
 import { CallCredentials } from './call-credentials';
 import {
   Call,
+  DeadlineInfoProvider,
   InterceptingListener,
   MessageContext,
   StatusObject,
 } from './call-interface';
 import { SubchannelCall } from './subchannel-call';
 import { ConnectivityState } from './connectivity-state';
 import { LogVerbosity, Status } from './constants';
-import { Deadline, getDeadlineTimeoutString } from './deadline';
+import { Deadline, formatDateDifference, getDeadlineTimeoutString } from './deadline';
 import { InternalChannel } from './internal-channel';
 import { Metadata } from './metadata';
 import { PickResultType } from './picker';
@@ -48,7 +49,7 @@ export interface LoadBalancingCallInterceptingListener
   onReceiveStatus(status: StatusObjectWithProgress): void;
 }
 
-export class LoadBalancingCall implements Call {
+export class LoadBalancingCall implements Call, DeadlineInfoProvider {
   private child: SubchannelCall | null = null;
   private readPending = false;
   private pendingMessage: { context: MessageContext; message: Buffer } | null =
@@ -59,6 +60,8 @@ export class LoadBalancingCall implements Call {
   private metadata: Metadata | null = null;
   private listener: InterceptingListener | null = null;
   private onCallEnded: ((statusCode: Status) => void) | null = null;
+  private startTime: Date;
+  private childStartTime: Date | null = null;
   constructor(
     private readonly channel: InternalChannel,
     private readonly callConfig: CallConfig,
@@ -80,6 +83,26 @@ export class LoadBalancingCall implements Call {
     /* Currently, call credentials are only allowed on HTTPS connections, so we
      * can assume that the scheme is "https" */
     this.serviceUrl = `https://${hostname}/${serviceName}`;
+    this.startTime = new Date();
+  }
+  getDeadlineInfo(): string[] {
+    const deadlineInfo: string[] = [];
+    if (this.childStartTime) {
+      if (this.childStartTime > this.startTime) {
+        if (this.metadata?.getOptions().waitForReady) {
+          deadlineInfo.push('wait_for_ready');
+        }
+        deadlineInfo.push(`LB pick: ${formatDateDifference(this.startTime, this.childStartTime)}`);
+      }
+      deadlineInfo.push(...this.child!.getDeadlineInfo());
+      return deadlineInfo;
+    } else {
+      if (this.metadata?.getOptions().waitForReady) {
+        deadlineInfo.push('wait_for_ready');
+      }
+      deadlineInfo.push('Waiting for LB pick');
+    }
+    return deadlineInfo;
   }
 
   private trace(text: string): void {
@@ -98,7 +121,8 @@ export class LoadBalancingCall implements Call {
           status.code +
           ' details="' +
           status.details +
-          '"'
+          '" start time=' +
+          this.startTime.toISOString()
       );
       const finalStatus = { ...status, progress };
       this.listener?.onReceiveStatus(finalStatus);
@@ -209,6 +233,7 @@ export class LoadBalancingCall implements Call {
                       }
                     },
                   });
+                this.childStartTime = new Date();
               } catch (error) {
                 this.trace(
                   'Failed to start call on picked subchannel ' +

packages/grpc-js/src/resolving-call.ts

@@ -19,6 +19,7 @@ import { CallCredentials } from './call-credentials';
 import {
   Call,
   CallStreamOptions,
+  DeadlineInfoProvider,
   InterceptingListener,
   MessageContext,
   StatusObject,
@@ -27,6 +28,7 @@ import { LogVerbosity, Propagate, Status } from './constants';
 import {
   Deadline,
   deadlineToString,
+  formatDateDifference,
   getRelativeTimeout,
   minDeadline,
 } from './deadline';
@@ -39,7 +41,7 @@ import { restrictControlPlaneStatusCode } from './control-plane-status';
 const TRACER_NAME = 'resolving_call';
 
 export class ResolvingCall implements Call {
-  private child: Call | null = null;
+  private child: (Call & DeadlineInfoProvider) | null = null;
   private readPending = false;
   private pendingMessage: { context: MessageContext; message: Buffer } | null =
     null;
@@ -56,6 +58,10 @@ export class ResolvingCall implements Call {
   private deadlineTimer: NodeJS.Timeout = setTimeout(() => {}, 0);
   private filterStack: FilterStack | null = null;
 
+  private deadlineStartTime: Date | null = null;
+  private configReceivedTime: Date | null = null;
+  private childStartTime: Date | null = null;
+
   constructor(
     private readonly channel: InternalChannel,
     private readonly method: string,
@@ -97,12 +103,37 @@ export class ResolvingCall implements Call {
 
   private runDeadlineTimer() {
     clearTimeout(this.deadlineTimer);
+    this.deadlineStartTime = new Date();
     this.trace('Deadline: ' + deadlineToString(this.deadline));
     const timeout = getRelativeTimeout(this.deadline);
     if (timeout !== Infinity) {
       this.trace('Deadline will be reached in ' + timeout + 'ms');
       const handleDeadline = () => {
-        this.cancelWithStatus(Status.DEADLINE_EXCEEDED, 'Deadline exceeded');
+        if (!this.deadlineStartTime) {
+          this.cancelWithStatus(Status.DEADLINE_EXCEEDED, 'Deadline exceeded');
+          return;
+        }
+        const deadlineInfo: string[] = [];
+        const deadlineEndTime = new Date();
+        deadlineInfo.push(`Deadline exceeded after ${formatDateDifference(this.deadlineStartTime, deadlineEndTime)}`);
+        if (this.configReceivedTime) {
+          if (this.configReceivedTime > this.deadlineStartTime) {
+            deadlineInfo.push(`name resolution: ${formatDateDifference(this.deadlineStartTime, this.configReceivedTime)}`);
+          }
+          if (this.childStartTime) {
+            if (this.childStartTime > this.configReceivedTime) {
+              deadlineInfo.push(`metadata filters: ${formatDateDifference(this.configReceivedTime, this.childStartTime)}`);
+            }
+          } else {
+            deadlineInfo.push('waiting for metadata filters');
+          }
+        } else {
+          deadlineInfo.push('waiting for name resolution');
+        }
+        if (this.child) {
+          deadlineInfo.push(...this.child.getDeadlineInfo());
+        }
+        this.cancelWithStatus(Status.DEADLINE_EXCEEDED, deadlineInfo.join(','));
       };
       if (timeout <= 0) {
         process.nextTick(handleDeadline);
@@ -176,6 +207,7 @@ export class ResolvingCall implements Call {
       return;
     }
     // configResult.type === 'SUCCESS'
+    this.configReceivedTime = new Date();
     const config = configResult.config;
     if (config.status !== Status.OK) {
       const { code, details } = restrictControlPlaneStatusCode(
@@ -215,6 +247,7 @@ export class ResolvingCall implements Call {
           this.deadline
         );
         this.trace('Created child [' + this.child.getCallNumber() + ']');
+        this.childStartTime = new Date();
         this.child.start(filteredMetadata, {
           onReceiveMetadata: metadata => {
             this.trace('Received metadata');

packages/grpc-js/src/retrying-call.ts

@@ -17,12 +17,13 @@
 
 import { CallCredentials } from './call-credentials';
 import { LogVerbosity, Status } from './constants';
-import { Deadline } from './deadline';
+import { Deadline, formatDateDifference } from './deadline';
 import { Metadata } from './metadata';
 import { CallConfig } from './resolver';
 import * as logging from './logging';
 import {
   Call,
+  DeadlineInfoProvider,
   InterceptingListener,
   MessageContext,
   StatusObject,
@@ -121,6 +122,7 @@ interface UnderlyingCall {
   state: UnderlyingCallState;
   call: LoadBalancingCall;
   nextMessageToSend: number;
+  startTime: Date;
 }
 
 /**
@@ -170,7 +172,7 @@ interface WriteBufferEntry {
 
 const PREVIONS_RPC_ATTEMPTS_METADATA_KEY = 'grpc-previous-rpc-attempts';
 
-export class RetryingCall implements Call {
+export class RetryingCall implements Call, DeadlineInfoProvider {
   private state: RetryingCallState;
   private listener: InterceptingListener | null = null;
   private initialMetadata: Metadata | null = null;
@@ -198,6 +200,7 @@ export class RetryingCall implements Call {
   private committedCallIndex: number | null = null;
   private initialRetryBackoffSec = 0;
   private nextRetryBackoffSec = 0;
+  private startTime: Date;
   constructor(
     private readonly channel: InternalChannel,
     private readonly callConfig: CallConfig,
@@ -223,6 +226,22 @@ export class RetryingCall implements Call {
     } else {
       this.state = 'TRANSPARENT_ONLY';
     }
+    this.startTime = new Date();
+  }
+  getDeadlineInfo(): string[] {
+    if (this.underlyingCalls.length === 0) {
+      return [];
+    }
+    const deadlineInfo: string[] = [];
+    const latestCall = this.underlyingCalls[this.underlyingCalls.length - 1];
+    if (this.underlyingCalls.length > 1) {
+      deadlineInfo.push(`previous attempts: ${this.underlyingCalls.length - 1}`);
+    }
+    if (latestCall.startTime > this.startTime) {
+      deadlineInfo.push(`time to current attempt start: ${formatDateDifference(this.startTime, latestCall.startTime)}`);
+    }
+    deadlineInfo.push(...latestCall.call.getDeadlineInfo());
+    return deadlineInfo;
   }
   getCallNumber(): number {
     return this.callNumber;
@@ -242,7 +261,8 @@ export class RetryingCall implements Call {
         statusObject.code +
         ' details="' +
         statusObject.details +
-        '"'
+        '" start time=' +
+        this.startTime.toISOString()
     );
     this.bufferTracker.freeAll(this.callNumber);
     this.writeBufferOffset = this.writeBufferOffset + this.writeBuffer.length;
@@ -628,6 +648,7 @@ export class RetryingCall implements Call {
       state: 'ACTIVE',
       call: child,
       nextMessageToSend: 0,
+      startTime: new Date()
     });
     const previousAttempts = this.attempts - 1;
     const initialMetadata = this.initialMetadata!.clone();

packages/grpc-js/src/subchannel-address.ts

@@ -15,7 +15,7 @@
  *
  */
 
-import { isIP } from 'net';
+import { isIP, isIPv6 } from 'net';
 
 export interface TcpSubchannelAddress {
   port: number;
@@ -63,7 +63,11 @@ export function subchannelAddressEqual(
 
 export function subchannelAddressToString(address: SubchannelAddress): string {
   if (isTcpSubchannelAddress(address)) {
-    return address.host + ':' + address.port;
+    if (isIPv6(address.host)) {
+      return '[' + address.host + ']:' + address.port;
+    } else {
+      return address.host + ':' + address.port;
+    }
   } else {
     return address.path;
   }

packages/grpc-js/src/subchannel-call.ts

@@ -70,6 +70,7 @@ export interface SubchannelCall {
   startRead(): void;
   halfClose(): void;
   getCallNumber(): number;
+  getDeadlineInfo(): string[];
 }
 
 export interface StatusObjectWithRstCode extends StatusObject {
@@ -291,6 +292,9 @@ export class Http2SubchannelCall implements SubchannelCall {
       this.callEventTracker.onStreamEnd(false);
     });
   }
+  getDeadlineInfo(): string[] {
+    return [`remote_addr=${this.getPeer()}`];
+  }
 
   public onDisconnect() {
     this.endCall({