src/hero.mjs: Add timing data to "in-response" log entry

2 files changed, 14 insertions, 2 deletions

diff --git a/src/hero.mjs b/src/hero.mjs
index 9c6df64..3955eed 100644
--- a/src/hero.mjs
+++ b/src/hero.mjs
@@ -51,12 +51,21 @@ export const interceptorsFn = ({
 			method,
 			type: "in-request",
 		});
+		const beforeDate = new Date();
 		const response = await next(req);
+		const afterDate = new Date();
 		const { status } = response;
+
+		const before   = beforeDate.getTime();
+		const after    = afterDate.getTime();
+		const duration = after - before;
 		logger.info({
 			id,
 			status,
 			type: "in-response",
+			timings: {
+				ms: { before, after, duration },
+			},
 		});
 		return response;
 	},
diff --git a/tests/js/hero.mjs b/tests/js/hero.mjs
index 9a5cf25..ee35489 100644
--- a/tests/js/hero.mjs
+++ b/tests/js/hero.mjs
@@ -237,12 +237,15 @@ const test_interceptorsFn = async t => {
 				{ status },
 			);
 			assert.deepEqual(
-				contents,
+				contents.map(o => u.dissoc(o, "timings")),
 				[
 					{ ...req, type: "in-request"  },
 					{ id: req.id, status, type: "in-response" },
 				],
 			);
+			assert.equal(typeof contents[1].timings.ms.before,   "number");
+			assert.equal(typeof contents[1].timings.ms.after,    "number");
+			assert.equal(typeof contents[1].timings.ms.duration, "number");
 		});
 	};
 
@@ -501,7 +504,7 @@ const test_wrapHandler = async t => {
 			},
 		);
 		assert.deepEqual(
-			contents,
+			contents.map(o => u.dissoc(o, "timings")),
 			[
 				{
 					id:     "0",