Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down Expand Up @@ -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}`);
}
Comment on lines +113 to +121
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if this should be controlled by another config flag: I really see the potential of the HTTP timings for easy troubleshooting in production via HAR information.

However, leaking the underlying ES requests in prod is too much. But this is def interesting for devs.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree that we would have to revisit if we ever let this go to prod. But I would probably favor an allow-list instead of an opt-in. Anyway, I see it as a later discussion. LMK what you think

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Synced with @afharo — we agreed to go with the 2-config-flag strategy to provide flexibility in the future

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added here: 67fd817


logger.debug('CPS request completed', {
event: {
kind: routingType === 'none' && bypassReason ? 'alert' : 'metric',
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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();
});
});
});
Original file line number Diff line number Diff line change
Expand Up @@ -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);
};
};
}
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
Original file line number Diff line number Diff line change
@@ -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';
Original file line number Diff line number Diff line change
@@ -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);
});
});
Original file line number Diff line number Diff line change
@@ -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,
};
};
}
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,7 @@ export class ElasticsearchService
private readonly config$: Observable<ElasticsearchConfig>;
private readonly isServerless: boolean;
private onRequestHandlerFactory: OnRequestHandlerFactory;
private esTimingEnabled: boolean = false;
private stop$ = new Subject<void>();
private kibanaVersion: string;
private authHeaders?: IAuthHeadersStorage;
Expand Down Expand Up @@ -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);

Expand Down
Loading
Loading