Repository navigation
feat(gax): add error logging for low level network attempts - #9757
Conversation
There was a problem hiding this comment.
Code Review
This pull request refactors the logging utility by extracting common execution wrapping logic into executeLoggedOperation and introducing logNetworkAttempt to log individual RPC transport attempt failures at the DEBUG level. Feedback suggests adding a latch flag in logNetworkAttempt to prevent duplicate DEBUG logs if both callback and stream error events are triggered, and splitting the corresponding combined test into separate unit tests to verify each failure path independently.
| // Snapshot attempt context in case async rejection loses active context. | ||
| const initialContext = context.active(); | ||
|
|
||
| const emitL4DebugLog = (err: unknown) => { |
There was a problem hiding this comment.
To prevent duplicate DEBUG logs for a single network attempt (for example, when both a callback and a stream error event are triggered), we should introduce a latch flag similar to hasLoggedL3 in logCall.
| // Snapshot attempt context in case async rejection loses active context. | |
| const initialContext = context.active(); | |
| const emitL4DebugLog = (err: unknown) => { | |
| // Latch to emit at most one debug log per network attempt. | |
| let hasLoggedAttempt = false; | |
| // Snapshot attempt context in case async rejection loses active context. | |
| const initialContext = context.active(); | |
| const emitL4DebugLog = (err: unknown) => { | |
| // Suppress duplicate emissions for the same attempt. | |
| if (hasLoggedAttempt) { | |
| return; | |
| } | |
| hasLoggedAttempt = true; |
| it('captures the attempt span context and logs on callback and stream failures', () => { | ||
| const stream = new EventEmitter(); | ||
| let receivedCallback: APICallback | undefined; | ||
|
|
||
| traceCall(dynamicArgs, staticArgs, () => | ||
| traceAttempt(dynamicArgs, staticArgs, () => | ||
| logNetworkAttempt( | ||
| dynamicArgs, | ||
| staticArgs, | ||
| loggedCallback => { | ||
| receivedCallback = loggedCallback; | ||
| return stream; | ||
| }, | ||
| true, | ||
| () => {}, | ||
| ), | ||
| ), | ||
| ); | ||
|
|
||
| const attemptErr = new GoogleError('attempt failed'); | ||
| receivedCallback!(attemptErr); | ||
| stream.emit('error', attemptErr); | ||
|
|
||
| const spans = harness.getSpans('google-gax'); | ||
| assert.strictEqual(spans.length, 2); | ||
| const attemptSpan = spans[0]; | ||
|
|
||
| assert.strictEqual(sink.logs.length, 2); | ||
| for (const logEntry of sink.logs) { | ||
| assert.strictEqual(logEntry.fields.severity, 'DEBUG'); | ||
| assert.strictEqual( | ||
| logEntry.fields.telemetryTraceId, | ||
| attemptSpan.spanContext().traceId, | ||
| ); | ||
| assert.strictEqual( | ||
| logEntry.fields.telemetrySpanId, | ||
| attemptSpan.spanContext().spanId, | ||
| ); | ||
| assert.deepStrictEqual(logEntry.args, [ | ||
| 'RPC attempt failed: %s', | ||
| 'attempt failed', | ||
| ]); | ||
| } | ||
| }); |
There was a problem hiding this comment.
With the introduction of the latch flag to prevent duplicate logging, we should split the combined callback and stream failure test into two separate, clean unit tests to verify each failure path independently.
it('captures the attempt span context and logs on callback failures', () => {
let receivedCallback: APICallback | undefined;
traceCall(dynamicArgs, staticArgs, () =>
traceAttempt(dynamicArgs, staticArgs, () =>
logNetworkAttempt(
dynamicArgs,
staticArgs,
loggedCallback => {
receivedCallback = loggedCallback;
return {ok: true};
},
false,
() => {},
),
),
);
const attemptErr = new GoogleError('attempt failed');
receivedCallback!(attemptErr);
const spans = harness.getSpans('google-gax');
assert.strictEqual(spans.length, 2);
const attemptSpan = spans[0];
assert.strictEqual(sink.logs.length, 1);
const logEntry = sink.logs[0];
assert.strictEqual(logEntry.fields.severity, 'DEBUG');
assert.strictEqual(
logEntry.fields.telemetryTraceId,
attemptSpan.spanContext().traceId,
);
assert.strictEqual(
logEntry.fields.telemetrySpanId,
attemptSpan.spanContext().spanId,
);
assert.deepStrictEqual(logEntry.args, [
'RPC attempt failed: %s',
'attempt failed',
]);
});
it('captures the attempt span context and logs on stream failures', () => {
const stream = new EventEmitter();
traceCall(dynamicArgs, staticArgs, () =>
traceAttempt(dynamicArgs, staticArgs, () =>
logNetworkAttempt(
dynamicArgs,
staticArgs,
() => stream,
true,
),
),
);
const attemptErr = new GoogleError('attempt failed');
stream.emit('error', attemptErr);
const spans = harness.getSpans('google-gax');
assert.strictEqual(spans.length, 2);
const attemptSpan = spans[0];
assert.strictEqual(sink.logs.length, 1);
const logEntry = sink.logs[0];
assert.strictEqual(logEntry.fields.severity, 'DEBUG');
assert.strictEqual(
logEntry.fields.telemetryTraceId,
attemptSpan.spanContext().traceId,
);
assert.strictEqual(
logEntry.fields.telemetrySpanId,
attemptSpan.spanContext().spanId,
);
assert.deepStrictEqual(logEntry.args, [
'RPC attempt failed: %s',
'attempt failed',
]);
});573c15b to
5197780
Compare
7bdfdf4 to
39becf7
Compare
quirogas
left a comment
There was a problem hiding this comment.
Reviewed #9757 against the Milestone 2 Error Logging design doc and live gRPC/REST (fallback: 'rest') error payloads. Approving to unblock merging once the 3 inline items below (and 1 minor nit) are addressed.
| const attributes = buildLogAttributes(err, attemptDynamicArgs, staticArgs); | ||
| const responsePayload = resolveResponsePayload( | ||
| (err as {metadata?: unknown} | null | undefined)?.metadata, | ||
| ); | ||
| if (responsePayload !== undefined) { | ||
| attributes['response.payload'] = responsePayload; | ||
| } |
There was a problem hiding this comment.
Passing (err as {metadata?: unknown} | null | undefined)?.metadata directly to resolveResponsePayload for response.payload (L4 Attributes table: "The full raw response payload (if any).") fails in three real-world cases:
- HTTP REST errors: On all HTTP
GoogleErrors (fallbackRest.ts/fallbackServiceStub.ts),err.metadataisundefined, soresponse.payloadis never populated on HTTP L4 logs. - Empty
grpc.Metadataon pre-connection failures:@grpc/grpc-jsattaches an emptynew grpc.Metadata()to everyServiceError(even when no response arrived, such asECONNREFUSED), whichMetadata#toJSON()serializes as"response.payload": "{}"instead of omittingresponse.payload. - Populated
grpc.Metadataarray values: Unlike the plain object{ 'x-goog-request-id': 'req-123' }mocked intest/unit/loggerHelper.ts, a realgrpc.Metadatainstance has a.toJSON()method that serializes header values as arrays ({"x-goog-request-id":["req-123"]}) unless.getMap()is unwrapped first.
Unwrap metadata.getMap(), ignore empty metadata maps, and fall back to err.statusDetails:
const rawMeta = (err as {metadata?: {getMap?: () => Record<string, unknown>}} | null)?.metadata;
const metaMap = typeof rawMeta?.getMap === 'function' ? rawMeta.getMap() : rawMeta;
const rawPayload = (metaMap && Object.keys(metaMap).length > 0 ? metaMap : undefined) ?? (err as {statusDetails?: unknown} | null)?.statusDetails;
const responsePayload = resolveResponsePayload(rawPayload);| function executeLoggedOperation<T>( | ||
| fn: (loggedCallback?: APICallback) => T, | ||
| onError: (err: unknown) => void, | ||
| isStreamCall: boolean, | ||
| userCallback?: APICallback, | ||
| ): T { | ||
| // Wrap user callback to log RPC errors before forwarding. | ||
| let callbackInvoked = false; | ||
| const loggedCallback: APICallback | undefined = userCallback | ||
| ? function (this: unknown, ...args: Parameters<APICallback>) { | ||
| callbackInvoked = true; | ||
| const err = args[0]; | ||
| if (err) { | ||
| onError(err); | ||
| } | ||
| userCallback.apply(this, args); | ||
| } | ||
| : undefined; | ||
|
|
||
| // Execute call and attach error handlers for streams, promises, or sync throws. | ||
| try { | ||
| const result = fn(loggedCallback); | ||
| const promiseTarget = !isStreamCall ? getPromiseTarget(result) : null; | ||
| if (isStreamCall && result instanceof EventEmitter) { | ||
| handleStream(result, onError, () => {}, Boolean(loggedCallback)); | ||
| } else if (promiseTarget) { | ||
| handlePromise(promiseTarget, onError, () => {}); | ||
| } | ||
| return result; | ||
| } catch (syncErr) { | ||
| // Avoid logging errors thrown inside userCallback after RPC completion. | ||
| if (!callbackInvoked) { | ||
| onError(syncErr); | ||
| } | ||
| throw syncErr; | ||
| } | ||
| } |
There was a problem hiding this comment.
Unlike logCall (which has let hasLoggedL3 = false), logNetworkAttempt has no one-time error latch. In fallbackServiceStub.ts, when an HTTP streaming attempt fails, the stub invokes both callback(err) and streamArrayParser.emit('error', err) for the same attempt. Without a latch, a single failed attempt emits 2 duplicate DEBUG logs (which test/unit/loggerHelper.ts currently asserts as assert.strictEqual(sink.logs.length, 2)), whereas the Milestone 2 Design Doc (## Testing item #5) requires logging the error at most once per attempt. Move the let hasLogged = false latch inside executeLoggedOperation so both logCall and logNetworkAttempt emit at most 1 log per invocation.
39becf7 to
0440ef0
Compare
de3af04 to
711ec8f
Compare
711ec8f to
6f98846
Compare
c654cf6 to
3599e52
Compare
3599e52 to
aa3f5e4
Compare
7bd5ba0 to
6600175
Compare
6600175 to
3889913
Compare
3889913 to
743a99d
Compare
c3e9982 to
616d88a
Compare
a217912 to
a33af5f
Compare
…uter span fallback in logNetworkAttempt
a33af5f to
c175381
Compare
🤖 I have created a release *beep* *boop* --- <details><summary>google-gax: 6.16.0</summary> ## [6.16.0](google-gax-v6.15.0...google-gax-v6.16.0) (2026-11-02) ### Features * **gax:** Add error logging for low level network attempts ([#9757](#9757)) ([1333570](1333570)) </details> <details><summary>google-auth-library: 11.3.3</summary> ## [11.3.3](google-auth-library-v11.3.2...google-auth-library-v11.3.3) (2026-11-02) ### Bug Fixes * **google-auth-library:** Strip -fips suffix from AWS service name in SigV4 signing ([#9779](#9779)) ([080f790](080f790)) </details> <details><summary>bigquery: 9.6.0</summary> ## [9.6.0](bigquery-v9.5.0...bigquery-v9.6.0) (2026-11-02) ### Features * **bigquery:** Enable picosecond support feature flag by default ([#9789](#9789)) ([7dfae1d](7dfae1d)) </details> --- This PR was generated with [Release Please](https://github.com/googleapis/release-please). See [documentation](https://github.com/googleapis/release-please#release-please). --------- Co-authored-by: release-please[bot] <55107282+release-please[bot]@users.noreply.github.com> Co-authored-by: feywind <57276408+feywind@users.noreply.github.com>
This pull request adds
logNetworkAttempttoLoggerHelperfor failed RPC attempts.Key Changes:
logNetworkAttemptinLoggerHelper.tsto emit a structuredDEBUGlog entry ('RPC attempt failed: %s') whenever an individual RPC transport attempt fails across promise, callback, stream, or synchronous execution boundaries.response.payloadon attempt debug logs usingresolveResponsePayload(err?.metadata)when metadata is present, while omittingexception.type,exception.message, andexception.stacktrace.executeLoggedOperationandresolveLogSeverityinLoggerHelper.tsto share promise, callback, stream, and synchronous error interception betweenlogCallandlogNetworkAttempt.