Fix client error timings further for multi-request connections

The previous fix handled simple cases OK, but assumed a request started
when the connection started, which isn't true for various cases. This is
starting to get overly precise about poorly defined details really, but
still - it's better if we use the time of the preceeding request as the
start, if there was one (either the start of this incomplete request, or
the previous request as a rough benchmark).

Author: pimterry

src/server/mockttp-server.ts

@@ -1,6 +1,5 @@
 import { Buffer } from 'buffer';
 import * as net from "net";
-import * as url from "url";
 import * as tls from "tls";
 import * as http from "http";
 import * as http2 from "http2";
@@ -62,7 +61,8 @@ import {
     buildRawSocketEventData,
     buildTlsSocketEventData,
     isSocketLoop,
-    resetOrDestroy
+    resetOrDestroy,
+    buildSocketErrorRequestTimings
 } from "../util/socket-util";
 import {
     ClientErrorInProgress,
@@ -708,6 +708,12 @@ export class MockttpServer extends AbstractMockttp implements Mockttp {
                 startTimestamp: now()
             };
 
+            // Set/update the last request time on the socket
+            let socketTimingInfo = req.socket[SocketTimingInfo];
+            if (socketTimingInfo) {
+                socketTimingInfo.lastRequestTimestamp = timingEvents.startTimestamp;
+            }
+
             req.on('end', () => {
                 timingEvents.bodyReceivedTimestamp ||= now();
             });
@@ -1090,13 +1096,7 @@ ${await this.suggestRule(request)}`
                     `client-error:${error.code || 'UNKNOWN'}`,
                     ...getSocketMetadataTags(socket[SocketMetadata])
                 ],
-                timingEvents: (socket?.[SocketTimingInfo]
-                    ? {
-                        startTime: socket[SocketTimingInfo].initialSocket,
-                        startTimestamp: socket[SocketTimingInfo].initialSocketTimestamp
-                    }
-                    : { startTime: Date.now(), startTimestamp: now() }
-                ) as TimingEvents
+                timingEvents: buildSocketErrorRequestTimings(socket)
             };
 
             const rawPacket = socket[ClientErrorInProgress]?.rawPacket
@@ -1190,13 +1190,7 @@ ${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() };
-
+        const timingEvents = buildSocketErrorRequestTimings(socket);
         timingEvents.abortedTimestamp = now();
 
         this.announceClientErrorAsync(session.initialSocket, {

src/util/socket-extensions.ts

@@ -54,6 +54,7 @@ declare module 'net' {
             initialSocketTimestamp: number;
             tunnelSetupTimestamp?: number; // Latest CONNECT completion, if any
             tlsConnectedTimestamp?: number; // Latest TLS handshake completion, if any
+            lastRequestTimestamp?: number; // Latest request or websocket request time, if any
         }
 
         // Set on TLSSocket, defined here for convenient access on _all_ sockets

src/util/socket-util.ts

@@ -9,6 +9,7 @@ import { isNode } from './util';
 import {
     OngoingRequest,
     RawPassthroughEvent,
+    TimingEvents,
     TlsConnectionEvent
 } from '../types';
 import {
@@ -210,3 +211,31 @@ export function buildSocketTimingInfo(): Required<net.Socket>[typeof SocketTimin
     return { initialSocket: Date.now(), initialSocketTimestamp: now() };
 }
 
+// If we get an error linked to a socket, we want to calculate a rough estimate of when the
+// request was started, using the socket timing data:
+export function buildSocketErrorRequestTimings(socket: net.Socket | undefined): TimingEvents {
+    if (socket?.[SocketTimingInfo]) {
+        if (socket[SocketTimingInfo].lastRequestTimestamp) {
+            // If this isn't the first request (or was partially received) we use the
+            // most recent received request time as the start of this request:
+            const startTimestamp = socket[SocketTimingInfo].lastRequestTimestamp;
+            const startTime = socket[SocketTimingInfo].initialSocket +
+                (startTimestamp - socket[SocketTimingInfo].initialSocketTimestamp);
+            return {
+                startTime,
+                startTimestamp
+            };
+        } else {
+            // If this is the first request, treat socket creation as the start:
+            return {
+                startTime: socket[SocketTimingInfo].initialSocket,
+                startTimestamp: socket[SocketTimingInfo].initialSocketTimestamp
+            };
+        }
+    } else {
+        return {
+            startTime: Date.now(),
+            startTimestamp: now()
+        };
+    }
+}