From ccb0d64e566bfa6fa5404354a5d2f188e4db1614 Mon Sep 17 00:00:00 2001
From: Harshit Suthar <harshit.su@browserstack.com>
Date: Fri, 4 Sep 2026 21:10:34 +0530
Subject: [PATCH] fix(observability): stamp HTTP logs with request-issue time

SDK-6164: HTTP logs rendered out of order in the Test Observability Logs
tab. createHttpLogEvent stamped the LogCreated event with httpResponse[0],
the instant the response landed. Nightwatch pushes each httpOutput entry as
[isoTimestamp, message, params] when the line is logged, so httpResponse[0]
is request-issue time plus the whole round trip. A slow request therefore
carried a later timestamp than logs emitted while it was still in flight and
sorted after them.

Stamp with httpRequest[0] instead. duration_ms is computed from both entries
independently, so it still spans request -> response and no metric changes.
This also matches createScreenshotLogEvent, which already stamps with the
command's startTime.

Adds test/src/test-observability/createHttpLogEvent.js (4 cases).
---
 src/testObservability.js                      |  5 +-
 .../test-observability/createHttpLogEvent.js  | 85 +++++++++++++++++++
 2 files changed, 89 insertions(+), 1 deletion(-)
 create mode 100644 test/src/test-observability/createHttpLogEvent.js

diff --git a/src/testObservability.js b/src/testObservability.js
index 582d37e..dd096dd 100644
--- a/src/testObservability.js
+++ b/src/testObservability.js
@@ -460,7 +460,10 @@ class TestObservability {
         logs: [
           {
             test_run_uuid: test_run_uuid,
-            timestamp: httpResponse[0],
+            // Stamp at request-issue time: a slow request would otherwise sort after
+            // logs emitted while it was still in flight. duration_ms below still
+            // spans request -> response.
+            timestamp: httpRequest[0],
             kind: 'HTTP',
             http_response: {
               path: stripAnsi(httpRequest[1] || '').replace(/&#39;/g, '\'').trim().split(' ')[2],
diff --git a/test/src/test-observability/createHttpLogEvent.js b/test/src/test-observability/createHttpLogEvent.js
new file mode 100644
index 0000000..340066a
--- /dev/null
+++ b/test/src/test-observability/createHttpLogEvent.js
@@ -0,0 +1,85 @@
+const assert = require('assert');
+const sinon = require('sinon');
+
+const helper = require('../../../src/utils/helper');
+const TestObservability = require('../../../src/testObservability');
+
+// Regression coverage for SDK-6164 / HTTP log ordering.
+//
+// createHttpLogEvent stamped the event with httpResponse[0] — the instant the
+// response landed. Nightwatch builds each httpOutput entry as
+// [isoTimestamp, message, params] at the moment the line is logged, so
+// httpResponse[0] is request-issue time plus the full round trip. A slow
+// request therefore carried a later timestamp than logs emitted while it was
+// still in flight, and rendered after them in the Logs tab.
+describe('TestObservability - createHttpLogEvent (SDK-6164)', function () {
+  const request = (ts, target = 'POST /session/1/url') => [ts, `  Request ${target} `, '{}'];
+  const response = (ts, status = 'Response 200 OK') => [ts, `  ${status}`, '{}'];
+
+  beforeEach(() => {
+    this.sandbox = sinon.createSandbox();
+    this.testObservability = new TestObservability();
+    this.captured = [];
+    this.sandbox.stub(helper, 'uploadEventData').callsFake(async (eventData) => {
+      this.captured.push(eventData.logs[0]);
+    });
+  });
+
+  afterEach(() => {
+    this.sandbox.restore();
+  });
+
+  it('stamps the log with the request-issued time, not the response time', async () => {
+    await this.testObservability.createHttpLogEvent(
+      request('2026-06-01T09:00:00.000Z'),
+      response('2026-06-01T09:00:05.000Z'),
+      'test-run-uuid'
+    );
+
+    assert.strictEqual(this.captured.length, 1);
+    assert.strictEqual(this.captured[0].timestamp, '2026-06-01T09:00:00.000Z');
+    assert.strictEqual(this.captured[0].kind, 'HTTP');
+  });
+
+  it('still measures duration_ms across the full request -> response span', async () => {
+    await this.testObservability.createHttpLogEvent(
+      request('2026-06-01T09:00:00.000Z'),
+      response('2026-06-01T09:00:05.000Z'),
+      'test-run-uuid'
+    );
+
+    assert.strictEqual(this.captured[0].http_response.duration_ms, 5000);
+    assert.strictEqual(this.captured[0].http_response.status_code, '200');
+  });
+
+  // The reported symptom: a slow request issued BEFORE a fast one must not
+  // render after it once the logs are ordered by timestamp.
+  it('keeps issue order for a slow request followed by a fast one', async () => {
+    await this.testObservability.createHttpLogEvent(
+      request('2026-06-01T09:00:00.000Z', 'POST /session/1/url'),
+      response('2026-06-01T09:00:05.000Z'),
+      'test-run-uuid'
+    );
+    await this.testObservability.createHttpLogEvent(
+      request('2026-06-01T09:00:01.000Z', 'POST /session/1/element'),
+      response('2026-06-01T09:00:01.100Z'),
+      'test-run-uuid'
+    );
+
+    const byTimestamp = [...this.captured].sort((a, b) => (a.timestamp < b.timestamp ? -1 : 1));
+    assert.deepStrictEqual(
+      byTimestamp.map((log) => log.http_response.path),
+      ['/session/1/url', '/session/1/element']
+    );
+  });
+
+  it('ignores output pairs that are not a Request/Response pair', async () => {
+    await this.testObservability.createHttpLogEvent(
+      ['2026-06-01T09:00:00.000Z', '  Some other line ', '{}'],
+      response('2026-06-01T09:00:01.000Z'),
+      'test-run-uuid'
+    );
+
+    assert.strictEqual(this.captured.length, 0);
+  });
+});