GPR_ASSERT fails deep in gRPC 1.59 code after adding a trivial new gRPC service

[Vadim G.]

Hi,

I ran into a situation where gRPC (1.59, C++) started aborting due to a failed  gRPC assertion deep within gRPC code, and I am not sure how to begin debugging this.

I can't find anything relevant in the gRPC documentation.

Any suggestions would be very welcome!

My starting point is a program that has a grpc::Server with a single gRPC service, which, AFAIK, functions correctly. 

My change is simple: I've registered an additional gRPC service (a trivial one-method service) with the same ServerBuilder.

Here's the issue: when I try to exercise the new service using a simple test client, the server aborts due to a failing assertion, well before getting to my service implementation.

Here's the failing assertion:

   GPR_ASSERT(server()->ValidateServerRequest(

                     cq(), call_info.tag, call_info.optional_payload,
                     registered_method_) == GRPC_CALL_OK);

It appears that the call to ValidateServerRequest is returning GRPC_CALL_ERROR_PAYLOAD_TYPE_MISMATCH instead of GRPC_CALL_OK.

Here's how ValidateServerRequest is defined; I added a comment, in green,

that shows the relevant parameter values:

grpc_call_error Server::ValidateServerRequest(

    grpc_completion_queue* cq_for_notification, void* tag,
    grpc_byte_buffer** optional_payload, RegisteredMethod* rm) {
  if ((rm == nullptr && optional_payload != nullptr) ||
      ((rm != nullptr) && ((optional_payload == nullptr) !=
                           (rm->payload_handling == GRPC_SRM_PAYLOAD_NONE)))) {

    // We get here because:

    // * `optional_payload` is nullptr

    // * `rm`, as shown by gdb, is:

    //       {method = "/foo.proto.BatchAdmissionControl/AcquireResource", 

    //               host = "",
    //                payload_handling = GRPC_SRM_PAYLOAD_READ_INITIAL_BYTE_BUFFER, 

    //                flags = 0,
    //                matcher = std::unique_ptr<grpc_core::Server::RequestMatcherInterface> = {get() = 0x7fa44d857640}}
    return GRPC_CALL_ERROR_PAYLOAD_TYPE_MISMATCH;
  }
  if (!grpc_cq_begin_op(cq_for_notification, tag)) {
    return GRPC_CALL_ERROR_COMPLETION_QUEUE_SHUTDOWN;
  }
  return GRPC_CALL_OK;
}

Below I've pasted the stack trace and the snippet with the assertion, in case they're useful.  Any suggestions re: what to look for are welcome. I'm really unclear how anything I've done could lead to this situation...

