Use new sdk time direcctly and indirectly for timetamps sent in SDK

embrace-android-okhttp3/src/main/java/io/embrace/android/embracesdk/okhttp3/EmbraceOkHttp3ApplicationInterceptor.java

@@ -48,7 +48,7 @@ public EmbraceOkHttp3ApplicationInterceptor() {
 
     @Override
     public Response intercept(Chain chain) throws IOException {
-        long startTime = System.currentTimeMillis();
+        long startTime = embrace.getInternalInterface().getSdkCurrentTime();
         Request request = chain.request();
         try {
             // we are not interested in response, just proceed
@@ -62,7 +62,7 @@ public Response intercept(Chain chain) throws IOException {
                         urlString,
                         HttpMethod.fromString(request.method()),
                         startTime,
-                        System.currentTimeMillis(),
+                        embrace.getInternalInterface().getSdkCurrentTime(),
                         causeName(e, UNKNOWN_EXCEPTION),
                         causeMessage(e, UNKNOWN_MESSAGE),
                         request.header(embrace.getTraceIdHeader()),
@@ -84,7 +84,7 @@ public Response intercept(Chain chain) throws IOException {
                         urlString,
                         HttpMethod.fromString(request.method()),
                         startTime,
-                        System.currentTimeMillis(),
+                        embrace.getInternalInterface().getSdkCurrentTime(),
                         errorType != null ? errorType : UNKNOWN_EXCEPTION,
                         errorMessage != null ? errorMessage : UNKNOWN_MESSAGE,
                         request.header(embrace.getTraceIdHeader()),

embrace-android-okhttp3/src/main/java/io/embrace/android/embracesdk/okhttp3/EmbraceOkHttp3NetworkInterceptor.java

@@ -10,6 +10,8 @@
 
 import io.embrace.android.embracesdk.Embrace;
 import io.embrace.android.embracesdk.InternalApi;
+import io.embrace.android.embracesdk.clock.Clock;
+import io.embrace.android.embracesdk.clock.SystemClock;
 import io.embrace.android.embracesdk.internal.ApkToolsConfig;
 import io.embrace.android.embracesdk.network.EmbraceNetworkRequest;
 import io.embrace.android.embracesdk.network.http.EmbraceHttpPathOverride;
@@ -59,12 +61,16 @@ public final class EmbraceOkHttp3NetworkInterceptor implements Interceptor {
 
     final Embrace embrace;
 
+    // A clock that mirrors the one used by OkHttp to get timestamps
+    final Clock systemClock;
+
     public EmbraceOkHttp3NetworkInterceptor() {
-        this(Embrace.getInstance());
+        this(Embrace.getInstance(), new SystemClock());
     }
 
-    EmbraceOkHttp3NetworkInterceptor(Embrace embrace) {
+    EmbraceOkHttp3NetworkInterceptor(Embrace embrace, Clock systemClock) {
         this.embrace = embrace;
+        this.systemClock = systemClock;
     }
 
     @Override
@@ -75,6 +81,7 @@ public Response intercept(Chain chain) throws IOException {
             return chain.proceed(originalRequest);
         }
 
+        long offset = sdkClockOffset();
         boolean networkSpanForwardingEnabled = embrace.getInternalInterface().isNetworkSpanForwardingEnabled();
 
         String traceparent = null;
@@ -156,8 +163,8 @@ public Response intercept(Chain chain) throws IOException {
             EmbraceNetworkRequest.fromCompletedRequest(
                 EmbraceHttpPathOverride.getURLString(new EmbraceOkHttp3PathOverrideRequest(request)),
                 HttpMethod.fromString(request.method()),
-                response.sentRequestAtMillis(),
-                response.receivedResponseAtMillis(),
+                response.sentRequestAtMillis() + offset,
+                response.receivedResponseAtMillis() + offset,
                 request.body() != null ? request.body().contentLength() : 0,
                 contentLength,
                 response.code(),
@@ -249,4 +256,12 @@ private byte[] getRequestBody(final Request request) {
         }
         return null;
     }
+
+    /**
+     * Get the difference between the SDK clock time and the time System.currentTimeMillis() returns, which is used by OkHttp for
+     * determining client-side timestamps.
+     */
+    private long sdkClockOffset() {
+        return embrace.getInternalInterface().getSdkCurrentTime() - systemClock.now();
+    }
 }

embrace-android-okhttp3/src/test/kotlin/io/embrace/android/embracesdk/okhttp3/EmbraceOkHttp3InterceptorsTest.kt

@@ -1,6 +1,7 @@
 package io.embrace.android.embracesdk.okhttp3
 
 import io.embrace.android.embracesdk.Embrace
+import io.embrace.android.embracesdk.clock.Clock
 import io.embrace.android.embracesdk.internal.EmbraceInternalInterface
 import io.embrace.android.embracesdk.network.EmbraceNetworkRequest
 import io.embrace.android.embracesdk.network.http.NetworkCaptureData
@@ -56,6 +57,9 @@ internal class EmbraceOkHttp3InterceptorsTest {
         private const val TRACEPARENT_HEADER = "traceparent"
         private const val CUSTOM_TRACEPARENT = "00-b583a45b2c7c813e0ebc6aa0835b9d98-b5475c618bb98e67-01"
         private const val GENERATED_TRACEPARENT = "00-3c72a77a7b51af6fb3778c06d4c165ce-4c1d710fffc88e35-01"
+        private const val FAKE_SDK_TIME = 1692201601000L
+        private const val CLOCK_DRIFT = 5000L
+        private const val FAKE_SYSTEM_TIME = FAKE_SDK_TIME + CLOCK_DRIFT
     }
 
     private lateinit var server: MockWebServer
@@ -69,6 +73,7 @@ internal class EmbraceOkHttp3InterceptorsTest {
     private lateinit var getRequestBuilder: Request.Builder
     private lateinit var postRequestBuilder: Request.Builder
     private lateinit var capturedEmbraceNetworkRequest: CapturingSlot<EmbraceNetworkRequest>
+    private lateinit var mockSystemClock: Clock
     private var preNetworkInterceptorBeforeRequestSupplier: (Request) -> Request = { request -> request }
     private var preNetworkInterceptorAfterResponseSupplier: (Response) -> Response = { response -> response }
     private var postNetworkInterceptorBeforeRequestSupplier: (Request) -> Request = { request -> request }
@@ -84,12 +89,15 @@ internal class EmbraceOkHttp3InterceptorsTest {
         every { mockInternalInterface.shouldCaptureNetworkBody(any(), "POST") } answers { true }
         every { mockInternalInterface.shouldCaptureNetworkBody(any(), "GET") } answers { false }
         every { mockInternalInterface.isNetworkSpanForwardingEnabled() } answers { isNetworkSpanForwardingEnabled }
+        every { mockInternalInterface.getSdkCurrentTime() } answers { FAKE_SDK_TIME }
         applicationInterceptor = EmbraceOkHttp3ApplicationInterceptor(mockEmbrace)
         preNetworkInterceptorTestInterceptor = TestInspectionInterceptor(
             beforeRequestSent = { request -> preNetworkInterceptorBeforeRequestSupplier.invoke(request) },
             afterResponseReceived = { response -> preNetworkInterceptorAfterResponseSupplier.invoke(response) }
         )
-        networkInterceptor = EmbraceOkHttp3NetworkInterceptor(mockEmbrace)
+        mockSystemClock = mockk(relaxed = true)
+        every { mockSystemClock.now() } answers { FAKE_SYSTEM_TIME }
+        networkInterceptor = EmbraceOkHttp3NetworkInterceptor(mockEmbrace, mockSystemClock)
         postNetworkInterceptorTestInterceptor = TestInspectionInterceptor(
             beforeRequestSent = { request -> postNetworkInterceptorBeforeRequestSupplier.invoke(request) },
             afterResponseReceived = { response -> postNetworkInterceptorAfterResponseSupplier.invoke(response) }
@@ -113,6 +121,8 @@ internal class EmbraceOkHttp3InterceptorsTest {
         every { mockEmbrace.recordNetworkRequest(capture(capturedEmbraceNetworkRequest)) } answers { }
         every { mockEmbrace.generateW3cTraceparent() } answers { GENERATED_TRACEPARENT }
         every { mockEmbrace.internalInterface } answers { mockInternalInterface }
+        isSDKStarted = true
+        isNetworkSpanForwardingEnabled = false
     }
 
     @After
@@ -187,7 +197,7 @@ internal class EmbraceOkHttp3InterceptorsTest {
         server.enqueue(createBaseMockResponse())
         runGetRequest()
         verify(exactly = 0) { mockInternalInterface.isNetworkSpanForwardingEnabled() }
-        verify(exactly = 0) { mockEmbrace.internalInterface.shouldCaptureNetworkBody(any(), any()) }
+        verify(exactly = 0) { mockInternalInterface.shouldCaptureNetworkBody(any(), any()) }
     }
 
     @Test
@@ -422,35 +432,44 @@ internal class EmbraceOkHttp3InterceptorsTest {
         expectedPath: String = defaultPath,
         expectedHttpStatus: Int = 200
     ) {
+        val realSystemClockStartTime = System.currentTimeMillis()
         runPostRequest()
+        val realSystemClockEndTime = System.currentTimeMillis()
         validateWholeRequest(
             path = expectedPath,
             httpStatus = expectedHttpStatus,
             responseBodySize = expectedResponseBodySize,
             httpMethod = "POST",
             requestSize = requestBodySize,
-            responseBody = responseBody
+            responseBody = responseBody,
+            realSystemClockStartTime = realSystemClockStartTime,
+            realSystemClockEndTime = realSystemClockEndTime
         )
     }
 
     private fun runAndValidateGetRequest(
         expectedResponseBodySize: Int
     ) {
+        val realSystemClockStartTime = System.currentTimeMillis()
         runGetRequest()
+        val realSystemClockEndTime = System.currentTimeMillis()
         validateWholeRequest(
             path = defaultPath,
             httpStatus = 200,
             httpMethod = "GET",
             requestSize = 0,
             responseBodySize = expectedResponseBodySize,
-            responseBody = null
+            responseBody = null,
+            realSystemClockStartTime = realSystemClockStartTime,
+            realSystemClockEndTime = realSystemClockEndTime
         )
     }
 
     private fun runPostRequest() = assertNotNull(okHttpClient.newCall(postRequestBuilder.build()).execute())
 
     private fun runGetRequest() = assertNotNull(okHttpClient.newCall(getRequestBuilder.build()).execute())
 
+    @Suppress("LongParameterList")
     private fun validateWholeRequest(
         path: String,
         httpMethod: String,
@@ -461,16 +480,17 @@ internal class EmbraceOkHttp3InterceptorsTest {
         errorMessage: String? = null,
         traceId: String? = null,
         w3cTraceparent: String? = null,
-        responseBody: String?
+        responseBody: String?,
+        realSystemClockStartTime: Long,
+        realSystemClockEndTime: Long
     ) {
         with(capturedEmbraceNetworkRequest) {
             assertTrue(captured.url.endsWith("$path?$defaultQueryString"))
             assertEquals(httpMethod, captured.httpMethod)
-
-            // assert expected start/end times when we fix the issue of not using a custom clock instance.
-            assertTrue(captured.startTime > 0)
-            assertTrue(captured.endTime > 0)
-
+            assertTrue(realSystemClockStartTime - CLOCK_DRIFT <= captured.startTime)
+            assertTrue(realSystemClockStartTime > captured.startTime)
+            assertTrue(realSystemClockEndTime - CLOCK_DRIFT >= captured.endTime)
+            assertTrue(realSystemClockEndTime > captured.endTime)
             assertEquals(httpStatus, captured.responseCode)
             assertEquals(requestSize.toLong(), captured.bytesOut)
             assertEquals(responseBodySize.toLong(), captured.bytesIn)

embrace-android-sdk/api/embrace-android-sdk.api

@@ -177,6 +177,15 @@ public final class io/embrace/android/embracesdk/WebViewClientSwazzledHooks {
 public abstract interface annotation class io/embrace/android/embracesdk/annotation/StartupActivity : java/lang/annotation/Annotation {
 }
 
+public abstract interface class io/embrace/android/embracesdk/clock/Clock {
+	public abstract fun now ()J
+}
+
+public final class io/embrace/android/embracesdk/clock/SystemClock : io/embrace/android/embracesdk/clock/Clock {
+	public fun <init> ()V
+	public fun now ()J
+}
+
 public abstract interface class io/embrace/android/embracesdk/internal/EmbraceInternalInterface {
 	public abstract fun getSdkCurrentTime ()J
 	public abstract fun isNetworkSpanForwardingEnabled ()Z

embrace-android-sdk/src/integrationTest/kotlin/io/embrace/android/embracesdk/IntegrationTestRule.kt

@@ -190,7 +190,7 @@ internal class IntegrationTestRule(
     )
 
     companion object {
-        const val DEFAULT_SDK_START_TIME_MS = 1692201600L
+        const val DEFAULT_SDK_START_TIME_MS = 169220160000L
 
         fun newHarness(startImmediately: Boolean) = Harness(startImmediately = startImmediately)
 

embrace-android-sdk/src/integrationTest/kotlin/io/embrace/android/embracesdk/testcases/EmbraceInternalInterfaceTest.kt

@@ -254,7 +254,7 @@ internal class EmbraceInternalInterfaceTest {
 
     companion object {
         private const val URL = "https://embrace.io"
-        private const val START_TIME = 1692201601L
-        private const val END_TIME = 1692202600L
+        private const val START_TIME = 1692201601000L
+        private const val END_TIME = 1692201603000L
     }
 }

embrace-android-sdk/src/integrationTest/kotlin/io/embrace/android/embracesdk/testcases/NetworkRequestApiTest.kt

@@ -343,8 +343,8 @@ internal class NetworkRequestApiTest {
     companion object {
         private const val URL = "https://embrace.io"
         private const val DISABLED_URL = "https://dontlogmebro.pizza/yum"
-        private const val START_TIME = 1692201601L
-        private const val END_TIME = 1692202600L
+        private const val START_TIME = 1692201601000L
+        private const val END_TIME = 1692201603000L
         private const val BYTES_SENT = 100L
         private const val BYTES_RECEIVED = 500L
         private const val TRACE_ID = "rAnDoM-traceId"

embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/clock/Clock.kt

@@ -1,9 +1,12 @@
 package io.embrace.android.embracesdk.clock
 
-internal fun interface Clock {
+import io.embrace.android.embracesdk.InternalApi
+
+@InternalApi
+public fun interface Clock {
 
     /**
      * Returns the current milliseconds from epoch.
      */
-    fun now(): Long
+    public fun now(): Long
 }

embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/clock/SystemClock.kt

@@ -1,6 +1,9 @@
 package io.embrace.android.embracesdk.clock
 
-internal class SystemClock : Clock {
+import io.embrace.android.embracesdk.InternalApi
+
+@InternalApi
+public class SystemClock : Clock {
     override fun now(): Long {
         return System.currentTimeMillis()
     }