diff --git a/src/core/packages/elasticsearch/client-server-internal/src/cluster_client.ts b/src/core/packages/elasticsearch/client-server-internal/src/cluster_client.ts index 6a384bd2fd085..bb32db33114d8 100644 --- a/src/core/packages/elasticsearch/client-server-internal/src/cluster_client.ts +++ b/src/core/packages/elasticsearch/client-server-internal/src/cluster_client.ts @@ -42,10 +42,13 @@ import { import { createTransport, type OnRequestHandler } from './create_transport'; import type { AgentFactoryProvider } from './agent_manager'; +export type { OnRequestHandler }; + const noop = () => undefined; interface CommonFactoryRoutingOpts { logger: Logger; + request?: ScopeableUrlRequest; } interface SpaceFactoryRoutingOpts extends CommonFactoryRoutingOpts { @@ -140,7 +143,7 @@ export class ClusterClient implements ICustomClusterClient { const scopedHeaders = this.getScopedHeaders(request); const factoryOpts: FactoryRoutingOpts = opts ? { ...opts, logger: this.logger, request } - : { logger: this.logger }; + : { logger: this.logger, request }; const transportClass = createTransport({ scoped: true, getExecutionContext: this.getExecutionContext, diff --git a/src/core/packages/elasticsearch/client-server-internal/src/configure_client.ts b/src/core/packages/elasticsearch/client-server-internal/src/configure_client.ts index 23c50466b690b..765bc8e777a09 100644 --- a/src/core/packages/elasticsearch/client-server-internal/src/configure_client.ts +++ b/src/core/packages/elasticsearch/client-server-internal/src/configure_client.ts @@ -7,6 +7,7 @@ * License v3.0 only", or the "Server Side Public License, v 1". */ +import { performance } from 'perf_hooks'; import { Client, HttpConnection, ClusterConnectionPool } from '@elastic/elasticsearch'; import type { Logger } from '@kbn/logging'; import type { ElasticsearchClientConfig } from '@kbn/core-elasticsearch-server'; @@ -109,6 +110,16 @@ function instrumentCpsMetrics({ client, logger }: { client: Client; logger: Logg cpsRequestCounter.add(1, metricAttributes); + // Report ES request timing to Server-Timing header + const timingContext = (event.meta.request.options?.context as any)?.timingContext; + if (timingContext?.kibanaRequest?.serverTiming && timingContext.startTime) { + const duration = performance.now() - timingContext.startTime; + const method = event.meta.request.params.method || 'unknown'; + const path = event.meta.request.params.path || 'unknown'; + + timingContext.kibanaRequest.serverTiming.measure('es-request', duration, `${method} ${path}`); + } + logger.debug('CPS request completed', { event: { kind: routingType === 'none' && bypassReason ? 'alert' : 'metric', diff --git a/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.test.ts b/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.test.ts index 15a0c176c39a8..594fc2b004b35 100644 --- a/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.test.ts +++ b/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.test.ts @@ -54,4 +54,85 @@ describe('getRequestHandlerFactory', () => { ); }); }); + + describe('timing context', () => { + it('sets timing context for internal user', () => { + const factory = getRequestHandlerFactory(true); + const handler = factory({ logger: mockLogger }); + const params = makeSearchParams(); + const options = {}; + + handler({ scoped: false }, params, options, mockLogger); + + expect((options as any).context).toBeDefined(); + expect((options as any).context.timingContext).toBeDefined(); + expect((options as any).context.timingContext.startTime).toBeGreaterThan(0); + }); + + it('sets timing context with kibanaRequest for scoped user', () => { + const factory = getRequestHandlerFactory(true); + const request = httpServerMock.createKibanaRequest({ path: '/s/my-space/app/discover' }); + const handler = factory({ projectRouting: 'space', request, logger: mockLogger }); + const params = makeSearchParams(); + const options = {}; + + handler({ scoped: true }, params, options, mockLogger); + + expect((options as any).context).toBeDefined(); + expect((options as any).context.timingContext).toBeDefined(); + expect((options as any).context.timingContext.startTime).toBeGreaterThan(0); + expect((options as any).context.timingContext.kibanaRequest).toBe(request); + }); + + it('sets both timing and CPS contexts', () => { + const factory = getRequestHandlerFactory(true); + const request = httpServerMock.createKibanaRequest({ path: '/s/my-space/app/discover' }); + const handler = factory({ projectRouting: 'space', request, logger: mockLogger }); + const params = makeSearchParams(); + const options = {}; + + handler({ scoped: true }, params, options, mockLogger); + + expect((options as any).context.timingContext).toBeDefined(); + expect((options as any).context.cpsRoutingContext).toBeDefined(); + }); + + it('does not set timing context when esTimingEnabled is false', () => { + const factory = getRequestHandlerFactory(true, false); + const request = httpServerMock.createKibanaRequest({ path: '/s/my-space/app/discover' }); + const handler = factory({ projectRouting: 'space', request, logger: mockLogger }); + const params = makeSearchParams(); + const options = {}; + + handler({ scoped: true }, params, options, mockLogger); + + expect((options as any).context?.timingContext).toBeUndefined(); + expect((options as any).context?.cpsRoutingContext).toBeDefined(); + }); + + it('sets timing context when esTimingEnabled is true (explicit)', () => { + const factory = getRequestHandlerFactory(true, true); + const handler = factory({ logger: mockLogger }); + const params = makeSearchParams(); + const options = {}; + + handler({ scoped: false }, params, options, mockLogger); + + expect((options as any).context).toBeDefined(); + expect((options as any).context.timingContext).toBeDefined(); + expect((options as any).context.timingContext.startTime).toBeGreaterThan(0); + }); + + it('defaults esTimingEnabled to true when not specified', () => { + const factory = getRequestHandlerFactory(true); + const handler = factory({ logger: mockLogger }); + const params = makeSearchParams(); + const options = {}; + + handler({ scoped: false }, params, options, mockLogger); + + expect((options as any).context).toBeDefined(); + expect((options as any).context.timingContext).toBeDefined(); + }); + }); }); diff --git a/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.ts b/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.ts index 68cde4106b8c5..2dfd551b62153 100644 --- a/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.ts +++ b/src/core/packages/elasticsearch/client-server-internal/src/cps_request_handler/cps_request_handler_factory.ts @@ -8,21 +8,40 @@ */ import { getSpaceNPRE, PROJECT_ROUTING_ORIGIN } from '@kbn/cps-server-utils'; -import type { OnRequestHandlerFactory } from '../cluster_client'; +import { isKibanaRequest } from '@kbn/core-http-router-server-internal'; +import type { OnRequestHandlerFactory, OnRequestHandler } from '../cluster_client'; import { getCpsRequestHandler } from './cps_request_handler'; +import { getTimingRequestHandler } from '../timing'; + +const noopHandler: OnRequestHandler = () => undefined; /** * Returns an {@link OnRequestHandlerFactory} that maps routing options to the - * appropriate CPS `OnRequestHandler` for each client scope. + * appropriate CPS `OnRequestHandler` for each client scope, composed with + * timing instrumentation. * * @internal */ -export function getRequestHandlerFactory(cpsEnabled: boolean): OnRequestHandlerFactory { +export function getRequestHandlerFactory( + cpsEnabled: boolean, + esTimingEnabled: boolean = true +): OnRequestHandlerFactory { return (opts) => { - if ('projectRouting' in opts && opts.projectRouting === 'space') { - return getCpsRequestHandler(cpsEnabled, getSpaceNPRE(opts.request), opts.logger); - } else { - return getCpsRequestHandler(cpsEnabled, PROJECT_ROUTING_ORIGIN, opts.logger); - } + const request = 'request' in opts && isKibanaRequest(opts.request) ? opts.request : undefined; + + // Get the timing handler (or noop if disabled) + const timingHandler = esTimingEnabled ? getTimingRequestHandler(request) : noopHandler; + + // Get the CPS handler based on routing options + const cpsHandler = + 'projectRouting' in opts && opts.projectRouting === 'space' + ? getCpsRequestHandler(cpsEnabled, getSpaceNPRE(opts.request), opts.logger) + : getCpsRequestHandler(cpsEnabled, PROJECT_ROUTING_ORIGIN, opts.logger); + + // Return a composed handler that calls both in sequence + return (ctx, params, options, logger) => { + timingHandler(ctx, params, options, logger); + cpsHandler(ctx, params, options, logger); + }; }; } diff --git a/src/core/packages/elasticsearch/client-server-internal/src/create_transport.ts b/src/core/packages/elasticsearch/client-server-internal/src/create_transport.ts index 8b511a8fcef2e..7a47166a9dc69 100644 --- a/src/core/packages/elasticsearch/client-server-internal/src/create_transport.ts +++ b/src/core/packages/elasticsearch/client-server-internal/src/create_transport.ts @@ -17,9 +17,28 @@ import { } from '@elastic/elasticsearch'; import { isUnauthorizedError } from '@kbn/es-errors'; import type { Logger } from '@kbn/logging'; +import type { KibanaRequest } from '@kbn/core-http-server'; import type { InternalUnauthorizedErrorHandler } from './retry_unauthorized'; import { isRetryResult } from './retry_unauthorized'; +/** + * Timing context stored in Transport request options for instrumentation + * @internal + */ +export interface TimingContext { + startTime: number; + kibanaRequest: KibanaRequest; +} + +/** + * Extended context type for Transport request options + * @internal + */ +export interface TransportContext { + cpsRoutingContext?: any; + timingContext?: TimingContext; +} + type TransportClass = typeof Transport; export type ErrorHandlerAccessor = () => InternalUnauthorizedErrorHandler; diff --git a/src/core/packages/elasticsearch/client-server-internal/src/timing/index.ts b/src/core/packages/elasticsearch/client-server-internal/src/timing/index.ts new file mode 100644 index 0000000000000..563ec7dad5030 --- /dev/null +++ b/src/core/packages/elasticsearch/client-server-internal/src/timing/index.ts @@ -0,0 +1,10 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +export { getTimingRequestHandler } from './timing_request_handler'; diff --git a/src/core/packages/elasticsearch/client-server-internal/src/timing/timing_request_handler.test.ts b/src/core/packages/elasticsearch/client-server-internal/src/timing/timing_request_handler.test.ts new file mode 100644 index 0000000000000..63cadc23c4a16 --- /dev/null +++ b/src/core/packages/elasticsearch/client-server-internal/src/timing/timing_request_handler.test.ts @@ -0,0 +1,104 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +import type { TransportRequestParams, TransportRequestOptions } from '@elastic/elasticsearch'; +import type { KibanaRequest } from '@kbn/core-http-server'; +import { httpServerMock } from '@kbn/core-http-server-mocks'; +import { loggerMock } from '@kbn/logging-mocks'; +import { getTimingRequestHandler } from './timing_request_handler'; + +describe('getTimingRequestHandler', () => { + const mockLogger = loggerMock.create(); + + beforeEach(() => { + jest.clearAllMocks(); + }); + + it('sets timing context with startTime', () => { + const handler = getTimingRequestHandler(); + const params: TransportRequestParams = { + method: 'GET', + path: '/_search', + }; + const options: TransportRequestOptions = {}; + + handler({ scoped: true }, params, options, mockLogger); + + expect(options.context).toBeDefined(); + expect((options.context as any).timingContext).toBeDefined(); + expect((options.context as any).timingContext.startTime).toBeGreaterThan(0); + expect((options.context as any).timingContext.kibanaRequest).toBeUndefined(); + }); + + it('includes kibanaRequest in timing context when provided', () => { + const mockRequest = httpServerMock.createKibanaRequest() as KibanaRequest; + const handler = getTimingRequestHandler(mockRequest); + const params: TransportRequestParams = { + method: 'GET', + path: '/_search', + }; + const options: TransportRequestOptions = {}; + + handler({ scoped: true }, params, options, mockLogger); + + expect(options.context).toBeDefined(); + expect((options.context as any).timingContext).toBeDefined(); + expect((options.context as any).timingContext.kibanaRequest).toBe(mockRequest); + expect((options.context as any).timingContext.startTime).toBeGreaterThan(0); + }); + + it('creates context object if not present', () => { + const handler = getTimingRequestHandler(); + const params: TransportRequestParams = { + method: 'GET', + path: '/_search', + }; + const options: TransportRequestOptions = {}; + + expect(options.context).toBeUndefined(); + handler({ scoped: true }, params, options, mockLogger); + + expect(options.context).toBeDefined(); + expect((options.context as any).timingContext).toBeDefined(); + }); + + it('preserves existing context properties', () => { + const handler = getTimingRequestHandler(); + const params: TransportRequestParams = { + method: 'GET', + path: '/_search', + }; + const existingContext = { someOtherContext: { foo: 'bar' } }; + const options: TransportRequestOptions = { + context: existingContext, + }; + + handler({ scoped: true }, params, options, mockLogger); + + expect((options.context as any).someOtherContext).toEqual({ foo: 'bar' }); + expect((options.context as any).timingContext).toBeDefined(); + }); + + it('records timing at invocation time', () => { + const handler = getTimingRequestHandler(); + const params: TransportRequestParams = { + method: 'GET', + path: '/_search', + }; + const options: TransportRequestOptions = {}; + + const beforeTime = performance.now(); + handler({ scoped: true }, params, options, mockLogger); + const afterTime = performance.now(); + + const startTime = (options.context as any).timingContext.startTime; + expect(startTime).toBeGreaterThanOrEqual(beforeTime); + expect(startTime).toBeLessThanOrEqual(afterTime); + }); +}); diff --git a/src/core/packages/elasticsearch/client-server-internal/src/timing/timing_request_handler.ts b/src/core/packages/elasticsearch/client-server-internal/src/timing/timing_request_handler.ts new file mode 100644 index 0000000000000..9d453310280fb --- /dev/null +++ b/src/core/packages/elasticsearch/client-server-internal/src/timing/timing_request_handler.ts @@ -0,0 +1,33 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +import { performance } from 'perf_hooks'; +import type { KibanaRequest } from '@kbn/core-http-server'; +import type { OnRequestHandler } from '../create_transport'; + +/** + * Returns an {@link OnRequestHandler} that instruments ES request timing + * and stores timing context for response-phase measurement. + * + * @param kibanaRequest - Optional KibanaRequest to attach Server-Timing measurements to + * @returns Handler that sets timing context in options.context + * + * @internal + */ +export function getTimingRequestHandler(kibanaRequest?: KibanaRequest): OnRequestHandler { + return (_ctx, _params, options, _receivedLogger) => { + if (!options.context) { + options.context = {}; + } + (options.context as any).timingContext = { + startTime: performance.now(), + kibanaRequest, + }; + }; +} diff --git a/src/core/packages/elasticsearch/server-internal/src/elasticsearch_service.ts b/src/core/packages/elasticsearch/server-internal/src/elasticsearch_service.ts index c12e586c421ed..22fb6d0ec7bc9 100644 --- a/src/core/packages/elasticsearch/server-internal/src/elasticsearch_service.ts +++ b/src/core/packages/elasticsearch/server-internal/src/elasticsearch_service.ts @@ -66,6 +66,7 @@ export class ElasticsearchService private readonly config$: Observable; private readonly isServerless: boolean; private onRequestHandlerFactory: OnRequestHandlerFactory; + private esTimingEnabled: boolean = false; private stop$ = new Subject(); private kibanaVersion: string; private authHeaders?: IAuthHeadersStorage; @@ -117,7 +118,8 @@ export class ElasticsearchService ).catch(() => ({ cpsEnabled: false })) ).cpsEnabled ?? false : false; - this.onRequestHandlerFactory = getRequestHandlerFactory(cpsEnabled); + this.esTimingEnabled = deps.http.config.serverTimingElasticsearch; + this.onRequestHandlerFactory = getRequestHandlerFactory(cpsEnabled, this.esTimingEnabled); const agentManager = this.getAgentManager(config); diff --git a/src/core/packages/http/router-server-internal/src/request.ts b/src/core/packages/http/router-server-internal/src/request.ts index fe20cb481be33..38fb17631521e 100644 --- a/src/core/packages/http/router-server-internal/src/request.ts +++ b/src/core/packages/http/router-server-internal/src/request.ts @@ -34,6 +34,7 @@ import type { HttpProtocol, RouteSecurityGetter, RouteSecurity, + RequestTiming, } from '@kbn/core-http-server'; import { ELASTIC_INTERNAL_ORIGIN_QUERY_PARAM, @@ -43,6 +44,7 @@ import { RouteValidator } from './validator'; import { isSafeMethod } from './route'; import { KibanaSocket } from './socket'; import { patchRequest } from './patch_requests'; +import { RequestTimingImpl } from './timing'; // patching at module load patchRequest(); @@ -150,6 +152,8 @@ export class CoreKibanaRequest< public readonly protocol: HttpProtocol; /** {@inheritDoc KibanaRequest.authzResult} */ public readonly authzResult?: Record; + /** {@inheritDoc KibanaRequest.timing} */ + public readonly serverTiming: RequestTiming; /** @internal */ protected readonly [requestSymbol]!: Request; @@ -169,10 +173,16 @@ export class CoreKibanaRequest< const appState = request.app as KibanaRequestState | undefined; const isRealReq = isRealRawRequest(request); + // Initialize timing state if not present + if (appState && !appState.timingState) { + appState.timingState = { events: [] }; + } + this.id = appState?.requestId ?? uuidv4(); this.uuid = appState?.requestUuid ?? uuidv4(); this.rewrittenUrl = appState?.rewrittenUrl; this.authzResult = appState?.authzResult; + this.serverTiming = new RequestTimingImpl(appState?.timingState ?? { events: [] }); this.injectHostInfo(request); this.url = request.url ?? new URL('https://fake-request/url'); diff --git a/src/core/packages/http/router-server-internal/src/timing/index.ts b/src/core/packages/http/router-server-internal/src/timing/index.ts new file mode 100644 index 0000000000000..ce3b4f2b9e652 --- /dev/null +++ b/src/core/packages/http/router-server-internal/src/timing/index.ts @@ -0,0 +1,11 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +export { RequestTimingImpl } from './request_timing'; +export type { RequestTimingState } from './types'; diff --git a/src/core/packages/http/router-server-internal/src/timing/request_timing.test.ts b/src/core/packages/http/router-server-internal/src/timing/request_timing.test.ts new file mode 100644 index 0000000000000..f51c9b02bae2b --- /dev/null +++ b/src/core/packages/http/router-server-internal/src/timing/request_timing.test.ts @@ -0,0 +1,179 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +import { RequestTimingImpl } from './request_timing'; +import type { RequestTimingState } from './types'; + +describe('RequestTimingImpl', () => { + let state: RequestTimingState; + let timing: RequestTimingImpl; + + beforeEach(() => { + state = { events: [] }; + timing = new RequestTimingImpl(state); + }); + + describe('start()', () => { + it('returns a timer with an end() method', () => { + const timer = timing.start('test-operation'); + + expect(timer).toBeDefined(); + expect(typeof timer.end).toBe('function'); + }); + + it('creates an event when timer.end() is called', () => { + const timer = timing.start('test-operation'); + timer.end(); + + expect(state.events).toHaveLength(1); + expect(state.events[0].name).toBe('test-operation'); + expect(state.events[0].duration).toBeGreaterThanOrEqual(0); + }); + + it('includes description in the event', () => { + const timer = timing.start('test-operation', 'Test description'); + timer.end(); + + expect(state.events[0].description).toBe('Test description'); + }); + + it('measures correct duration', async () => { + const timer = timing.start('test-operation'); + await new Promise((resolve) => setTimeout(resolve, 10)); + timer.end(); + + expect(state.events[0].duration).toBeGreaterThanOrEqual(10); + }); + + it('does not create an event if timer.end() is not called', () => { + timing.start('test-operation'); + + expect(state.events).toHaveLength(0); + }); + + it('handles multiple timer.end() calls idempotently', () => { + const timer = timing.start('test-operation'); + timer.end(); + timer.end(); + timer.end(); + + expect(state.events).toHaveLength(1); + }); + + it('handles overlapping timers correctly', () => { + const timer1 = timing.start('operation-1'); + const timer2 = timing.start('operation-2'); + + timer2.end(); + timer1.end(); + + expect(state.events).toHaveLength(2); + expect(state.events[0].name).toBe('operation-2'); + expect(state.events[1].name).toBe('operation-1'); + }); + + it('allows multiple simultaneous operations', async () => { + const timer1 = timing.start('operation-1'); + const timer2 = timing.start('operation-2'); + + await Promise.all([ + new Promise((resolve) => + setTimeout(() => { + timer1.end(); + resolve(undefined); + }, 10) + ), + new Promise((resolve) => + setTimeout(() => { + timer2.end(); + resolve(undefined); + }, 5) + ), + ]); + + expect(state.events).toHaveLength(2); + expect(state.events.find((e) => e.name === 'operation-1')).toBeDefined(); + expect(state.events.find((e) => e.name === 'operation-2')).toBeDefined(); + }); + }); + + describe('measure()', () => { + it('records a timing event with explicit duration', () => { + timing.measure('test-operation', 123.45); + + expect(state.events).toHaveLength(1); + expect(state.events[0].name).toBe('test-operation'); + expect(state.events[0].duration).toBe(123.45); + }); + + it('includes description when provided', () => { + timing.measure('test-operation', 123.45, 'Test description'); + + expect(state.events[0].description).toBe('Test description'); + }); + + it('skips events with negative duration', () => { + timing.measure('test-operation', -10); + + expect(state.events).toHaveLength(0); + }); + + it('skips events with names longer than 100 characters', () => { + const longName = 'a'.repeat(101); + timing.measure(longName, 123.45); + + expect(state.events).toHaveLength(0); + }); + + it('allows events with names exactly 100 characters', () => { + const exactName = 'a'.repeat(100); + timing.measure(exactName, 123.45); + + expect(state.events).toHaveLength(1); + expect(state.events[0].name).toBe(exactName); + }); + + it('allows zero duration', () => { + timing.measure('test-operation', 0); + + expect(state.events).toHaveLength(1); + expect(state.events[0].duration).toBe(0); + }); + }); + + describe('getEvents()', () => { + it('returns empty array when no events recorded', () => { + const events = timing.getEvents(); + + expect(events).toEqual([]); + }); + + it('returns all recorded events', () => { + const timer1 = timing.start('operation-1'); + timer1.end(); + timing.measure('operation-2', 50); + + const events = timing.getEvents(); + + expect(events).toHaveLength(2); + expect(events[0].name).toBe('operation-1'); + expect(events[1].name).toBe('operation-2'); + expect(events[1].duration).toBe(50); + }); + + it('returns readonly array', () => { + timing.measure('operation-1', 100); + const events = timing.getEvents(); + + expect(Object.isFrozen(events)).toBe(false); // Array itself is not frozen + // But the type ensures it's readonly at compile time + expect(events).toEqual(state.events); + }); + }); +}); diff --git a/src/core/packages/http/router-server-internal/src/timing/request_timing.ts b/src/core/packages/http/router-server-internal/src/timing/request_timing.ts new file mode 100644 index 0000000000000..f2be775b93b07 --- /dev/null +++ b/src/core/packages/http/router-server-internal/src/timing/request_timing.ts @@ -0,0 +1,46 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +import type { RequestTiming, Timer, TimingEvent } from '@kbn/core-http-server'; +import type { RequestTimingState } from './types'; + +/** + * Internal implementation of the RequestTiming API + * @internal + */ +export class RequestTimingImpl implements RequestTiming { + constructor(private readonly state: RequestTimingState) {} + + start(name: string, description?: string): Timer { + const startTime = performance.now(); + let ended = false; + + return { + end: () => { + if (ended) return; + ended = true; + + const duration = performance.now() - startTime; + this.state.events.push({ name, duration, description }); + }, + }; + } + + measure(name: string, duration: number, description?: string): void { + if (name.length > 100 || duration < 0) { + return; + } + + this.state.events.push({ name, duration, description }); + } + + getEvents(): readonly TimingEvent[] { + return this.state.events; + } +} diff --git a/src/core/packages/http/router-server-internal/src/timing/types.ts b/src/core/packages/http/router-server-internal/src/timing/types.ts new file mode 100644 index 0000000000000..b47a1754b96d6 --- /dev/null +++ b/src/core/packages/http/router-server-internal/src/timing/types.ts @@ -0,0 +1,18 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +import type { TimingEvent } from '@kbn/core-http-server'; + +/** + * Internal state for request timing + * @internal + */ +export interface RequestTimingState { + events: TimingEvent[]; +} diff --git a/src/core/packages/http/server-internal/src/__snapshots__/http_config.test.ts.snap b/src/core/packages/http/server-internal/src/__snapshots__/http_config.test.ts.snap index 430c7789d0744..89a7b785dd126 100644 --- a/src/core/packages/http/server-internal/src/__snapshots__/http_config.test.ts.snap +++ b/src/core/packages/http/server-internal/src/__snapshots__/http_config.test.ts.snap @@ -103,6 +103,8 @@ Object { "strictTransportSecurity": null, "xContentTypeOptions": "nosniff", }, + "serverTiming": false, + "serverTimingElasticsearch": false, "shutdownTimeout": "PT30S", "socketTimeout": 120000, "ssl": Object { diff --git a/src/core/packages/http/server-internal/src/http_config.test.ts b/src/core/packages/http/server-internal/src/http_config.test.ts index 81642bbe0ea36..970a0e841ada4 100644 --- a/src/core/packages/http/server-internal/src/http_config.test.ts +++ b/src/core/packages/http/server-internal/src/http_config.test.ts @@ -524,6 +524,72 @@ describe('versioned', () => { }); }); +describe('serverTiming', () => { + it('defaults to true in dev', () => { + expect(config.schema.validate({}, { dev: true })).toMatchObject({ + serverTiming: true, + }); + }); + + it('defaults to false in production', () => { + expect(config.schema.validate({}, { dev: false })).toMatchObject({ + serverTiming: false, + }); + }); + + it('allows enabling in dev', () => { + expect(config.schema.validate({ serverTiming: true }, { dev: true })).toMatchObject({ + serverTiming: true, + }); + }); + + it('allows disabling in dev', () => { + expect(config.schema.validate({ serverTiming: false }, { dev: true })).toMatchObject({ + serverTiming: false, + }); + }); + + it('throws when trying to enable in production', () => { + expect(() => config.schema.validate({ serverTiming: true }, { dev: false })).toThrow(); + }); +}); + +describe('serverTimingElasticsearch', () => { + it('defaults to true in dev', () => { + expect(config.schema.validate({}, { dev: true })).toMatchObject({ + serverTimingElasticsearch: true, + }); + }); + + it('defaults to false in production', () => { + expect(config.schema.validate({}, { dev: false })).toMatchObject({ + serverTimingElasticsearch: false, + }); + }); + + it('allows enabling in dev', () => { + expect( + config.schema.validate({ serverTimingElasticsearch: true }, { dev: true }) + ).toMatchObject({ + serverTimingElasticsearch: true, + }); + }); + + it('allows disabling in dev', () => { + expect( + config.schema.validate({ serverTimingElasticsearch: false }, { dev: true }) + ).toMatchObject({ + serverTimingElasticsearch: false, + }); + }); + + it('throws when trying to enable in production', () => { + expect(() => + config.schema.validate({ serverTimingElasticsearch: true }, { dev: false }) + ).toThrow(); + }); +}); + describe('restrictInternalApis', () => { it('is allowed on serverless and traditional', () => { expect(() => config.schema.validate({ restrictInternalApis: false }, {})).not.toThrow(); diff --git a/src/core/packages/http/server-internal/src/http_config.ts b/src/core/packages/http/server-internal/src/http_config.ts index f257448b915a6..9cf0864a92f52 100644 --- a/src/core/packages/http/server-internal/src/http_config.ts +++ b/src/core/packages/http/server-internal/src/http_config.ts @@ -260,6 +260,24 @@ const configSchema = schema.object( serverless: schema.never(), }), }), + + serverTiming: schema.conditional( + schema.contextRef('dev'), + true, + /** In dev mode: allow true/false, default to true */ + schema.boolean({ defaultValue: true }), + /** In production: only allow false, default to false */ + schema.oneOf([schema.literal(false)], { defaultValue: false }) + ), + + serverTimingElasticsearch: schema.conditional( + schema.contextRef('dev'), + true, + /** In dev mode: allow true/false, default to true */ + schema.boolean({ defaultValue: true }), + /** In production: only allow false, default to false */ + schema.oneOf([schema.literal(false)], { defaultValue: false }) + ), }, { validate: (rawConfig) => { @@ -375,6 +393,8 @@ export class HttpConfig implements IHttpConfig { public shutdownTimeout: Duration; public restrictInternalApis: boolean; public rateLimiter: RateLimiterConfig; + public serverTiming: boolean; + public serverTimingElasticsearch: boolean; public eluMonitor: IHttpEluMonitorConfig; @@ -425,6 +445,8 @@ export class HttpConfig implements IHttpConfig { this.requestId = rawHttpConfig.requestId; this.shutdownTimeout = rawHttpConfig.shutdownTimeout; this.rateLimiter = rawHttpConfig.rateLimiter; + this.serverTiming = rawHttpConfig.serverTiming; + this.serverTimingElasticsearch = rawHttpConfig.serverTimingElasticsearch; // defaults to `true` if not set through config. this.restrictInternalApis = rawHttpConfig.restrictInternalApis; diff --git a/src/core/packages/http/server-internal/src/http_server.test.ts b/src/core/packages/http/server-internal/src/http_server.test.ts index 11e49175ee0ca..d111757a180c6 100644 --- a/src/core/packages/http/server-internal/src/http_server.test.ts +++ b/src/core/packages/http/server-internal/src/http_server.test.ts @@ -2228,3 +2228,71 @@ test('properly treats minimal authentication as required', async () => { }, }); }); + +test('includes Server-Timing header with custom events', async () => { + const router = new Router('/foo', logger, enhanceWithContext, routerOptions); + router.get( + { + path: '/timing-test', + validate: false, + security: { + authz: { + requiredPrivileges: ['foo'], + }, + }, + }, + (context, req, res) => { + // Use timing API + const timer = req.serverTiming.start('test-operation', 'Test operation'); + timer.end(); + req.serverTiming.measure('manual-metric', 42.5, 'Manual measurement'); + + return res.ok({ body: 'ok' }); + } + ); + + const { registerRouter, server: innerServer } = await server.setup({ + config$: of({ ...config, serverTiming: true }), + }); + registerRouter(router); + await server.start(); + + const response = await supertest(innerServer.listener).get('/foo/timing-test').expect(200); + + // Verify Server-Timing header exists and contains expected metrics + expect(response.headers['server-timing']).toBeDefined(); + const headerValue = response.headers['server-timing']; + expect(headerValue).toMatch( + /app-total;dur=[\d.]+;desc="Application Server Processing Time \(Total\)"/ + ); + expect(headerValue).toMatch(/test-operation;dur=[\d.]+;desc="Test operation"/); + expect(headerValue).toContain('manual-metric;dur=42.50;desc="Manual measurement"'); +}); + +test('does not set Server-Timing header when serverTiming is disabled', async () => { + const router = new Router('/foo', logger, enhanceWithContext, routerOptions); + router.get( + { + path: '/', + validate: false, + security: { + authz: { + requiredPrivileges: ['foo'], + }, + }, + }, + (context, req, res) => { + return res.ok({ body: 'ok' }); + } + ); + + const { registerRouter, server: innerServer } = await server.setup({ + config$: of({ ...config, serverTiming: false }), + }); + registerRouter(router); + await server.start(); + + const response = await supertest(innerServer.listener).get('/foo/').expect(200); + + expect(response.headers['server-timing']).toBeUndefined(); +}); diff --git a/src/core/packages/http/server-internal/src/http_server.ts b/src/core/packages/http/server-internal/src/http_server.ts index 519f099c9170e..c2e347df5d6af 100644 --- a/src/core/packages/http/server-internal/src/http_server.ts +++ b/src/core/packages/http/server-internal/src/http_server.ts @@ -43,6 +43,7 @@ import type { RouterDeprecatedApiDetails, RouterRoute, SessionStorageCookieOptions, + TimingEvent, VersionedRouterRoute, } from '@kbn/core-http-server'; import { performance } from 'perf_hooks'; @@ -544,6 +545,31 @@ export class HttpServer { this.server.events.on('response', this.handleServerResponseEvent); } + private formatServerTimingHeader( + totalTime: number, + customEvents: readonly TimingEvent[] + ): string { + const timingMetrics = [ + `app-total;dur=${totalTime.toFixed(2)};desc="Application Server Processing Time (Total)"`, + ]; + + // Limit to 20 events, sanitize names, escape descriptions + for (const event of customEvents.slice(0, 20)) { + const safeName = event.name.replace(/[^a-zA-Z0-9_-]/g, '_'); + let metric = `${safeName};dur=${event.duration.toFixed(2)}`; + if (event.description) { + const safeDesc = event.description + .replace(/\\/g, '\\\\') + .replace(/"/g, '\\"') + .slice(0, 100); + metric += `;desc="${safeDesc}"`; + } + timingMetrics.push(metric); + } + + return timingMetrics.join(', '); + } + private setupRequestStateAssignment( config: HttpConfig, executionContext?: InternalExecutionContextSetup, @@ -559,6 +585,21 @@ export class HttpServer { return responseToolkit.continue; } + // Only add Server-Timing header if enabled in config (dev mode by default) + if (this.config?.serverTiming) { + const appState = request.app as KibanaRequestState; + const startTime = appState.startTime; + const totalTime = performance.now() - startTime; + const customEvents = appState.timingState?.events ?? []; + const serverTimingValue = this.formatServerTimingHeader(totalTime, customEvents); + + if (isBoom(request.response)) { + request.response.output.headers['Server-Timing'] = serverTimingValue; + } else { + request.response.header('Server-Timing', serverTimingValue); + } + } + if (isBoom(request.response)) { stop(app.httpSpan); app.otelSubSpan?.end(); diff --git a/src/core/packages/http/server-internal/src/http_service.ts b/src/core/packages/http/server-internal/src/http_service.ts index 9d15d33d034ca..bca2f4cba7254 100644 --- a/src/core/packages/http/server-internal/src/http_service.ts +++ b/src/core/packages/http/server-internal/src/http_service.ts @@ -202,6 +202,7 @@ export class HttpService this.internalSetup = { ...serverContract, + config, rateLimiter: config.rateLimiter, registerOnPostValidation: (cb) => { Router.on('onPostValidate', cb); diff --git a/src/core/packages/http/server-internal/src/types.ts b/src/core/packages/http/server-internal/src/types.ts index e84ec60503c6d..f110cde36d871 100644 --- a/src/core/packages/http/server-internal/src/types.ts +++ b/src/core/packages/http/server-internal/src/types.ts @@ -26,6 +26,7 @@ import type { HttpServerSetup } from './http_server'; import type { ExternalUrlConfig } from './external_url'; import type { InternalStaticAssets } from './static_assets'; import type { RateLimiterConfig } from './rate_limiter'; +import type { HttpConfig } from './http_config'; /** @internal */ export interface InternalHttpServicePreboot @@ -58,6 +59,7 @@ export interface InternalHttpServiceSetup staticAssets: InternalStaticAssets; externalUrl: ExternalUrlConfig; prototypeHardening: boolean; + config: HttpConfig; createRouter: ( path: string, plugin?: PluginOpaqueId diff --git a/src/core/packages/http/server-mocks/src/http_service.mock.ts b/src/core/packages/http/server-mocks/src/http_service.mock.ts index 1f3e9300c60f5..4bda328fc27eb 100644 --- a/src/core/packages/http/server-mocks/src/http_service.mock.ts +++ b/src/core/packages/http/server-mocks/src/http_service.mock.ts @@ -27,7 +27,14 @@ import { AuthStatus } from '@kbn/core-http-server'; import type { RouterMock } from '@kbn/core-http-router-server-mocks'; import { mockRouter } from '@kbn/core-http-router-server-mocks'; -import { CspConfig, ExternalUrlConfig, config } from '@kbn/core-http-server-internal'; +import { + CspConfig, + ExternalUrlConfig, + HttpConfig, + config, + cspConfig, + permissionsPolicyConfig, +} from '@kbn/core-http-server-internal'; import type { HttpService, InternalHttpServicePreboot, @@ -186,6 +193,12 @@ const createInternalSetupContractMock = () => { createRouter: jest.fn().mockImplementation(() => mockRouter.create({})), registerStaticDir: jest.fn(), basePath, + config: new HttpConfig( + config.schema.validate({}), + cspConfig.schema.validate({}), + ExternalUrlConfig.DEFAULT, + permissionsPolicyConfig.schema.validate({}) + ), csp: CspConfig.DEFAULT, prototypeHardening: false, staticAssets: createInternalStaticAssetsMock(basePath), diff --git a/src/core/packages/http/server/index.ts b/src/core/packages/http/server/index.ts index 75ac4253fe40c..1e9d631a20ade 100644 --- a/src/core/packages/http/server/index.ts +++ b/src/core/packages/http/server/index.ts @@ -129,6 +129,10 @@ export type { RouteDeprecationInfo, PostValidationMetadata, AnyKibanaRequest, + RequestTiming, + Timer, + TimingEvent, + RequestTimingState, } from './src/router'; export { validBodyOutput, diff --git a/src/core/packages/http/server/src/router/index.ts b/src/core/packages/http/server/src/router/index.ts index 730c688ec9ed8..f808b27d4f240 100644 --- a/src/core/packages/http/server/src/router/index.ts +++ b/src/core/packages/http/server/src/router/index.ts @@ -32,6 +32,7 @@ export type { RouteSecurityGetter, InternalRouteSecurity, AnyKibanaRequest, + RequestTimingState, } from './request'; export type { RequestHandlerWrapper, RequestHandler } from './request_handler'; export type { RequestHandlerContextBase } from './request_handler_context'; @@ -96,6 +97,7 @@ export type { RouterRouteDeprecatedApiDetails, } from './router'; export type { IKibanaSocket } from './socket'; +export type { RequestTiming, Timer, TimingEvent } from './timing'; export type { KibanaErrorResponseFactory, KibanaRedirectionResponseFactory, diff --git a/src/core/packages/http/server/src/router/request.ts b/src/core/packages/http/server/src/router/request.ts index 2cf36b5ae8d93..93ab69fdd6e76 100644 --- a/src/core/packages/http/server/src/router/request.ts +++ b/src/core/packages/http/server/src/router/request.ts @@ -17,6 +17,7 @@ import type { HttpProtocol } from '../http_contract'; import type { IKibanaSocket } from './socket'; import type { RouteMethod, RouteConfigOptions, RouteSecurity, RouteDeprecationInfo } from './route'; import type { Headers } from './headers'; +import type { RequestTiming, TimingEvent } from './timing'; export type RouteSecurityGetter = (request?: { headers: KibanaRequest['headers']; @@ -35,6 +36,14 @@ export interface KibanaRouteOptions extends RouteOptionsApp { excludeFromRateLimiter?: boolean; } +/** + * Internal state for request timing + * @internal + */ +export interface RequestTimingState { + events: TimingEvent[]; +} + /** * @public */ @@ -53,6 +62,7 @@ export interface KibanaRequestState extends RequestApplicationState { measureElu?: (httpSpan?: OTelSpan) => void; startTime: number; redactedSessionId?: string; + timingState?: RequestTimingState; } /** @@ -227,6 +237,14 @@ export interface KibanaRequest< * The body payload of this request. */ readonly body: Body; + + /** + * API for recording custom timing events during request processing. + * These events are automatically included in the Server-Timing response header. + * + * Only available during development. + */ + readonly serverTiming: RequestTiming; } /** diff --git a/src/core/packages/http/server/src/router/timing.ts b/src/core/packages/http/server/src/router/timing.ts new file mode 100644 index 0000000000000..7c1133edb827c --- /dev/null +++ b/src/core/packages/http/server/src/router/timing.ts @@ -0,0 +1,83 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the "Elastic License + * 2.0", the "GNU Affero General Public License v3.0 only", and the "Server Side + * Public License v 1"; you may not use this file except in compliance with, at + * your election, the "Elastic License 2.0", the "GNU Affero General Public + * License v3.0 only", or the "Server Side Public License, v 1". + */ + +/** + * API for recording custom timing events during request processing. + * These events are automatically included in the Server-Timing response header. + * + * @public + */ +export interface RequestTiming { + /** + * Start timing an operation. Returns a timer object with an end() method. + * This prevents mismatched timings when operations overlap. + * + * @param name - Metric name (alphanumeric, underscore, dash only) + * @param description - Optional human-readable description + * @returns Timer object with end() method + * + * @example + * ```typescript + * const timer = request.timing.start('es-query', 'Elasticsearch query'); + * const results = await elasticsearch.search(query); + * timer.end(); + * ``` + */ + start(name: string, description?: string): Timer; + + /** + * Manually record a timing event with explicit duration. + * Use when you already have the duration calculated. + * + * @param name - Metric name (alphanumeric, underscore, dash only) + * @param duration - Duration in milliseconds + * @param description - Optional human-readable description + * + * @example + * ```typescript + * const start = performance.now(); + * await processData(); + * request.timing.measure('processing', performance.now() - start, 'Data transform'); + * ``` + */ + measure(name: string, duration: number, description?: string): void; + + /** + * Get all recorded timing events (internal use) + * @internal + */ + getEvents(): readonly TimingEvent[]; +} + +/** + * Timer object returned by RequestTiming.start() + * + * @public + */ +export interface Timer { + /** + * End timing for this specific operation. + * Can be called multiple times (subsequent calls are no-ops). + */ + end(): void; +} + +/** + * A recorded timing event + * + * @public + */ +export interface TimingEvent { + /** Metric name */ + name: string; + /** Duration in milliseconds */ + duration: number; + /** Optional human-readable description */ + description?: string; +}