fix(gax): update error messages to be set to span.status.message - #9347
shivanee-p wants to merge 13 commits into
Conversation
`addTimeoutArg` computes `options.deadline` for every call and `CallSettings.timeout` defaults to 30s, but the fallback stub never read it. gRPC enforces its own deadline and cancels with DEADLINE_EXCEEDED; REST did not, so an endpoint that accepted the connection and then went quiet left the request outstanding forever, stranding the promise or callback waiting on it, and any span bound to that callback with it. The deadline was already being passed in. The stub's parameter names were inverted relative to gax's `UnaryCall` order: the third argument is what gRPC calls `options` and is the one carrying the deadline, but it was named `_metadata` and discarded, while the second carries the metadata that becomes request headers and was named `options`. Rename both so the argument that matters is identifiable. Forward the remaining time to gaxios as `timeout`. gaxios v7 arms an `AbortSignal.timeout` and merges it with the existing cancel signal through `AbortSignal.any`, so `cancel()` is unaffected. An already-expired deadline clamps to 1ms rather than 0, because gaxios reads `timeout: 0` as "no timeout" and would otherwise silently drop the bound in the case that most needs it. Translate the resulting abort into a GoogleError carrying Status.DEADLINE_EXCEEDED. Nothing downstream understands a DOMException named TimeoutError: `retryCodes` matching, caller `err.code` checks and the tracer's `error.type` all key off the numeric gRPC status. The translation is skipped when no deadline was forwarded, so an unrelated timeout is never relabelled, and the AbortError from `cancel()` keeps its existing handling. Server-streaming RPCs are excluded. The signal stays armed once the response body starts flowing, so forwarding the deadline would abort a healthy long-lived stream mid-read. That leaves REST streams unbounded where gRPC bounds them; closing that gap is user-visible and belongs in its own change. Six tests cover the forwarding, both cases where no timeout should be set, the expired-deadline clamp and the error translation. Each was mutation-tested by deliberately breaking the corresponding behavior and confirming the matching assertion fails.
The previous commit renamed the parameters on the exported
`FallbackServiceStub` interface and narrowed the third one from `{}` to
`{deadline?: Date}`. That is a public type change: an object literal passed as
the third argument by downstream code would now trip excess-property checks,
and implementors of the interface would see a narrower contract. Neither is
needed to enforce the deadline.
Restore the interface to its original shape. The accurate parameter names stay
inside `generateServiceStub`, where they are an implementation detail, with a
comment recording that the interface declares the middle two arguments the
other way round. That inversion is why the deadline-bearing argument read as
metadata and went unused for so long.
Also add a test that drives the call through `createApiCall` rather than
handing the stub a deadline directly. The existing tests all fabricate
`{deadline}` themselves, so they cover the stub but not the hand-off from
`addTimeoutArg`, which is the seam where the deadline was actually being
dropped. Commenting out the assignment in `addTimeoutArg` leaves all six of
them passing and fails only the new one.
The DEADLINE_EXCEEDED translation added in cd42784 never ran. It decided whether a deadline had expired by inspecting the error, and the error it was written against does not occur. Measured end to end against a server that accepts the connection and then never replies: rejected after 1513ms (timeout was 1500ms) constructor : GaxiosError name : Error code : undefined message : The operation was aborted. cause.name : AbortError node-fetch discards signal.reason and throws its own AbortError. gaxios wraps that in a GaxiosError, which never sets its own `name` (so it stays the inherited 'Error') and copies `code` only from a DOMException cause, which this is not. So the predicate's `instanceof Error` guard was not merely fragile across realms or for serialized errors, it was gating on evidence that never arrives. Every timeout returned the raw transport error. Worse, the evidence cannot be made to arrive. A deadline expiry and a caller's cancel() produce byte-identical errors: same constructor, same name, same undefined code, same cause.name. No amount of sniffing can separate them, because the distinction does not exist in the error. It exists only in the caller, which armed the timer. So arm it explicitly. Rather than hand `timeout` to gaxios and let it build the AbortSignal internally, build the same signal here, set a flag when it fires, and merge it with the cancel signal. The request behaves identically; the difference is that we now know which of the two aborts happened. The predicate is gone, along with the error inspection it existed to do. The clamp moves from Math.max(1, ...) to Math.max(0, ...). Passing 0 to gaxios meant "no timeout", but AbortSignal.timeout(0) aborts on the next tick, which is the right answer for a deadline that has already passed. Negative values still have to be clamped: AbortSignal.timeout throws RangeError on them. This also fixes the cancel guard in the body-read handler, which tested `err.name !== 'AbortError'`. For the reason above that name is 'Error', so the check never matched and a cancelled call still reported an error. It now uses the recorded state. The outer handler deliberately keeps no cancel suppression, matching its previous behavior; whether a cancelled call should report CANCELLED the way gRPC does is a separate, user-visible question. Tests: the fixtures fabricated a TimeoutError that production never produces, which is exactly why mutation-tested unit tests still passed against dead code. They now assert on the signal the stub owns and reject with the measured error shape. Two cases were added that the old approach could not have satisfied: cancelling a call that has a deadline armed must not report DEADLINE_EXCEEDED, and a cancelled call must not report an error at all. Each of the six behaviors was mutation-tested by breaking it and confirming the corresponding assertion fails: the timeout flag never set, the old err.name guard restored, the timeout signal not attached, server streams bounded, the expired-deadline clamp removed, and the translation applied without checking the flag. All six were caught. Verified against a real silent server through the real stub: a direct call with a 1500ms deadline settles at 1507ms with code 4, the same call through createApiCall with CallSettings.timeout 1200ms settles at 1203ms with code 4, and a cancel() with a 60s deadline armed settles at 53ms and is left untranslated.
The metadata parameter was typed `{[name: string]: string}` while the
code read it as `metadata[key][0]`. Both could not be right, and the
disagreement was hiding two silent data-loss bugs.
gRPC metadata is multi-valued. `buildMetadata` normalizes every value
to an array for exactly that reason, with the comment "Since gRPC
expects each header to be an array, we are doing the same for fallback
here", and it appends when a header appears more than once. Reading
index 0 discarded everything after the first value.
Measured through the real stub with a recording transport:
buildMetadata output what the stub sent
x-multi = ["a","b","c"] x-multi = "a"
x-plain = "hello" x-plain = "h"
The second row is the type error made visible: indexing a string
yields its first character, so a caller who passed a plain string, as
the declared type invited, silently sent one character of it.
Widen the type to `string | string[]` and handle both. Arrays are
appended so all values survive; the Headers API joins them with ', '.
The delete before appending preserves the previous semantics, where
`set` replaced whatever the request encoder had put there rather than
accumulating onto it.
The exported `FallbackServiceStub` interface is unchanged. It types
this parameter as `{}`, which already permits both shapes.
Four mutation tests, all caught: restoring the original single-value
read fails the multi-valued and plain-string assertions, appending
without clearing fails the override assertion, sending only element
zero fails the multi-valued assertion, and indexing a plain string
fails the plain-string assertion.
Apply prettier formatting to the node-fetch import attribute and the agentOption union type, and add an explicit return to the response-body then() so it satisfies promise/always-return. These violations predate this branch, but the monorepo linter checks every file a PR touches in full, so they surface here.
Wire TracerHelper.traceCall into createApiCall so gRPC calls emit spans when telemetry tracing is enabled. Covers unary, streaming, and callback-style calls, passing the isStreamingCall flag and the maxDurationMs backstop, and keeps the _fallback parameter type intact. Adds unit tests for the createApiCall tracing branch, stream retries, listener cleanup, and premature span closure. Squashed from 42 commits (24 of which were stale duplicates of shivaneep-o11y-tracer-helper-updates work) to restore linear history across the stack. Content is identical to the previous branch tip.
The staticArgs block started its optional chain at internalTelemetryInfo, leaving otherArgs itself unguarded, while internalMethodName a few lines below already used settings.otherArgs?.* This is not currently reachable: checkTelemetryEnabled(settings) guarantees otherArgs is defined before the tracing branch runs. It is also invisible to the compiler, since CallSettings declares otherArgs as required (CallOptions declares it optional), so tsc accepts the unguarded access. That combination means a refactor of the gating would surface this as a runtime TypeError with no compile-time warning. No behavior change.
traceCall now wraps the user's callback for stream calls as well, so the comment describing it as non-streaming only no longer holds. The tracedCallback ?? callback fallback is unchanged and still correct.
Extend telemetry tracing to the HTTP/REST fallback path so fallback calls emit spans through TracerHelper.traceCall, consistent with the gRPC path. Adds unit tests covering traceCall behavior in the HTTP fallback, including merged maxDurationMs handling via gaxCreateApiCall. Squashed from the previous merge-based history to restore linear history across the stack. Content is identical to the previous branch tip.
…ssing The fallback tracing tests all drive a fake `func` that calls back immediately with a success, so every one of them exercises the happy path. There was no error case on the fallback path at all, and no deadline case anywhere. That is the gap that matters here: an unenforced deadline is precisely what leaves a span open forever, and it was the symptom that started this work. Add a test that drives `fallback.createApiCall` with the error the REST transport now produces on timeout — a GoogleError carrying Status.DEADLINE_EXCEEDED — and asserts the span is not ended while the call is still outstanding, is ended afterwards, and is labelled `gcp.method.type: 'http'` and `error.type: 'DEADLINE_EXCEEDED'`. The `error.type` value is the seam between this change and the REST deadline work. `resolveErrorType` maps the numeric code through the Status enum, so the transports report a deadline identically. Before the REST transport enforced its deadline the attribute would have read 'GaxiosError', and only in the case where the call completed at all. Also rename 'passes explicit _fallback through when using fallback createApiCall'. It did not test that. `_fallback` is documented as "unused; for compatibility only" and is never read; the function hardcodes `true`. Verified by passing `false` instead of 'rest', which still yields rpcType 'http' and still passes. The test is now named for the override it actually exercises, and passes `false` so that it would fail if the argument were ever honored, which would mislabel a call that reached this function over the fallback transport. Mutation-tested. Reverting the hardcoded `true` to `false` fails four tests including the new one. Making `resolveErrorType` return the class name instead of mapping the numeric code fails three, the new one plus the two pre-existing TracerHelper cases that cover the mapping itself; the new test's own contribution is the composition of that mapping with the fallback path and the span lifetime, which nothing covered before. Note for after both branches land: no test here can catch the underlying regression, because these tests never touch the real transport. A hung REST call is caught by the deadline tests in grpc-fallback.ts. An end-to-end test wiring the real stub to a non-responsive server and asserting the span closes would cover the whole path, and is worth adding once the two branches are merged.
Spans now carry the status of the call they measure. rpc.response.status_code holds the gRPC status name on both transports, since that is the one status gax resolves everywhere and the only value comparable across them. grpc.response.status_code mirrors it on gRPC spans, and http.response.status_code carries the received HTTP status on fallback spans. The HTTP status could not simply be derived from the gRPC code: rpcCodeFromHttpStatusCode collapses whole ranges, so the received status is unrecoverable from the mapping. It is now plumbed from the fetch response through decodeResponse onto GoogleError.httpStatusCode, and is absent when no response arrived at all, such as an expired deadline. Success is inferred rather than observed. The unary path never surfaces a status object to gax, so a call that reported no error is recorded as OK, and 200 on the fallback. Adds OtelHarness.assertResponseStatus, which derives the expected attribute shape from the span's own gcp.method.type and asserts both the presence of the attribute that applies and the absence of the one that does not, so a test cannot assert a combination the tracer should never produce.
Three deviations from the semantic conventions, all in traceCall: - error.message was set on every failed span. semconv deprecated the attribute and calls it NOT RECOMMENDED on spans, because it has unbounded cardinality and restates the span status description that already carries the message. The status description is now its only home. - Successful calls set the span status to OK. semconv requires the status to be left unset when an operation ends without any errors; OK is reserved for an application explicitly overriding the instrumentation's judgement, which a library must never claim on the application's behalf. - A non-Error throw reported no error.type at all, leaving the failure invisible to any error-rate query that groups on it. It now reports the semconv-defined _OTHER fallback. The accompanying exception event is dropped: recordException on a bare string yields an event with no exception.type and no stacktrace, which adds nothing the status description does not already carry. rpc.response.status_code is unaffected. It is a domain-specific RPC status rather than the span status, and semconv recommends reporting a domain-specific attribute alongside error.type.
There was a problem hiding this comment.
Code Review
This pull request enhances telemetry tracing and adds robust deadline/timeout enforcement for the REST fallback transport in google-gax. It integrates OpenTelemetry tracing into API calls, maps transport-specific timeout failures to DEADLINE_EXCEEDED errors, and tracks HTTP status codes on fallback errors. The review feedback highlights critical compatibility and robustness improvements: avoiding AbortSignal.any to maintain Node.js 18 compatibility, handling invalid Date objects for deadlines to prevent runtime crashes, and filtering out null or undefined metadata values to avoid sending literal string headers.
| // Arm the deadline here rather than handing `timeout` to gaxios, which | ||
| // would build the identical `AbortSignal.timeout` internally. The | ||
| // difference is bookkeeping: both a deadline expiry and a `cancel()` | ||
| // abort the same request and surface the same error, so unless we record | ||
| // which one fired, the handlers below cannot tell them apart. | ||
| let timedOut = false; | ||
| let requestSignal = cancelSignal; | ||
| if (timeoutMs !== undefined) { | ||
| const timeoutSignal = AbortSignal.timeout(timeoutMs); | ||
| timeoutSignal.addEventListener('abort', () => (timedOut = true), { | ||
| once: true, | ||
| }); | ||
| requestSignal = AbortSignal.any([cancelSignal, timeoutSignal]); | ||
| } |
There was a problem hiding this comment.
AbortSignal.any is only supported in Node.js v20+ and modern browsers. Since this library supports Node.js 18, using AbortSignal.any will cause runtime crashes in Node.js 18 environments. We can avoid this by manually listening to the timeoutSignal and calling cancelController.abort() when it fires. This eliminates the need for AbortSignal.any entirely and is fully backward-compatible.
// Arm the deadline here rather than handing `timeout` to gaxios, which
// would build the identical `AbortSignal.timeout` internally. The
// difference is bookkeeping: both a deadline expiry and a `cancel()`
// abort the same request and surface the same error, so unless we record
// which one fired, the handlers below cannot tell them apart.
let timedOut = false;
if (timeoutMs !== undefined) {
const timeoutSignal = AbortSignal.timeout(timeoutMs);
timeoutSignal.addEventListener('abort', () => {
timedOut = true;
cancelController.abort();
}, {
once: true,
});
}| : Buffer.from(fetchParameters.body), | ||
| method: fetchParameters.method, | ||
| signal: cancelSignal, | ||
| signal: requestSignal, |
| let timeoutMs: number | undefined; | ||
| if (callOptions?.deadline && !rpc.responseStream) { | ||
| // `AbortSignal.timeout` rejects a negative delay with a RangeError, so | ||
| // an already-expired deadline is clamped. Zero is a fine value here: it | ||
| // aborts on the next tick, which is the right answer for a deadline | ||
| // that has already passed. | ||
| timeoutMs = Math.max(0, callOptions.deadline.getTime() - Date.now()); | ||
| } |
There was a problem hiding this comment.
If callOptions.deadline is an invalid Date object, getTime() will return NaN. This will result in timeoutMs being NaN, which can cause unexpected behavior or crashes when passed to AbortSignal.timeout(). We should check if the parsed time is a valid number before calculating timeoutMs.
let timeoutMs: number | undefined;
if (callOptions?.deadline && !rpc.responseStream) {
const time = callOptions.deadline.getTime();
if (!isNaN(time)) {
// `AbortSignal.timeout` rejects a negative delay with a RangeError, so
// an already-expired deadline is clamped. Zero is a fine value here: it
// aborts on the next tick, which is the right answer for a deadline
// that has already passed.
timeoutMs = Math.max(0, time - Date.now());
}
}| for (const key of Object.keys(metadata)) { | ||
| const value = metadata[key]; | ||
| if (Array.isArray(value)) { | ||
| headers.delete(key); | ||
| for (const item of value) { | ||
| headers.append(key, String(item)); | ||
| } | ||
| } else { | ||
| headers.set(key, String(value)); | ||
| } | ||
| } |
There was a problem hiding this comment.
If any metadata key has an undefined or null value, converting it directly using String(value) will set the header value to the literal string "undefined" or "null". We should defensively filter out undefined or null values to prevent sending invalid headers.
for (const key of Object.keys(metadata)) {
const value = metadata[key];
if (value === undefined || value === null) {
continue;
}
if (Array.isArray(value)) {
headers.delete(key);
for (const item of value) {
if (item !== undefined && item !== null) {
headers.append(key, String(item));
}
}
} else {
headers.set(key, String(value));
}
}The previous commit changed which signal carries what, but the existing tests only assert each attribute where it happens to be used. Nothing pinned the split itself, so the deprecated attribute or an instrumented OK status could return without a single failure. Adds a suite covering the contract directly: - error information (status + error.type) and exception information (the event) stay on their own signal, with neither leaking onto the other - error.message is never set, while the message stays reachable via the status description and the exception event - the exception event carries a stacktrace, the one detail no span attribute may hold - error.type agrees with the RPC status resolved for the same call - exactly one exception event is recorded however many completion signals a stream emits - a non-Error, a coded non-Error and a thrown null all still produce a usable error.type and RPC status - a successful call reports no error information at all The first case also documents that OTel derives exception.type from an error's code property before its name property, so a coded gax error reports '5' on the event where the span reports 'NOT_FOUND'. That asymmetry is the clearest argument for resolving error.type separately.
No description provided.