fix(observability): order TRA logs by request time + monotonic sequence (SDK-6164)

src/testObservability.js

@@ -13,6 +13,7 @@ const AccessibilityAutomation = require('./accessibilityAutomation');
 const accessibilityScripts = require('./scripts/accessibilityScripts');
 const TestMap = require('./utils/testMap');
 const CustomTagManager = require('./utils/customTagManager');
+const logSequence = require('./utils/logSequence');
 const hooksMap = {};
 const accessibilityAutomation = new AccessibilityAutomation();
 
@@ -446,6 +447,7 @@ class TestObservability {
           test_run_uuid: testUuid,
           kind: 'TEST_SCREENSHOT',
           timestamp: new Date(timestamp).toISOString(),
+          sequence: logSequence.next(),
           message: screenshot
         }
       ]
@@ -460,7 +462,8 @@ class TestObservability {
         logs: [
           {
             test_run_uuid: test_run_uuid,
-            timestamp: httpResponse[0],
+            timestamp: httpRequest[0],
+            sequence: logSequence.next(),
             kind: 'HTTP',
             http_response: {
               path: stripAnsi(httpRequest[1] || '').replace(/'/g, '\'').trim().split(' ')[2],

src/utils/logPatcher.js

@@ -4,6 +4,7 @@ const CrashReporter = require('./crashReporter');
 const TestObservability = require('../testObservability');
 const helper = require('./helper');
 const eventHelper = require('./eventHelper');
+const logSequence = require('./logSequence');
 const testObservability = new TestObservability();
 
 let testLogs = [];
@@ -44,6 +45,7 @@ class LogPatcher extends Transport {
       const pid = process.pid;
       const loggingData = {
         timestamp: new Date().toISOString(),
+        sequence: logSequence.next(),
         level: level.toUpperCase(),
         message: `"${message.join(', ')}"`,
         kind: 'TEST_LOG',

src/utils/logSequence.js

@@ -0,0 +1,20 @@
+/**
+ * Per-process monotonic log sequence (SDK-6164).
+ *
+ * Every LogCreated log event (TEST_LOG, HTTP, TEST_SCREENSHOT) carries a
+ * `sequence` integer drawn from this single per-process counter. It gives the
+ * Test Observability backend a deterministic tiebreaker when two logs share the
+ * same millisecond `timestamp`: the server sorts by (timestamp, sequence).
+ *
+ * The counter is intentionally global-per-process (not scoped per test_run_uuid)
+ * so that all logs emitted by a worker — across tests, HTTP, and screenshots —
+ * share one strictly-increasing emission order. Each parallel worker process has
+ * its own counter starting at 0, matching the ticket's "per-process" design.
+ */
+let counter = 0;
+
+module.exports = {
+  next: () => counter++,
+  // test-only hook
+  _reset: () => { counter = 0 }
+};

test/src/test-observability/logOrdering.js

@@ -0,0 +1,82 @@
+const {expect} = require('chai');
+const sinon = require('sinon');
+const helper = require('../../../src/utils/helper');
+const TestObservability = require('../../../src/testObservability');
+const logSequence = require('../../../src/utils/logSequence');
+
+// SDK-6164: TRA log timestamp ordering.
+// 1. HTTP logs must be stamped with the request-issued time (httpRequest[0]),
+//    not the response-received time, so a slow request does not sort after
+//    logs that were emitted while it was still in flight.
+// 2. Every LogCreated log carries a per-process monotonic `sequence` so the
+//    backend has a deterministic tiebreaker for same-millisecond timestamps.
+describe('TestObservability - log ordering (SDK-6164)', function () {
+  beforeEach(() => {
+    this.sandbox = sinon.createSandbox();
+    this.testObservability = new TestObservability();
+    this.captured = [];
+    this.sandbox.stub(helper, 'uploadEventData').callsFake(async (e) => {
+      this.captured.push(e.logs[0]);
+    });
+    logSequence._reset();
+  });
+
+  afterEach(() => {
+    this.sandbox.restore();
+  });
+
+  it('stamps HTTP logs with the request-issued time, not the response time', async () => {
+    const httpRequest = ['2026-06-01T09:00:00.000Z', 'Request POST /session/1/url', 'body'];
+    const httpResponse = ['2026-06-01T09:00:05.000Z', 'Response 200 OK', 'resp'];
+
+    await this.testObservability.createHttpLogEvent(httpRequest, httpResponse, 'uuid');
+
+    const log = this.captured[0];
+    expect(log.timestamp).to.equal('2026-06-01T09:00:00.000Z'); // request time
+    expect(log.timestamp).to.not.equal('2026-06-01T09:00:05.000Z'); // not response time
+    // duration is still measured request->response
+    expect(log.http_response.duration_ms).to.equal(5000);
+  });
+
+  it('keeps emission order on the wire after server-side (timestamp, sequence) sort', async () => {
+    // R1 issued first but slow (5s); R2 issued 1s later but fast.
+    await this.testObservability.createHttpLogEvent(
+      ['2026-06-01T09:00:00.000Z', 'Request POST /session/1/url', 'b1'],
+      ['2026-06-01T09:00:05.000Z', 'Response 200 OK', 'r1'], 'uuid');
+    await this.testObservability.createHttpLogEvent(
+      ['2026-06-01T09:00:01.000Z', 'Request POST /session/1/element', 'b2'],
+      ['2026-06-01T09:00:01.100Z', 'Response 200 OK', 'r2'], 'uuid');
+
+    const sorted = [...this.captured].sort((a, b) => {
+      if (a.timestamp !== b.timestamp) {return a.timestamp < b.timestamp ? -1 : 1}
+
+      return a.sequence - b.sequence;
+    });
+    expect(sorted.map(l => l.http_response.path)).to.deep.equal(['/session/1/url', '/session/1/element']);
+  });
+
+  it('assigns a deterministic monotonic sequence so same-ms logs never tie', async () => {
+    const tie = '2026-06-01T09:00:02.000Z';
+    await this.testObservability.createHttpLogEvent(
+      [tie, 'Request GET /tie/a', 'b3'], [tie, 'Response 200 OK', 'r3'], 'uuid');
+    await this.testObservability.createHttpLogEvent(
+      [tie, 'Request GET /tie/b', 'b4'], [tie, 'Response 200 OK', 'r4'], 'uuid');
+
+    const a = this.captured[0];
+    const b = this.captured[1];
+    expect(a.timestamp).to.equal(b.timestamp); // genuine same-ms tie
+    expect(a.sequence).to.be.a('number');
+    expect(b.sequence).to.be.a('number');
+    expect(b.sequence).to.be.greaterThan(a.sequence); // tie broken deterministically
+  });
+
+  it('shares one per-process sequence across log kinds (HTTP + screenshot)', async () => {
+    await this.testObservability.createScreenshotLogEvent('uuid', 'base64data', Date.now());
+    await this.testObservability.createHttpLogEvent(
+      ['2026-06-01T09:00:00.000Z', 'Request GET /x', 'b'],
+      ['2026-06-01T09:00:00.001Z', 'Response 200 OK', 'r'], 'uuid');
+
+    expect(this.captured[0].sequence).to.equal(0);
+    expect(this.captured[1].sequence).to.equal(1);
+  });
+});