Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add LogRecord observed timestamp field #5370

Merged
merged 1 commit into from
Apr 15, 2023
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
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,16 @@ public LogRecordBuilder setTimestamp(Instant instant) {
return this;
}

@Override
public LogRecordBuilder setObservedTimestamp(long timestamp, TimeUnit unit) {
return this;
}

@Override
public LogRecordBuilder setObservedTimestamp(Instant instant) {
return this;
}

@Override
public LogRecordBuilder setContext(Context context) {
return this;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,26 @@ public interface LogRecordBuilder {
*/
LogRecordBuilder setTimestamp(Instant instant);

/**
* Set the epoch {@code observedTimestamp}, using the timestamp and unit.
*
* <p>The {@code observedTimestamp} is the time at which the log record was observed. If unset, it
* will be set to the {@code timestamp}. {@code observedTimestamp} may be different from {@code
* timestamp} if logs are being processed asynchronously (e.g. from a file or on a different
* thread).
*/
LogRecordBuilder setObservedTimestamp(long timestamp, TimeUnit unit);

/**
* Set the {@code observedTimestamp}, using the instant.
*
* <p>The {@code observedTimestamp} is the time at which the log record was observed. If unset, it
* will be set to the {@code timestamp}. {@code observedTimestamp} may be different from {@code
* timestamp} if logs are being processed asynchronously (e.g. from a file or on a different
* thread).
*/
LogRecordBuilder setObservedTimestamp(Instant instant);

/** Set the context. */
LogRecordBuilder setContext(Context context);

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@ void buildAndEmit() {
.logRecordBuilder()
.setTimestamp(100, TimeUnit.SECONDS)
.setTimestamp(Instant.now())
.setObservedTimestamp(100, TimeUnit.SECONDS)
.setObservedTimestamp(Instant.now())
jack-berg marked this conversation as resolved.
Show resolved Hide resolved
.setContext(Context.root())
.setSeverity(Severity.DEBUG)
.setSeverityText("debug")
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,7 @@ public static LogRecordData generateFakeLogRecordData() {
.setSeverity(Severity.INFO)
.setSeverityText(Severity.INFO.name())
.setTimestamp(Instant.now())
.setObservedTimestamp(Instant.now().plusNanos(100))
jack-berg marked this conversation as resolved.
Show resolved Hide resolved
.build();
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,20 @@ public LogRecordDataAssert hasTimestamp(long timestampEpochNanos) {
return this;
}

/** Asserts the log has the given epoch {@code observedTimestamp}. */
public LogRecordDataAssert hasObservedTimestamp(long observedEpochNanos) {
isNotNull();
if (actual.getObservedTimestampEpochNanos() != observedEpochNanos) {
failWithActualExpectedAndMessage(
actual.getObservedTimestampEpochNanos(),
observedEpochNanos,
"Expected log to have observed timestamp <%s> nanos but was <%s>",
observedEpochNanos,
actual.getObservedTimestampEpochNanos());
}
return this;
}

/** Asserts the log has the given span context. */
public LogRecordDataAssert hasSpanContext(SpanContext spanContext) {
isNotNull();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@ public static Builder builder() {
.setResource(Resource.empty())
.setInstrumentationScopeInfo(InstrumentationScopeInfo.empty())
.setTimestamp(0, TimeUnit.NANOSECONDS)
.setObservedTimestamp(0, TimeUnit.NANOSECONDS)
.setSpanContext(SpanContext.getInvalid())
.setSeverity(Severity.UNDEFINED_SEVERITY_NUMBER)
.setBody("")
Expand Down Expand Up @@ -81,6 +82,32 @@ public Builder setTimestamp(long timestamp, TimeUnit unit) {
*/
abstract Builder setTimestampEpochNanos(long epochNanos);

/**
* Set the {@code observedTimestamp}, using the instant.
*
* <p>The {@code observedTimestamp} is the time at which the log record was observed.
*/
public Builder setObservedTimestamp(Instant instant) {
return setObservedTimestampEpochNanos(
TimeUnit.SECONDS.toNanos(instant.getEpochSecond()) + instant.getNano());
}

/**
* Set the epoch {@code observedTimestamp}, using the timestamp and unit.
*
* <p>The {@code observedTimestamp} is the time at which the log record was observed.
*/
public Builder setObservedTimestamp(long timestamp, TimeUnit unit) {
return setObservedTimestampEpochNanos(unit.toNanos(timestamp));
}

/**
* Set the epoch {@code observedTimestamp}.
*
* <p>The {@code observedTimestamp} is the time at which the log record was observed.
*/
abstract Builder setObservedTimestampEpochNanos(long epochNanos);

/** Set the span context. */
public abstract Builder setSpanContext(SpanContext spanContext);

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,7 @@ public class LogAssertionsTest {
.setResource(RESOURCE)
.setInstrumentationScopeInfo(INSTRUMENTATION_SCOPE_INFO)
.setTimestamp(100, TimeUnit.NANOSECONDS)
.setObservedTimestamp(200, TimeUnit.NANOSECONDS)
.setSpanContext(
SpanContext.create(
TRACE_ID, SPAN_ID, TraceFlags.getDefault(), TraceState.getDefault()))
Expand All @@ -65,6 +66,7 @@ void passing() {
.hasResource(RESOURCE)
.hasInstrumentationScope(INSTRUMENTATION_SCOPE_INFO)
.hasTimestamp(100)
.hasObservedTimestamp(200)
.hasSpanContext(
SpanContext.create(TRACE_ID, SPAN_ID, TraceFlags.getDefault(), TraceState.getDefault()))
.hasSeverity(Severity.INFO)
Expand Down Expand Up @@ -133,6 +135,7 @@ void failure() {
assertThatThrownBy(
() -> assertThat(LOG_DATA).hasInstrumentationScope(InstrumentationScopeInfo.empty()));
assertThatThrownBy(() -> assertThat(LOG_DATA).hasTimestamp(200));
assertThatThrownBy(() -> assertThat(LOG_DATA).hasObservedTimestamp(100));
assertThatThrownBy(
() ->
assertThat(LOG_DATA)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ final class SdkLogRecordBuilder implements LogRecordBuilder {

private final InstrumentationScopeInfo instrumentationScopeInfo;
private long timestampEpochNanos;
private long observedTimestampEpochNanos;
@Nullable private Context context;
private Severity severity = Severity.UNDEFINED_SEVERITY_NUMBER;
@Nullable private String severityText;
Expand All @@ -51,6 +52,19 @@ public SdkLogRecordBuilder setTimestamp(Instant instant) {
return this;
}

@Override
public LogRecordBuilder setObservedTimestamp(long timestamp, TimeUnit unit) {
this.observedTimestampEpochNanos = unit.toNanos(timestamp);
return this;
}

@Override
public LogRecordBuilder setObservedTimestamp(Instant instant) {
this.observedTimestampEpochNanos =
TimeUnit.SECONDS.toNanos(instant.getEpochSecond()) + instant.getNano();
return this;
}

@Override
public SdkLogRecordBuilder setContext(Context context) {
this.context = context;
Expand Down Expand Up @@ -95,6 +109,10 @@ public void emit() {
return;
}
Context context = this.context == null ? Context.current() : this.context;
long observedTimestampEpochNanos =
this.observedTimestampEpochNanos == 0
? this.loggerSharedState.getClock().now()
: this.observedTimestampEpochNanos;
jack-berg marked this conversation as resolved.
Show resolved Hide resolved
loggerSharedState
.getLogRecordProcessor()
.onEmit(
Expand All @@ -103,7 +121,8 @@ public void emit() {
loggerSharedState.getLogLimits(),
loggerSharedState.getResource(),
instrumentationScopeInfo,
this.timestampEpochNanos,
timestampEpochNanos,
observedTimestampEpochNanos,
Span.fromContext(context).getSpanContext(),
severity,
severityText,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ static SdkLogRecordData create(
Resource resource,
InstrumentationScopeInfo instrumentationScopeInfo,
long epochNanos,
long observedEpochNanos,
SpanContext spanContext,
Severity severity,
@Nullable String severityText,
Expand All @@ -37,6 +38,7 @@ static SdkLogRecordData create(
resource,
instrumentationScopeInfo,
epochNanos,
observedEpochNanos,
spanContext,
severity,
severityText,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,8 @@ class SdkReadWriteLogRecord implements ReadWriteLogRecord {
private final LogLimits logLimits;
private final Resource resource;
private final InstrumentationScopeInfo instrumentationScopeInfo;
private final long epochNanos;
private final long timestampEpochNanos;
private final long observedTimestampEpochNanos;
private final SpanContext spanContext;
private final Severity severity;
@Nullable private final String severityText;
Expand All @@ -39,7 +40,8 @@ private SdkReadWriteLogRecord(
LogLimits logLimits,
Resource resource,
InstrumentationScopeInfo instrumentationScopeInfo,
long epochNanos,
long timestampEpochNanos,
long observedTimestampEpochNanos,
SpanContext spanContext,
Severity severity,
@Nullable String severityText,
Expand All @@ -48,7 +50,8 @@ private SdkReadWriteLogRecord(
this.logLimits = logLimits;
this.resource = resource;
this.instrumentationScopeInfo = instrumentationScopeInfo;
this.epochNanos = epochNanos;
this.timestampEpochNanos = timestampEpochNanos;
this.observedTimestampEpochNanos = observedTimestampEpochNanos;
this.spanContext = spanContext;
this.severity = severity;
this.severityText = severityText;
Expand All @@ -61,7 +64,8 @@ static SdkReadWriteLogRecord create(
LogLimits logLimits,
Resource resource,
InstrumentationScopeInfo instrumentationScopeInfo,
long epochNanos,
long timestampEpochNanos,
long observedTimestampEpochNanos,
SpanContext spanContext,
Severity severity,
@Nullable String severityText,
Expand All @@ -71,7 +75,8 @@ static SdkReadWriteLogRecord create(
logLimits,
resource,
instrumentationScopeInfo,
epochNanos,
timestampEpochNanos,
observedTimestampEpochNanos,
spanContext,
severity,
severityText,
Expand Down Expand Up @@ -110,7 +115,8 @@ public LogRecordData toLogRecordData() {
return SdkLogRecordData.create(
resource,
instrumentationScopeInfo,
epochNanos,
timestampEpochNanos,
observedTimestampEpochNanos,
spanContext,
severity,
severityText,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,9 @@ public interface LogRecordData {
/** Returns the timestamp at which the log record occurred, in epoch nanos. */
long getTimestampEpochNanos();

/** Returns the timestamp at which the log record was observed, in epoch nanos. */
long getObservedTimestampEpochNanos();

/** Return the span context for this log, or {@link SpanContext#getInvalid()} if unset. */
SpanContext getSpanContext();

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@
import io.opentelemetry.api.trace.TraceFlags;
import io.opentelemetry.api.trace.TraceState;
import io.opentelemetry.context.Context;
import io.opentelemetry.sdk.common.Clock;
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
import io.opentelemetry.sdk.logs.data.Body;
import io.opentelemetry.sdk.resources.Resource;
Expand All @@ -38,6 +39,7 @@ class SdkLogRecordBuilderTest {
private static final InstrumentationScopeInfo SCOPE_INFO = InstrumentationScopeInfo.empty();

@Mock LoggerSharedState loggerSharedState;
@Mock Clock clock;

private final AtomicReference<ReadWriteLogRecord> emittedLog = new AtomicReference<>();
private SdkLogRecordBuilder builder;
Expand All @@ -48,13 +50,15 @@ void setup() {
when(loggerSharedState.getLogRecordProcessor())
.thenReturn((context, logRecord) -> emittedLog.set(logRecord));
when(loggerSharedState.getResource()).thenReturn(RESOURCE);
when(loggerSharedState.getClock()).thenReturn(clock);

builder = new SdkLogRecordBuilder(loggerSharedState, SCOPE_INFO);
}

@Test
void emit_AllFields() {
Instant timestamp = Instant.now();
Instant observedTimestamp = Instant.now().plusNanos(100);

String bodyStr = "body";
String sevText = "sevText";
Expand All @@ -69,6 +73,8 @@ void emit_AllFields() {
builder.setBody(bodyStr);
builder.setTimestamp(123, TimeUnit.SECONDS);
builder.setTimestamp(timestamp);
builder.setObservedTimestamp(456, TimeUnit.SECONDS);
builder.setObservedTimestamp(observedTimestamp);
builder.setAttribute(null, null);
builder.setAttribute(AttributeKey.stringKey("k1"), "v1");
builder.setAllAttributes(Attributes.builder().put("k2", "v2").put("k3", "v3").build());
Expand All @@ -81,6 +87,9 @@ void emit_AllFields() {
.hasInstrumentationScope(SCOPE_INFO)
.hasBody(bodyStr)
.hasTimestamp(TimeUnit.SECONDS.toNanos(timestamp.getEpochSecond()) + timestamp.getNano())
.hasObservedTimestamp(
TimeUnit.SECONDS.toNanos(observedTimestamp.getEpochSecond())
+ observedTimestamp.getNano())
.hasAttributes(Attributes.builder().put("k1", "v1").put("k2", "v2").put("k3", "v3").build())
.hasSpanContext(spanContext)
.hasSeverity(severity)
Expand All @@ -89,13 +98,16 @@ void emit_AllFields() {

@Test
void emit_NoFields() {
when(clock.now()).thenReturn(10L);

builder.emit();

assertThat(emittedLog.get().toLogRecordData())
.hasResource(RESOURCE)
.hasInstrumentationScope(SCOPE_INFO)
.hasBody(Body.empty().asString())
.hasTimestamp(0L)
.hasObservedTimestamp(10L)
.hasAttributes(Attributes.empty())
.hasSpanContext(SpanContext.getInvalid())
.hasSeverity(Severity.UNDEFINED_SEVERITY_NUMBER);
Expand Down