Report a read or write error only when it is the result

Choosing between an error line that can describe an export the caller was
told succeeded, and a debug line the default log level hides, was a false
choice. recordCompletion() now reports whether it was the write that
decided the outcome, and the log follows that.

So an I/O error that ends the export says so at error level, and one that
arrives after a response has already succeeded says nothing.

Also: give the cases a CTest timeout, since a wait that stops returning
would otherwise stall the job rather than fail it; and drop the claim that
the request timeout arrives as a TimedOut event, which nothing dispatches.

Author: thc1006

exporters/elasticsearch/CMakeLists.txt

@@ -55,4 +55,8 @@ if(BUILD_TESTING)
     TARGET es_log_record_exporter_test
     TEST_PREFIX exporter.
     TEST_LIST es_log_record_exporter_test)
+
+  # These cases exist to catch a wait that never returns. Without a per test
+  # bound a regression stalls the job instead of failing it.
+  set_tests_properties(${es_log_record_exporter_test} PROPERTIES TIMEOUT 30)
 endif() # BUILD_TESTING

exporters/elasticsearch/src/es_log_record_exporter.cc

@@ -108,8 +108,8 @@ class ResponseHandler : public http_client::EventHandler
 
   /**
    * A method the user calls to block their thread until the request has either produced a
-   * response or failed. The longest duration is the timeout of the request, set by
-   * SetTimeoutMs(), which arrives here as a TimedOut session event.
+   * response or failed. It has no deadline of its own and relies on the HTTP client reporting
+   * one of the terminal session states.
    */
   bool waitForResponse()
   {
@@ -182,15 +182,19 @@ class ResponseHandler : public http_client::EventHandler
         recordCompletion(CompletionState::Failure);
         break;
       case http_client::SessionState::ReadError:
-        OTEL_INTERNAL_LOG_DEBUG("[ES Log Exporter] Read error");
-        // Kept at debug, like Destroyed above: recording is first writer wins, so this can
-        // arrive after a response has already succeeded, and an error line there would not
-        // describe the outcome Export() reports.
-        recordCompletion(CompletionState::Failure);
+        // Reported only when this is the outcome Export() returns. Recording is first writer
+        // wins, so either of these can arrive after a response has already succeeded, and an
+        // error line there would describe a failure the caller was never told about.
+        if (recordCompletion(CompletionState::Failure))
+        {
+          OTEL_INTERNAL_LOG_ERROR("[ES Log Exporter] Read error");
+        }
         break;
       case http_client::SessionState::WriteError:
-        OTEL_INTERNAL_LOG_DEBUG("[ES Log Exporter] Write error");
-        recordCompletion(CompletionState::Failure);
+        if (recordCompletion(CompletionState::Failure))
+        {
+          OTEL_INTERNAL_LOG_ERROR("[ES Log Exporter] Write error");
+        }
         break;
       case http_client::SessionState::Cancelled:
         OTEL_INTERNAL_LOG_ERROR("[ES Log Exporter] (manually) cancelled");
@@ -211,22 +215,27 @@ class ResponseHandler : public http_client::EventHandler
    * Record the outcome of the request, first writer wins, then release any waiter. Keeping the
    * first outcome means a session destroyed after a successful response does not overwrite it.
    */
-  void recordCompletion(CompletionState state)
+  /// Returns whether this call is the one that decided the outcome.
+  bool recordCompletion(CompletionState state)
   {
+    bool recorded = false;
     {
       std::unique_lock<std::mutex> lk(mutex_);
-      recordCompletionLocked(state);
+      recorded = recordCompletionLocked(state);
     }
     cv_.notify_all();
+    return recorded;
   }
 
   /// As recordCompletion(), for callers that already hold mutex_ and notify themselves.
-  void recordCompletionLocked(CompletionState state)
+  bool recordCompletionLocked(CompletionState state)
   {
-    if (completion_ == CompletionState::Pending)
+    if (completion_ != CompletionState::Pending)
     {
-      completion_ = state;
+      return false;
     }
+    completion_ = state;
+    return true;
   }
 
   // Define a condition variable and mutex

exporters/elasticsearch/test/es_log_record_exporter_test.cc

@@ -353,8 +353,8 @@ TEST(ElasticsearchLogsExporterSyncTests, SessionDestroyedAfterAResponseKeepsTheS
   EXPECT_EQ(result, opentelemetry::sdk::common::ExportResult::kSuccess);
 }
 
-// Same rule for the two states this change makes terminal. It is why they log at debug rather
-// than error: reaching one of them says nothing about the result Export() goes on to report.
+// Same rule for the two states this change makes terminal, and the reason their error line is
+// conditional: reaching one of them says nothing on its own about the result Export() reports.
 TEST(ElasticsearchLogsExporterSyncTests, IoErrorAfterAResponseKeepsTheSuccess)
 {
   SKIP_WITHOUT_SYNC_EXPORT();
@@ -369,3 +369,21 @@ TEST(ElasticsearchLogsExporterSyncTests, IoErrorAfterAResponseKeepsTheSuccess)
     EXPECT_EQ(result, opentelemetry::sdk::common::ExportResult::kSuccess);
   }
 }
+
+// The mirror image, and the case where the error line is the only diagnostic the caller gets:
+// the I/O error is recorded first, so a response arriving afterwards does not rescue the export.
+TEST(ElasticsearchLogsExporterSyncTests, IoErrorBeforeAResponseKeepsTheFailure)
+{
+  SKIP_WITHOUT_SYNC_EXPORT();
+  for (const auto state :
+       {http_client::SessionState::ReadError, http_client::SessionState::WriteError})
+  {
+    SCOPED_TRACE(static_cast<int>(state));
+    const auto result = ExportWith([state](http_client::EventHandler &handler) {
+      handler.OnEvent(state, "");
+      FakeResponse response(200, kAcceptedBody);
+      handler.OnResponse(response);
+    });
+    EXPECT_EQ(result, opentelemetry::sdk::common::ExportResult::kFailure);
+  }
+}