From b1147052d362e13ee25418d0ee079b2d7ec626c3 Mon Sep 17 00:00:00 2001
From: Prashant Jaikumar <pjaikumar@google.com>
Date: Fri, 24 May 2019 14:10:11 -0700
Subject: [PATCH] cfstream_test: print HTTP2 stream id of completed RPCs

Log stream id of completed RPCs. This helps in debugging test failures.
---
 test/cpp/end2end/cfstream_test.cc | 37 ++++++++++++++++++++++---------
 1 file changed, 27 insertions(+), 10 deletions(-)

diff --git a/test/cpp/end2end/cfstream_test.cc b/test/cpp/end2end/cfstream_test.cc
index 59cf98ffc20..b0c55616de3 100644
--- a/test/cpp/end2end/cfstream_test.cc
+++ b/test/cpp/end2end/cfstream_test.cc
@@ -42,6 +42,7 @@
 #include "src/core/lib/gpr/env.h"
 
 #include "src/proto/grpc/testing/echo.grpc.pb.h"
+#include "test/core/util/debugger_macros.h"
 #include "test/core/util/port.h"
 #include "test/core/util/test_config.h"
 #include "test/cpp/end2end/test_service_impl.h"
@@ -144,6 +145,18 @@ class CFStreamTest : public ::testing::TestWithParam<TestScenario> {
     return CreateCustomChannel(server_address.str(), channel_creds, args);
   }
 
+  int GetStreamID(ClientContext& context) {
+    int stream_id = 0;
+    grpc_call* call = context.c_call();
+    if (call) {
+      grpc_chttp2_stream* stream = grpc_chttp2_stream_from_call(call);
+      if (stream) {
+        stream_id = stream->id;
+      }
+    }
+    return stream_id;
+  }
+
   void SendRpc(
       const std::unique_ptr<grpc::testing::EchoTestService::Stub>& stub,
       bool expect_success = false) {
@@ -153,10 +166,13 @@ class CFStreamTest : public ::testing::TestWithParam<TestScenario> {
     request.set_message(msg);
     ClientContext context;
     Status status = stub->Echo(&context, request, response.get());
+    int stream_id = GetStreamID(context);
     if (status.ok()) {
+      gpr_log(GPR_DEBUG, "RPC with stream_id %d succeeded", stream_id);
       EXPECT_EQ(msg, response->message());
     } else {
-      gpr_log(GPR_DEBUG, "RPC failed: %s", status.error_message().c_str());
+      gpr_log(GPR_DEBUG, "RPC with stream_id %d failed: %s", stream_id,
+              status.error_message().c_str());
     }
     if (expect_success) {
       EXPECT_TRUE(status.ok());
@@ -359,14 +375,17 @@ TEST_P(CFStreamTest, NetworkFlapRpcsInFlight) {
       ++total_completions;
       GPR_ASSERT(ok);
       AsyncClientCall* call = static_cast<AsyncClientCall*>(got_tag);
+      int stream_id = GetStreamID(call->context);
       if (!call->status.ok()) {
-        gpr_log(GPR_DEBUG, "RPC failed with error: %s",
-                call->status.error_message().c_str());
+        gpr_log(GPR_DEBUG, "RPC with stream_id %d failed with error: %s",
+                stream_id, call->status.error_message().c_str());
         // Bring network up when RPCs start failing
         if (network_down) {
           NetworkUp();
           network_down = false;
         }
+      } else {
+        gpr_log(GPR_DEBUG, "RPC with stream_id %d succeeded", stream_id);
       }
       delete call;
     }
@@ -393,21 +412,19 @@ TEST_P(CFStreamTest, ConcurrentRpc) {
   std::thread thd = std::thread([this, &rpcs_sent]() {
     void* got_tag;
     bool ok = false;
-    bool network_down = true;
     int total_completions = 0;
 
     while (CQNext(&got_tag, &ok)) {
       ++total_completions;
       GPR_ASSERT(ok);
       AsyncClientCall* call = static_cast<AsyncClientCall*>(got_tag);
+      int stream_id = GetStreamID(call->context);
       if (!call->status.ok()) {
-        gpr_log(GPR_DEBUG, "RPC failed: %s",
-                call->status.error_message().c_str());
+        gpr_log(GPR_DEBUG, "RPC with stream_id %d failed with error: %s",
+                stream_id, call->status.error_message().c_str());
         // Bring network up when RPCs start failing
-        if (network_down) {
-          NetworkUp();
-          network_down = false;
-        }
+      } else {
+        gpr_log(GPR_DEBUG, "RPC with stream_id %d succeeded", stream_id);
       }
       delete call;
     }