SSL connection failure(status:12, empty err message returned)

[solomon lifshits]

Unable to connect to grpc server using SSL credentials, while connection without works ok.

Status 12(unimplemented) is returned.

Client connection code:

  std::string grpc_host(/*m_sIP*/m_sDestination + ":" + std::to_string(Config::config().grpc_port));

  std::string grpc_ip(m_sIP + ":" + std::to_string(Config::config().grpc_port));

             grpc::ChannelArguments channelArgs;

      grpc::SslCredentialsOptions sslOpts;

      utils::getFileContent(Config::config().ssl.chain_cert_file_path, sslOpts.pem_root_certs);      

      utils::getFileContent(Config::config().ssl.key_file_path, sslOpts.pem_private_key);      

      utils::getFileContent(Config::config().ssl.cert_file_path, sslOpts.pem_cert_chain);

      

m_pStub = ClientServer::NewStub(grpc::CreateCustomChannel(grpc_ip, grpc::SslCredentials(sslOpts), channelArgs));

m_pStub->AsyncStartLogRetrieval(&calldata->context, lctx->header(), m_Poller.cq());

Server connection code:

    grpc::SslServerCredentialsOptions sslOpts(GRPC_SSL_DONT_REQUEST_CLIENT_CERTIFICATE);

    std::string certificate;

            std::string chaincert;

            std::string key;

            std::string rootca;

            utils::getFileContent(config.Certificate(),certificate)

            utils::getFileContent(config.ChainCert(), chaincert);

            utils::getFileContent(config.PrivateKey(), key);

            utils::getFileContent(config.RootCA(), rootca);

                

                LOGINFO("successfully load TLS secrets");

                grpc::SslServerCredentialsOptions::PemKeyCertPair kcp = { key, certificate };

                sslOpts.pem_root_certs = rootca;

                sslOpts.pem_key_cert_pairs.push_back ( kcp );

            std::shared_ptr<grpc::ServerCredentials> serverCred;

    if (m_conf->EnableTLS() == true)

    {

        serverCred = grpc::SslServerCredentials(sslOpts);

    }

    else

    {

        serverCred = grpc::InsecureServerCredentials();

    }

    builder.AddListeningPort(m_serveraddress, serverCred);

    builder.AddListeningPort(m_serveraddress_ss, serverCred);

    builder.RegisterService(m_serveraddress, &m_service);

    builder.RegisterService(m_serveraddress_ss, &m_service_ss);

    m_Cq = builder.AddCompletionQueue();

    m_server = builder.BuildAndStart();

    m_server->GrpcService().RequestStartLogRetrieval(&m_ctx,

                                                     &m_logHeader,

                                                     &m_responder,

                                                     m_Cq.get(),

                                                     m_Cq.get(),

                                                     this);

grpc log server side

1536861059.980 I bzs.cc:141: main():successfully load TLS secrets

1536861059.980 I bzs.cc:142: main():TEST ONLY: cert = 1736 key= 1708

rootca= 2701

D0913 17:50:59.981257225   10521 ev_posix.cc:142]            Using

polling engine: epollex

D0913 17:50:59.981354852   10521 dns_resolver.cc:331]        Using

native dns resolver

I0913 17:50:59.981398500   10521 init.cc:155]                grpc_init(void)

I0913 17:50:59.981423808   10521 completion_queue.cc:433]   

grpc_completion_queue_create_internal(completion_type=0, polling_type=0)

I0913 17:50:59.981442286   10521 init.cc:155]                grpc_init(void)

I0913 17:50:59.981473600   10521 server.cc:944]             

grpc_server_create(0xffe70c24, (nil))

I0913 17:50:59.981486846   10521 server.cc:930]             

grpc_server_register_completion_queue(server=0x89ebbc8, cq=0x89eb998,

reserved=(nil))

I0913 17:50:59.981499676   10521 server.cc:978]             

grpc_server_register_method(server=0x89ebbc8,

method=/banzai.ClientServer/StartLogRetrieval, host=198.18.87.44:50051,

flags=0x00000000)

I0913 17:50:59.981511620   10521 server.cc:978]             

grpc_server_register_method(server=0x89ebbc8,

method=/banzai.ClientServer/SendBlock, host=198.18.87.44:50051,

flags=0x00000000)

I0913 17:50:59.981529888   10521 server.cc:978]             

