From 185efbceb4b3d99dc8e5f0b2c9d782231137cc55 Mon Sep 17 00:00:00 2001 From: Harshit Suthar Date: Mon, 1 Jun 2026 15:09:29 +0530 Subject: [PATCH] fix(observability): order TRA logs by request time + monotonic sequence MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit SDK-6164: logs reach Test Observability but the Logs tab renders them out of order because the backend sorts by the event timestamp. - createHttpLogEvent stamped HTTP logs with the response-received time (httpResponse[0]), so a slow request sorted after logs emitted while it was in flight. Stamp with the request-issued time (httpRequest[0]) instead; duration_ms is still measured request->response. - No LogCreated event carried a tiebreaker, so same-millisecond logs had a non-deterministic order. Add a per-process monotonic `sequence` (new src/utils/logSequence.js) to every log event (TEST_LOG, HTTP, TEST_SCREENSHOT) so the backend can sort by (timestamp, sequence). Adds test/src/test-observability/logOrdering.js (4 cases) covering both. Note: the `sequence` tiebreaker is inert until the TRA backend adds it as a secondary sort key — tracked as a cross-team follow-up. Co-Authored-By: Claude Opus 4.8 --- src/testObservability.js | 5 +- src/utils/logPatcher.js | 2 + src/utils/logSequence.js | 20 ++++++ test/src/test-observability/logOrdering.js | 82 ++++++++++++++++++++++ 4 files changed, 108 insertions(+), 1 deletion(-) create mode 100644 src/utils/logSequence.js create mode 100644 test/src/test-observability/logOrdering.js diff --git a/src/testObservability.js b/src/testObservability.js index 7dcef52..f7e70d2 100644 --- a/src/testObservability.js +++ b/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], diff --git a/src/utils/logPatcher.js b/src/utils/logPatcher.js index e0ecd1e..6ab2741 100644 --- a/src/utils/logPatcher.js +++ b/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', diff --git a/src/utils/logSequence.js b/src/utils/logSequence.js new file mode 100644 index 0000000..be43889 --- /dev/null +++ b/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 } +}; diff --git a/test/src/test-observability/logOrdering.js b/test/src/test-observability/logOrdering.js new file mode 100644 index 0000000..cdb135e --- /dev/null +++ b/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); + }); +});