Skip to content

fix(client): log push-mode request deserializer failures#672

Closed
untitaker wants to merge 1 commit into
mainfrom
fix-grpc-deserializer-logging
Closed

fix(client): log push-mode request deserializer failures#672
untitaker wants to merge 1 commit into
mainfrom
fix-grpc-deserializer-logging

Conversation

@untitaker
Copy link
Copy Markdown
Member

@untitaker untitaker commented Jun 3, 2026

Summary

In push mode the Python worker runs a gRPC server (PushTaskWorkerWorkerServicer). When a PushTask request body fails to deserialize — proto schema mismatch between broker and worker, or a corrupted payload — the underlying exception is silently swallowed and the broker only sees an opaque INTERNAL status. Nothing lands on our own logger and no metric is emitted, so the failure is effectively invisible in worker logs.

This PR logs the exception on the taskbroker_client.worker.client logger before re-raising.

Where the exception is swallowed

The request deserializer (our RequestSignatureServerInterceptor wraps it) is invoked by gRPC, and gRPC catches any exception it raises. Links below are pinned to the grpcio==1.75.1 tag (the version this repo locks).

  1. The swallowgrpc/_common.py _transform(), lines 88–92:

    try:
        return transformer(message)        # <- our deserializer
    except Exception:                      # pylint: disable=broad-except
        _LOGGER.exception(exception_message)   # logged on the `grpc._common` logger only
        return None                            # exception turned into None

    deserialize() calls this with exception_message="Exception deserializing message!".

  2. The opaque statusgrpc/_server.py _receive_message(), lines 333–343:

    request = _common.deserialize(serialized_request, request_deserializer)
    ...
    if request is None:
        _abort(state, call, cygrpc.StatusCode.internal,
               b"Exception deserializing request!")

So the real traceback exists only on the grpc._common logger at ERROR. Unless the worker explicitly routes gRPC's internal loggers to a handler, it is lost — and the broker just gets INTERNAL "Exception deserializing request!" with no detail about why.

Fix

Wrap the deserializer body in the interceptor and log on our own logger before re-raising (gRPC still produces the INTERNAL status for the caller, but now there's a visible, attributable record on the worker side):

try:
    return inner_deserializer(serialized_request)
except Exception:
    logger.exception(
        "taskworker.grpc_server.request_deserialization_failed",
        extra={"method": method},
    )
    raise

Test

test_request_signature_server_interceptor_logs_deserialization_errors stands up a real grpc.server with the interceptor, sends a correctly-signed but unparseable body, and asserts:

  • the caller receives StatusCode.INTERNAL
  • the servicer never runs
  • a taskworker.grpc_server.request_deserialization_failed record is emitted on our logger

Verified the test fails without the fix (no such log record) and passes with it. A real server is required because the deserializer runs on gRPC's event-polling thread, not the servicer thread — a mocked channel cannot exercise this path.

🤖 Generated with Claude Code

In push mode the worker runs a gRPC server. When a `PushTask` request body
fails to deserialize (e.g. proto mismatch or corruption), gRPC swallows the
exception in `grpc._common._transform` — it logs only to the `grpc._common`
logger and returns `None` — and the server then aborts the call with an opaque
`INTERNAL "Exception deserializing request!"`. Unless the worker happens to
route gRPC's internal loggers somewhere, the actual exception is invisible: no
record on our own `taskbroker_client` logger, no metric, just an `INTERNAL` on
the broker side.

Wrap the deserializer body in the signature interceptor so the exception is
logged on the `taskbroker_client.worker.client` logger before it is re-raised
and swallowed by gRPC.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
@untitaker
Copy link
Copy Markdown
Member Author

bogus actually. i'll just check the grpc logger setup in sentry.

@untitaker untitaker closed this Jun 3, 2026
untitaker added a commit to getsentry/sentry that referenced this pull request Jun 3, 2026
…6806)

sentry's `LOGGING` uses `disable_existing_loggers: True` and has no
`grpc` logger entry, so grpc's own logging is dropped or
nondeterministically routed depending on import order. grpc catches a
lot of exceptions internally (e.g. request deserialization failures in
the push-mode taskworker) and logs them on the `grpc._common` logger, so
we want those to be reliably visible.

Configure `grpc` explicitly — `ERROR`, `console`, `propagate: False` —
matching how other third-party loggers (`arroyo`, `taskbroker_client`,
`urllib3`) are handled.

Context: getsentry/taskbroker#672 (closed) — originally attempted to log
these in the client before realizing the fix belongs here.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 4.8 <noreply@anthropic.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.

1 participant