Hi, Sree, I do not have a minimum code snippet that can reproduce (and I only encountered the assertion once). I can only discribe the scenario: 1. I am using bidirectional async stream to maintain the heartbeat between server and client. 2. The assertion is in client side exiting phase. 3. The client stream will periodically send msg to server (around 500ms a msg). The test case will first try cancel client stream and when there is no inflight-read/write, it will try to shutdown the client CQ. (Notice at that time the server stream and CQ are still running)
In the log above, the ThreadId 14901 is using to process the server completion queue; 14886 is using to process the client completion queue. Hope you can get some information from my description. Thanks, Yihao 在 2017年9月15日星期五 UTC-7上午7:12:23，Sree Kuchibhotla写道： > > It does look like a bug in the completion queue shutdown path. Can you > share the test program you have been using to reproduce this ? > > thanks, > Sree > > On Thu, Sep 14, 2017 at 6:23 PM, yihao yang <[email protected] > <javascript:>> wrote: > >> I0914 12:05:40.258058747 14907 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x7fa87c004af0, deadline=gpr_timespec { >> tv_sec: 10, tv_nsec: 0, clock_type: 3 }, reserved=(nil)) >> I0914 12:05:40.262040844 14901 completion_queue.c:861] >> RETURN_EVENT[0x1fca250]: QUEUE_TIMEOUT >> I0914 12:05:40.262107598 14901 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fca250, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 362102878, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.262387036 14886 completion_queue.c:861] >> RETURN_EVENT[0x1fd21e0]: QUEUE_TIMEOUT >> I0914 12:05:40.262416496 14886 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fd21e0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 362410478, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.288670933 8291 completion_queue.c:861] >> RETURN_EVENT[0x1fc20c0]: QUEUE_TIMEOUT >> I0914 12:05:40.288740234 8291 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fc20c0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 388734668, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.362347155 14901 completion_queue.c:861] >> RETURN_EVENT[0x1fca250]: QUEUE_TIMEOUT >> I0914 12:05:40.362500837 14901 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fca250, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 462491875, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.362647536 14886 completion_queue.c:861] >> RETURN_EVENT[0x1fd21e0]: QUEUE_TIMEOUT >> I0914 12:05:40.362678953 14886 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fd21e0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 462672886, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.388942072 8291 completion_queue.c:861] >> RETURN_EVENT[0x1fc20c0]: QUEUE_TIMEOUT >> I0914 12:05:40.389056726 8291 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fc20c0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 489047123, clock_type: 1 }, reserved=(nil)) >> D0914 12:05:40.392114240 14901 connectivity_state.c:135] CONWATCH: >> 0x7fa80c01eed8 server_transport: from IDLE [cur=READY] notify=0x7fa80c01a138 >> D0914 12:05:40.392180813 14901 connectivity_state.c:135] CONWATCH: >> 0x7fa80c01eed8 server_transport: from READY [cur=READY] >> notify=0x7fa80c01a138 >> I0914 12:05:40.462920251 14886 completion_queue.c:861] >> RETURN_EVENT[0x1fd21e0]: QUEUE_TIMEOUT >> I0914 12:05:40.463057779 14886 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fd21e0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 563049680, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.463475112 14901 completion_queue.c:861] >> RETURN_EVENT[0x1fca250]: QUEUE_TIMEOUT >> I0914 12:05:40.463502256 14901 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fca250, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 563497963, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.489336198 8291 completion_queue.c:861] >> RETURN_EVENT[0x1fc20c0]: QUEUE_TIMEOUT >> I0914 12:05:40.489426090 8291 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fc20c0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 589417977, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.563312610 14886 completion_queue.c:861] >> RETURN_EVENT[0x1fd21e0]: QUEUE_TIMEOUT >> I0914 12:05:40.563392795 14886 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fd21e0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 663385808, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.563684056 14901 completion_queue.c:861] >> RETURN_EVENT[0x1fca250]: QUEUE_TIMEOUT >> I0914 12:05:40.563706730 14901 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fca250, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 663702959, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.589633763 8291 completion_queue.c:861] >> RETURN_EVENT[0x1fc20c0]: QUEUE_TIMEOUT >> I0914 12:05:40.589719300 8291 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fc20c0, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 689710645, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.663776 14906 single_thread_worker.cpp:84] >> SingleThreadWorker stop: HeartbeatClient >> >> // stop bidirectional stream >> I0914 12:05:40.663796024 8267 call.c:583] >> grpc_call_cancel(call=0x1fdb758, reserved=(nil)) >> I0914 12:05:40.664022389 8267 client_channel.c:1300] >> OP[client-channel:0x1fdbe10]: [UNCOVERED] CANCEL:"Cancelled" >> I0914 12:05:40.664053075 8267 http_client_filter.c:435] >> OP[http-client:0x1fe0900]: [UNCOVERED] CANCEL:"Cancelled" >> I0914 12:05:40.664066269 8267 connected_channel.c:70] >> OP[connected:0x1fe0930]: [UNCOVERED] CANCEL:"Cancelled" >> I0914 12:05:40.664119609 8267 completion_queue.c:564] >> cq_end_op_for_next(exec_ctx=0x7fffc824c4b0, cc=0x1fd21e0, tag=0x1fdc078, >> error="No Error", done=0x552280, done_arg=0x1fe1778, storage=0x1fe1780) >> I0914 12:05:40.664163094 14901 completion_queue.c:861] >> RETURN_EVENT[0x1fca250]: QUEUE_TIMEOUT >> I0914 12:05:40.664193123 14901 completion_queue.c:764] >> grpc_completion_queue_next(cc=0x1fca250, deadline=gpr_timespec { tv_sec: >> 1505415940, tv_nsec: 764188067, clock_type: 1 }, reserved=(nil)) >> I0914 12:05:40.664274513 14901 completion_queue.c:564] >> cq_end_op_for_next(exec_ctx=0x7fa86f7fdb80, cc=0x1fca250, >> tag=0x7fa87c01d138, error="No Error", done=0x552280, >> done_arg=0x7fa80c010f58, storage=0x7fa80c010f60) >> D0914 12:05:40.664341644 14901 call.c:706] >> get_final_status SVR >> D0914 12:05:40.664383484 14901 call.c:709] 1: >> {"created":"@1505415940.664334949","description":"Error received from >> peer","file":"src/core/lib/surface/call.c","file_line":955,"grpc_message":"Received >> >> RST_STREAM with error code 8","grpc_status":1} >> I0914 12:05:40.664424456 14901 completion_queue.c:564] >> cq_end_op_for_next(exec_ctx=0x7fa86f7fdb80, cc=0x1fca250, >> tag=0x7fa80c005dc0, error="No Error", done=0x552280, >> done_arg=0x7fa80c010e88, storage=0x7fa80c010e90) >> >> I0914 12:05:40.664525623 14901 completion_queue.c:861] >> RETURN_EVENT[0x1fca250]: OP_COMPLETE: tag:0x7fa87c01d138 OK >> I0914 12:05:40.664557682 14901 call.c:634] >> grpc_call_cancel_with_status(c=0x7fa80c00f7f8, status=1, >> description=Cancelled on the server side, reserved=(nil)) >> >> >> // start to shutdown CQ >> I0914 12:05:40.664123966 14886 completion_queue.c:861] >> RETURN_EVENT[0x1fd21e0]: QUEUE_TIMEOUT >> I0914 12:05:40.664660 14886 completion_queue_manager.cpp:103] Client >> CompletionQueue (0x1fd6670) quit. >> I0914 12:05:40.664697968 8267 completion_queue.c:1086] >> grpc_completion_queue_shutdown(cc=0x1fd21e0) >> I0914 12:05:40.664711547 8267 completion_queue.c:1105] >> grpc_completion_queue_destroy(cc=0x1fd21e0) >> I0914 12:05:40.664717709 8267 completion_queue.c:1086] >> grpc_completion_queue_shutdown(cc=0x1fd21e0) >> E0914 12:05:40.664723704 8267 completion_queue.c:1112] assertion >> failed: cq_event_queue_num_items(&cc->data.queue) == 0 >> >> Hi, all >> >> When testing upgradation of the grpc to version 1.4.2. I encountered >> assertion in CQ shutdown. Can anyone give me some hint? >> >> Thanks, >> Yihao >> >> -- >> You received this message because you are subscribed to the Google Groups >> "grpc.io" group. >> To unsubscribe from this group and stop receiving emails from it, send an >> email to [email protected] <javascript:>. >> To post to this group, send email to [email protected] >> <javascript:>. >> Visit this group at https://groups.google.com/group/grpc-io. >> To view this discussion on the web visit >> https://groups.google.com/d/msgid/grpc-io/32b0826a-ea6f-4188-85d8-1435c134f0ab%40googlegroups.com >> >> <https://groups.google.com/d/msgid/grpc-io/32b0826a-ea6f-4188-85d8-1435c134f0ab%40googlegroups.com?utm_medium=email&utm_source=footer> >> . >> For more options, visit https://groups.google.com/d/optout. >> > > -- You received this message because you are subscribed to the Google Groups "grpc.io" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. Visit this group at https://groups.google.com/group/grpc-io. To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/a63b6995-596f-4426-a137-bd130683698a%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
