Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand Down
51 changes: 49 additions & 2 deletions exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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_;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down
109 changes: 109 additions & 0 deletions exporters/etw/test/etw_logger_test.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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
Loading