grpc_server_register_method(server=0x89ebbc8,

method=/banzai.ServerServer/GetChunks, host=198.18.87.44:50052,

flags=0x00000000)

I0913 17:50:59.981542015   10521 server.cc:978]             

grpc_server_register_method(server=0x89ebbc8,

method=/banzai.ServerServer/GetChunkMetadata, host=198.18.87.44:50052,

flags=0x00000000)

I0913 17:50:59.981561414   10521 server_secure_chttp2.cc:50]

grpc_server_add_secure_http2_port(server=0x89ebbc8,

addr=198.18.87.44:50051, creds=0x89e95e0)

I0913 17:50:59.983945963   10521 server_secure_chttp2.cc:50]

grpc_server_add_secure_http2_port(server=0x89ebbc8,

addr=198.18.87.44:50052, creds=0x89e95e0)

I0913 17:50:59.985015540   10521 server.cc:1024]            

grpc_server_start(server=0x89ebbc8)

I0913 17:50:59.985044734   10521 call_details.cc:31]        

grpc_call_details_init(cd=0x8a118f0)

I0913 17:50:59.985057268   10521 server.cc:1336]            

grpc_server_request_call(server=0x89ebbc8, call=0x8a118ec,

details=0x8a118f0, initial_metadata=0x8a11958,

cq_bound_to_call=0x89eb998, cq_for_notification=0x89eb998, tag=0x8a118d0)

1536861059.985 I server.cc:60: Run():Server listening on: 198.18.87.44:50051

I0913 17:50:59.985269613   10535 server.cc:1385]            

grpc_server_request_registered_call(server=0x89ebbc8, rmp=0x89eedb8,

call=0xf38006dc, deadline=0xf3800484, initial_metadata=0xf38004a8,

optional_payload=0xf3800700, cq_bound_to_call=0x89eb998,

cq_for_notification=0x89eb998, tag=0xf38006c0)

1536861059I0913 17:50:59.985299807   10534 server.cc:1385]            

grpc_server_request_registered_call(server=0x89ebbc8, rmp=0x89ebe68,

call=0xf3a00684, deadline=0xf3a00484, initial_metadata=0xf3a004a8,

optional_payload=0xf3a006a8, cq_bound_to_call=0x89eb998,

cq_for_notification=0x89eb998, tag=0xf3a00668)

I0913 17:50:59.985328278   10534 completion_queue.cc:853]   

grpc_completion_queue_next(cq=0x89eb998, deadline=gpr_timespec { tv_sec:

9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))

.985 I server.cc:85: HandleBzcRpcs():handle rpc call from client

I0913 17:50:59.985385393   10535 completion_queue.cc:853]   

grpc_completion_queue_next(cq=0x89eb998, deadline=gpr_timespec { tv_sec:

9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))

I0913 17:52:29.390936255   10534 security_context.cc:295]   

grpc_auth_context_add_cstring_property(ctx=0xf3a00748,

name=transport_security_type, value=ssl)

I0913 17:52:29.390979766   10534 security_context.cc:279]   

grpc_auth_context_add_property(ctx=0xf3a00748, name=ssl_session_reused,

value= false, value_length=6)

I0913 17:52:29.391512134   10534 call.cc:1552]               ops[0]:

RECV_INITIAL_METADATA ptr=0xf3a17d54

I0913 17:52:29.391560744   10534 completion_queue.cc:632]   

cq_end_op_for_next(cq=0x89eb998, tag=0x8a118d0, error="No Error",

done=0x837f8d0, done_arg=0x8a11d98, storage=0x8a11db4)

I0913 17:52:29.391580272   10534 completion_queue.cc:953]   

RETURN_EVENT[0x89eb998]: OP_COMPLETE: tag:0x8a118d0 OK

I0913 17:52:29.391595925   10534 call.cc:1926]              

grpc_call_start_batch(call=0xf3a177a0, ops=0xf4bfec7c, nops=1,

tag=0xf3a16c50, reserved=(nil))

I0913 17:52:29.391607536   10534 call.cc:1552]               ops[0]:

RECV_CLOSE_ON_SERVER cancelled=0xf3a16c7c

I0913 17:52:29.391621173   10534 call_details.cc:31]        

grpc_call_details_init(cd=0xf3a0b510)

I0913 17:52:29.391634021   10534 server.cc:1336]            

