ext_proc: Increase log verbosity in a possible flake test (#36583)

Commit Message: Increase log verbosity and add tracing logs to help
diagnose potential flakiness in the GetAndCloseStreamWithTracing test
case.
Additional Description: As per discussed in
#36041 (comment)
Risk Level: Low

---------

Signed-off-by: Fernando Cainelli <fernando.cainelli-external@getyourguide.com>

test/extensions/filters/http/ext_proc/ext_proc_integration_test.cc

@@ -736,7 +736,14 @@ TEST_P(ExtProcIntegrationTest, GetAndCloseStream) {
 }
 
 TEST_P(ExtProcIntegrationTest, GetAndCloseStreamWithTracing) {
+  // Turn on debug to troubleshoot possible flaky test.
+  // TODO(cainelli): Remove this and the debug logs in the tracer test filter after a test failure
+  // occurs.
+  LogLevelSetter save_levels(spdlog::level::trace);
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing Initializing config");
   initializeConfig();
+
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing configuring test tracer");
   config_helper_.addConfigModifier([&](HttpConnectionManager& cm) {
     test::integration::filters::ExpectSpan ext_proc_span;
     ext_proc_span.set_operation_name(
@@ -759,19 +766,31 @@ TEST_P(ExtProcIntegrationTest, GetAndCloseStreamWithTracing) {
     tracing->mutable_provider()->mutable_typed_config()->PackFrom(test_config);
   });
 
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing initializing http integration test");
   HttpIntegrationTest::initialize();
+
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing sending downstream request");
   auto response = sendDownstreamRequest(absl::nullopt);
 
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing waiting for first message");
   ProcessingRequest request_headers_msg;
   waitForFirstMessage(*grpc_upstreams_[0], request_headers_msg);
 
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing starting gRPC stream");
   processor_stream_->startGrpcStream();
   EXPECT_FALSE(processor_stream_->headers().get(LowerCaseString("traceparent")).empty())
       << "expected traceparent header";
 
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing finishing gRPC stream");
   processor_stream_->finishGrpcStream(Grpc::Status::Ok);
+
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing handling upstream request");
   handleUpstreamRequest();
+
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing verifying downstream response");
   verifyDownstreamResponse(*response, 200);
+
+  ENVOY_LOG(trace, "GetAndCloseStreamWithTracing done");
 }
 
 TEST_P(ExtProcIntegrationTest, GetAndCloseStreamWithLogging) {

test/extensions/filters/http/ext_proc/tracer_test_filter.cc

@@ -31,9 +31,12 @@ using ExpectedSpansSharedPtr = std::shared_ptr<std::vector<ExpectedSpan>>;
 class Span : public Tracing::Span {
 public:
   Span(const std::string& operation_name, ExpectedSpansSharedPtr& expected_spans)
-      : operation_name_(operation_name), expected_spans_(expected_spans){};
+      : operation_name_(operation_name), expected_spans_(expected_spans) {
+    ENVOY_LOG_MISC(trace, "TestTracer creating span with operation: {}", operation_name);
+  };
 
   ~Span() override {
+    ENVOY_LOG_MISC(trace, "TestTracer asserting span: {}", operation_name_);
     EXPECT_TRUE(finished_) << fmt::format("span not finished in operation: {}", operation_name_);
     for (auto& expect_span : *expected_spans_) {
       if (expect_span.operation_name != operation_name_) {
@@ -54,20 +57,31 @@ class Span : public Tracing::Span {
       expect_span.tested = true;
       break;
     }
+    ENVOY_LOG_MISC(trace, "TestTracer span tagged and finished correctly: {}", operation_name_);
   }
 
   void setTag(absl::string_view name, absl::string_view value) override {
+    ENVOY_LOG_MISC(trace, "TestTracer setTag: {}={}", name, value);
     tags_.insert_or_assign(std::string(name), std::string(value));
+    ENVOY_LOG_MISC(trace, "TestTracer tags size: {}", tags_.size());
   }
 
-  void setOperation(absl::string_view operation_name) override { operation_name_ = operation_name; }
-  void setSampled(bool do_sample) override { sampled_ = do_sample; }
+  void setOperation(absl::string_view operation_name) override {
+    ENVOY_LOG_MISC(trace, "TestTracer setOperation: {}", operation_name);
+    operation_name_ = operation_name;
+  }
+  void setSampled(bool do_sample) override {
+    ENVOY_LOG_MISC(trace, "TestTracer setSampled: {}", do_sample);
+    sampled_ = do_sample;
+  }
 
   void injectContext(Tracing::TraceContext& trace_context,
                      const Tracing::UpstreamContext&) override {
+    ENVOY_LOG_MISC(trace, "TestTracer injectContext");
     std::string traceparent_header_value = "1";
     traceParentHeader().setRefKey(trace_context, traceparent_header_value);
     context_injected_ = true;
+    ENVOY_LOG_MISC(trace, "TestTracer context injected");
   }
   void setBaggage(absl::string_view, absl::string_view) override { /* not implemented */
   }
@@ -88,10 +102,14 @@ class Span : public Tracing::Span {
 
   Tracing::SpanPtr spawnChild(const Tracing::Config&, const std::string& operation_name,
                               SystemTime) override {
+    ENVOY_LOG_MISC(trace, "TestTracer spawnChild: {}", operation_name);
     return std::make_unique<Span>(operation_name, expected_spans_);
   }
 
-  void finishSpan() override { finished_ = true; }
+  void finishSpan() override {
+    ENVOY_LOG_MISC(trace, "TestTracer finishSpan");
+    finished_ = true;
+  }
 
 private:
   std::string operation_name_;
@@ -108,6 +126,7 @@ class Driver : public Tracing::Driver, Logger::Loggable<Logger::Id::tracing> {
   Driver(const test::integration::filters::TracerTestConfig& test_config,
          Server::Configuration::CommonFactoryContext&)
       : expected_spans_(std::make_shared<std::vector<ExpectedSpan>>()) {
+    ENVOY_LOG_MISC(trace, "TestTracer creating driver with config: {}", test_config.DebugString());
     for (const auto& expected_span : test_config.expect_spans()) {
       ExpectedSpan span;
       span.operation_name = expected_span.operation_name();
@@ -116,20 +135,24 @@ class Driver : public Tracing::Driver, Logger::Loggable<Logger::Id::tracing> {
       span.tags.insert(expected_span.tags().begin(), expected_span.tags().end());
       expected_spans_->push_back(span);
     };
+    ENVOY_LOG_MISC(trace, "TestTracer created driver with {} expected spans",
+                   expected_spans_->size());
   };
   // Tracing::Driver
   Tracing::SpanPtr startSpan(const Tracing::Config&, Tracing::TraceContext&,
                              const StreamInfo::StreamInfo&, const std::string& operation_name,
                              Tracing::Decision) override {
-
+    ENVOY_LOG_MISC(trace, "TestTracer startSpan: {}", operation_name);
     return std::make_unique<Span>(operation_name, expected_spans_);
   };
 
   ~Driver() override {
+    ENVOY_LOG_MISC(trace, "TestTracer asserting all spans were tested");
     for (auto& span : *expected_spans_) {
       EXPECT_TRUE(span.tested) << fmt::format("missing span with operation '{}'",
                                               span.operation_name);
     }
+    ENVOY_LOG_MISC(trace, "TestTracer all spans tested");
   };
 
 private: