[ETW] Fix ETW Log Exporter: incorrect timestamp, traceId, and spanId (open-telemetry#3836)

Author: ThomsonTan

CHANGELOG.md

@@ -15,6 +15,9 @@ Increment the:
 
 ## [Unreleased]
 
+* [ETW] Fix ETW Log Exporter: incorrect timestamp, traceId, and spanId
+  [#3836](https://github.com/open-telemetry/opentelemetry-cpp/pull/3836)
+
 * [ETW] Fix infinite loop in ETWProvider::close
   [#3827](https://github.com/open-telemetry/opentelemetry-cpp/pull/3827)
 

exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h

@@ -31,6 +31,11 @@
 #include "opentelemetry/trace/span_id.h"
 #include "opentelemetry/trace/trace_id.h"
 
+#include "opentelemetry/context/runtime_context.h"
+#include "opentelemetry/trace/span.h"
+#include "opentelemetry/trace/span_context.h"
+#include "opentelemetry/trace/span_metadata.h"
+
 #include "opentelemetry/exporters/etw/etw_config.h"
 #include "opentelemetry/exporters/etw/etw_fields.h"
 #include "opentelemetry/exporters/etw/etw_properties.h"
@@ -121,7 +126,7 @@ class LogRecord : public opentelemetry::logs::LogRecord
 
   std::unordered_map<std::string, opentelemetry::common::AttributeValue> attributes_map_;
   opentelemetry::common::AttributeValue body_ = opentelemetry::nostd::string_view();
-  opentelemetry::common::SystemTimestamp timestamp_;
+  opentelemetry::common::SystemTimestamp timestamp_;  // unset (epoch) by default
   opentelemetry::common::SystemTimestamp observed_timestamp_ = std::chrono::system_clock::now();
 
   opentelemetry::trace::TraceId trace_id_;
@@ -194,7 +199,44 @@ class Logger : public opentelemetry::logs::Logger
 
   nostd::unique_ptr<opentelemetry::logs::LogRecord> CreateLogRecord() noexcept
   {
-    return nostd::unique_ptr<opentelemetry::logs::LogRecord>(new LogRecord());
+    nostd::unique_ptr<LogRecord> log_record(new LogRecord());
+
+    // Populate trace context from the current active span (if any)
+    if (opentelemetry::context::RuntimeContext::GetCurrent().HasKey(opentelemetry::trace::kSpanKey))
+    {
+      opentelemetry::context::ContextValue context_value =
+          opentelemetry::context::RuntimeContext::GetCurrent().GetValue(
+              opentelemetry::trace::kSpanKey);
+      if (opentelemetry::nostd::holds_alternative<
+              opentelemetry::nostd::shared_ptr<opentelemetry::trace::Span>>(context_value))
+      {
+        opentelemetry::nostd::shared_ptr<opentelemetry::trace::Span> &span =
+            opentelemetry::nostd::get<opentelemetry::nostd::shared_ptr<opentelemetry::trace::Span>>(
+                context_value);
+        if (span)
+        {
+          log_record->SetTraceId(span->GetContext().trace_id());
+          log_record->SetSpanId(span->GetContext().span_id());
+          log_record->SetTraceFlags(span->GetContext().trace_flags());
+        }
+      }
+      else if (opentelemetry::nostd::holds_alternative<
+                   opentelemetry::nostd::shared_ptr<opentelemetry::trace::SpanContext>>(
+                   context_value))
+      {
+        opentelemetry::nostd::shared_ptr<opentelemetry::trace::SpanContext> &span_context =
+            opentelemetry::nostd::get<
+                opentelemetry::nostd::shared_ptr<opentelemetry::trace::SpanContext>>(context_value);
+        if (span_context)
+        {
+          log_record->SetTraceId(span_context->trace_id());
+          log_record->SetSpanId(span_context->span_id());
+          log_record->SetTraceFlags(span_context->trace_flags());
+        }
+      }
+    }
+
+    return nostd::unique_ptr<opentelemetry::logs::LogRecord>(log_record.release());
   }
 
   using opentelemetry::logs::Logger::EmitLogRecord;
@@ -305,6 +347,11 @@ class Logger : public opentelemetry::logs::Logger
     }
     evt[ETW_FIELD_PAYLOAD_NAME]              = std::string(name.data(), name.size());
     std::chrono::system_clock::time_point ts = timestamp;
+    // Per OTel Log Data Model: if timestamp is unset (epoch), fall back to observed time (now)
+    if (ts.time_since_epoch().count() == 0)
+    {
+      ts = std::chrono::system_clock::now();
+    }
     int64_t tsNs =
         std::chrono::duration_cast<std::chrono::nanoseconds>(ts.time_since_epoch()).count();
     evt[ETW_FIELD_TIMESTAMP] = utils::formatUtcTimestampNsAsISO8601(tsNs);

exporters/etw/test/etw_logger_test.cc

@@ -11,6 +11,7 @@
 #  define OPENTELEMETRY_ATTRIBUTE_TIMESTAMP_PREVIEW
 
 #  include "opentelemetry/exporters/etw/etw_logger_exporter.h"
+#  include "opentelemetry/exporters/etw/etw_tracer_exporter.h"
 #  include "opentelemetry/sdk/trace/simple_processor.h"
 
 using namespace OPENTELEMETRY_NAMESPACE;
@@ -195,4 +196,112 @@ TEST(ETWLogger, LoggerCheckWithTimestampAttributes)
       logger->Debug("This is a debug log body", opentelemetry::common::MakeAttributes(attribs)));
 }
 
+/**
+ * @brief Test that LogRecord created within an active span context
+ *        inherits TraceId, SpanId, and TraceFlags from the current span.
+ *
+ * This test verifies the fix for issue #3830 where traceId and spanId
+ * were incorrectly reported as all zeros.
+ */
+TEST(ETWLogger, LoggerInheritsTraceContextFromActiveSpan)
+{
+  std::string providerName = kGlobalProviderName;
+
+  // Create tracer and logger providers
+  exporter::etw::TracerProvider tp;
+  exporter::etw::LoggerProvider lp;
+
+  auto tracer = tp.GetTracer(providerName);
+  auto logger = lp.GetLogger(providerName, "test");
+
+  // Create a span and set it as the active span
+  auto span  = tracer->StartSpan("TestSpan");
+  auto scope = tracer->WithActiveSpan(span);
+
+  // Get the span's trace context for verification
+  auto span_context = span->GetContext();
+
+  // Create a log record while the span is active
+  auto log_record = logger->CreateLogRecord();
+  ASSERT_NE(log_record, nullptr);
+
+  // Cast to ETW LogRecord to access trace context
+  auto *etw_record = static_cast<exporter::etw::LogRecord *>(log_record.get());
+
+  // Verify TraceId matches the active span's TraceId
+  EXPECT_EQ(etw_record->GetTraceId(), span_context.trace_id());
+
+  // Verify SpanId matches the active span's SpanId
+  EXPECT_EQ(etw_record->GetSpanId(), span_context.span_id());
+
+  // Verify TraceFlags match
+  EXPECT_EQ(etw_record->GetTraceFlags(), span_context.trace_flags());
+
+  // Emit the log (should not throw)
+  EXPECT_NO_THROW(logger->EmitLogRecord(std::move(log_record)));
+
+  span->End();
+}
+
+/**
+ * @brief Test that LogRecord created without an active span context
+ *        has default (invalid/zero) TraceId and SpanId.
+ */
+TEST(ETWLogger, LoggerWithoutActiveSpanHasDefaultTraceContext)
+{
+  std::string providerName = kGlobalProviderName;
+  exporter::etw::LoggerProvider lp;
+
+  auto logger = lp.GetLogger(providerName, "test");
+
+  // Create a log record without any active span
+  auto log_record = logger->CreateLogRecord();
+  ASSERT_NE(log_record, nullptr);
+
+  auto *etw_record = static_cast<exporter::etw::LogRecord *>(log_record.get());
+
+  // TraceId and SpanId should be invalid (all zeros) when no span is active
+  EXPECT_FALSE(etw_record->GetTraceId().IsValid());
+  EXPECT_FALSE(etw_record->GetSpanId().IsValid());
+
+  EXPECT_NO_THROW(logger->EmitLogRecord(std::move(log_record)));
+}
+
+/**
+ * @brief Test that LogRecord timestamp defaults to a valid time (not epoch).
+ *
+ * This test verifies the fix for issue #3830 where timestamp was
+ * incorrectly reported as 1970-01-01 (epoch).
+ */
+TEST(ETWLogger, LoggerTimestampIsNotEpoch)
+{
+  std::string providerName = kGlobalProviderName;
+  exporter::etw::LoggerProvider lp;
+
+  auto logger = lp.GetLogger(providerName, "test");
+
+  // Capture time before creating log record
+  auto before = std::chrono::system_clock::now();
+
+  auto log_record = logger->CreateLogRecord();
+  ASSERT_NE(log_record, nullptr);
+
+  // Capture time after creating log record
+  auto after = std::chrono::system_clock::now();
+
+  auto *etw_record = static_cast<exporter::etw::LogRecord *>(log_record.get());
+
+  // Get the observed timestamp (which should be initialized to now())
+  std::chrono::system_clock::time_point observed_ts = etw_record->GetObservedTimestamp();
+
+  // Verify observed timestamp is not epoch (1970-01-01)
+  EXPECT_GT(observed_ts.time_since_epoch().count(), 0);
+
+  // Verify observed timestamp is within the expected range
+  EXPECT_GE(observed_ts, before);
+  EXPECT_LE(observed_ts, after);
+
+  EXPECT_NO_THROW(logger->EmitLogRecord(std::move(log_record)));
+}
+
 #endif  // _WIN32