assertion failed: driver_join_status == 0 json_run_localhost_cpp_protobuf_async_streaming_qps_unconstrained_1mps_insecure #21014
Description
exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //test/cpp/qps:json_run_localhost_cpp_protobuf_async_streaming_qps_unconstrained_1mps_insecure@poller=epoll1
-----------------------------------------------------------------------------
+ export GRPC_POLL_STRATEGY=epoll1
+ shift
+ test/cpp/qps/json_run_localhost_cpp_protobuf_async_streaming_qps_unconstrained_1mps_insecure --scenarios_json {scenarios : [{"name": "cpp_protobuf_async_streaming_qps_unconstrained_1mps_insecure", "warmup_seconds": 0, "benchmark_seconds": 1, "num_servers": 1, "server_config": {"security_params": null, "server_type": "ASYNC_SERVER", "async_server_threads": 0, "threads_per_cq": 0, "channel_args": [{"str_value": "throughput", "name": "grpc.optimization_target"}, {"int_value": 1, "name": "grpc.minimal_stack"}]}, "client_config": {"security_params": null, "channel_args": [{"str_value": "throughput", "name": "grpc.optimization_target"}, {"int_value": 1, "name": "grpc.minimal_stack"}], "async_client_threads": 0, "outstanding_rpcs_per_channel": 100, "rpc_type": "STREAMING", "load_params": {"closed_loop": {}}, "histogram_params": {"resolution": 0.01, "max_possible": 60000000000.0}, "client_type": "ASYNC_CLIENT", "messages_per_stream": 1, "payload_config": {"simple_params": {"resp_size": 0, "req_size": 0}}, "client_channels": 64, "threads_per_cq": 0}, "num_clients": 0}]}
I1111 19:18:05.034732024 18 ev_epoll1_linux.cc:116] grpc epoll fd: 3
D1111 19:18:05.034802995 18 ev_posix.cc:174] Using polling engine: epoll1
D1111 19:18:05.035444502 18 dns_resolver_ares.cc:503] Using ares dns resolver
I1111 19:18:05.035814056 18 server_builder.cc:307] Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 2, CQ timeout (msec): 10000
I1111 19:18:05.044738342 19 ev_epoll1_linux.cc:116] grpc epoll fd: 3
D1111 19:18:05.045006439 19 ev_posix.cc:174] Using polling engine: epoll1
D1111 19:18:05.045384915 19 dns_resolver_ares.cc:503] Using ares dns resolver
I1111 19:18:05.045694547 19 server_builder.cc:307] Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 2, CQ timeout (msec): 10000
RUNNING SCENARIO: cpp_protobuf_async_streaming_qps_unconstrained_1mps_insecure
I1111 19:18:05.047018850 20 driver.cc:297] Starting server on localhost:2821 (worker #0)
I1111 19:18:05.047711091 20 ev_epoll1_linux.cc:116] grpc epoll fd: 3
D1111 19:18:05.047737226 20 ev_posix.cc:174] Using polling engine: epoll1
D1111 19:18:05.048151668 20 dns_resolver_ares.cc:503] Using ares dns resolver
D1111 19:18:05.049624466 20 tcp_posix.cc:1261] cannot set inq fd=5 errno=92
D1111 19:18:05.049883032 24 tcp_posix.cc:1261] cannot set inq fd=6 errno=92
I1111 19:18:05.049923665 20 subchannel.cc:1055] New connected subchannel at 0x564d9f0 for subchannel 0x5675d00
I1111 19:18:05.051162221 24 qps_worker.cc:236] RunServerBody: about to create server
I1111 19:18:05.052990657 24 qps_worker.cc:72] Starting server of type ASYNC_SERVER
I1111 19:18:05.053403126 24 server_async.cc:94] Sizing async server to 2 threads
I1111 19:18:05.697450746 24 qps_worker.cc:244] RunServerBody: server created
I1111 19:18:05.698343918 20 driver.cc:357] Starting client on localhost:2822 (worker #1)
D1111 19:18:05.698687054 20 driver.cc:381] Client 0 gets 64 channels
D1111 19:18:05.699767019 20 tcp_posix.cc:1261] cannot set inq fd=6 errno=92
D1111 19:18:05.699843134 32 tcp_posix.cc:1261] cannot set inq fd=9 errno=92
I1111 19:18:05.699932850 20 subchannel.cc:1055] New connected subchannel at 0x56a8600 for subchannel 0x56a6300
I1111 19:18:05.699940115 32 chttp2_transport.cc:323] GRPC_ARG_OPTIMIZATION_TARGET is deprecated
I1111 19:18:05.700718616 24 qps_worker.cc:251] RunServerBody: creation status reported
E1111 19:18:05.700887693 20 driver.cc:396] Client 0 did not yield initial status
I1111 19:18:05.700899735 20 driver.cc:402] Initiating
E1111 19:18:05.700958306 20 driver.cc:412] Couldn't write mark to client 0
E1111 19:18:05.701024173 20 driver.cc:418] Couldn't get status from client 0
I1111 19:18:05.701030606 20 driver.cc:423] Warming up
I1111 19:18:05.701035336 20 driver.cc:429] Starting
E1111 19:18:05.701167386 20 driver.cc:439] Couldn't write mark to client 0
I1111 19:18:05.701627910 24 qps_worker.cc:253] RunServerBody: Message read
I1111 19:18:05.702666355 24 qps_worker.cc:262] RunServerBody: Mark response given
E1111 19:18:05.703483964 20 driver.cc:451] Couldn't get status from client 0
I1111 19:18:05.703493997 20 driver.cc:456] Running
I1111 19:18:06.701210333 20 driver.cc:470] Finishing clients
E1111 19:18:06.701423806 20 driver.cc:474] Couldn't write mark to client 0
I1111 19:18:06.701458366 20 driver.cc:480] Finishing servers
I1111 19:18:06.701947887 24 qps_worker.cc:253] RunServerBody: Message read
E1111 19:18:06.702186597 20 driver.cc:506] Couldn't get final status from client 0
E1111 19:18:06.702308831 20 driver.cc:518] Client 0 had an error
I1111 19:18:06.703491283 24 qps_worker.cc:262] RunServerBody: Mark response given
I1111 19:18:06.703532728 24 qps_worker.cc:265] RunServerBody: Returning
I1111 19:18:06.704879545 20 driver.cc:535] Received final status from server 0
I1111 19:18:06.750609313 37 chttp2_transport.cc:1770] ipv6:[::1]:54606: Sending goaway err={"created":"@1573499886.750482594","description":"Server shutdown","file":"src/core/lib/surface/server.cc","file_line":323,"grpc_status":0}
I1111 19:18:06.896671448 24 qps_worker.cc:132] RunServer: Returning
I1111 19:18:06.898288817 20 report.cc:82] QPS: -nan
D1111 19:18:06.898820030 20 report.cc:106] SERVER[0].client_calls_created = 0
D1111 19:18:06.898947516 20 report.cc:106] SERVER[0].server_calls_created = 0
D1111 19:18:06.899116088 20 report.cc:106] SERVER[0].cqs_created = 0
D1111 19:18:06.899240414 20 report.cc:106] SERVER[0].client_channels_created = 0
D1111 19:18:06.899333754 20 report.cc:106] SERVER[0].client_subchannels_created = 0
D1111 19:18:06.899456732 20 report.cc:106] SERVER[0].server_channels_created = 0
D1111 19:18:06.899584203 20 report.cc:106] SERVER[0].syscall_poll = 0
D1111 19:18:06.899723981 20 report.cc:106] SERVER[0].syscall_wait = 0
D1111 19:18:06.899829433 20 report.cc:106] SERVER[0].pollset_kick = 0
D1111 19:18:06.899912565 20 report.cc:106] SERVER[0].pollset_kicked_without_poller = 0
D1111 19:18:06.900014648 20 report.cc:106] SERVER[0].pollset_kicked_again = 0
D1111 19:18:06.900141899 20 report.cc:106] SERVER[0].pollset_kick_wakeup_fd = 0
D1111 19:18:06.900256858 20 report.cc:106] SERVER[0].pollset_kick_wakeup_cv = 0
D1111 19:18:06.900374824 20 report.cc:106] SERVER[0].pollset_kick_own_thread = 0
D1111 19:18:06.900471619 20 report.cc:106] SERVER[0].syscall_epoll_ctl = 0
D1111 19:18:06.900570359 20 report.cc:106] SERVER[0].pollset_fd_cache_hits = 0
D1111 19:18:06.900682479 20 report.cc:106] SERVER[0].histogram_slow_lookups = 0
D1111 19:18:06.900814973 20 report.cc:106] SERVER[0].syscall_write = 0
D1111 19:18:06.900930050 20 report.cc:106] SERVER[0].syscall_read = 0
D1111 19:18:06.900940933 20 report.cc:106] SERVER[0].tcp_backup_pollers_created = 0
D1111 19:18:06.900945119 20 report.cc:106] SERVER[0].tcp_backup_poller_polls = 0
D1111 19:18:06.900949426 20 report.cc:106] SERVER[0].http2_op_batches = 0
D1111 19:18:06.900953203 20 report.cc:106] SERVER[0].http2_op_cancel = 0
D1111 19:18:06.901133197 20 report.cc:106] SERVER[0].http2_op_send_initial_metadata = 0
D1111 19:18:06.901162750 20 report.cc:106] SERVER[0].http2_op_send_message = 0
D1111 19:18:06.901181720 20 report.cc:106] SERVER[0].http2_op_send_trailing_metadata = 0
D1111 19:18:06.901280012 20 report.cc:106] SERVER[0].http2_op_recv_initial_metadata = 0
D1111 19:18:06.901329518 20 report.cc:106] SERVER[0].http2_op_recv_message = 0
D1111 19:18:06.901349665 20 report.cc:106] SERVER[0].http2_op_recv_trailing_metadata = 0
D1111 19:18:06.901369736 20 report.cc:106] SERVER[0].http2_settings_writes = 0
D1111 19:18:06.901412395 20 report.cc:106] SERVER[0].http2_pings_sent = 0
D1111 19:18:06.901463189 20 report.cc:106] SERVER[0].http2_writes_begun = 0
D1111 19:18:06.901482769 20 report.cc:106] SERVER[0].http2_writes_offloaded = 0
D1111 19:18:06.901499417 20 report.cc:106] SERVER[0].http2_writes_continued = 0
D1111 19:18:06.901514787 20 report.cc:106] SERVER[0].http2_partial_writes = 0
D1111 19:18:06.901530997 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_initial_write = 0
D1111 19:18:06.901550959 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_start_new_stream = 0
D1111 19:18:06.901611000 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_send_message = 0
D1111 19:18:06.901682131 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_send_initial_metadata = 0
D1111 19:18:06.901749639 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_send_trailing_metadata = 0
D1111 19:18:06.901773120 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_retry_send_ping = 0
D1111 19:18:06.901789976 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_continue_pings = 0
D1111 19:18:06.901806945 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_goaway_sent = 0
D1111 19:18:06.901823062 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_rst_stream = 0
D1111 19:18:06.901851024 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_close_from_api = 0
D1111 19:18:06.901855688 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_stream_flow_control = 0
D1111 19:18:06.901860392 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_transport_flow_control = 0
D1111 19:18:06.901865236 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_send_settings = 0
D1111 19:18:06.901870253 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_bdp_estimator_ping = 0
D1111 19:18:06.901875043 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_flow_control_unstalled_by_setting = 0
D1111 19:18:06.901879578 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_flow_control_unstalled_by_update = 0
D1111 19:18:06.901883633 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_application_ping = 0
D1111 19:18:06.901887837 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_keepalive_ping = 0
D1111 19:18:06.901892300 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_transport_flow_control_unstalled = 0
D1111 19:18:06.901896496 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_ping_response = 0
D1111 19:18:06.901900455 20 report.cc:106] SERVER[0].http2_initiate_write_due_to_force_rst_stream = 0
D1111 19:18:06.902045533 20 report.cc:106] SERVER[0].http2_spurious_writes_begun = 0
D1111 19:18:06.902063048 20 report.cc:106] SERVER[0].hpack_recv_indexed = 0
D1111 19:18:06.902079728 20 report.cc:106] SERVER[0].hpack_recv_lithdr_incidx = 0
D1111 19:18:06.902095568 20 report.cc:106] SERVER[0].hpack_recv_lithdr_incidx_v = 0
D1111 19:18:06.902160406 20 report.cc:106] SERVER[0].hpack_recv_lithdr_notidx = 0
D1111 19:18:06.902216065 20 report.cc:106] SERVER[0].hpack_recv_lithdr_notidx_v = 0
D1111 19:18:06.902287685 20 report.cc:106] SERVER[0].hpack_recv_lithdr_nvridx = 0
D1111 19:18:06.902363380 20 report.cc:106] SERVER[0].hpack_recv_lithdr_nvridx_v = 0
D1111 19:18:06.902385951 20 report.cc:106] SERVER[0].hpack_recv_uncompressed = 0
D1111 19:18:06.902401380 20 report.cc:106] SERVER[0].hpack_recv_huffman = 0
D1111 19:18:06.902415819 20 report.cc:106] SERVER[0].hpack_recv_binary = 0
D1111 19:18:06.902431391 20 report.cc:106] SERVER[0].hpack_recv_binary_base64 = 0
D1111 19:18:06.902447372 20 report.cc:106] SERVER[0].hpack_send_indexed = 0
D1111 19:18:06.902463068 20 report.cc:106] SERVER[0].hpack_send_lithdr_incidx = 0
D1111 19:18:06.902482695 20 report.cc:106] SERVER[0].hpack_send_lithdr_incidx_v = 0
D1111 19:18:06.902512083 20 report.cc:106] SERVER[0].hpack_send_lithdr_notidx = 0
D1111 19:18:06.902516756 20 report.cc:106] SERVER[0].hpack_send_lithdr_notidx_v = 0
D1111 19:18:06.902521044 20 report.cc:106] SERVER[0].hpack_send_lithdr_nvridx = 0
D1111 19:18:06.902525156 20 report.cc:106] SERVER[0].hpack_send_lithdr_nvridx_v = 0
D1111 19:18:06.902529361 20 report.cc:106] SERVER[0].hpack_send_uncompressed = 0
D1111 19:18:06.902533312 20 report.cc:106] SERVER[0].hpack_send_huffman = 0
D1111 19:18:06.902537416 20 report.cc:106] SERVER[0].hpack_send_binary = 0
D1111 19:18:06.902541641 20 report.cc:106] SERVER[0].hpack_send_binary_base64 = 0
D1111 19:18:06.902545807 20 report.cc:106] SERVER[0].combiner_locks_initiated = 0
D1111 19:18:06.902550042 20 report.cc:106] SERVER[0].combiner_locks_scheduled_items = 0
D1111 19:18:06.902554592 20 report.cc:106] SERVER[0].combiner_locks_scheduled_final_items = 0
D1111 19:18:06.902558861 20 report.cc:106] SERVER[0].combiner_locks_offloaded = 0
D1111 19:18:06.902562956 20 report.cc:106] SERVER[0].call_combiner_locks_initiated = 0
D1111 19:18:06.902566922 20 report.cc:106] SERVER[0].call_combiner_locks_scheduled_items = 0
D1111 19:18:06.902571279 20 report.cc:106] SERVER[0].call_combiner_set_notify_on_cancel = 0
D1111 19:18:06.902575445 20 report.cc:106] SERVER[0].call_combiner_cancelled = 0
D1111 19:18:06.902579556 20 report.cc:106] SERVER[0].executor_scheduled_short_items = 0
D1111 19:18:06.902583647 20 report.cc:106] SERVER[0].executor_scheduled_long_items = 0
D1111 19:18:06.902739011 20 report.cc:106] SERVER[0].executor_scheduled_to_self = 0
D1111 19:18:06.902756208 20 report.cc:106] SERVER[0].executor_wakeup_initiated = 0
D1111 19:18:06.902771285 20 report.cc:106] SERVER[0].executor_queue_drained = 0
D1111 19:18:06.902786533 20 report.cc:106] SERVER[0].executor_push_retries = 0
D1111 19:18:06.902826426 20 report.cc:106] SERVER[0].server_requested_calls = 0
D1111 19:18:06.902868853 20 report.cc:106] SERVER[0].server_slowpath_requests_queued = 0
D1111 19:18:06.902924858 20 report.cc:106] SERVER[0].cq_ev_queue_trylock_failures = 0
D1111 19:18:06.902986091 20 report.cc:106] SERVER[0].cq_ev_queue_trylock_successes = 0
D1111 19:18:06.903042508 20 report.cc:106] SERVER[0].cq_ev_queue_transient_pop_failures = 0
D1111 19:18:06.903130922 20 report.cc:110] SERVER[0].call_initial_size = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903214337 20 report.cc:110] SERVER[0].poll_events_returned = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903242098 20 report.cc:110] SERVER[0].tcp_write_size = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903265188 20 report.cc:110] SERVER[0].tcp_write_iov_size = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903289496 20 report.cc:110] SERVER[0].tcp_read_size = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903311996 20 report.cc:110] SERVER[0].tcp_read_offer = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903361165 20 report.cc:110] SERVER[0].tcp_read_offer_iov_size = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903412425 20 report.cc:110] SERVER[0].http2_send_message_size = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903491906 20 report.cc:110] SERVER[0].http2_send_initial_metadata_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903557343 20 report.cc:110] SERVER[0].http2_send_message_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903633519 20 report.cc:110] SERVER[0].http2_send_trailing_metadata_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903690942 20 report.cc:110] SERVER[0].http2_send_flowctl_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1111 19:18:06.903712439 20 report.cc:110] SERVER[0].server_cqs_checked = 0.0/0.0/0.0 (50/95/99%-ile)
I1111 19:18:06.903734111 20 report.cc:122] QPS: -nan (-nan/server core)
I1111 19:18:06.903754510 20 report.cc:127] Latencies (50/90/95/99/99.9%-ile): 0.0/0.0/0.0/0.0/0.0 us
I1111 19:18:06.903773344 20 report.cc:137] Server system time: 0.05%
I1111 19:18:06.903789831 20 report.cc:139] Server user time: 0.17%
I1111 19:18:06.903805638 20 report.cc:141] Client system time: -nan%
I1111 19:18:06.903833362 20 report.cc:143] Client user time: -nan%
I1111 19:18:06.903839596 20 report.cc:148] Server CPU usage: 1.01%
I1111 19:18:06.903844415 20 report.cc:153] Client Polls per Request: -nan
I1111 19:18:06.903848229 20 report.cc:155] Server Polls per Request: -nan
I1111 19:18:06.903853309 20 report.cc:160] Server Queries/CPU-sec: 0.00
I1111 19:18:06.903857196 20 report.cc:162] Client Queries/CPU-sec: -nan
I1111 19:18:06.905067494 17 json_run_localhost.cc:71] driver: subprocess exited with status 1
E1111 19:18:10.048226875 17 json_run_localhost.cc:133] assertion failed: driver_join_status == 0
Aborted (core dumped)
Seen in PR: #20929