(gdb) where
#0  0x00007fa69232000b in raise () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007fa6922ff859 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x0000560c51e19cf5 in grpc_core::Crash (message=..., location=...) at /workspace/grpc/grpc.source/src/core/lib/gprpp/crash.cc:33
#3  0x0000560c525887be in gpr_assertion_failed (filename=filename@entry=0x560c528bae98 "/workspace/grpc/grpc.source/src/core/lib/surface/server.cc", line=line@entry=556, message=message@entry=0x560c528bb630 "server()->ValidateServerRequest( cq(), call_info.tag, call_info.optional_payload, registered_method_) == GRPC_CALL_OK") at /workspace/common/include/absl/strings/string_view.h:597
#4  0x0000560c522cedb8 in grpc_core::Server::AllocatingRequestMatcherRegistered::MatchOrQueue (this=0x7fa691e57460, calld=0x7fa686863120) at /workspace/grpc/grpc.source/src/core/lib/surface/server.cc:556
#5  0x0000560c520f6f1c in grpc_core::Closure::Run (location=..., closure=0x7fa686863310, error=...) at /workspace/common/include/absl/status/status.h:871
#6  0x0000560c52293035 in grpc_core::FilterStackCall::BatchControl::PostCompletion (this=0x7fa6868851a0) at /workspace/grpc/grpc.source/src/core/lib/gprpp/debug_location.h:61
#7  0x0000560c52293750 in grpc_core::FilterStackCall::BatchControl::FinishStep (this=0x7fa6868851a0, op=<optimized out>) at /workspace/grpc/grpc.source/src/core/lib/surface/call.cc:1365
#8  0x0000560c522939fa in grpc_core::FilterStackCall::BatchControl::ReceivingStreamReady (this=0x7fa6868851a0, error=...) at /workspace/grpc/grpc.source/src/core/lib/surface/call.cc:1417
#9  0x0000560c52293ca8 in grpc_core::FilterStackCall::<lambda(void*, grpc_error_handle)>::operator() (__closure=0x0, error=..., bctlp=0x7fa6868851a0) at /workspace/common/include/absl/status/status.h:871
#10 grpc_core::FilterStackCall::<lambda(void*, grpc_error_handle)>::_FUN(void *, grpc_error_handle) () at /workspace/grpc/grpc.source/src/core/lib/surface/call.cc:1778
#11 0x0000560c521dd53b in exec_ctx_run (closure=0x7fa686862e88) at /workspace/common/include/absl/status/status.h:853
#12 grpc_core::ExecCtx::Flush (this=0x7fa6875fb260) at /workspace/grpc/grpc.source/src/core/lib/iomgr/exec_ctx.cc:84
#13 0x0000560c524d28cb in end_worker (pollset=pollset@entry=0x7fa691e410c8, worker=worker@entry=0x7fa6875fb0e0, worker_hdl=worker_hdl@entry=0x0) at /workspace/grpc/grpc.source/src/core/lib/iomgr/exec_ctx.h:237
#14 0x0000560c524d3284 in pollset_work (ps=0x7fa691e410c8, worker_hdl=<optimized out>, deadline=...) at /workspace/grpc/grpc.source/src/core/lib/iomgr/ev_epoll1_linux.cc:1048
#15 0x0000560c521dc616 in pollset_work (pollset=0x7fa691e410c8, worker=0x0, deadline=...) at /workspace/grpc/grpc.source/src/core/lib/iomgr/ev_posix.cc:248
#16 0x0000560c521e017a in grpc_pollset_work (pollset=<optimized out>, worker=<optimized out>, deadline=...) at /workspace/grpc/grpc.source/src/core/lib/iomgr/pollset.cc:48
#17 0x0000560c522bd1c6 in cq_next (cq=0x7fa691e40f00, deadline=..., reserved=<optimized out>) at /workspace/grpc/grpc.source/src/core/lib/surface/completion_queue.cc:1050
#18 0x0000560c520c6021 in grpc::CompletionQueue::AsyncNextInternal (this=0x7fa691e572d0, tag=tag@entry=0x7fa6875fb380, ok=ok@entry=0x7fa6875fb37f, deadline=...) at /workspace/grpc/grpc.source/src/cpp/common/completion_queue_cc.cc:146
#19 0x0000560c520b74d2 in grpc::CompletionQueue::AsyncNext<gpr_timespec> (deadline=<synthetic pointer>..., ok=0x7fa6875fb37f, tag=0x7fa6875fb380, this=<optimized out>) at /workspace/grpc/grpc.source/include/grpcpp/support/time.h:55
#20 grpc::Server::SyncRequestThreadManager::PollForWork (this=0x7fa691e36000, tag=0x7fa6875fb380, ok=0x7fa6875fb37f) at /workspace/grpc/grpc.source/src/cpp/server/server_cc.cc:808
#21 0x0000560c520c4701 in grpc::ThreadManager::MainWorkLoop (this=0x7fa691e36000) at /workspace/grpc/grpc.source/src/cpp/thread_manager/thread_manager.cc:155
#22 0x0000560c520c4900 in grpc::ThreadManager::WorkerThread::Run (this=0x7fa691e26320) at /workspace/grpc/grpc.source/src/cpp/thread_manager/thread_manager.cc:49
#23 0x0000560c5258bd85 in grpc_core::(anonymous namespace)::ThreadInternalsPosix::<lambda(void*)>::operator() (__closure=0x0, v=<optimized out>) at /workspace/grpc/grpc.source/src/core/lib/gprpp/posix/thd.cc:145
#24 grpc_core::(anonymous namespace)::ThreadInternalsPosix::<lambda(void*)>::_FUN(void *) () at /workspace/grpc/grpc.source/src/core/lib/gprpp/posix/thd.cc:150
#25 0x00007fa692c7d609 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#26 0x00007fa6923fc313 in clone () from /lib/x86_64-linux-gnu/libc.so.6

Relevant code snippet (from frame #4, server.cc:

--snip--

// An allocating request matcher for registered methods.
class Server::AllocatingRequestMatcherRegistered
    : public AllocatingRequestMatcherBase {
 public:
  AllocatingRequestMatcherRegistered(
      Server* server, grpc_completion_queue* cq, RegisteredMethod* rm,
      std::function<RegisteredCallAllocation()> allocator)
      : AllocatingRequestMatcherBase(server, cq),
        registered_method_(rm),
        allocator_(std::move(allocator)) {}

  void MatchOrQueue(size_t /*start_request_queue_index*/,
                    CallData* calld) override {
    auto cleanup_ref =
        absl::MakeCleanup([this] { server()->ShutdownUnrefOnRequest(); });
    if (server()->ShutdownRefOnRequest()) {
      RegisteredCallAllocation call_info = allocator_();
      GPR_ASSERT(server()->ValidateServerRequest(
                     cq(), call_info.tag, call_info.optional_payload,
                     registered_method_) == GRPC_CALL_OK);
      RequestedCall* rc =
          new RequestedCall(call_info.tag, call_info.cq, call_info.call,
                            call_info.initial_metadata, registered_method_,
                            call_info.deadline, call_info.optional_payload);
      calld->SetState(CallData::CallState::ACTIVATED);
      calld->Publish(cq_idx(), rc);
    } else {

...

--snip--