grpc_server_request_call(server=0x89ebbc8, call=0xf3a0b50c,

details=0xf3a0b510, initial_metadata=0xf3a0b578,

cq_bound_to_call=0x89eb998, cq_for_notification=0x89eb998, tag=0xf3a0b4f0)

I0913 17:52:29.391651465   10534 call.cc:1926]              

grpc_call_start_batch(call=0xf3a177a0, ops=0xf4bfebdc, nops=2,

tag=0xf3a16c88, reserved=(nil))

I0913 17:52:29.391662933   10534 call.cc:1552]               ops[0]:

SEND_INITIAL_METADATA(nil)

I0913 17:52:29.391674168   10534 call.cc:1552]               ops[1]:

SEND_STATUS_FROM_SERVER status=12 details=(null)(nil)

I0913 17:52:29.391698494   10534 completion_queue.cc:632]   

cq_end_op_for_next(cq=0x89eb998, tag=0xf3a16c50, error="No Error",

done=0x8378fd0, done_arg=0xf3a18990, storage=0xf3a18994)

I0913 17:52:29.391729534   10534 completion_queue.cc:632]   

cq_end_op_for_next(cq=0x89eb998, tag=0xf3a16c88, error="No Error",

done=0x8378fd0, done_arg=0xf3a18a10, storage=0xf3a18a14)

I0913 17:52:29.391743776   10534 completion_queue.cc:853]   

grpc_completion_queue_next(cq=0x89eb998, deadline=gpr_timespec { tv_sec:

9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))

I0913 17:52:29.391763139   10534 completion_queue.cc:953]   

RETURN_EVENT[0x89eb998]: OP_COMPLETE: tag:0xf3a16c88 OK

I0913 17:52:29.391774396   10534 call.cc:568]               

grpc_call_unref(c=0xf3a177a0)

I0913 17:52:29.391748870   10535 completion_queue.cc:953]   

RETURN_EVENT[0x89eb998]: OP_COMPLETE: tag:0xf3a16c50 OK

I0913 17:52:29.391785787   10534 metadata_array.cc:34]      

grpc_metadata_array_destroy(array=0xf3a17d54)

I0913 17:52:29.391853468   10534 metadata_array.cc:34]      

grpc_metadata_array_destroy(array=0x8a11958)

I0913 17:52:29.391833145   10535 completion_queue.cc:853]   

grpc_completion_queue_next(cq=0x89eb998, deadline=gpr_timespec { tv_sec:

9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))

I0913 17:52:29.391878503   10534 completion_queue.cc:853]   

grpc_completion_queue_next(cq=0x89eb998, deadline=gpr_timespec { tv_sec:

9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))

Any thoughts on potential cause?

   

[Carl Mastrangelo]

Is there an error message provided with Unimplemented?  Usually that error code is for calling a method that the server doesn't know about.  

[solomon lifshits]

Thank you for reply!

No, the error message is empty. I patched the grpc code and put unique error messages in all the places where UNIMPLEMENTED status was returned. What I figured out is that it was a completion tag of type 
UnimplementedAsyncRequest  that is placed on server cq(
src/cpp/server/server_cc.cc:line 557) on startup and is apparently not supposed to be picked up by Next method unless something goes wrong(this is my understanding of grpc code). When 'FinalizeResults' for this tag is called it allocates a tag of type 

UnimplementedAsyncResponse which in turn calls UnknownMethodHandler::FillOps that issues the abovementioned status

(include/grpcpp/impl/codegen/method_handler_impl.h) :

class UnknownMethodHandler : public MethodHandler {

 public:

  template <class T>

  static void FillOps(ServerContext* context, T* ops) {

    Status status(StatusCode::UNIMPLEMENTED, "");

    if (!context->sent_initial_metadata_) {

      ops->SendInitialMetadata(context->initial_metadata_,

                               context->initial_metadata_flags());

      if (context->compression_level_set()) {

        ops->set_compression_level(context->compression_level());

      }

      context->sent_initial_metadata_ = true;

    }

    ops->ServerSendStatus(context->trailing_metadata_, status);

  }.

[Yang Gao]

is your client and server using the same proto? Can you collect the client side trace as well? From the server log it does not seem like using ssl is related.

[solomon lifshits]

The problem is solved. The issue was because of overloaded target name mismatch with the rpc method authority. Thanks!