Fix timing event data on client-error events

Previously HTTP/2 events didn't get any abortedTimestamp at all (so had
no duration information whatsoever) and both HTTP/1 & HTTP/2 did not use
the raw socket timing data to capture the full connection duration info.

Author: pimterry

src/server/mockttp-server.ts

@@ -70,7 +70,8 @@ import {
     LastTunnelAddress,
     TlsSetupCompleted,
     SocketMetadata,
-    TlsMetadata
+    TlsMetadata,
+    SocketTimingInfo
 } from '../util/socket-extensions';
 import { getSocketMetadataTags, getSocketMetadataFromProxyAuth } from '../util/socket-metadata'
 import {
@@ -1089,7 +1090,13 @@ ${await this.suggestRule(request)}`
                     `client-error:${error.code || 'UNKNOWN'}`,
                     ...getSocketMetadataTags(socket[SocketMetadata])
                 ],
-                timingEvents: { startTime: Date.now(), startTimestamp: now() } as TimingEvents
+                timingEvents: (socket?.[SocketTimingInfo]
+                    ? {
+                        startTime: socket[SocketTimingInfo].initialSocket,
+                        startTimestamp: socket[SocketTimingInfo].initialSocketTimestamp
+                    }
+                    : { startTime: Date.now(), startTimestamp: now() }
+                ) as TimingEvents
             };
 
             const rawPacket = socket[ClientErrorInProgress]?.rawPacket
@@ -1183,6 +1190,15 @@ ${await this.suggestRule(request)}`
             ? pairFlatRawHeaders(error.badRequest?.rawHeaders as string[])
             : error.badRequest?.rawHeaders as RawHeaders | undefined;
 
+        const timingEvents: TimingEvents = socket?.[SocketTimingInfo]
+            ? {
+                startTime: socket[SocketTimingInfo].initialSocket,
+                startTimestamp: socket[SocketTimingInfo].initialSocketTimestamp
+            }
+            : { startTime: Date.now(), startTimestamp: now() };
+
+        timingEvents.abortedTimestamp = now();
+
         this.announceClientErrorAsync(session.initialSocket, {
             errorCode: error.code,
             request: {
@@ -1193,9 +1209,9 @@ ${await this.suggestRule(request)}`
                     ...getSocketMetadataTags(socket?.[SocketMetadata])
                 ],
                 httpVersion: error.badRequest?.httpVersion ?? '2',
+                timingEvents,
 
                 // Best guesses:
-                timingEvents: { startTime: Date.now(), startTimestamp: now() },
                 protocol: error.badRequest?.protocol || (isTLS ? "https" : "http"),
                 url: error.badRequest?.url ||
                     (isTLS ? `https://${(socket as tls.TLSSocket).servername}/` : undefined),

test/integration/subscriptions/client-error-events.spec.ts

@@ -73,6 +73,11 @@ describe("Client error subscription", () => {
                 'client-error:HPE_HEADER_OVERFLOW',
                 'header-overflow'
             ]);
+
+            expect(clientError.request.timingEvents.startTime).to.be.greaterThan(0);
+            expect(clientError.request.timingEvents.startTimestamp).to.be.greaterThan(0);
+            expect(clientError.request.timingEvents.responseSentTimestamp)
+                .to.be.greaterThan(clientError.request.timingEvents.startTimestamp);
         });
 
         nodeOnly(() => {
@@ -150,6 +155,11 @@ describe("Client error subscription", () => {
 
                 expect(response.statusCode).to.equal(undefined);
                 expect(response.statusMessage).to.equal(undefined);
+
+                expect(clientError.request.timingEvents.startTime).to.be.greaterThan(0);
+                expect(clientError.request.timingEvents.startTimestamp).to.be.greaterThan(0);
+                expect(clientError.request.timingEvents.abortedTimestamp)
+                    .to.be.greaterThan(clientError.request.timingEvents.startTimestamp);
             });
         });
     });
@@ -290,6 +300,11 @@ describe("Client error subscription", () => {
                 ]);
                 expect(error.request.url).to.equal(server.url + '/');
                 expect(error.response).to.equal('aborted');
+
+                expect(error.request.timingEvents.startTime).to.be.greaterThan(0);
+                expect(error.request.timingEvents.startTimestamp).to.be.greaterThan(0);
+                expect(error.request.timingEvents.abortedTimestamp)
+                    .to.be.greaterThan(error.request.timingEvents.startTimestamp);
             });
 
             it("should report HTTP/2 requests that fail after the preface", async () => {