Can't connect to gRPC server running inside docker. What am I doing wrong? "Failed to dial target host ... tls: first record does not look like a TLS handshake"
2,028 views
Skip to first unread message
rick...@improbable.io
Nov 15, 2019, 11:14:56 AM11/15/19
to grpc.io
Hi all, thanks in advance and I hope this is the right forum to ask this question.
I've
got a simple gRPC c++ server application that works fine locally (on
macOS). I can build and run the app and query it successfully with
BloomRPC. When I run the same app within Docker (with the port open, of
course) it receives the request, but the response never makes it back to
the client. I'm giving some code snippets, and at the end I'll post the
gRPC debug output.
The app establishes a server via this code:
//... snip
std::string serverAddress = "0.0.0.0:50051"; grpc::ServerBuilder builder;
builder.AddListeningPort(serverAddress, grpc::InsecureServerCredentials());
builder.RegisterService(&service);
std::unique_ptr<grpc::Server> server(builder.BuildAndStart());
std::cout << "Server startup successful, listening on " << serverAddress << std::endl;
server->Wait();
exit(0);
I
am building and linking the static libraries of gRPC and protobuf.
Relevant dockerfile snippet that shows my build environment:
WORKDIR /repos
RUN git clone -b v1.24.3 https://github.com/grpc/grpc
WORKDIR /repos/grpcRUN git submodule update --initWORKDIR /repos/grpc/third_party/protobufRUN ./autogen.sh && ./configure --enable-staticRUN make -j4 && make install && ldconfigWORKDIR /repos/grpcRUN make -j4 && make install && ldconfig... and the relevant cmake linking:
target_link_libraries(my_app
gRPC::grpc++
protobuf::libprotobuf)
... and finally, the relevant dockerfile for the container where I'm running my server:
As I mentioned earlier, the gRPC server is reacting to the query and doing... something. Logs are below.
Things I've tried:
- Changing OS in the docker container (so far I've tried Ubuntu and Debian)
- Running my app in a known good container (tobegit3hub/grpc-helloworld) (the helloworld app works, mine does not)
- Changing gRPC versions (I've tried 1.24.3 and 1.25.0)
- Building and linking protobuf separately (tried protobuf versions 3.8.0 and 3.9.1)
- Manually linking JUST the _unsecure grpc libraries (this always results in missing symbols, even if I link both libgrpc_unsecure and libgrpc++_unsecure - it won't ever work until I also link in libgrpc)
- Endless variations of opening the ports in Docker. "docker run -p 50051:50051 my_app", docker-compose "ports" configuration...
- Docker host networking (this results on no log messages from gRPC whatsoever, as if when using host networking the client can't reach the server)
- Using grpcurl instead of BloomRPC. Interestingly, this gives an error: "Failed to dial target host "0.0.0.0:50051": tls: first record does not look like a TLS handshake"
Below are the gRPC verbose logs:
journal-service_1
| I1115 15:52:45.888260872 10 completion_queue.cc:960]
grpc_completion_queue_next(cq=0x237aaa0, deadline=gpr_timespec {
tv_sec: 7601, tv_nsec: 444925114, clock_type: 0 }, reserved=(nil))
journal-service_1 | I1115 15:52:47.684328068 9 completion_queue.cc:960] grpc_completion_queue_next(cq=0x237aaa0, deadline=gpr_timespec { tv_sec: 7603, tv_nsec: 240983924, clock_type: 0 }, reserved=(nil))
journal-service_1 | I1115 15:52:48.886953532 10 tcp_server_posix.cc:242] SERVER_CONNECT: incoming connection: ipv4:172.18.0.1:55780
journal-service_1 | D1115 15:52:48.887007693 10 tcp_posix.cc:1253] cannot set inq fd=8 errno=92
journal-service_1 | I1115 15:52:48.887062609 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
journal-service_1 | I1115 15:52:48.887070206 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> WRITING+MORE [INITIAL_WRITE]
journal-service_1 | I1115 15:52:48.887074250 10 init.cc:164] grpc_init(void)
journal-service_1 | I1115 15:52:48.887093265 10 chttp2_transport.cc:1900] perform_transport_op[t=0x7f5440001f50]: ON_CONNECTIVITY_STATE_CHANGE:p=0x7f5440003cf0:from=IDLE SET_ACCEPT_STREAM:0x7feb10(0x7f5440003c88,...)
journal-service_1 | I1115 15:52:48.887100719 10 chttp2_transport.cc:1900] perform_transport_op[t=0x7f5440001f50]: ON_CONNECTIVITY_STATE_CHANGE:p=0x7f5440003cf0:from=READY
journal-service_1 | I1115 15:52:48.887104135 10 tcp_posix.cc:265] TCP:0x7f54400018d0 notify_on_read
journal-service_1 | I1115 15:52:48.887109550 10 writing.cc:116] SERVER: Ping sent [ipv4:172.18.0.1:55780]: 2/2
journal-service_1 | I1115 15:52:48.887113039 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING+MORE -> WRITING [begin write in current thread]
journal-service_1 | I1115 15:52:48.887123552 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887157759 10 tcp_posix.cc:1062] DATA: 00 00 18 04 00 00 00 00 00 00 04 00 40 00 00 00 05 00 40 00 00 00 06 00 00 20 00 fe 03 00 00 00 01 '............@.....@...... .......'
journal-service_1 | I1115 15:52:48.887162534 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887165687 10 tcp_posix.cc:1062] DATA: 00 00 04 08 00 00 00 00 00 00 3f 00 01 00 00 08 06 00 00 00 00 00 00 '..........?............'
journal-service_1 | I1115 15:52:48.887168113 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887170653 10 tcp_posix.cc:1062] DATA: 00 00 00 00 00 00 00 '.......'
journal-service_1 | I1115 15:52:48.887276538 10 tcp_posix.cc:1096] write: "No Error"
journal-service_1 | I1115 15:52:48.887287956 10 chttp2_transport.cc:2660] ipv4:172.18.0.1:55780: Start BDP ping err="No Error"
journal-service_1 | I1115 15:52:48.887293261 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> IDLE [finish writing]
journal-service_1 | I1115 15:52:48.887551243 10 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.887559234 10 tcp_posix.cc:590] TCP:0x7f54400018d0 alloc_slices
journal-service_1 | I1115 15:52:48.887571028 10 tcp_posix.cc:571] TCP:0x7f54400018d0 read_allocation_done: "No Error"
journal-service_1 | I1115 15:52:48.887658860 10 tcp_posix.cc:401] TCP:0x7f54400018d0 call_cb 0x7f5440002090 0x83ca50:0x7f5440001f50
journal-service_1 | I1115 15:52:48.887669585 10 tcp_posix.cc:404] READ 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780) error="No Error"
journal-service_1 | D1115 15:52:48.887700032 10 tcp_posix.cc:410] DATA: 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 00 00 24 04 00 00 00 00 00 00 02 00 00 00 00 00 03 00 00 00 00 00 04 00 40 00 00 00 05 00 40 00 00 00 06 00 00 20 00 fe 03 00 00 00 01 00 00 04 08 00 00 00 00 00 00 3f 00 01 00 00 08 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 05 01 04 00 00 00 01 86 83 40 0a 3a 61 75 74 68 6f 72 69 74 79 0d 30 2e 30 2e 30 2e 30 3a 35 30 30 35 31 40 05 3a 70 61 74 68 2b 2f 73 65 72 76 69 63 65 2e 6a 6f 75 72 6e 61 6c 2e 4a 6f 75 72 6e 61 6c 53 65 72 76 69 63 65 2f 47 65 74 53 6e 61 70 73 68 6f 74 40 02 74 65 08 74 72 61 69 6c 65 72 73 40 0c 63 6f 6e 74 65 6e 74 2d 74 79 70 65 10 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 40 0a 75 73 65 72 2d 61 67 65 6e 74 32 67 72 70 63 2d 6e 6f 64 65 2f 31 2e 31 37 2e 30 20 67 72 70 63 2d 63 2f 37 2e 30 2e 30 20 28 6f 73 78 3b 20 63 68 74 74 70 32 3b 20 67 69 7a 6d 6f 29 40 14 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 15 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 40 0f 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 0d 69 64 65 6e 74 69 74 79 2c 67 7a 69 70 00 00 04 08 00 00 00 00 01 00 00 00 05 00 00 1f 00 01 00 00 00 01 00 00 00 00 1a 0a 06 0a 04 72 75 6e 32 12 10 0a 02 08 01 12 06 08 c4 e0 86 ee 05 1a 02 08 01 00 00 04 08 00 00 00 00 00 00 00 00 05 'PRI * HTTP/2.0....SM......$.....................@.....@...... .................?..............................@.:authority.0.0.0.0:50051@.:path+/service.journal.JournalService/GetSnapshot@.te.trailers@.content-type.application/grpc@.user-agent2grpc-node/1.17.0 grpc-c/7.0.0 (osx; chttp2; gizmo)@.grpc-accept-encoding.identity,deflate,gzip@.accept-encoding.identity,gzip...............................run2...............................'
journal-service_1 | I1115 15:52:48.887711722 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting ENABLE_PUSH = 0
journal-service_1 | I1115 15:52:48.887715289 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting MAX_CONCURRENT_STREAMS = 0
journal-service_1 | I1115 15:52:48.887718017 10 frame_settings.cc:223] 0x7f5440001f50[svr] adding 4128769 for initial_window change
journal-service_1 | I1115 15:52:48.887720656 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting INITIAL_WINDOW_SIZE = 4194304
journal-service_1 | I1115 15:52:48.887723161 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting MAX_FRAME_SIZE = 4194304
journal-service_1 | I1115 15:52:48.887725675 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting MAX_HEADER_LIST_SIZE = 8192
journal-service_1 | I1115 15:52:48.887728010 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting GRPC_ALLOW_TRUE_BINARY_METADATA = 1
journal-service_1 | I1115 15:52:48.887731968 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state IDLE -> WRITING [PING_RESPONSE]
journal-service_1 | I1115 15:52:48.887743241 10 call.cc:1566] ops[0]: RECV_INITIAL_METADATA ptr=0x7f5440006b38
journal-service_1 | I1115 15:52:48.887747725 10 parsing.cc:681] parsing initial_metadata
journal-service_1 | I1115 15:52:48.887752449 10 parsing.cc:430] HTTP:1:HDR:SVR: :scheme: 68 74 74 70 'http'
journal-service_1 | I1115 15:52:48.887755845 10 parsing.cc:430] HTTP:1:HDR:SVR: :method: 50 4f 53 54 'POST'
journal-service_1 | I1115 15:52:48.887761879 10 parsing.cc:430] HTTP:1:HDR:SVR: :authority: 30 2e 30 2e 30 2e 30 3a 35 30 30 35 31 '0.0.0.0:50051'
journal-service_1 | I1115 15:52:48.887766754 10 parsing.cc:430] HTTP:1:HDR:SVR: :path: 2f 73 65 72 76 69 63 65 2e 6a 6f 75 72 6e 61 6c 2e 4a 6f 75 72 6e 61 6c 53 65 72 76 69 63 65 2f 47 65 74 53 6e 61 70 73 68 6f 74 '/service.journal.JournalService/GetSnapshot'
journal-service_1 | I1115 15:52:48.887770751 10 parsing.cc:430] HTTP:1:HDR:SVR: te: 74 72 61 69 6c 65 72 73 'trailers'
journal-service_1 | I1115 15:52:48.887774505 10 parsing.cc:430] HTTP:1:HDR:SVR: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
journal-service_1 | I1115 15:52:48.887780236 10 parsing.cc:430] HTTP:1:HDR:SVR: user-agent: 67 72 70 63 2d 6e 6f 64 65 2f 31 2e 31 37 2e 30 20 67 72 70 63 2d 63 2f 37 2e 30 2e 30 20 28 6f 73 78 3b 20 63 68 74 74 70 32 3b 20 67 69 7a 6d 6f 29 'grpc-node/1.17.0 grpc-c/7.0.0 (osx; chttp2; gizmo)'
journal-service_1 | I1115 15:52:48.887784312 10 parsing.cc:430] HTTP:1:HDR:SVR: grpc-accept-encoding: 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'
journal-service_1 | I1115 15:52:48.887787801 10 parsing.cc:430] HTTP:1:HDR:SVR: accept-encoding: 69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'
journal-service_1 | I1115 15:52:48.887794660 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: RECV_INITIAL_METADATA
journal-service_1 | I1115 15:52:48.887797899 10 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.887800536 10 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.887804697 10 tcp_posix.cc:265] TCP:0x7f54400018d0 notify_on_read
journal-service_1 | I1115 15:52:48.887809455 10 chttp2_transport.cc:1435] perform_stream_op_locked: RECV_INITIAL_METADATA; on_complete = (nil)
journal-service_1 | I1115 15:52:48.887815426 10 call.cc:1566] ops[0]: RECV_MESSAGE ptr=0x7f5440006b58
journal-service_1 | I1115 15:52:48.887819081 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: RECV_MESSAGE
journal-service_1 | I1115 15:52:48.887822124 10 chttp2_transport.cc:1435] perform_stream_op_locked: RECV_MESSAGE; on_complete = (nil)
journal-service_1 | I1115 15:52:48.887849739 10 completion_queue.cc:682] cq_end_op_for_next(cq=0x237aaa0, tag=0x237b960, error="No Error", done=0x7fc8e0, done_arg=0x7f54480008e0, storage=0x7f5448000918)
journal-service_1 | I1115 15:52:48.887862750 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> WRITING [begin write in current thread]
journal-service_1 | I1115 15:52:48.887882260 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887891216 10 tcp_posix.cc:1062] DATA: 00 00 08 06 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 01 00 '.......................'
journal-service_1 | I1115 15:52:48.887895779 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887900032 10 tcp_posix.cc:1062] DATA: 00 00 00 00 00 04 08 00 00 00 00 00 00 00 00 1f '................'
journal-service_1 | I1115 15:52:48.887927279 10 tcp_posix.cc:1096] write: "No Error"
journal-service_1 | I1115 15:52:48.887938364 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> IDLE [finish writing]
journal-service_1 | I1115 15:52:48.887978281 10 completion_queue.cc:1060] RETURN_EVENT[0x237aaa0]: OP_COMPLETE: tag:0x237b960 OK
journal-service_1 | I1115 15:52:48.888025273 10 completion_queue.cc:504] grpc_completion_queue_create_internal(completion_type=1, polling_type=0)
journal-service_1 | I1115 15:52:48.888216980 10 server.cc:1525] grpc_server_request_registered_call(server=0x237b300, rmp=0x237ba70, call=0x237b980, deadline=0x237b990, initial_metadata=0x237b9a0, optional_payload=0x237b9b8, cq_bound_to_call=0x7f5440001bc0, cq_for_notification=0x237aaa0, tag=0x237b960)
journal-service_1 | I1115 15:52:48.888257792 10 call.cc:1967] grpc_call_start_batch(call=0x7f54400060a0, ops=0x7f544d719af0, nops=1, tag=0x7f5440008550, reserved=(nil))
journal-service_1 | I1115 15:52:48.888024194 9 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.888314290 9 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.888329702 9 tcp_posix.cc:401] TCP:0x7f54400018d0 call_cb 0x7f5440002090 0x83ca50:0x7f5440001f50
journal-service_1 | I1115 15:52:48.888335434 9 tcp_posix.cc:404] READ 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780) error="No Error"
journal-service_1 | I1115 15:52:48.888272266 10 call.cc:1566] ops[0]: RECV_CLOSE_ON_SERVER cancelled=0x7f54400085dc
journal-service_1 | I1115 15:52:48.888373084 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: RECV_TRAILING_METADATA
journal-service_1 | I1115 15:52:48.888455399 10 chttp2_transport.cc:1435] perform_stream_op_locked: RECV_TRAILING_METADATA; on_complete = (nil)
journal-service_1 | D1115 15:52:48.888342155 9 tcp_posix.cc:410] DATA: 00 00 08 06 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 01 00 00 00 00 '..........................'
journal-service_1 | I1115 15:52:48.888577114 9 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.888583848 9 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.888590804 9 tcp_posix.cc:265] TCP:0x7f54400018d0 notify_on_read
journal-service_1 | I1115 15:52:48.888594508 9 chttp2_transport.cc:2676] ipv4:172.18.0.1:55780: Complete BDP ping err="No Error"
journal-service_1 | I found data for run2 in 1 directories that I own.
journal-service_1 | I1115 15:52:48.894985433 10 call.cc:1967] grpc_call_start_batch(call=0x7f54400060a0, ops=0x7f544d719680, nops=2, tag=0x7f544d7199e0, reserved=(nil))
journal-service_1 | I1115 15:52:48.895006636 10 call.cc:1566] ops[0]: SEND_INITIAL_METADATA(nil)
journal-service_1 | I1115 15:52:48.895014011 10 call.cc:1566] ops[1]: SEND_STATUS_FROM_SERVER status=2 details=Unexpected error in RPC handling(nil)
journal-service_1 | I1115 15:52:48.895077932 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: SEND_INITIAL_METADATA{key=3a 73 74 61 74 75 73 ':status' value=32 30 30 '200', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=32 '2', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=55 6e 65 78 70 65 63 74 65 64 20 65 72 72 6f 72 20 69 6e 20 52 50 43 20 68 61 6e 64 6c 69 6e 67 'Unexpected error in RPC handling'}
journal-service_1 | I1115 15:52:48.895119707 10 chttp2_transport.cc:1435] perform_stream_op_locked: SEND_INITIAL_METADATA{key=3a 73 74 61 74 75 73 ':status' value=32 30 30 '200', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=32 '2', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=55 6e 65 78 70 65 63 74 65 64 20 65 72 72 6f 72 20 69 6e 20 52 50 43 20 68 61 6e 64 6c 69 6e 67 'Unexpected error in RPC handling'}; on_complete = 0x7f54400073c8
journal-service_1 | I1115 15:52:48.895131125 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: :status: 200
journal-service_1 | I1115 15:52:48.895134700 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: content-type: application/grpc
journal-service_1 | I1115 15:52:48.895137310 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: grpc-accept-encoding: identity,deflate,gzip
journal-service_1 | I1115 15:52:48.895147091 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: accept-encoding: identity,gzip
journal-service_1 | I1115 15:52:48.895153883 10 chttp2_transport.cc:1411] HTTP:1:TRL:SVR: grpc-status: 2
journal-service_1 | I1115 15:52:48.895158938 10 chttp2_transport.cc:1411] HTTP:1:TRL:SVR: grpc-message: Unexpected error in RPC handling
journal-service_1 | I1115 15:52:48.895205876 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state IDLE -> WRITING [SEND_INITIAL_METADATA]
journal-service_1 | I1115 15:52:48.895218008 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> WRITING+MORE [SEND_TRAILING_METADATA]
journal-service_1 | I1115 15:52:48.895227726 10 chttp2_transport.cc:1284] complete_closure_step: t=0x7f5440001f50 0x7f54400073c8 refs=2 flags=0x0001 desc=op->on_complete err="No Error" write_state=WRITING+MORE
journal-service_1 | I1115 15:52:48.895240378 10 writing.cc:434] W:0x7f5440001f50 SERVER[1] im-(sent,send)=(0,1) announce=0
journal-service_1 | I1115 15:52:48.895247361 10 writing.cc:590] not sending initial_metadata (Trailers-Only)
journal-service_1 | I1115 15:52:48.895260851 10 chttp2_transport.cc:1284] complete_closure_step: t=0x7f5440001f50 0x7f54400073c8 refs=1 flags=0x0001 desc=send_initial_metadata_finished err="No Error" write_state=WRITING+MORE
journal-service_1 | I1115 15:52:48.895265551 10 writing.cc:557] sending trailing_metadata
journal-service_1 | I1115 15:52:48.895270278 10 hpack_encoder.cc:486] Encode: 'content-type: application/grpc', elem_interned=1 [1], k_interned=1, v_interned=1
journal-service_1 | I1115 15:52:48.895275797 10 hpack_encoder.cc:486] Encode: 'grpc-status: 2', elem_interned=1 [1], k_interned=1, v_interned=1
journal-service_1 | I1115 15:52:48.895280774 10 hpack_encoder.cc:486] Encode: 'grpc-message: Unexpected error in RPC handling', elem_interned=0 [2], k_interned=1, v_interned=0
journal-service_1 | I1115 15:52:48.895287052 10 chttp2_transport.cc:1284] complete_closure_step: t=0x7f5440001f50 0x7f54400073c8 refs=0 flags=0x0001 desc=send_trailing_metadata_finished err="No Error" write_state=WRITING+MORE
journal-service_1 | I1115 15:52:48.895294233 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING+MORE -> WRITING [begin write in current thread]
journal-service_1 | I1115 15:52:48.895298023 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895301616 10 tcp_posix.cc:1062] DATA: 00 00 5e 01 05 00 00 00 01 88 40 0c '..^.......@.'
journal-service_1 | I1115 15:52:48.895304811 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895308809 10 tcp_posix.cc:1062] DATA: 63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type'
journal-service_1 | I1115 15:52:48.895312357 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895316110 10 tcp_posix.cc:1062] DATA: 10 '.'
journal-service_1 | I1115 15:52:48.895319685 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895323521 10 tcp_posix.cc:1062] DATA: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
journal-service_1 | I1115 15:52:48.895338694 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895370800 10 tcp_posix.cc:1062] DATA: 40 0b '@.'
journal-service_1 | I1115 15:52:48.895378830 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895386495 10 tcp_posix.cc:1062] DATA: 67 72 70 63 2d 73 74 61 74 75 73 'grpc-status'
journal-service_1 | I1115 15:52:48.895391926 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895395862 10 tcp_posix.cc:1062] DATA: 01 '.'
journal-service_1 | I1115 15:52:48.895399384 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895401963 10 tcp_posix.cc:1062] DATA: 32 '2'
journal-service_1 | I1115 15:52:48.895404244 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895406731 10 tcp_posix.cc:1062] DATA: 40 0c '@.'
journal-service_1 | I1115 15:52:48.895436701 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895476220 10 tcp_posix.cc:1062] DATA: 67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message'
journal-service_1 | I1115 15:52:48.895483121 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895487321 10 tcp_posix.cc:1062] DATA: 20 ' '
journal-service_1 | I1115 15:52:48.895490852 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895495475 10 tcp_posix.cc:1062] DATA: 55 6e 65 78 70 65 63 74 65 64 20 65 72 72 6f 72 20 69 6e 20 52 50 43 20 68 61 6e 64 6c 69 6e 67 'Unexpected error in RPC handling'
journal-service_1 | I1115 15:52:48.895597061 10 tcp_posix.cc:1096] write: "No Error"
journal-service_1 | I1115 15:52:48.895610227 10 completion_queue.cc:764] cq_end_op_for_pluck(cq=0x7f54480044c0, tag=0x7f5440008550, error="No Error", done=0x7f58b0, done_arg=0x7f54400086f0, storage=0x7f5440008740)
journal-service_1 | I1115 15:52:48.895619122 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> IDLE [finish writing]
journal-service_1 | I1115 15:52:48.895627333 10 completion_queue.cc:764] cq_end_op_for_pluck(cq=0x7f54480044c0, tag=0x7f544d7199e0, error="No Error", done=0x7f58b0, done_arg=0x7f54400087d0, storage=0x7f5440008820)
journal-service_1 | I1115 15:52:48.895639296 10 completion_queue.cc:1296] RETURN_EVENT[0x7f54480044c0]: OP_COMPLETE: tag:0x7f544d7199e0 OK
journal-service_1 | I1115 15:52:48.895653047 10 completion_queue.cc:1398] grpc_completion_queue_shutdown(cq=0x7f54480044c0)
journal-service_1 | I1115 15:52:48.895662468 10 completion_queue.cc:1296] RETURN_EVENT[0x7f54480044c0]: OP_COMPLETE: tag:0x7f5440008550 OK
journal-service_1 | I1115 15:52:48.895670097 10 completion_queue.cc:1296] RETURN_EVENT[0x7f54480044c0]: QUEUE_SHUTDOWN
journal-service_1 | I1115 15:52:48.895675991 10 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f54400091e0)
journal-service_1 | I1115 15:52:48.895683204 10 call.cc:573] grpc_call_unref(c=0x7f54400060a0)
journal-service_1 | I1115 15:52:48.895706621 10 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f5440006b38)
journal-service_1 | I1115 15:52:48.895724730 10 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f54400091e0)
journal-service_1 | I1115 15:52:47.684328068 9 completion_queue.cc:960] grpc_completion_queue_next(cq=0x237aaa0, deadline=gpr_timespec { tv_sec: 7603, tv_nsec: 240983924, clock_type: 0 }, reserved=(nil))
journal-service_1 | I1115 15:52:48.886953532 10 tcp_server_posix.cc:242] SERVER_CONNECT: incoming connection: ipv4:172.18.0.1:55780
journal-service_1 | D1115 15:52:48.887007693 10 tcp_posix.cc:1253] cannot set inq fd=8 errno=92
journal-service_1 | I1115 15:52:48.887062609 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
journal-service_1 | I1115 15:52:48.887070206 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> WRITING+MORE [INITIAL_WRITE]
journal-service_1 | I1115 15:52:48.887074250 10 init.cc:164] grpc_init(void)
journal-service_1 | I1115 15:52:48.887093265 10 chttp2_transport.cc:1900] perform_transport_op[t=0x7f5440001f50]: ON_CONNECTIVITY_STATE_CHANGE:p=0x7f5440003cf0:from=IDLE SET_ACCEPT_STREAM:0x7feb10(0x7f5440003c88,...)
journal-service_1 | I1115 15:52:48.887100719 10 chttp2_transport.cc:1900] perform_transport_op[t=0x7f5440001f50]: ON_CONNECTIVITY_STATE_CHANGE:p=0x7f5440003cf0:from=READY
journal-service_1 | I1115 15:52:48.887104135 10 tcp_posix.cc:265] TCP:0x7f54400018d0 notify_on_read
journal-service_1 | I1115 15:52:48.887109550 10 writing.cc:116] SERVER: Ping sent [ipv4:172.18.0.1:55780]: 2/2
journal-service_1 | I1115 15:52:48.887113039 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING+MORE -> WRITING [begin write in current thread]
journal-service_1 | I1115 15:52:48.887123552 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887157759 10 tcp_posix.cc:1062] DATA: 00 00 18 04 00 00 00 00 00 00 04 00 40 00 00 00 05 00 40 00 00 00 06 00 00 20 00 fe 03 00 00 00 01 '............@.....@...... .......'
journal-service_1 | I1115 15:52:48.887162534 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887165687 10 tcp_posix.cc:1062] DATA: 00 00 04 08 00 00 00 00 00 00 3f 00 01 00 00 08 06 00 00 00 00 00 00 '..........?............'
journal-service_1 | I1115 15:52:48.887168113 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887170653 10 tcp_posix.cc:1062] DATA: 00 00 00 00 00 00 00 '.......'
journal-service_1 | I1115 15:52:48.887276538 10 tcp_posix.cc:1096] write: "No Error"
journal-service_1 | I1115 15:52:48.887287956 10 chttp2_transport.cc:2660] ipv4:172.18.0.1:55780: Start BDP ping err="No Error"
journal-service_1 | I1115 15:52:48.887293261 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> IDLE [finish writing]
journal-service_1 | I1115 15:52:48.887551243 10 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.887559234 10 tcp_posix.cc:590] TCP:0x7f54400018d0 alloc_slices
journal-service_1 | I1115 15:52:48.887571028 10 tcp_posix.cc:571] TCP:0x7f54400018d0 read_allocation_done: "No Error"
journal-service_1 | I1115 15:52:48.887658860 10 tcp_posix.cc:401] TCP:0x7f54400018d0 call_cb 0x7f5440002090 0x83ca50:0x7f5440001f50
journal-service_1 | I1115 15:52:48.887669585 10 tcp_posix.cc:404] READ 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780) error="No Error"
journal-service_1 | D1115 15:52:48.887700032 10 tcp_posix.cc:410] DATA: 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 00 00 24 04 00 00 00 00 00 00 02 00 00 00 00 00 03 00 00 00 00 00 04 00 40 00 00 00 05 00 40 00 00 00 06 00 00 20 00 fe 03 00 00 00 01 00 00 04 08 00 00 00 00 00 00 3f 00 01 00 00 08 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 05 01 04 00 00 00 01 86 83 40 0a 3a 61 75 74 68 6f 72 69 74 79 0d 30 2e 30 2e 30 2e 30 3a 35 30 30 35 31 40 05 3a 70 61 74 68 2b 2f 73 65 72 76 69 63 65 2e 6a 6f 75 72 6e 61 6c 2e 4a 6f 75 72 6e 61 6c 53 65 72 76 69 63 65 2f 47 65 74 53 6e 61 70 73 68 6f 74 40 02 74 65 08 74 72 61 69 6c 65 72 73 40 0c 63 6f 6e 74 65 6e 74 2d 74 79 70 65 10 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 40 0a 75 73 65 72 2d 61 67 65 6e 74 32 67 72 70 63 2d 6e 6f 64 65 2f 31 2e 31 37 2e 30 20 67 72 70 63 2d 63 2f 37 2e 30 2e 30 20 28 6f 73 78 3b 20 63 68 74 74 70 32 3b 20 67 69 7a 6d 6f 29 40 14 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 15 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 40 0f 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 0d 69 64 65 6e 74 69 74 79 2c 67 7a 69 70 00 00 04 08 00 00 00 00 01 00 00 00 05 00 00 1f 00 01 00 00 00 01 00 00 00 00 1a 0a 06 0a 04 72 75 6e 32 12 10 0a 02 08 01 12 06 08 c4 e0 86 ee 05 1a 02 08 01 00 00 04 08 00 00 00 00 00 00 00 00 05 'PRI * HTTP/2.0....SM......$.....................@.....@...... .................?..............................@.:authority.0.0.0.0:50051@.:path+/service.journal.JournalService/GetSnapshot@.te.trailers@.content-type.application/grpc@.user-agent2grpc-node/1.17.0 grpc-c/7.0.0 (osx; chttp2; gizmo)@.grpc-accept-encoding.identity,deflate,gzip@.accept-encoding.identity,gzip...............................run2...............................'
journal-service_1 | I1115 15:52:48.887711722 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting ENABLE_PUSH = 0
journal-service_1 | I1115 15:52:48.887715289 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting MAX_CONCURRENT_STREAMS = 0
journal-service_1 | I1115 15:52:48.887718017 10 frame_settings.cc:223] 0x7f5440001f50[svr] adding 4128769 for initial_window change
journal-service_1 | I1115 15:52:48.887720656 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting INITIAL_WINDOW_SIZE = 4194304
journal-service_1 | I1115 15:52:48.887723161 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting MAX_FRAME_SIZE = 4194304
journal-service_1 | I1115 15:52:48.887725675 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting MAX_HEADER_LIST_SIZE = 8192
journal-service_1 | I1115 15:52:48.887728010 10 frame_settings.cc:230] CHTTP2:SVR:ipv4:172.18.0.1:55780: got setting GRPC_ALLOW_TRUE_BINARY_METADATA = 1
journal-service_1 | I1115 15:52:48.887731968 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state IDLE -> WRITING [PING_RESPONSE]
journal-service_1 | I1115 15:52:48.887743241 10 call.cc:1566] ops[0]: RECV_INITIAL_METADATA ptr=0x7f5440006b38
journal-service_1 | I1115 15:52:48.887747725 10 parsing.cc:681] parsing initial_metadata
journal-service_1 | I1115 15:52:48.887752449 10 parsing.cc:430] HTTP:1:HDR:SVR: :scheme: 68 74 74 70 'http'
journal-service_1 | I1115 15:52:48.887755845 10 parsing.cc:430] HTTP:1:HDR:SVR: :method: 50 4f 53 54 'POST'
journal-service_1 | I1115 15:52:48.887761879 10 parsing.cc:430] HTTP:1:HDR:SVR: :authority: 30 2e 30 2e 30 2e 30 3a 35 30 30 35 31 '0.0.0.0:50051'
journal-service_1 | I1115 15:52:48.887766754 10 parsing.cc:430] HTTP:1:HDR:SVR: :path: 2f 73 65 72 76 69 63 65 2e 6a 6f 75 72 6e 61 6c 2e 4a 6f 75 72 6e 61 6c 53 65 72 76 69 63 65 2f 47 65 74 53 6e 61 70 73 68 6f 74 '/service.journal.JournalService/GetSnapshot'
journal-service_1 | I1115 15:52:48.887770751 10 parsing.cc:430] HTTP:1:HDR:SVR: te: 74 72 61 69 6c 65 72 73 'trailers'
journal-service_1 | I1115 15:52:48.887774505 10 parsing.cc:430] HTTP:1:HDR:SVR: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
journal-service_1 | I1115 15:52:48.887780236 10 parsing.cc:430] HTTP:1:HDR:SVR: user-agent: 67 72 70 63 2d 6e 6f 64 65 2f 31 2e 31 37 2e 30 20 67 72 70 63 2d 63 2f 37 2e 30 2e 30 20 28 6f 73 78 3b 20 63 68 74 74 70 32 3b 20 67 69 7a 6d 6f 29 'grpc-node/1.17.0 grpc-c/7.0.0 (osx; chttp2; gizmo)'
journal-service_1 | I1115 15:52:48.887784312 10 parsing.cc:430] HTTP:1:HDR:SVR: grpc-accept-encoding: 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'
journal-service_1 | I1115 15:52:48.887787801 10 parsing.cc:430] HTTP:1:HDR:SVR: accept-encoding: 69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'
journal-service_1 | I1115 15:52:48.887794660 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: RECV_INITIAL_METADATA
journal-service_1 | I1115 15:52:48.887797899 10 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.887800536 10 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.887804697 10 tcp_posix.cc:265] TCP:0x7f54400018d0 notify_on_read
journal-service_1 | I1115 15:52:48.887809455 10 chttp2_transport.cc:1435] perform_stream_op_locked: RECV_INITIAL_METADATA; on_complete = (nil)
journal-service_1 | I1115 15:52:48.887815426 10 call.cc:1566] ops[0]: RECV_MESSAGE ptr=0x7f5440006b58
journal-service_1 | I1115 15:52:48.887819081 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: RECV_MESSAGE
journal-service_1 | I1115 15:52:48.887822124 10 chttp2_transport.cc:1435] perform_stream_op_locked: RECV_MESSAGE; on_complete = (nil)
journal-service_1 | I1115 15:52:48.887849739 10 completion_queue.cc:682] cq_end_op_for_next(cq=0x237aaa0, tag=0x237b960, error="No Error", done=0x7fc8e0, done_arg=0x7f54480008e0, storage=0x7f5448000918)
journal-service_1 | I1115 15:52:48.887862750 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> WRITING [begin write in current thread]
journal-service_1 | I1115 15:52:48.887882260 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887891216 10 tcp_posix.cc:1062] DATA: 00 00 08 06 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 01 00 '.......................'
journal-service_1 | I1115 15:52:48.887895779 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.887900032 10 tcp_posix.cc:1062] DATA: 00 00 00 00 00 04 08 00 00 00 00 00 00 00 00 1f '................'
journal-service_1 | I1115 15:52:48.887927279 10 tcp_posix.cc:1096] write: "No Error"
journal-service_1 | I1115 15:52:48.887938364 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> IDLE [finish writing]
journal-service_1 | I1115 15:52:48.887978281 10 completion_queue.cc:1060] RETURN_EVENT[0x237aaa0]: OP_COMPLETE: tag:0x237b960 OK
journal-service_1 | I1115 15:52:48.888025273 10 completion_queue.cc:504] grpc_completion_queue_create_internal(completion_type=1, polling_type=0)
journal-service_1 | I1115 15:52:48.888216980 10 server.cc:1525] grpc_server_request_registered_call(server=0x237b300, rmp=0x237ba70, call=0x237b980, deadline=0x237b990, initial_metadata=0x237b9a0, optional_payload=0x237b9b8, cq_bound_to_call=0x7f5440001bc0, cq_for_notification=0x237aaa0, tag=0x237b960)
journal-service_1 | I1115 15:52:48.888257792 10 call.cc:1967] grpc_call_start_batch(call=0x7f54400060a0, ops=0x7f544d719af0, nops=1, tag=0x7f5440008550, reserved=(nil))
journal-service_1 | I1115 15:52:48.888024194 9 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.888314290 9 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.888329702 9 tcp_posix.cc:401] TCP:0x7f54400018d0 call_cb 0x7f5440002090 0x83ca50:0x7f5440001f50
journal-service_1 | I1115 15:52:48.888335434 9 tcp_posix.cc:404] READ 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780) error="No Error"
journal-service_1 | I1115 15:52:48.888272266 10 call.cc:1566] ops[0]: RECV_CLOSE_ON_SERVER cancelled=0x7f54400085dc
journal-service_1 | I1115 15:52:48.888373084 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: RECV_TRAILING_METADATA
journal-service_1 | I1115 15:52:48.888455399 10 chttp2_transport.cc:1435] perform_stream_op_locked: RECV_TRAILING_METADATA; on_complete = (nil)
journal-service_1 | D1115 15:52:48.888342155 9 tcp_posix.cc:410] DATA: 00 00 08 06 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 01 00 00 00 00 '..........................'
journal-service_1 | I1115 15:52:48.888577114 9 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.888583848 9 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.888590804 9 tcp_posix.cc:265] TCP:0x7f54400018d0 notify_on_read
journal-service_1 | I1115 15:52:48.888594508 9 chttp2_transport.cc:2676] ipv4:172.18.0.1:55780: Complete BDP ping err="No Error"
journal-service_1 | I found data for run2 in 1 directories that I own.
journal-service_1 | I1115 15:52:48.894985433 10 call.cc:1967] grpc_call_start_batch(call=0x7f54400060a0, ops=0x7f544d719680, nops=2, tag=0x7f544d7199e0, reserved=(nil))
journal-service_1 | I1115 15:52:48.895006636 10 call.cc:1566] ops[0]: SEND_INITIAL_METADATA(nil)
journal-service_1 | I1115 15:52:48.895014011 10 call.cc:1566] ops[1]: SEND_STATUS_FROM_SERVER status=2 details=Unexpected error in RPC handling(nil)
journal-service_1 | I1115 15:52:48.895077932 10 chttp2_transport.cc:1733] perform_stream_op[s=0x7f5440007608]: SEND_INITIAL_METADATA{key=3a 73 74 61 74 75 73 ':status' value=32 30 30 '200', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=32 '2', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=55 6e 65 78 70 65 63 74 65 64 20 65 72 72 6f 72 20 69 6e 20 52 50 43 20 68 61 6e 64 6c 69 6e 67 'Unexpected error in RPC handling'}
journal-service_1 | I1115 15:52:48.895119707 10 chttp2_transport.cc:1435] perform_stream_op_locked: SEND_INITIAL_METADATA{key=3a 73 74 61 74 75 73 ':status' value=32 30 30 '200', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=32 '2', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=55 6e 65 78 70 65 63 74 65 64 20 65 72 72 6f 72 20 69 6e 20 52 50 43 20 68 61 6e 64 6c 69 6e 67 'Unexpected error in RPC handling'}; on_complete = 0x7f54400073c8
journal-service_1 | I1115 15:52:48.895131125 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: :status: 200
journal-service_1 | I1115 15:52:48.895134700 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: content-type: application/grpc
journal-service_1 | I1115 15:52:48.895137310 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: grpc-accept-encoding: identity,deflate,gzip
journal-service_1 | I1115 15:52:48.895147091 10 chttp2_transport.cc:1411] HTTP:1:HDR:SVR: accept-encoding: identity,gzip
journal-service_1 | I1115 15:52:48.895153883 10 chttp2_transport.cc:1411] HTTP:1:TRL:SVR: grpc-status: 2
journal-service_1 | I1115 15:52:48.895158938 10 chttp2_transport.cc:1411] HTTP:1:TRL:SVR: grpc-message: Unexpected error in RPC handling
journal-service_1 | I1115 15:52:48.895205876 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state IDLE -> WRITING [SEND_INITIAL_METADATA]
journal-service_1 | I1115 15:52:48.895218008 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> WRITING+MORE [SEND_TRAILING_METADATA]
journal-service_1 | I1115 15:52:48.895227726 10 chttp2_transport.cc:1284] complete_closure_step: t=0x7f5440001f50 0x7f54400073c8 refs=2 flags=0x0001 desc=op->on_complete err="No Error" write_state=WRITING+MORE
journal-service_1 | I1115 15:52:48.895240378 10 writing.cc:434] W:0x7f5440001f50 SERVER[1] im-(sent,send)=(0,1) announce=0
journal-service_1 | I1115 15:52:48.895247361 10 writing.cc:590] not sending initial_metadata (Trailers-Only)
journal-service_1 | I1115 15:52:48.895260851 10 chttp2_transport.cc:1284] complete_closure_step: t=0x7f5440001f50 0x7f54400073c8 refs=1 flags=0x0001 desc=send_initial_metadata_finished err="No Error" write_state=WRITING+MORE
journal-service_1 | I1115 15:52:48.895265551 10 writing.cc:557] sending trailing_metadata
journal-service_1 | I1115 15:52:48.895270278 10 hpack_encoder.cc:486] Encode: 'content-type: application/grpc', elem_interned=1 [1], k_interned=1, v_interned=1
journal-service_1 | I1115 15:52:48.895275797 10 hpack_encoder.cc:486] Encode: 'grpc-status: 2', elem_interned=1 [1], k_interned=1, v_interned=1
journal-service_1 | I1115 15:52:48.895280774 10 hpack_encoder.cc:486] Encode: 'grpc-message: Unexpected error in RPC handling', elem_interned=0 [2], k_interned=1, v_interned=0
journal-service_1 | I1115 15:52:48.895287052 10 chttp2_transport.cc:1284] complete_closure_step: t=0x7f5440001f50 0x7f54400073c8 refs=0 flags=0x0001 desc=send_trailing_metadata_finished err="No Error" write_state=WRITING+MORE
journal-service_1 | I1115 15:52:48.895294233 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING+MORE -> WRITING [begin write in current thread]
journal-service_1 | I1115 15:52:48.895298023 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895301616 10 tcp_posix.cc:1062] DATA: 00 00 5e 01 05 00 00 00 01 88 40 0c '..^.......@.'
journal-service_1 | I1115 15:52:48.895304811 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895308809 10 tcp_posix.cc:1062] DATA: 63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type'
journal-service_1 | I1115 15:52:48.895312357 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895316110 10 tcp_posix.cc:1062] DATA: 10 '.'
journal-service_1 | I1115 15:52:48.895319685 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895323521 10 tcp_posix.cc:1062] DATA: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
journal-service_1 | I1115 15:52:48.895338694 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895370800 10 tcp_posix.cc:1062] DATA: 40 0b '@.'
journal-service_1 | I1115 15:52:48.895378830 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895386495 10 tcp_posix.cc:1062] DATA: 67 72 70 63 2d 73 74 61 74 75 73 'grpc-status'
journal-service_1 | I1115 15:52:48.895391926 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895395862 10 tcp_posix.cc:1062] DATA: 01 '.'
journal-service_1 | I1115 15:52:48.895399384 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895401963 10 tcp_posix.cc:1062] DATA: 32 '2'
journal-service_1 | I1115 15:52:48.895404244 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895406731 10 tcp_posix.cc:1062] DATA: 40 0c '@.'
journal-service_1 | I1115 15:52:48.895436701 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895476220 10 tcp_posix.cc:1062] DATA: 67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message'
journal-service_1 | I1115 15:52:48.895483121 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895487321 10 tcp_posix.cc:1062] DATA: 20 ' '
journal-service_1 | I1115 15:52:48.895490852 10 tcp_posix.cc:1058] WRITE 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780)
journal-service_1 | D1115 15:52:48.895495475 10 tcp_posix.cc:1062] DATA: 55 6e 65 78 70 65 63 74 65 64 20 65 72 72 6f 72 20 69 6e 20 52 50 43 20 68 61 6e 64 6c 69 6e 67 'Unexpected error in RPC handling'
journal-service_1 | I1115 15:52:48.895597061 10 tcp_posix.cc:1096] write: "No Error"
journal-service_1 | I1115 15:52:48.895610227 10 completion_queue.cc:764] cq_end_op_for_pluck(cq=0x7f54480044c0, tag=0x7f5440008550, error="No Error", done=0x7f58b0, done_arg=0x7f54400086f0, storage=0x7f5440008740)
journal-service_1 | I1115 15:52:48.895619122 10 chttp2_transport.cc:839] W:0x7f5440001f50 SERVER [ipv4:172.18.0.1:55780] state WRITING -> IDLE [finish writing]
journal-service_1 | I1115 15:52:48.895627333 10 completion_queue.cc:764] cq_end_op_for_pluck(cq=0x7f54480044c0, tag=0x7f544d7199e0, error="No Error", done=0x7f58b0, done_arg=0x7f54400087d0, storage=0x7f5440008820)
journal-service_1 | I1115 15:52:48.895639296 10 completion_queue.cc:1296] RETURN_EVENT[0x7f54480044c0]: OP_COMPLETE: tag:0x7f544d7199e0 OK
journal-service_1 | I1115 15:52:48.895653047 10 completion_queue.cc:1398] grpc_completion_queue_shutdown(cq=0x7f54480044c0)
journal-service_1 | I1115 15:52:48.895662468 10 completion_queue.cc:1296] RETURN_EVENT[0x7f54480044c0]: OP_COMPLETE: tag:0x7f5440008550 OK
journal-service_1 | I1115 15:52:48.895670097 10 completion_queue.cc:1296] RETURN_EVENT[0x7f54480044c0]: QUEUE_SHUTDOWN
journal-service_1 | I1115 15:52:48.895675991 10 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f54400091e0)
journal-service_1 | I1115 15:52:48.895683204 10 call.cc:573] grpc_call_unref(c=0x7f54400060a0)
journal-service_1 | I1115 15:52:48.895706621 10 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f5440006b38)
journal-service_1 | I1115 15:52:48.895724730 10 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f54400091e0)
journal-service_1
| I1115 15:52:48.895733132 10 completion_queue.cc:1404]
grpc_completion_queue_destroy(cq=0x7f54480044c0)
journal-service_1 | I1115 15:52:48.895737667 10 completion_queue.cc:1398] grpc_completion_queue_shutdown(cq=0x7f54480044c0)
journal-service_1 | I1115 15:52:48.895747282 10 completion_queue.cc:960] grpc_completion_queue_next(cq=0x237aaa0, deadline=gpr_timespec { tv_sec: 7604, tv_nsec: 452416786, clock_type: 0 }, reserved=(nil))
journal-service_1 | I1115 15:52:48.909412760 9 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.909466978 9 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.909481404 9 tcp_posix.cc:401] TCP:0x7f54400018d0 call_cb 0x7f5440002090 0x83ca50:0x7f5440001f50
journal-service_1 | I1115 15:52:48.909492130 9 tcp_posix.cc:404] READ 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780) error={"created":"@1573833168.909479700","description":"Socket closed","fd":8,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":502,"grpc_status":14,"target_address":"ipv4:172.18.0.1:55780"}
journal-service_1 | I1115 15:52:48.909497666 9 chttp2_transport.cc:2866] transport 0x7f5440001f50 set connectivity_state=4
journal-service_1 | I1115 15:52:48.909584127 9 chttp2_transport.cc:1900] perform_transport_op[t=0x7f5440001f50]: SET_ACCEPT_STREAM:(nil)((nil),...)
journal-service_1 | I1115 15:52:48.909612733 9 tcp_posix.cc:854] TCP:0x7f54400018d0 got_error: {"created":"@1573833168.909578991","description":"FD Shutdown","file":"src/core/lib/iomgr/lockfree_event.cc","file_line":194,"referenced_errors":[{"created":"@1573833168.909495939","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2559,"occurred_during_write":0,"referenced_errors":[{"created":"@1573833168.909479700","description":"Socket closed","fd":8,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":502,"grpc_status":14,"target_address":"ipv4:172.18.0.1:55780"}]}]}
journal-service_1 | I1115 15:52:48.909624929 9 init.cc:211] grpc_shutdown(void)
journal-service_1 | I1115 15:52:57.689572394 9 completion_queue.cc:960] grpc_completion_queue_next(cq=0x237aaa0, deadline=gpr_timespec { tv_sec: 7613, tv_nsec: 246234878, clock_type: 0 }, reserved=(nil))
journal-service_1 | I1115 15:52:48.895737667 10 completion_queue.cc:1398] grpc_completion_queue_shutdown(cq=0x7f54480044c0)
journal-service_1 | I1115 15:52:48.895747282 10 completion_queue.cc:960] grpc_completion_queue_next(cq=0x237aaa0, deadline=gpr_timespec { tv_sec: 7604, tv_nsec: 452416786, clock_type: 0 }, reserved=(nil))
journal-service_1 | I1115 15:52:48.909412760 9 tcp_posix.cc:605] TCP:0x7f54400018d0 got_read: "No Error"
journal-service_1 | I1115 15:52:48.909466978 9 tcp_posix.cc:596] TCP:0x7f54400018d0 do_read
journal-service_1 | I1115 15:52:48.909481404 9 tcp_posix.cc:401] TCP:0x7f54400018d0 call_cb 0x7f5440002090 0x83ca50:0x7f5440001f50
journal-service_1 | I1115 15:52:48.909492130 9 tcp_posix.cc:404] READ 0x7f54400018d0 (peer=ipv4:172.18.0.1:55780) error={"created":"@1573833168.909479700","description":"Socket closed","fd":8,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":502,"grpc_status":14,"target_address":"ipv4:172.18.0.1:55780"}
journal-service_1 | I1115 15:52:48.909497666 9 chttp2_transport.cc:2866] transport 0x7f5440001f50 set connectivity_state=4
journal-service_1 | I1115 15:52:48.909584127 9 chttp2_transport.cc:1900] perform_transport_op[t=0x7f5440001f50]: SET_ACCEPT_STREAM:(nil)((nil),...)
journal-service_1 | I1115 15:52:48.909612733 9 tcp_posix.cc:854] TCP:0x7f54400018d0 got_error: {"created":"@1573833168.909578991","description":"FD Shutdown","file":"src/core/lib/iomgr/lockfree_event.cc","file_line":194,"referenced_errors":[{"created":"@1573833168.909495939","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2559,"occurred_during_write":0,"referenced_errors":[{"created":"@1573833168.909479700","description":"Socket closed","fd":8,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":502,"grpc_status":14,"target_address":"ipv4:172.18.0.1:55780"}]}]}
journal-service_1 | I1115 15:52:48.909624929 9 init.cc:211] grpc_shutdown(void)
journal-service_1 | I1115 15:52:57.689572394 9 completion_queue.cc:960] grpc_completion_queue_next(cq=0x237aaa0, deadline=gpr_timespec { tv_sec: 7613, tv_nsec: 246234878, clock_type: 0 }, reserved=(nil))
rick...@improbable.io
Nov 15, 2019, 12:29:52 PM11/15/19
to grpc.io
For those googling this in the future, the problem was in my server code. The server was responding to the request with:
ERROR:
Code: Unknown
ERROR:
Code: Unknown
Message: Unexpected error in RPC handling
...it just didn't look like it was working in BloomRPC. I was finally able to get the request to work in grpcurl.
The message "Failed to dial target host ... tls: first record does not look like a TLS handshake" was due to me not passing "-plaintext" to the grpcurl command.
Reply all
Reply to author
Forward
0 new messages