-
Notifications
You must be signed in to change notification settings - Fork 617
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
grpc-js: Add more info to deadline exceeded errors #2692
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -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) { | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This is okay but we should never reach here right in lieu of line 106? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. That's true but TypeScript doesn't see a guarantee that the value doesn't change before the timer triggers, so it's easier to just have the check for type safety. |
||
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'); | ||
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For my knowledge, I often see either of these or
ResolvingCall
on mygrpc
traces. Curious what the difference between the 3 are and whether they indicate any specific pattern?RetryingCall
is the one that's a bit confusing as we don't have gRPC retries enabled by default. Does this account for thetransparent
retries?There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Those classes do have tracers set up, specifically
load_balancing_call
,retrying_call
, andresolving_call
. You should see them if you have them enabled and you make any requests. All of those are part of the call stack that makes up the internal implementation of a call object. As you say,RetryingCall
is used by default for transparent retries.