Fix log4j timestamp (#3137)

Author: trask

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/SecondEntryPoint.java

@@ -648,7 +648,7 @@ private static SdkLoggerProviderBuilder configureLogging(
               .setScheduleDelay(getBatchProcessorDelay())
               .build();
 
-      builder.addLogRecordProcessor(batchLogProcessor);
+      builder.addLogRecordProcessor(new TimestampingLogRecordProcessor(batchLogProcessor));
     }
 
     return builder;

agent/agent-tooling/src/main/java/com/microsoft/applicationinsights/agent/internal/init/TimestampingLogRecordProcessor.java

@@ -0,0 +1,139 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+package com.microsoft.applicationinsights.agent.internal.init;
+
+import static java.util.concurrent.TimeUnit.SECONDS;
+
+import io.opentelemetry.api.common.AttributeKey;
+import io.opentelemetry.api.common.Attributes;
+import io.opentelemetry.api.logs.Severity;
+import io.opentelemetry.api.trace.SpanContext;
+import io.opentelemetry.context.Context;
+import io.opentelemetry.sdk.common.CompletableResultCode;
+import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
+import io.opentelemetry.sdk.logs.LogRecordProcessor;
+import io.opentelemetry.sdk.logs.ReadWriteLogRecord;
+import io.opentelemetry.sdk.logs.data.Body;
+import io.opentelemetry.sdk.logs.data.LogRecordData;
+import io.opentelemetry.sdk.resources.Resource;
+import java.time.Instant;
+import javax.annotation.Nullable;
+
+// this is just needed temporarily until
+// https://github.com/open-telemetry/opentelemetry-java-instrumentation/pull/8761
+class TimestampingLogRecordProcessor implements LogRecordProcessor {
+
+  private final LogRecordProcessor delegate;
+
+  public TimestampingLogRecordProcessor(LogRecordProcessor delegate) {
+    this.delegate = delegate;
+  }
+
+  @Override
+  public void onEmit(Context context, ReadWriteLogRecord logRecord) {
+    delegate.onEmit(context, new TimestampingReadWriteLogRecord(logRecord, Instant.now()));
+  }
+
+  @Override
+  public CompletableResultCode shutdown() {
+    return delegate.shutdown();
+  }
+
+  @Override
+  public CompletableResultCode forceFlush() {
+    return delegate.forceFlush();
+  }
+
+  @Override
+  public void close() {
+    delegate.close();
+  }
+
+  private static class TimestampingReadWriteLogRecord implements ReadWriteLogRecord {
+
+    private final ReadWriteLogRecord delegate;
+    private final Instant timestamp;
+
+    private TimestampingReadWriteLogRecord(ReadWriteLogRecord delegate, Instant timestamp) {
+      this.delegate = delegate;
+      this.timestamp = timestamp;
+    }
+
+    @Override
+    public <T> ReadWriteLogRecord setAttribute(AttributeKey<T> key, T value) {
+      return delegate.setAttribute(key, value);
+    }
+
+    @Override
+    public LogRecordData toLogRecordData() {
+      return new TimestampedLogRecordData(delegate.toLogRecordData(), timestamp);
+    }
+  }
+
+  private static class TimestampedLogRecordData implements LogRecordData {
+
+    private final LogRecordData delegate;
+    private final Instant timestamp;
+
+    private TimestampedLogRecordData(LogRecordData delegate, Instant timestamp) {
+      this.delegate = delegate;
+      this.timestamp = timestamp;
+    }
+
+    @Override
+    public Resource getResource() {
+      return delegate.getResource();
+    }
+
+    @Override
+    public InstrumentationScopeInfo getInstrumentationScopeInfo() {
+      return delegate.getInstrumentationScopeInfo();
+    }
+
+    @Override
+    public long getTimestampEpochNanos() {
+      long timestampEpochNanos = delegate.getTimestampEpochNanos();
+      if (timestampEpochNanos == 0) {
+        return SECONDS.toNanos(timestamp.getEpochSecond()) + timestamp.getNano();
+      }
+      return timestampEpochNanos;
+    }
+
+    @Override
+    public long getObservedTimestampEpochNanos() {
+      return delegate.getObservedTimestampEpochNanos();
+    }
+
+    @Override
+    public SpanContext getSpanContext() {
+      return delegate.getSpanContext();
+    }
+
+    @Override
+    public Severity getSeverity() {
+      return delegate.getSeverity();
+    }
+
+    @Override
+    @Nullable
+    public String getSeverityText() {
+      return delegate.getSeverityText();
+    }
+
+    @Override
+    public Body getBody() {
+      return delegate.getBody();
+    }
+
+    @Override
+    public Attributes getAttributes() {
+      return delegate.getAttributes();
+    }
+
+    @Override
+    public int getTotalAttributeCount() {
+      return delegate.getTotalAttributeCount();
+    }
+  }
+}

smoke-tests/apps/Log4j2/src/smokeTest/java/com/microsoft/applicationinsights/smoketest/Log4j2Test.java

@@ -21,6 +21,8 @@
 import com.microsoft.applicationinsights.smoketest.schemav2.MessageData;
 import com.microsoft.applicationinsights.smoketest.schemav2.RequestData;
 import com.microsoft.applicationinsights.smoketest.schemav2.SeverityLevel;
+import java.time.Instant;
+import java.time.temporal.ChronoUnit;
 import java.util.Comparator;
 import java.util.List;
 import org.junit.jupiter.api.Test;
@@ -45,6 +47,16 @@ void test() throws Exception {
     Envelope mdEnvelope3 = mdList.get(2);
     Envelope mdEnvelope4 = mdList.get(3);
 
+    Instant now = Instant.now();
+    assertThat(Instant.parse(mdEnvelope1.getTime()))
+        .isBetween(now.minus(1, ChronoUnit.MINUTES), now);
+    assertThat(Instant.parse(mdEnvelope2.getTime()))
+        .isBetween(now.minus(1, ChronoUnit.MINUTES), now);
+    assertThat(Instant.parse(mdEnvelope3.getTime()))
+        .isBetween(now.minus(1, ChronoUnit.MINUTES), now);
+    assertThat(Instant.parse(mdEnvelope4.getTime()))
+        .isBetween(now.minus(1, ChronoUnit.MINUTES), now);
+
     assertThat(rdEnvelope.getSampleRate()).isNull();
     assertThat(mdEnvelope1.getSampleRate()).isNull();
     assertThat(mdEnvelope2.getSampleRate()).isNull();