Add timestamps & explicit start/end events to client API

Author: pimterry

src/api/rest-api.ts

@@ -119,16 +119,12 @@ export function exposeRestAPI(
             res.write('\n');
         });
 
-        resultStream.on('end', () => {
-            res.write(JSON.stringify({
-                'type': 'response-end'
-            }) + '\n');
-            res.end();
-        });
+        resultStream.on('end', () => res.end());
 
         resultStream.on('error', (error: ErrorLike) => {
             res.write(JSON.stringify({
                 type: 'error',
+                timestamp: performance.now(),
                 error: {
                     code: error.code,
                     message: error.message,

src/client/client.ts

@@ -30,20 +30,35 @@ export interface RequestOptions {
 }
 
 export type ResponseStreamEvents =
+    | RequestStart
     | ResponseHead
-    | ResponseBodyPart;
+    | ResponseBodyPart
+    | ResponseEnd;
 // Other notable events: errors (via 'error' event) and clean closure (via 'end').
 
+export interface RequestStart {
+    type: 'request-start';
+    startTime: number; // Unix timestamp
+    timestamp: number; // High precision timer (for relative calculations on later events)
+}
+
 export interface ResponseHead {
     type: 'response-head';
     statusCode: number;
     statusMessage?: string;
     headers: RawHeaders;
+    timestamp: number;
 }
 
 export interface ResponseBodyPart {
     type: 'response-body-part';
     rawBody: Buffer;
+    timestamp: number;
+}
+
+export interface ResponseEnd {
+    type: 'response-end';
+    timestamp: number;
 }
 
 export function sendRequest(
@@ -86,6 +101,12 @@ export function sendRequest(
         read() {} // Can't pull data - we manually fill this with .push() instead.
     });
 
+    resultsStream.push({
+        type: 'request-start',
+        startTime: Date.now(),
+        timestamp: performance.now()
+    });
+
     new Promise<http.IncomingMessage>((resolve, reject) => {
         request.on('error', reject);
         request.on('response', resolve);
@@ -94,15 +115,20 @@ export function sendRequest(
             type: 'response-head',
             statusCode: response.statusCode!,
             statusMessage: response.statusMessage,
-            headers: pairFlatRawHeaders(response.rawHeaders)
+            headers: pairFlatRawHeaders(response.rawHeaders),
+            timestamp: performance.now()
         });
 
         response.on('data', (data) => resultsStream.push({
             type: 'response-body-part',
-            rawBody: data
+            rawBody: data,
+            timestamp: performance.now()
         }));
 
-        response.on('end', () => resultsStream.push(null));
+        response.on('end', () => {
+            resultsStream.push({ type: 'response-end', timestamp: performance.now() });
+            resultsStream.push(null);
+        });
         response.on('error', (error) => resultsStream.destroy(error));
     }).catch((error) => {
         resultsStream.destroy(error);

test/client/send-request.spec.ts

@@ -1,7 +1,8 @@
+import * as _ from 'lodash';
 import { expect } from 'chai';
 import * as mockttp from 'mockttp';
 
-import { ResponseStreamEvents, sendRequest } from '../../src/client/client';
+import { sendRequest } from '../../src/client/client';
 import { streamToArray } from '../../src/util/stream';
 import { delay } from '../../src/util/promise';
 
@@ -44,8 +45,11 @@ describe("The HTTP client API", () => {
 
         const responseEvents = await streamToArray<any>(responseStream);
 
-        expect(responseEvents.length).to.equal(2);
-        expect(responseEvents[0]).to.deep.equal({
+        expect(responseEvents.length).to.equal(4);
+        expect(_.omit(responseEvents[0], 'timestamp', 'startTime')).to.deep.equal({
+            type: 'request-start'
+        });
+        expect(_.omit(responseEvents[1], 'timestamp')).to.deep.equal({
             type: 'response-head',
             statusCode: 200,
             statusMessage: 'Custom status message',
@@ -54,8 +58,11 @@ describe("The HTTP client API", () => {
             ]
         });
 
-        expect(responseEvents[1].type).equal('response-body-part');
-        expect(responseEvents[1].rawBody.toString()).to.equal('Mock response body');
+        expect(responseEvents[2].type).equal('response-body-part');
+        expect(responseEvents[2].rawBody.toString()).to.equal('Mock response body');
+        expect(_.omit(responseEvents[3], 'timestamp')).to.deep.equal({
+            type: 'response-end'
+        });
     });
 
     it("should stop requests if cancelled", async () => {
@@ -83,18 +90,23 @@ describe("The HTTP client API", () => {
 
         expect(requests.length).to.equal(1);
         expect(aborts.length).to.equal(0);
-        expect(responseEvents.length).to.equal(0);
+
+        // Start is emitted immediately:
+        expect(responseEvents.length).to.equal(1);
+        expect(_.omit(responseEvents[0], 'timestamp', 'startTime')).to.deep.equal({
+            type: 'request-start'
+        });
 
         abortController.abort();
         await delay(10);
 
         expect(requests.length).to.equal(1);
         expect(aborts.length).to.equal(1); // <-- Server sees the request cancelled
 
-        // Only emitted event is a thrown error:
-        expect(responseEvents.length).to.equal(1);
-        expect(responseEvents[0]).to.be.instanceOf(Error);
-        expect(responseEvents[0].code).to.be.oneOf([
+        // Only other events is a thrown error:
+        expect(responseEvents.length).to.equal(2);
+        expect(responseEvents[1]).to.be.instanceOf(Error);
+        expect(responseEvents[1].code).to.be.oneOf([
             // Depends on the Node version you're testing with:
             'ECONNRESET',
             'ABORT_ERR'

test/integration-test.spec.ts

@@ -1,3 +1,4 @@
+import * as _ from 'lodash';
 import { spawn, ChildProcess } from 'child_process';
 import * as path from 'path';
 
@@ -358,8 +359,11 @@ describe('Integration test', function () {
                 .filter(l => l.trim().length)
                 .map(l => JSON.parse(l));
 
-            expect(responseEvents.length).to.equal(3);
-            expect(responseEvents[0]).to.deep.equal({
+            expect(responseEvents.length).to.equal(4);
+            expect(_.omit(responseEvents[0], 'timestamp', 'startTime')).to.deep.equal({
+                type: 'request-start'
+            });
+            expect(_.omit(responseEvents[1], 'timestamp')).to.deep.equal({
                 type: 'response-head',
                 statusCode: 200,
                 statusMessage: 'Custom status message',
@@ -368,13 +372,13 @@ describe('Integration test', function () {
                 ]
             });
 
-            expect(responseEvents[1].type).equal('response-body-part');
+            expect(responseEvents[2].type).equal('response-body-part');
             expect(
-                Buffer.from(responseEvents[1].rawBody, 'base64').toString('utf8')
+                Buffer.from(responseEvents[2].rawBody, 'base64').toString('utf8')
             ).to.equal('Mock response body');
 
 
-            expect(responseEvents[2]).to.deep.equal({ type: 'response-end' });
+            expect(_.omit(responseEvents[3], 'timestamp')).to.deep.equal({ type: 'response-end' });
         });
     })
 });