Skip to content

feat(gax): add error logging for low level network attempts - #9757

Merged
shivanee-p merged 5 commits into
mainfrom
shivaneep-o11y-logattempt
Nov 2, 2026
Merged

shivanee-p merged 5 commits into
mainfrom
shivaneep-o11y-logattempt

Conversation

@shivanee-p

@shivanee-p shivanee-p commented Oct 28, 2026 •

Copy link
Copy Markdown
Contributor

This pull request adds logNetworkAttempt to LoggerHelper for failed RPC attempts.

Key Changes:

  • Added logNetworkAttempt in LoggerHelper.ts to emit a structured DEBUG log entry ('RPC attempt failed: %s') whenever an individual RPC transport attempt fails across promise, callback, stream, or synchronous execution boundaries.
  • Populated response.payload on attempt debug logs using resolveResponsePayload(err?.metadata) when metadata is present, while omitting exception.type, exception.message, and exception.stacktrace.
  • Extracted executeLoggedOperation and resolveLogSeverity in LoggerHelper.ts to share promise, callback, stream, and synchronous error interception between logCall and logNetworkAttempt.

@shivanee-p
shivanee-p added this pull request to stack #9746 October 28, 2026 00:18

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment on lines +275 to +278
// Snapshot attempt context in case async rejection loses active context.
const initialContext = context.active();

const emitL4DebugLog = (err: unknown) => {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

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.

Suggested change
// 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;

Comment on lines +560 to +603
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',
]);
}
});

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

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',
      ]);
    });

@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch from 573c15b to 5197780 Compare October 28, 2026 00:25
@shivanee-p
shivanee-p marked this pull request as ready for review October 28, 2026 00:29
@shivanee-p
shivanee-p requested a review from a team as a code owner October 28, 2026 00:29
@github-actions
github-actions Bot requested a review from feywind October 28, 2026 00:30
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch 2 times, most recently from 7bdfdf4 to 39becf7 Compare October 28, 2026 16:03

@quirogas quirogas left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment on lines 291 to 297
const attributes = buildLogAttributes(err, attemptDynamicArgs, staticArgs);
const responsePayload = resolveResponsePayload(
(err as {metadata?: unknown} | null | undefined)?.metadata,
);
if (responsePayload !== undefined) {
attributes['response.payload'] = responsePayload;
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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:

  1. HTTP REST errors: On all HTTP GoogleErrors (fallbackRest.ts / fallbackServiceStub.ts), err.metadata is undefined, so response.payload is never populated on HTTP L4 logs.
  2. Empty grpc.Metadata on pre-connection failures: @grpc/grpc-js attaches an empty new grpc.Metadata() to every ServiceError (even when no response arrived, such as ECONNREFUSED), which Metadata#toJSON() serializes as "response.payload": "{}" instead of omitting response.payload.
  3. Populated grpc.Metadata array values: Unlike the plain object { 'x-goog-request-id': 'req-123' } mocked in test/unit/loggerHelper.ts, a real grpc.Metadata instance 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);

Comment on lines +149 to +185
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;
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch from 39becf7 to 0440ef0 Compare October 29, 2026 16:56
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch 2 times, most recently from de3af04 to 711ec8f Compare October 29, 2026 18:12
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch from 711ec8f to 6f98846 Compare October 29, 2026 18:15
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch 3 times, most recently from c654cf6 to 3599e52 Compare October 29, 2026 19:58
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch from 3599e52 to aa3f5e4 Compare October 29, 2026 20:11
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch 2 times, most recently from 7bd5ba0 to 6600175 Compare October 30, 2026 02:09
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch from 6600175 to 3889913 Compare October 30, 2026 02:12
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch from 3889913 to 743a99d Compare October 30, 2026 02:52
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch 2 times, most recently from c3e9982 to 616d88a Compare October 30, 2026 04:21
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch 2 times, most recently from a217912 to a33af5f Compare October 30, 2026 23:35
Base automatically changed from shivaneep-o11y-logCall to main November 2, 2026 16:03
@shivanee-p
shivanee-p force-pushed the shivaneep-o11y-logattempt branch from a33af5f to c175381 Compare November 2, 2026 16:03
@shivanee-p
shivanee-p merged commit 1333570 into main Nov 2, 2026
51 checks passed
@shivanee-p
shivanee-p deleted the shivaneep-o11y-logattempt branch November 2, 2026 16:30
@release-please release-please Bot mentioned this pull request Nov 2, 2026
feywind added a commit that referenced this pull request Nov 2, 2026
🤖 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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants