gRPC send of 6MB data size with 'poll' as GRPC_POLL_STRATEGY cause errors at receiver
58 views
Skip to first unread message
kiran...@gmail.com
Feb 26, 2018, 8:09:56 PM2/26/18
to grpc.io
We have a system that has to use gRPC and doesn't support epoll. So we are using 'poll' as GRPC_POLL_STRATEGY. With that change we are seeing a strange behavior when we send data with 6MB of data size. Below mentioned error was seen with the python receiver.
gRPC client(c++) is built with 1.0.0 and gRPC receiver(python) is built using 1.9.0.
Please note that with same c++ grpc client running with 'epoll' as GRPC_POLL_STRATEGY on a system that supports epoll we don't see the issue with the same data. Also the receiver is set with max receiver size of 32MB.
Can you please let me know how can I debug this issue further?
<Error>
E0226 16:01:37.708911000 123145525346304 call.cc:1406] receiving_slice_ready: {"created":"@1519689697.708873000","description":"Stream removed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2063,"referenced_errors":[{"created":"@1519689697.708859000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519689697.708832000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:39632"}]}]}
</Error>
<Snip>
https://grpc.io/grpc/cpp/md_doc_environment_variables.html
GRPC_POLL_STRATEGY [posix-style environments only] Declares which polling engines to try when starting gRPC. This is a comma-separated list of engines, which are tried in priority order first -> last. Available polling engines include:
gRPC client(c++) is built with 1.0.0 and gRPC receiver(python) is built using 1.9.0.
Please note that with same c++ grpc client running with 'epoll' as GRPC_POLL_STRATEGY on a system that supports epoll we don't see the issue with the same data. Also the receiver is set with max receiver size of 32MB.
Can you please let me know how can I debug this issue further?
<Error>
E0226 16:01:37.708911000 123145525346304 call.cc:1406] receiving_slice_ready: {"created":"@1519689697.708873000","description":"Stream removed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2063,"referenced_errors":[{"created":"@1519689697.708859000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519689697.708832000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:39632"}]}]}
</Error>
<Snip>
https://grpc.io/grpc/cpp/md_doc_environment_variables.html
GRPC_POLL_STRATEGY [posix-style environments only] Declares which polling engines to try when starting gRPC. This is a comma-separated list of engines, which are tried in priority order first -> last. Available polling engines include:
- epoll (linux-only) - a polling engine based around the epoll family of system calls
- poll - a portable polling engine based around poll(), intended to be a fallback engine when nothing better exists
- legacy - the (deprecated) original polling engine for gRPC
</Snip>
Message has been deleted
kiran...@gmail.com
Feb 26, 2018, 8:28:06 PM2/26/18
to grpc.io
Providing more logs incase if its helpful.
<logs>
I0226 17:22:02.352157000 123145447886848 init.cc:154] grpc_init(void)
I0226 17:22:02.352177000 123145447886848 init.cc:154] grpc_init(void)
I0226 17:22:02.352189000 123145447886848 call_details.cc:29] grpc_call_details_init(cd=0x10291e890)
I0226 17:22:02.352230000 123145453142016 call.cc:2049] grpc_call_start_batch(call=0x7ffc48043c78, ops=0x7ffc44e62450, nops=1, tag=0x102937258, reserved=0x0)
I0226 17:22:02.352242000 123145453142016 call.cc:1648] ops[0]: RECV_MESSAGE ptr=0x102771b20
I0226 17:22:02.352253000 123145453142016 call.cc:617] OP[server:0x7ffc48044488]: RECV_MESSAGE
I0226 17:22:02.352261000 123145453142016 channel_stack.cc:229] OP[message_size:0x7ffc480444a0]: RECV_MESSAGE
I0226 17:22:02.352267000 123145453142016 channel_stack.cc:229] OP[deadline:0x7ffc480444b8]: RECV_MESSAGE
I0226 17:22:02.352274000 123145453142016 channel_stack.cc:229] OP[http-server:0x7ffc480444d0]: RECV_MESSAGE
I0226 17:22:02.352280000 123145453142016 channel_stack.cc:229] OP[message_compress:0x7ffc480444e8]: RECV_MESSAGE
I0226 17:22:02.352286000 123145453142016 channel_stack.cc:229] OP[connected:0x7ffc48044500]: RECV_MESSAGE
I0226 17:22:02.352384000 123145447886848 metadata_array.cc:27] grpc_metadata_array_init(array=0x10291d798)
I0226 17:22:02.352406000 123145447886848 server.cc:1329] grpc_server_request_call(server=0x7ffc44e7adc0, call=0x1029518e0, details=0x10291e890, initial_metadata=0x10291d798, cq_bound_to_call=0x7ffc44e53630, cq_for_notification=0x7ffc44e53630, tag=0x10291d768)
I0226 17:22:02.352423000 123145447886848 completion_queue.cc:856] grpc_completion_queue_next(cq=0x7ffc44e53630, deadline=gpr_timespec { tv_sec: 1519694522, tv_nsec: 552420000, clock_type: 1 }, reserved=0x0)
E0226 17:22:02.518663000 123145447886848 call.cc:1406] receiving_slice_ready: {"created":"@1519694522.518612000","description":"Stream removed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2063,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]}
I0226 17:22:02.518727000 123145447886848 completion_queue.cc:633] cq_end_op_for_next(cq=0x7ffc44e53630, tag=0x102937258, error="No Error", done=0x101f8e6a0, done_arg=0x7ffc48045bf8, storage=0x7ffc48045c00)
I0226 17:22:02.518780000 123145447886848 completion_queue.cc:633] cq_end_op_for_next(cq=0x7ffc44e53630, tag=0x102937200, error="No Error", done=0x101f8e6a0, done_arg=0x7ffc48045af8, storage=0x7ffc48045b00)
I0226 17:22:02.519073000 123145447886848 server.cc:423] Disconnected client: {"created":"@1519694522.518627000","description":"Delayed close due to in-progress write","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":595,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]}
I0226 17:22:02.519130000 123145447886848 completion_queue.cc:956] RETURN_EVENT[0x7ffc44e53630]: OP_COMPLETE: tag:0x102937258 OK
I0226 17:22:02.519379000 123145447886848 completion_queue.cc:856] grpc_completion_queue_next(cq=0x7ffc44e53630, deadline=gpr_timespec { tv_sec: 1519694522, tv_nsec: 719368000, clock_type: 1 }, reserved=0x0)
I0226 17:22:02.519411000 123145447886848 completion_queue.cc:956] RETURN_EVENT[0x7ffc44e53630]: OP_COMPLETE: tag:0x102937200 OK
I0226 17:22:02.519501000 123145453142016 call.cc:2049] grpc_call_start_batch(call=0x7ffc48043c78, ops=0x7ffc48b00060, nops=2, tag=0x102937258, reserved=0x0)
I0226 17:22:02.519529000 123145453142016 call.cc:1648] ops[0]: SEND_STATUS_FROM_SERVER status=0 details=(nil)
I0226 17:22:02.519544000 123145453142016 call.cc:1648] ops[1]: SEND_INITIAL_METADATA(nil)
I0226 17:22:02.519619000 123145453142016 call.cc:617] OP[server:0x7ffc48044488]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519672000 123145453142016 channel_stack.cc:229] OP[message_size:0x7ffc480444a0]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519699000 123145453142016 channel_stack.cc:229] OP[deadline:0x7ffc480444b8]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519720000 123145453142016 channel_stack.cc:229] OP[http-server:0x7ffc480444d0]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519752000 123145453142016 channel_stack.cc:229] OP[message_compress:0x7ffc480444e8]: 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'} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519843000 123145453142016 channel_stack.cc:229] OP[connected:0x7ffc48044500]: 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=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519923000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: :status: 200
I0226 17:22:02.519936000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: content-type: application/grpc
I0226 17:22:02.519975000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: grpc-accept-encoding: identity,deflate,gzip
I0226 17:22:02.520060000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: accept-encoding: identity,gzip
I0226 17:22:02.520078000 123145453142016 chttp2_transport.cc:1329] HTTP:1:TRL:SVR: grpc-status: 0
I0226 17:22:02.520088000 123145453142016 chttp2_transport.cc:1329] HTTP:1:TRL:SVR: grpc-message:
I0226 17:22:02.520214000 123145453142016 completion_queue.cc:633] cq_end_op_for_next(cq=0x7ffc44e53630, tag=0x102937258, error={"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}, done=0x101f8e6a0, done_arg=0x7ffc48045d38, storage=0x7ffc48045d40)
E0226 17:22:02.520381000 123145453142016 completion_queue.cc:635] Operation failed: tag=0x102937258, error={"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.520495000 123145453142016 call.cc:617] OP[server:0x7ffc48044488]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.520672000 123145453142016 channel_stack.cc:229] OP[message_size:0x7ffc480444a0]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.520759000 123145453142016 channel_stack.cc:229] OP[deadline:0x7ffc480444b8]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521018000 123145453142016 channel_stack.cc:229] OP[http-server:0x7ffc480444d0]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521062000 123145453142016 channel_stack.cc:229] OP[message_compress:0x7ffc480444e8]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521283000 123145453142016 channel_stack.cc:229] OP[connected:0x7ffc48044500]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521453000 123145453142016 call_details.cc:36] grpc_call_details_destroy(cd=0x10291e820)
I0226 17:22:02.521520000 123145447886848 completion_queue.cc:856] grpc_completion_queue_next(cq=0x7ffc44e53630, deadline=gpr_timespec { tv_sec: 1519694522, tv_nsec: 721515000, clock_type: 1 }, reserved=0x0)
I0226 17:22:02.521541000 123145447886848 completion_queue.cc:956] RETURN_EVENT[0x7ffc44e53630]: OP_COMPLETE: tag:0x102937258 ERROR
I0226 17:22:02.521552000 123145453142016 init.cc:159] grpc_shutdown(void)
I0226 17:22:02.521611000 123145447886848 call.cc:566] grpc_call_unref(c=0x7ffc48043c78)
I0226 17:22:02.521647000 123145447886848 metadata_array.cc:32] grpc_metadata_array_destroy(array=0x7ffc48044590)
I0226 17:22:02.521708000 123145447886848 init.cc:159] grpc_shutdown(void)
</logs>
<logs>
I0226 17:22:02.352157000 123145447886848 init.cc:154] grpc_init(void)
I0226 17:22:02.352177000 123145447886848 init.cc:154] grpc_init(void)
I0226 17:22:02.352189000 123145447886848 call_details.cc:29] grpc_call_details_init(cd=0x10291e890)
I0226 17:22:02.352230000 123145453142016 call.cc:2049] grpc_call_start_batch(call=0x7ffc48043c78, ops=0x7ffc44e62450, nops=1, tag=0x102937258, reserved=0x0)
I0226 17:22:02.352242000 123145453142016 call.cc:1648] ops[0]: RECV_MESSAGE ptr=0x102771b20
I0226 17:22:02.352253000 123145453142016 call.cc:617] OP[server:0x7ffc48044488]: RECV_MESSAGE
I0226 17:22:02.352261000 123145453142016 channel_stack.cc:229] OP[message_size:0x7ffc480444a0]: RECV_MESSAGE
I0226 17:22:02.352267000 123145453142016 channel_stack.cc:229] OP[deadline:0x7ffc480444b8]: RECV_MESSAGE
I0226 17:22:02.352274000 123145453142016 channel_stack.cc:229] OP[http-server:0x7ffc480444d0]: RECV_MESSAGE
I0226 17:22:02.352280000 123145453142016 channel_stack.cc:229] OP[message_compress:0x7ffc480444e8]: RECV_MESSAGE
I0226 17:22:02.352286000 123145453142016 channel_stack.cc:229] OP[connected:0x7ffc48044500]: RECV_MESSAGE
I0226 17:22:02.352384000 123145447886848 metadata_array.cc:27] grpc_metadata_array_init(array=0x10291d798)
I0226 17:22:02.352406000 123145447886848 server.cc:1329] grpc_server_request_call(server=0x7ffc44e7adc0, call=0x1029518e0, details=0x10291e890, initial_metadata=0x10291d798, cq_bound_to_call=0x7ffc44e53630, cq_for_notification=0x7ffc44e53630, tag=0x10291d768)
I0226 17:22:02.352423000 123145447886848 completion_queue.cc:856] grpc_completion_queue_next(cq=0x7ffc44e53630, deadline=gpr_timespec { tv_sec: 1519694522, tv_nsec: 552420000, clock_type: 1 }, reserved=0x0)
E0226 17:22:02.518663000 123145447886848 call.cc:1406] receiving_slice_ready: {"created":"@1519694522.518612000","description":"Stream removed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2063,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]}
I0226 17:22:02.518727000 123145447886848 completion_queue.cc:633] cq_end_op_for_next(cq=0x7ffc44e53630, tag=0x102937258, error="No Error", done=0x101f8e6a0, done_arg=0x7ffc48045bf8, storage=0x7ffc48045c00)
I0226 17:22:02.518780000 123145447886848 completion_queue.cc:633] cq_end_op_for_next(cq=0x7ffc44e53630, tag=0x102937200, error="No Error", done=0x101f8e6a0, done_arg=0x7ffc48045af8, storage=0x7ffc48045b00)
I0226 17:22:02.519073000 123145447886848 server.cc:423] Disconnected client: {"created":"@1519694522.518627000","description":"Delayed close due to in-progress write","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":595,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]}
I0226 17:22:02.519130000 123145447886848 completion_queue.cc:956] RETURN_EVENT[0x7ffc44e53630]: OP_COMPLETE: tag:0x102937258 OK
I0226 17:22:02.519379000 123145447886848 completion_queue.cc:856] grpc_completion_queue_next(cq=0x7ffc44e53630, deadline=gpr_timespec { tv_sec: 1519694522, tv_nsec: 719368000, clock_type: 1 }, reserved=0x0)
I0226 17:22:02.519411000 123145447886848 completion_queue.cc:956] RETURN_EVENT[0x7ffc44e53630]: OP_COMPLETE: tag:0x102937200 OK
I0226 17:22:02.519501000 123145453142016 call.cc:2049] grpc_call_start_batch(call=0x7ffc48043c78, ops=0x7ffc48b00060, nops=2, tag=0x102937258, reserved=0x0)
I0226 17:22:02.519529000 123145453142016 call.cc:1648] ops[0]: SEND_STATUS_FROM_SERVER status=0 details=(nil)
I0226 17:22:02.519544000 123145453142016 call.cc:1648] ops[1]: SEND_INITIAL_METADATA(nil)
I0226 17:22:02.519619000 123145453142016 call.cc:617] OP[server:0x7ffc48044488]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519672000 123145453142016 channel_stack.cc:229] OP[message_size:0x7ffc480444a0]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519699000 123145453142016 channel_stack.cc:229] OP[deadline:0x7ffc480444b8]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519720000 123145453142016 channel_stack.cc:229] OP[http-server:0x7ffc480444d0]: SEND_INITIAL_METADATA{} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519752000 123145453142016 channel_stack.cc:229] OP[message_compress:0x7ffc480444e8]: 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'} SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519843000 123145453142016 channel_stack.cc:229] OP[connected:0x7ffc48044500]: 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=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
I0226 17:22:02.519923000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: :status: 200
I0226 17:22:02.519936000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: content-type: application/grpc
I0226 17:22:02.519975000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: grpc-accept-encoding: identity,deflate,gzip
I0226 17:22:02.520060000 123145453142016 chttp2_transport.cc:1329] HTTP:1:HDR:SVR: accept-encoding: identity,gzip
I0226 17:22:02.520078000 123145453142016 chttp2_transport.cc:1329] HTTP:1:TRL:SVR: grpc-status: 0
I0226 17:22:02.520088000 123145453142016 chttp2_transport.cc:1329] HTTP:1:TRL:SVR: grpc-message:
I0226 17:22:02.520214000 123145453142016 completion_queue.cc:633] cq_end_op_for_next(cq=0x7ffc44e53630, tag=0x102937258, error={"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}, done=0x101f8e6a0, done_arg=0x7ffc48045d38, storage=0x7ffc48045d40)
E0226 17:22:02.520381000 123145453142016 completion_queue.cc:635] Operation failed: tag=0x102937258, error={"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.520495000 123145453142016 call.cc:617] OP[server:0x7ffc48044488]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.520672000 123145453142016 channel_stack.cc:229] OP[message_size:0x7ffc480444a0]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.520759000 123145453142016 channel_stack.cc:229] OP[deadline:0x7ffc480444b8]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521018000 123145453142016 channel_stack.cc:229] OP[http-server:0x7ffc480444d0]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521062000 123145453142016 channel_stack.cc:229] OP[message_compress:0x7ffc480444e8]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521283000 123145453142016 channel_stack.cc:229] OP[connected:0x7ffc48044500]: CANCEL:{"created":"@1519694522.520161000","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1209,"referenced_errors":[{"created":"@1519694522.520134000","description":"Attempt to send initial metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1458,"referenced_errors":[{"created":"@1519694522.518595000","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2410,"occurred_during_write":0,"referenced_errors":[{"created":"@1519694522.518562000","description":"Socket closed","fd":9,"file":"src/core/lib/iomgr/tcp_posix.cc","file_line":421,"grpc_status":14,"target_address":"ipv4:1.2.3.4:43471"}]}]},{"created":"@1519694522.520162000","description":"Attempt to send trailing metadata after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":1553}],"target_address":"ipv4:1.2.3.4:43471"}
I0226 17:22:02.521453000 123145453142016 call_details.cc:36] grpc_call_details_destroy(cd=0x10291e820)
I0226 17:22:02.521520000 123145447886848 completion_queue.cc:856] grpc_completion_queue_next(cq=0x7ffc44e53630, deadline=gpr_timespec { tv_sec: 1519694522, tv_nsec: 721515000, clock_type: 1 }, reserved=0x0)
I0226 17:22:02.521541000 123145447886848 completion_queue.cc:956] RETURN_EVENT[0x7ffc44e53630]: OP_COMPLETE: tag:0x102937258 ERROR
I0226 17:22:02.521552000 123145453142016 init.cc:159] grpc_shutdown(void)
I0226 17:22:02.521611000 123145447886848 call.cc:566] grpc_call_unref(c=0x7ffc48043c78)
I0226 17:22:02.521647000 123145447886848 metadata_array.cc:32] grpc_metadata_array_destroy(array=0x7ffc48044590)
I0226 17:22:02.521708000 123145447886848 init.cc:159] grpc_shutdown(void)
</logs>
Reply all
Reply to author
Forward
0 new messages