From 8c02418caa84d938964f2c441b7ff565eedefc06 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Thu, 31 Jan 2019 11:55:42 -0800 Subject: [PATCH 1/5] Reset keepalive timer on reading bytes --- src/core/ext/transport/chttp2/transport/chttp2_transport.cc | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc index c2b57ed2905..a0ca89ec510 100644 --- a/src/core/ext/transport/chttp2/transport/chttp2_transport.cc +++ b/src/core/ext/transport/chttp2/transport/chttp2_transport.cc @@ -2554,6 +2554,10 @@ static void read_action_locked(void* tp, grpc_error* error) { } else if (t->closed_with_error == GRPC_ERROR_NONE) { keep_reading = true; GRPC_CHTTP2_REF_TRANSPORT(t, "keep_reading"); + /* Since we have read a byte, reset the keepalive timer */ + if (t->keepalive_state == GRPC_CHTTP2_KEEPALIVE_STATE_WAITING) { + grpc_timer_cancel(&t->keepalive_ping_timer); + } } grpc_slice_buffer_reset_and_unref_internal(&t->read_buffer); From 058ceccd71a61e6b1a717996df10147784b2d442 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Wed, 6 Feb 2019 13:31:10 -0800 Subject: [PATCH 2/5] Add test to check that reads reset the keepalive timer --- test/core/end2end/tests/keepalive_timeout.cc | 206 +++++++++++++++++++ 1 file changed, 206 insertions(+) diff --git a/test/core/end2end/tests/keepalive_timeout.cc b/test/core/end2end/tests/keepalive_timeout.cc index 5f6a36dac44..d4e1fe34af3 100644 --- a/test/core/end2end/tests/keepalive_timeout.cc +++ b/test/core/end2end/tests/keepalive_timeout.cc @@ -220,8 +220,214 @@ static void test_keepalive_timeout(grpc_end2end_test_config config) { config.tear_down_data(&f); } +/* Verify that reads reset the keepalive ping timer. The client sends 10 pings + * with a sleep of 5ms in between. It has a configured keepalive timer of 10ms. + * In the success case, each ping ack should reset the keepalive timer so that + * the keepalive ping is never sent. */ +static void test_read_delays_keepalive(grpc_end2end_test_config config) { + const int kPingIntervalMS = 5; + grpc_arg keepalive_arg_elems[3]; + keepalive_arg_elems[0].type = GRPC_ARG_INTEGER; + keepalive_arg_elems[0].key = const_cast(GRPC_ARG_KEEPALIVE_TIME_MS); + keepalive_arg_elems[0].value.integer = kPingIntervalMS * 2; + keepalive_arg_elems[1].type = GRPC_ARG_INTEGER; + keepalive_arg_elems[1].key = const_cast(GRPC_ARG_KEEPALIVE_TIMEOUT_MS); + keepalive_arg_elems[1].value.integer = 0; + keepalive_arg_elems[2].type = GRPC_ARG_INTEGER; + keepalive_arg_elems[2].key = const_cast(GRPC_ARG_HTTP2_BDP_PROBE); + keepalive_arg_elems[2].value.integer = 0; + grpc_channel_args keepalive_args = {GPR_ARRAY_SIZE(keepalive_arg_elems), + keepalive_arg_elems}; + grpc_end2end_test_fixture f = begin_test(config, "test_read_delays_keepalive", + &keepalive_args, nullptr); + /* Disable ping ack to trigger the keepalive timeout */ + grpc_set_disable_ping_ack(true); + grpc_call* c; + grpc_call* s; + cq_verifier* cqv = cq_verifier_create(f.cq); + grpc_op ops[6]; + grpc_op* op; + grpc_metadata_array initial_metadata_recv; + grpc_metadata_array trailing_metadata_recv; + grpc_metadata_array request_metadata_recv; + grpc_call_details call_details; + grpc_status_code status; + grpc_call_error error; + grpc_slice details; + int was_cancelled = 2; + grpc_byte_buffer* request_payload; + grpc_byte_buffer* request_payload_recv; + grpc_byte_buffer* response_payload; + grpc_byte_buffer* response_payload_recv; + int i; + grpc_slice request_payload_slice = + grpc_slice_from_copied_string("hello world"); + grpc_slice response_payload_slice = + grpc_slice_from_copied_string("hello you"); + + gpr_timespec deadline = five_seconds_from_now(); + c = grpc_channel_create_call(f.client, nullptr, GRPC_PROPAGATE_DEFAULTS, f.cq, + grpc_slice_from_static_string("/foo"), nullptr, + deadline, nullptr); + GPR_ASSERT(c); + + grpc_metadata_array_init(&initial_metadata_recv); + grpc_metadata_array_init(&trailing_metadata_recv); + grpc_metadata_array_init(&request_metadata_recv); + grpc_call_details_init(&call_details); + + memset(ops, 0, sizeof(ops)); + op = ops; + op->op = GRPC_OP_SEND_INITIAL_METADATA; + op->data.send_initial_metadata.count = 0; + op->flags = 0; + op->reserved = nullptr; + op++; + op->op = GRPC_OP_RECV_INITIAL_METADATA; + op->data.recv_initial_metadata.recv_initial_metadata = &initial_metadata_recv; + op->flags = 0; + op->reserved = nullptr; + op++; + op->op = GRPC_OP_RECV_STATUS_ON_CLIENT; + op->data.recv_status_on_client.trailing_metadata = &trailing_metadata_recv; + op->data.recv_status_on_client.status = &status; + op->data.recv_status_on_client.status_details = &details; + op->flags = 0; + op->reserved = nullptr; + op++; + error = grpc_call_start_batch(c, ops, static_cast(op - ops), tag(1), + nullptr); + GPR_ASSERT(GRPC_CALL_OK == error); + + error = + grpc_server_request_call(f.server, &s, &call_details, + &request_metadata_recv, f.cq, f.cq, tag(100)); + GPR_ASSERT(GRPC_CALL_OK == error); + CQ_EXPECT_COMPLETION(cqv, tag(100), 1); + cq_verify(cqv); + + memset(ops, 0, sizeof(ops)); + op = ops; + op->op = GRPC_OP_SEND_INITIAL_METADATA; + op->data.send_initial_metadata.count = 0; + op->flags = 0; + op->reserved = nullptr; + op++; + op->op = GRPC_OP_RECV_CLOSE_ON_SERVER; + op->data.recv_close_on_server.cancelled = &was_cancelled; + op->flags = 0; + op->reserved = nullptr; + op++; + error = grpc_call_start_batch(s, ops, static_cast(op - ops), tag(101), + nullptr); + GPR_ASSERT(GRPC_CALL_OK == error); + + for (i = 0; i < 10; i++) { + request_payload = grpc_raw_byte_buffer_create(&request_payload_slice, 1); + response_payload = grpc_raw_byte_buffer_create(&response_payload_slice, 1); + + memset(ops, 0, sizeof(ops)); + op = ops; + op->op = GRPC_OP_SEND_MESSAGE; + op->data.send_message.send_message = request_payload; + op->flags = 0; + op->reserved = nullptr; + op++; + op->op = GRPC_OP_RECV_MESSAGE; + op->data.recv_message.recv_message = &response_payload_recv; + op->flags = 0; + op->reserved = nullptr; + op++; + error = grpc_call_start_batch(c, ops, static_cast(op - ops), tag(2), + nullptr); + GPR_ASSERT(GRPC_CALL_OK == error); + + memset(ops, 0, sizeof(ops)); + op = ops; + op->op = GRPC_OP_RECV_MESSAGE; + op->data.recv_message.recv_message = &request_payload_recv; + op->flags = 0; + op->reserved = nullptr; + op++; + error = grpc_call_start_batch(s, ops, static_cast(op - ops), + tag(102), nullptr); + GPR_ASSERT(GRPC_CALL_OK == error); + CQ_EXPECT_COMPLETION(cqv, tag(102), 1); + cq_verify(cqv); + + memset(ops, 0, sizeof(ops)); + op = ops; + op->op = GRPC_OP_SEND_MESSAGE; + op->data.send_message.send_message = response_payload; + op->flags = 0; + op->reserved = nullptr; + op++; + error = grpc_call_start_batch(s, ops, static_cast(op - ops), + tag(103), nullptr); + GPR_ASSERT(GRPC_CALL_OK == error); + CQ_EXPECT_COMPLETION(cqv, tag(103), 1); + CQ_EXPECT_COMPLETION(cqv, tag(2), 1); + cq_verify(cqv); + + grpc_byte_buffer_destroy(request_payload); + grpc_byte_buffer_destroy(response_payload); + grpc_byte_buffer_destroy(request_payload_recv); + grpc_byte_buffer_destroy(response_payload_recv); + /* Sleep for a short interval to check if the client sends any pings */ + gpr_sleep_until(grpc_timeout_milliseconds_to_deadline(kPingIntervalMS)); + } + + grpc_slice_unref(request_payload_slice); + grpc_slice_unref(response_payload_slice); + + memset(ops, 0, sizeof(ops)); + op = ops; + op->op = GRPC_OP_SEND_CLOSE_FROM_CLIENT; + op->flags = 0; + op->reserved = nullptr; + op++; + error = grpc_call_start_batch(c, ops, static_cast(op - ops), tag(3), + nullptr); + GPR_ASSERT(GRPC_CALL_OK == error); + + memset(ops, 0, sizeof(ops)); + op = ops; + op->op = GRPC_OP_SEND_STATUS_FROM_SERVER; + op->data.send_status_from_server.trailing_metadata_count = 0; + op->data.send_status_from_server.status = GRPC_STATUS_UNIMPLEMENTED; + grpc_slice status_details = grpc_slice_from_static_string("xyz"); + op->data.send_status_from_server.status_details = &status_details; + op->flags = 0; + op->reserved = nullptr; + op++; + error = grpc_call_start_batch(s, ops, static_cast(op - ops), tag(104), + nullptr); + GPR_ASSERT(GRPC_CALL_OK == error); + + CQ_EXPECT_COMPLETION(cqv, tag(1), 1); + CQ_EXPECT_COMPLETION(cqv, tag(3), 1); + CQ_EXPECT_COMPLETION(cqv, tag(101), 1); + CQ_EXPECT_COMPLETION(cqv, tag(104), 1); + cq_verify(cqv); + + grpc_call_unref(c); + grpc_call_unref(s); + + cq_verifier_destroy(cqv); + + grpc_metadata_array_destroy(&initial_metadata_recv); + grpc_metadata_array_destroy(&trailing_metadata_recv); + grpc_metadata_array_destroy(&request_metadata_recv); + grpc_call_details_destroy(&call_details); + grpc_slice_unref(details); + + end_test(&f); + config.tear_down_data(&f); +} + void keepalive_timeout(grpc_end2end_test_config config) { test_keepalive_timeout(config); + test_read_delays_keepalive(config); } void keepalive_timeout_pre_init(void) {} From 6b74b1350b259d5b75b3871f94ff3f56ce281fc1 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Wed, 6 Feb 2019 15:59:40 -0800 Subject: [PATCH 3/5] Experiment with timing values to make sure that tests pass --- test/core/end2end/tests/keepalive_timeout.cc | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/test/core/end2end/tests/keepalive_timeout.cc b/test/core/end2end/tests/keepalive_timeout.cc index d4e1fe34af3..38ff37fca6a 100644 --- a/test/core/end2end/tests/keepalive_timeout.cc +++ b/test/core/end2end/tests/keepalive_timeout.cc @@ -91,6 +91,7 @@ static void end_test(grpc_end2end_test_fixture* f) { /* Client sends a request, server replies with a payload, then waits for the keepalive watchdog timeouts before returning status. */ +#if 0 static void test_keepalive_timeout(grpc_end2end_test_config config) { grpc_call* c; grpc_call* s; @@ -219,17 +220,19 @@ static void test_keepalive_timeout(grpc_end2end_test_config config) { end_test(&f); config.tear_down_data(&f); } +#endif -/* Verify that reads reset the keepalive ping timer. The client sends 10 pings - * with a sleep of 5ms in between. It has a configured keepalive timer of 10ms. - * In the success case, each ping ack should reset the keepalive timer so that - * the keepalive ping is never sent. */ +/* Verify that reads reset the keepalive ping timer. The client sends 30 pings + * with a sleep of 10ms in between. It has a configured keepalive timer of + * 200ms. In the success case, each ping ack should reset the keepalive timer so + * that the keepalive ping is never sent. */ static void test_read_delays_keepalive(grpc_end2end_test_config config) { + gpr_log(GPR_ERROR, "ura"); const int kPingIntervalMS = 5; grpc_arg keepalive_arg_elems[3]; keepalive_arg_elems[0].type = GRPC_ARG_INTEGER; keepalive_arg_elems[0].key = const_cast(GRPC_ARG_KEEPALIVE_TIME_MS); - keepalive_arg_elems[0].value.integer = kPingIntervalMS * 2; + keepalive_arg_elems[0].value.integer = 20 * kPingIntervalMS; keepalive_arg_elems[1].type = GRPC_ARG_INTEGER; keepalive_arg_elems[1].key = const_cast(GRPC_ARG_KEEPALIVE_TIMEOUT_MS); keepalive_arg_elems[1].value.integer = 0; @@ -322,7 +325,7 @@ static void test_read_delays_keepalive(grpc_end2end_test_config config) { nullptr); GPR_ASSERT(GRPC_CALL_OK == error); - for (i = 0; i < 10; i++) { + for (i = 0; i < 30; i++) { request_payload = grpc_raw_byte_buffer_create(&request_payload_slice, 1); response_payload = grpc_raw_byte_buffer_create(&response_payload_slice, 1); @@ -374,7 +377,9 @@ static void test_read_delays_keepalive(grpc_end2end_test_config config) { grpc_byte_buffer_destroy(request_payload_recv); grpc_byte_buffer_destroy(response_payload_recv); /* Sleep for a short interval to check if the client sends any pings */ + gpr_log(GPR_ERROR, "before sleep"); gpr_sleep_until(grpc_timeout_milliseconds_to_deadline(kPingIntervalMS)); + gpr_log(GPR_ERROR, "after sleep"); } grpc_slice_unref(request_payload_slice); @@ -426,7 +431,7 @@ static void test_read_delays_keepalive(grpc_end2end_test_config config) { } void keepalive_timeout(grpc_end2end_test_config config) { - test_keepalive_timeout(config); + // test_keepalive_timeout(config); test_read_delays_keepalive(config); } From bfd89bcec589298780af86336b39ead756775a95 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Wed, 6 Feb 2019 17:56:03 -0800 Subject: [PATCH 4/5] Don't run for poll and poll-cv --- test/core/end2end/tests/keepalive_timeout.cc | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/test/core/end2end/tests/keepalive_timeout.cc b/test/core/end2end/tests/keepalive_timeout.cc index 38ff37fca6a..f39a33cff9b 100644 --- a/test/core/end2end/tests/keepalive_timeout.cc +++ b/test/core/end2end/tests/keepalive_timeout.cc @@ -91,7 +91,6 @@ static void end_test(grpc_end2end_test_fixture* f) { /* Client sends a request, server replies with a payload, then waits for the keepalive watchdog timeouts before returning status. */ -#if 0 static void test_keepalive_timeout(grpc_end2end_test_config config) { grpc_call* c; grpc_call* s; @@ -220,15 +219,20 @@ static void test_keepalive_timeout(grpc_end2end_test_config config) { end_test(&f); config.tear_down_data(&f); } -#endif /* Verify that reads reset the keepalive ping timer. The client sends 30 pings * with a sleep of 10ms in between. It has a configured keepalive timer of * 200ms. In the success case, each ping ack should reset the keepalive timer so * that the keepalive ping is never sent. */ static void test_read_delays_keepalive(grpc_end2end_test_config config) { - gpr_log(GPR_ERROR, "ura"); - const int kPingIntervalMS = 5; + char* poller = gpr_getenv("GRPC_POLL_STRATEGY"); + /* It is hard to get the timing right for the polling engines poll and poll-cv */ + if(poller != nullptr && (0 == strcmp(poller, "poll-cv") || 0 == strcmp(poller, "poll"))) { + gpr_free(poller); + return; + } + gpr_free(poller); + const int kPingIntervalMS = 100; grpc_arg keepalive_arg_elems[3]; keepalive_arg_elems[0].type = GRPC_ARG_INTEGER; keepalive_arg_elems[0].key = const_cast(GRPC_ARG_KEEPALIVE_TIME_MS); @@ -377,9 +381,7 @@ static void test_read_delays_keepalive(grpc_end2end_test_config config) { grpc_byte_buffer_destroy(request_payload_recv); grpc_byte_buffer_destroy(response_payload_recv); /* Sleep for a short interval to check if the client sends any pings */ - gpr_log(GPR_ERROR, "before sleep"); gpr_sleep_until(grpc_timeout_milliseconds_to_deadline(kPingIntervalMS)); - gpr_log(GPR_ERROR, "after sleep"); } grpc_slice_unref(request_payload_slice); @@ -431,7 +433,7 @@ static void test_read_delays_keepalive(grpc_end2end_test_config config) { } void keepalive_timeout(grpc_end2end_test_config config) { - // test_keepalive_timeout(config); + test_keepalive_timeout(config); test_read_delays_keepalive(config); } From 5a9eb31a3e6ca2aa80bd41e7018ccabd71a4e9c1 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Wed, 6 Feb 2019 18:15:28 -0800 Subject: [PATCH 5/5] Clang format --- test/core/end2end/tests/keepalive_timeout.cc | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/test/core/end2end/tests/keepalive_timeout.cc b/test/core/end2end/tests/keepalive_timeout.cc index f39a33cff9b..c4025e93b82 100644 --- a/test/core/end2end/tests/keepalive_timeout.cc +++ b/test/core/end2end/tests/keepalive_timeout.cc @@ -226,8 +226,10 @@ static void test_keepalive_timeout(grpc_end2end_test_config config) { * that the keepalive ping is never sent. */ static void test_read_delays_keepalive(grpc_end2end_test_config config) { char* poller = gpr_getenv("GRPC_POLL_STRATEGY"); - /* It is hard to get the timing right for the polling engines poll and poll-cv */ - if(poller != nullptr && (0 == strcmp(poller, "poll-cv") || 0 == strcmp(poller, "poll"))) { + /* It is hard to get the timing right for the polling engines poll and poll-cv + */ + if (poller != nullptr && + (0 == strcmp(poller, "poll-cv") || 0 == strcmp(poller, "poll"))) { gpr_free(poller); return; }