From d7d171776d686fbecdbf06e83ad278681c86cbda Mon Sep 17 00:00:00 2001 From: Michael Lumish Date: Fri, 15 Mar 2024 15:16:58 -0700 Subject: [PATCH 1/2] grpc-js: Add more info to deadline exceeded errors --- packages/grpc-js/src/call-interface.ts | 4 +++ packages/grpc-js/src/deadline.ts | 11 ++++++ packages/grpc-js/src/internal-channel.ts | 2 +- packages/grpc-js/src/load-balancing-call.ts | 28 ++++++++++++++-- packages/grpc-js/src/resolving-call.ts | 37 +++++++++++++++++++-- packages/grpc-js/src/retrying-call.ts | 24 +++++++++++-- packages/grpc-js/src/subchannel-address.ts | 8 +++-- packages/grpc-js/src/subchannel-call.ts | 4 +++ 8 files changed, 109 insertions(+), 9 deletions(-) diff --git a/packages/grpc-js/src/call-interface.ts b/packages/grpc-js/src/call-interface.ts index c0c63b957..c93c504f6 100644 --- a/packages/grpc-js/src/call-interface.ts +++ b/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[]; +} diff --git a/packages/grpc-js/src/deadline.ts b/packages/grpc-js/src/deadline.ts index 8f8fe67b7..de05e381e 100644 --- a/packages/grpc-js/src/deadline.ts +++ b/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'; +} diff --git a/packages/grpc-js/src/internal-channel.ts b/packages/grpc-js/src/internal-channel.ts index 823c935af..469ace557 100644 --- a/packages/grpc-js/src/internal-channel.ts +++ b/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( diff --git a/packages/grpc-js/src/load-balancing-call.ts b/packages/grpc-js/src/load-balancing-call.ts index 25a36553a..9940500bc 100644 --- a/packages/grpc-js/src/load-balancing-call.ts +++ b/packages/grpc-js/src/load-balancing-call.ts @@ -18,6 +18,7 @@ import { CallCredentials } from './call-credentials'; import { Call, + DeadlineInfoProvider, InterceptingListener, MessageContext, StatusObject, @@ -25,7 +26,7 @@ import { 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 { @@ -209,6 +232,7 @@ export class LoadBalancingCall implements Call { } }, }); + this.childStartTime = new Date(); } catch (error) { this.trace( 'Failed to start call on picked subchannel ' + diff --git a/packages/grpc-js/src/resolving-call.ts b/packages/grpc-js/src/resolving-call.ts index 723533dba..2c81e7883 100644 --- a/packages/grpc-js/src/resolving-call.ts +++ b/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'); diff --git a/packages/grpc-js/src/retrying-call.ts b/packages/grpc-js/src/retrying-call.ts index e6e1cbb44..14969916e 100644 --- a/packages/grpc-js/src/retrying-call.ts +++ b/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; @@ -628,6 +647,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(); diff --git a/packages/grpc-js/src/subchannel-address.ts b/packages/grpc-js/src/subchannel-address.ts index 70a7962f7..7e4f3e475 100644 --- a/packages/grpc-js/src/subchannel-address.ts +++ b/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; } diff --git a/packages/grpc-js/src/subchannel-call.ts b/packages/grpc-js/src/subchannel-call.ts index 3b9b6152f..33cf544d8 100644 --- a/packages/grpc-js/src/subchannel-call.ts +++ b/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 { @@ -288,6 +289,9 @@ export class Http2SubchannelCall implements SubchannelCall { this.callEventTracker.onStreamEnd(false); }); } + getDeadlineInfo(): string[] { + return [`remote_addr=${this.getPeer()}`]; + } public onDisconnect() { this.endCall({ From f4330f72c940645f910a7a78b3231ceab9cc2619 Mon Sep 17 00:00:00 2001 From: Michael Lumish Date: Thu, 21 Mar 2024 09:49:58 -0700 Subject: [PATCH 2/2] Use call start times in some trace logs --- packages/grpc-js/src/load-balancing-call.ts | 3 ++- packages/grpc-js/src/retrying-call.ts | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/packages/grpc-js/src/load-balancing-call.ts b/packages/grpc-js/src/load-balancing-call.ts index 9940500bc..764769753 100644 --- a/packages/grpc-js/src/load-balancing-call.ts +++ b/packages/grpc-js/src/load-balancing-call.ts @@ -121,7 +121,8 @@ export class LoadBalancingCall implements Call, DeadlineInfoProvider { status.code + ' details="' + status.details + - '"' + '" start time=' + + this.startTime.toISOString() ); const finalStatus = { ...status, progress }; this.listener?.onReceiveStatus(finalStatus); diff --git a/packages/grpc-js/src/retrying-call.ts b/packages/grpc-js/src/retrying-call.ts index 14969916e..1c5ffaa4f 100644 --- a/packages/grpc-js/src/retrying-call.ts +++ b/packages/grpc-js/src/retrying-call.ts @@ -261,7 +261,8 @@ export class RetryingCall implements Call, DeadlineInfoProvider { statusObject.code + ' details="' + statusObject.details + - '"' + '" start time=' + + this.startTime.toISOString() ); this.bufferTracker.freeAll(this.callNumber); this.writeBufferOffset = this.writeBufferOffset + this.writeBuffer.length;