diff --git a/.changeset/tame-beans-mate.md b/.changeset/tame-beans-mate.md new file mode 100644 index 0000000..0024de1 --- /dev/null +++ b/.changeset/tame-beans-mate.md @@ -0,0 +1,7 @@ +--- +'@envyjs/webui': patch +'@envyjs/core': patch +'@envyjs/node': patch +--- + +Support HAR timing data diff --git a/packages/core/src/http.ts b/packages/core/src/http.ts index a9e0767..f4c839c 100644 --- a/packages/core/src/http.ts +++ b/packages/core/src/http.ts @@ -59,6 +59,53 @@ export interface HttpRequest { */ statusMessage?: string; + /** + * HAR formatted timing information + * + * http://www.softwareishard.com/blog/har-12-spec/#timings + */ + timings?: { + /** + * Time spent in a queue waiting for a network connection. + * -1 if the timing does not apply to the current request. + */ + blocked: number; + + /** + * DNS resolution time. The time required to resolve a host name. + * -1 if the timing does not apply to the current request. + */ + dns: number; + + /** + * Time required for SSL/TLS negotiation. + * If this field is defined then the time is also included in the connect field (to ensure backward compatibility with HAR 1.1). + * -1 if the timing does not apply to the current request. + */ + ssl: number; + + /** + * Time required to create TCP connection. + * -1 if the timing does not apply to the current request. + */ + connect: number; + + /** + * Time required to send HTTP request to the server. + */ + send: number; + + /** + * Waiting for a response from the server. + */ + wait: number; + + /** + * Time required to read entire response from the server (or cache). + */ + receive: number; + }; + /** * The full url of the request */ diff --git a/packages/node/src/http.ts b/packages/node/src/http.ts index 9b35f7d..6243fdc 100644 --- a/packages/node/src/http.ts +++ b/packages/node/src/http.ts @@ -1,9 +1,8 @@ import http from 'http'; import https from 'https'; -import { types as utilTypes } from 'util'; +import process from 'process'; -import { Event, HttpRequest } from '@envyjs/core'; -import { wrap } from 'shimmer'; +import { Event, HttpRequest, Plugin } from '@envyjs/core'; // eslint thinks zlib is node20:builtin, but this is a node module // eslint-disable-next-line import/order @@ -11,28 +10,20 @@ import { createBrotliDecompress, unzip } from 'zlib'; import { generateId } from './id'; import log from './log'; -import { Plugin } from '@envyjs/core'; - -// ESM handling of wrapping -const _wrap: typeof wrap = (moduleExports, name, wrapper) => { - if (!utilTypes.isProxy(moduleExports)) { - return wrap(moduleExports, name, wrapper); - } else { - const wrapped = wrap(Object.assign({}, moduleExports), name, wrapper); - - return Object.defineProperty(moduleExports, name, { - value: wrapped, - }); - } -}; +import { Timestamps, calculateTiming, getDuration } from './utils/time'; +import { wrap } from './utils/wrap'; export const Http: Plugin = (_options, exporter) => { function override(module: any) { - _wrap(module, 'request', (original: any) => { + wrap(module, 'request', (original: any) => { return function (this: any, ...args: http.ClientRequestArgs[]) { const id = generateId(); const startTs = Date.now(); + const _timestamps: Timestamps = { + start: process.hrtime(), + }; + const request = original.apply(this, args) as http.ClientRequest; const write = request.write; const end = request.end; @@ -58,6 +49,40 @@ export const Http: Plugin = (_options, exporter) => { }, }; + // collect timing data + let removeSocketListeners: () => void; + request.on('socket', socket => { + _timestamps.socket = process.hrtime(); + + const onLookup = () => { + _timestamps.lookup = process.hrtime(); + }; + + const onConnect = () => { + _timestamps.connect = process.hrtime(); + }; + + const onSecureConnect = () => { + _timestamps.secureConnect = process.hrtime(); + }; + + socket.once('lookup', onLookup); + socket.once('connect', onConnect); + socket.once('secureConnect', onSecureConnect); + + removeSocketListeners = () => { + socket.removeListener('lookup', onLookup); + socket.removeListener('connect', onConnect); + socket.removeListener('secureConnect', onSecureConnect); + }; + }); + request.on('finish', () => { + _timestamps.sent = process.hrtime(); + if (removeSocketListeners) removeSocketListeners(); + }); + + // captures the request payload and waits until + // the caller is done writing to the stream const payload: any = []; request.write = function (...args: any) { const chunk = args[0]; @@ -76,7 +101,21 @@ export const Http: Plugin = (_options, exporter) => { return end.apply(this, args); }; + // captures the response request.addListener('response', response => { + _timestamps.firstByte = process.hrtime(); + + // Now we know whether `lookup` or `connect` happened. It's possible they + // were skipped if the hostname was already resolved (or we were given an + // IP directly), or if a connection was already open (e.g. due to + // `keep-alive`). + if (!_timestamps.lookup) { + _timestamps.lookup = _timestamps.socket; + } + if (!_timestamps.connect) { + _timestamps.connect = _timestamps.lookup; + } + const payload: any = []; const onRequestData = (chunk: any) => { @@ -86,14 +125,11 @@ export const Http: Plugin = (_options, exporter) => { }; const onRequestEnd = () => { - const endTs = Date.now(); - const httpResponse: Event = { ...httpRequest, http: { ...httpRequest.http!, - duration: endTs - startTs, httpVersion: response.httpVersion, responseBody: undefined, responseHeaders: response.headers, @@ -103,7 +139,12 @@ export const Http: Plugin = (_options, exporter) => { }; parsePayload(httpResponse.http!, payload, body => { + _timestamps.received = process.hrtime(); + httpResponse.http!.responseBody = body; + httpResponse.http!.timings = calculateTiming(_timestamps); + httpResponse.http!.duration = getDuration(_timestamps.start, _timestamps.received); + exporter.send(httpResponse); }); }; diff --git a/packages/node/src/utils/time.ts b/packages/node/src/utils/time.ts new file mode 100644 index 0000000..9167a13 --- /dev/null +++ b/packages/node/src/utils/time.ts @@ -0,0 +1,53 @@ +// HAR timing Data adapted from +// https://github.com/exogen/node-fetch-har/blob/master/index.js + +import { HttpRequest } from '@envyjs/core'; + +export type HRTime = [number, number]; + +export type Timestamps = { + firstByte?: HRTime; + start: HRTime; + socket?: HRTime; + lookup?: HRTime; + connect?: HRTime; + received?: HRTime; + secureConnect?: HRTime; + sent?: HRTime; +}; + +export function calculateTiming(time: Timestamps): HttpRequest['timings'] { + // For backwards compatibility with HAR 1.1, the `connect` timing + // includes `ssl` instead of being mutually exclusive. + const legacyConnnect = time.secureConnect || time.connect; + + const blocked = getDuration(time.start, time.socket); + const dns = getDuration(time.socket, time.lookup); + const connect = getDuration(time.lookup, legacyConnnect); + + let ssl = -1; + if (time.secureConnect) { + ssl = getDuration(time.connect, time.secureConnect); + } + + const send = getDuration(legacyConnnect, time.sent); + const wait = Math.max(getDuration(time.sent, time.firstByte), 0); + const receive = getDuration(time.firstByte, time.received); + + return { + blocked, + dns, + connect, + send, + wait, + receive, + ssl, + }; +} + +export function getDuration(a: HRTime | undefined, b: HRTime | undefined): number { + if (!(a && b)) return 0; + const seconds = b[0] - a[0]; + const nanoseconds = b[1] - a[1]; + return seconds * 1000 + nanoseconds / 1e6; +} diff --git a/packages/node/src/utils/wrap.ts b/packages/node/src/utils/wrap.ts new file mode 100644 index 0000000..e406a56 --- /dev/null +++ b/packages/node/src/utils/wrap.ts @@ -0,0 +1,16 @@ +import { types as utilTypes } from 'util'; + +import { wrap as _wrap } from 'shimmer'; + +// ESM handling of wrapping +export const wrap: typeof _wrap = (moduleExports, name, wrapper) => { + if (!utilTypes.isProxy(moduleExports)) { + return _wrap(moduleExports, name, wrapper); + } else { + const wrapped = _wrap(Object.assign({}, moduleExports), name, wrapper); + + return Object.defineProperty(moduleExports, name, { + value: wrapped, + }); + } +}; diff --git a/packages/webui/src/components/Fields.tsx b/packages/webui/src/components/Fields.tsx index 6e749ab..de4d4e5 100644 --- a/packages/webui/src/components/Fields.tsx +++ b/packages/webui/src/components/Fields.tsx @@ -12,8 +12,8 @@ type FieldsProps = Omit, 'children'> & { export default function Fields({ className, children, ...props }: FieldsProps) { return ( -
-
{children}
+
+
{children}
); } @@ -21,11 +21,11 @@ export default function Fields({ className, children, ...props }: FieldsProps) { export function Field({ label, className, children, ...props }: FieldProps) { if (!children) return null; return ( -
-
+
+
-
{children}
+
{children}
); } diff --git a/packages/webui/src/components/ui/TimingsDiagram.test.tsx b/packages/webui/src/components/ui/TimingsDiagram.test.tsx new file mode 100644 index 0000000..9c7a34f --- /dev/null +++ b/packages/webui/src/components/ui/TimingsDiagram.test.tsx @@ -0,0 +1,98 @@ +import { cleanup, render } from '@testing-library/react'; + +import { numberFormat } from '@/utils'; + +import TimingsDiagram from './TimingsDiagram'; + +const timings = { + blocked: 10, + dns: 20, + connect: 100, + ssl: 70, + send: 30, + wait: 30, + receive: 10, +}; + +const timingsWithoutSsl = { + blocked: 10, + dns: 20, + connect: 100, + ssl: -1, + send: 30, + wait: 30, + receive: 10, +}; + +describe('TimingsDiagram', () => { + afterEach(() => { + cleanup(); + }); + + it('should render without error', () => { + render(); + }); + + it('should not render anything if timings are `undefined`', () => { + const { container } = render(); + expect(container).toBeEmptyDOMElement(); + }); + + it('should not render anything if timings are `undefined`', () => { + const { container } = render(); + expect(container).toBeEmptyDOMElement(); + }); + + it('should render a row for each timing showing the correct value', () => { + const expectations = [ + { label: 'Blocked', value: 10 }, + { label: 'DNS', value: 20 }, + { label: 'Connecting', value: 30 }, + { label: 'TLS setup', value: 70 }, + { label: 'Sending', value: 30 }, + { label: 'Waiting', value: 30 }, + { label: 'Receiving', value: 10 }, + ]; + + const { getByTestId } = render(); + const tableBody = getByTestId('timings-table-body'); + + let row = tableBody.firstElementChild; + for (const { label, value } of expectations) { + if (!row) break; + + const heading = row.querySelector('th'); + const timing = row.querySelector('td'); + expect(heading).toHaveTextContent(label); + expect(timing).toHaveTextContent(numberFormat(value)); + + row = row.nextElementSibling; + } + }); + + it('should render a row for each timing showing the correct value when there is no SSL involved', () => { + const expectations = [ + { label: 'Blocked', value: 10 }, + { label: 'DNS', value: 20 }, + { label: 'Connecting', value: 100 }, + { label: 'Sending', value: 30 }, + { label: 'Waiting', value: 30 }, + { label: 'Receiving', value: 10 }, + ]; + + const { getByTestId } = render(); + const tableBody = getByTestId('timings-table-body'); + + let row = tableBody.firstElementChild; + for (const { label, value } of expectations) { + if (!row) break; + + const heading = row.querySelector('th'); + const timing = row.querySelector('td'); + expect(heading).toHaveTextContent(label); + expect(timing).toHaveTextContent(numberFormat(value)); + + row = row.nextElementSibling; + } + }); +}); diff --git a/packages/webui/src/components/ui/TimingsDiagram.tsx b/packages/webui/src/components/ui/TimingsDiagram.tsx new file mode 100644 index 0000000..4f589fb --- /dev/null +++ b/packages/webui/src/components/ui/TimingsDiagram.tsx @@ -0,0 +1,82 @@ +import { HttpRequest } from '@envyjs/core'; + +import { numberFormat, tw } from '@/utils'; + +type TimingsData = { + name: string; + color: string; + duration: number; + percentage: number; + offset: number; +}; + +type TimingsDiagramProps = { + timings: HttpRequest['timings']; +}; + +function calculateOffsets(data: TimingsData[]): TimingsData[] { + const dataWithOffsets: TimingsData[] = []; + + let currentOffset = 0; + for (const timing of data) { + dataWithOffsets.push({ ...timing, offset: currentOffset }); + currentOffset += timing.percentage; + } + + return dataWithOffsets; +} + +export default function TimingsDiagram({ timings }: TimingsDiagramProps) { + if (!timings) return null; + + const { blocked, dns, ssl, connect, send, wait, receive } = timings; + + const connecting = ssl === -1 ? connect : connect - ssl; + + // don't include SSL in total since it is included in the connect duration + const total = blocked + dns + connect + send + wait + receive; + + const data = [ + { name: 'Blocked', color: 'bg-red-300', duration: blocked, percentage: blocked / total, offset: 0 }, + { name: 'DNS', color: 'bg-purple-300', duration: dns, percentage: dns / total, offset: 0 }, + { name: 'Connecting', color: 'bg-orange-300', duration: connecting, percentage: connecting / total, offset: 0 }, + { name: 'TLS setup', color: 'bg-amber-300', duration: ssl, percentage: ssl / total, offset: 0 }, + { name: 'Sending', color: 'bg-blue-300', duration: send, percentage: send / total, offset: 0 }, + { name: 'Waiting', color: 'bg-indigo-300', duration: wait, percentage: wait / total, offset: 0 }, + { name: 'Receiving', color: 'bg-green-300', duration: receive, percentage: receive / total, offset: 0 }, + ].filter(x => x.duration >= 0); + + const presentationData = calculateOffsets(data); + + return ( +
+ + + {presentationData.map(({ name, color, duration, offset, percentage }, idx) => ( + + + + + ))} + +
{name} +
+
0.8 ? 'right-2' : 'left-[calc(100%+theme(space.2))]', + )} + > + {numberFormat(duration)}ms +
+
+
+
+ ); +} diff --git a/packages/webui/src/components/ui/TraceDetail.test.tsx b/packages/webui/src/components/ui/TraceDetail.test.tsx index 5b45b4a..939d386 100644 --- a/packages/webui/src/components/ui/TraceDetail.test.tsx +++ b/packages/webui/src/components/ui/TraceDetail.test.tsx @@ -48,7 +48,6 @@ jest.mock( return
Mock QueryParams component: {trace.id}
; }, ); - jest.mock( '@/components/ui/RequestHeaders', () => @@ -56,7 +55,6 @@ jest.mock( return
Mock RequestHeaders component: {trace.id}
; }, ); - jest.mock( '@/components/ui/ResponseHeaders', () => @@ -64,6 +62,13 @@ jest.mock( return
Mock ResponseHeaders component: {trace.id}
; }, ); +jest.mock( + '@/components/ui/TimingsDiagram', + () => + function MockTimingsDiagram({ timings, ...props }: any) { + return
Mock TimingsDiagram component: {JSON.stringify(timings)}
; + }, +); jest.mock('@/systems'); @@ -467,6 +472,16 @@ describe('TraceDetail', () => { expect(status).toHaveTextContent(`204 No Content`); }); + it('should render ResponseHeaders component for trace headers', () => { + const { getByTestId } = render(); + + const responseDetails = getByTestId('response-details'); + const headers = within(responseDetails).getByTestId('headers'); + + expect(headers).toBeVisible(); + expect(headers).toHaveTextContent(`Mock ResponseHeaders component: ${mockTrace.id}`); + }); + it('should display request duration', () => { getSelectedTraceFn.mockReturnValue({ ...mockTrace, @@ -485,14 +500,50 @@ describe('TraceDetail', () => { expect(duration).toHaveTextContent(`1,234ms`); }); - it('should render ResponseHeaders component for trace headers', () => { + it('should not render TimingsDiagram component if there are no timings in the trace', () => { + getSelectedTraceFn.mockReturnValue({ + ...mockTrace, + http: { + ...mockTrace.http, + duration: 1234, + timings: undefined, + }, + }); + const { getByTestId } = render(); const responseDetails = getByTestId('response-details'); - const headers = within(responseDetails).getByTestId('headers'); + const timings = within(responseDetails).queryByTestId('timings'); - expect(headers).toBeVisible(); - expect(headers).toHaveTextContent(`Mock ResponseHeaders component: ${mockTrace.id}`); + expect(timings).not.toBeInTheDocument(); + }); + + it('should render TimingsDiagram component if there are timings in the trace', () => { + const timingsData = { + blocked: 10, + dns: 20, + connect: 100, + ssl: 70, + send: 30, + wait: 30, + receive: 10, + }; + getSelectedTraceFn.mockReturnValue({ + ...mockTrace, + http: { + ...mockTrace.http, + duration: 1234, + timings: timingsData, + }, + }); + + const { getByTestId } = render(); + + const responseDetails = getByTestId('response-details'); + const timings = within(responseDetails).getByTestId('timings'); + + expect(timings).toBeVisible(); + expect(timings).toHaveTextContent(JSON.stringify(timingsData)); }); it('should render SystemResponseDetailsComponent component for trace headers', () => { diff --git a/packages/webui/src/components/ui/TraceDetail.tsx b/packages/webui/src/components/ui/TraceDetail.tsx index 5854027..d6bab56 100644 --- a/packages/webui/src/components/ui/TraceDetail.tsx +++ b/packages/webui/src/components/ui/TraceDetail.tsx @@ -14,6 +14,7 @@ import { getHeader, numberFormat, pathAndQuery } from '@/utils'; import QueryParams from './QueryParams'; import RequestHeaders from './RequestHeaders'; import ResponseHeaders from './ResponseHeaders'; +import TimingsDiagram from './TimingsDiagram'; type CodeDisplayProps = { contentType: string | null; @@ -158,10 +159,15 @@ export default function TraceDetail({ className }: DetailProps) { {statusCode} {statusMessage} + {numberFormat(duration)}ms - + {trace.http?.timings && ( + + + + )} diff --git a/packages/webui/src/testing/mockTraces.ts b/packages/webui/src/testing/mockTraces.ts index 408b39a..c73fab3 100644 --- a/packages/webui/src/testing/mockTraces.ts +++ b/packages/webui/src/testing/mockTraces.ts @@ -65,6 +65,15 @@ const mockTraces: Trace[] = [ 'eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJzdWIiOiIxMjM0NTY3ODkwIiwibmFtZSI6IkpvaG4gRG9lIiwiaWF0IjoxNTE2MjM5MDIyfQ.vqb33-7FqzFWPNlr0ElW1v2RjJRZBel3CdDHBWD7y_o', }), duration: 200, + timings: { + blocked: 10, + dns: 20, + connect: 100, + ssl: 70, + send: 30, + wait: 30, + receive: 10, + }, }, }, @@ -148,6 +157,15 @@ const mockTraces: Trace[] = [ crappyFeature: false, }), duration: 15, + timings: { + blocked: 1, + dns: 1, + connect: 5, + ssl: 2, + send: 3, + wait: 2, + receive: 3, + }, }, }, @@ -178,6 +196,15 @@ const mockTraces: Trace[] = [ }, responseBody: undefined, duration: 10, + timings: { + blocked: 1, + dns: 1, + connect: 3, + ssl: 1, + send: 2, + wait: 2, + receive: 1, + }, }, }, @@ -221,6 +248,15 @@ const mockTraces: Trace[] = [ id: '4', }), duration: 1300, + timings: { + blocked: 40, + dns: 60, + connect: 1000, + ssl: 800, + send: 50, + wait: 120, + receive: 30, + }, }, }, @@ -302,6 +338,15 @@ const mockTraces: Trace[] = [ }, responseBody: undefined, duration: 5000, + timings: { + blocked: 40, + dns: 60, + connect: 1000, + ssl: 800, + send: 500, + wait: 3390, + receive: 10, + }, }, }, @@ -331,7 +376,16 @@ const mockTraces: Trace[] = [ 'connection': 'close', }, responseBody: '1015', - duration: 5000, + duration: 200, + timings: { + blocked: 10, + dns: 20, + connect: 100, + ssl: 70, + send: 30, + wait: 30, + receive: 10, + }, }, },