[8.x] [HTTP] Log deprecated api usages (#207904) (#208548)

# Backport This will backport the following commits from `main` to `8.x`: - [[HTTP] Log deprecated api usages (#207904)](https://github.com/elastic/kibana/pull/207904)  ### Questions ? Please refer to the [Backport tool documentation](https://github.com/sqren/backport)  Co-authored-by: Jesus Wahrman <41008968+jesuswr@users.noreply.github.com>
2025-04-24 01:38:56 -04:00 · 2025-01-29 03:10:52 +11:00 · 2025-01-29 03:10:52 +11:00 · 01e51d3e6e
commit 01e51d3e6e
parent 4a03f10532
12 changed files with 196 additions and 29 deletions
--- a/docs/settings/logging-settings.asciidoc
+++ b/docs/settings/logging-settings.asciidoc
@ -86,4 +86,7 @@ The following table serves as a quick reference for different logging configurat
 | `logging.loggers[].<logger>.appenders`
 | Determines the appender to apply to a specific logger context as an array. Optional and falls back to the appender(s) of the `root` logger if not specified.

+|[[enable-http-debug-logs]] `deprecation.enable_http_debug_logs`
+| Optional boolean to log debug messages when a deprecated API is called. Default is `false`.
+
 |===
--- a/docs/setup/upgrade.asciidoc
+++ b/docs/setup/upgrade.asciidoc
@ -7,6 +7,7 @@ To upgrade from 7.16.0 or earlier to {version},
 Before you upgrade, you must resolve all critical issues identified by the *Upgrade Assistant*.

 In addition, we recommend to carefully review the <<breaking-changes-summary,list of breaking changes and deprecations>> and to take any necessary actions to mitigate their impact on the upgrade.
+You can enable the <<enable-http-debug-logs, deprecated APIs debug logs config>> to get information about calls to deprecated APIs.

 Rolling upgrades are unsupported in {kib}. To upgrade,
 you must shut down all {kib} instances, install the new software, and restart {kib}.
@ -75,4 +76,4 @@ include::upgrade/saved-objects-migration.asciidoc[]

 include::upgrade/resolving-migration-failures.asciidoc[]

-include::upgrade/rollback-migration.asciidoc[]
+include::upgrade/rollback-migration.asciidoc[]
--- a/src/core/packages/deprecations/server-internal/src/deprecation_config.ts
+++ b/src/core/packages/deprecations/server-internal/src/deprecation_config.ts
@ -13,6 +13,7 @@ import type { ServiceConfigDescriptor } from '@kbn/core-base-server-internal';
 const configSchema = schema.object({
  // `deprecation.skip_deprecated_settings` is consistent with the equivalent ES feature and config property
  skip_deprecated_settings: schema.arrayOf(schema.string(), { defaultValue: [] }),
+  enable_http_debug_logs: schema.boolean({ defaultValue: false }),
 });

 export type DeprecationConfigType = TypeOf<typeof configSchema>;
--- a/src/core/packages/deprecations/server-internal/src/deprecations_service.test.mocks.ts
+++ b/src/core/packages/deprecations/server-internal/src/deprecations_service.test.mocks.ts
@ -17,6 +17,10 @@ export const DeprecationsFactoryMock = jest
 export const registerConfigDeprecationsInfoMock = jest.fn();
 export const registerApiDeprecationsInfoMock = jest.fn();

+export const loggingMock = {
+  configure: jest.fn(),
+};
+
 jest.doMock('./deprecations', () => ({
  registerConfigDeprecationsInfo: registerConfigDeprecationsInfoMock,
  registerApiDeprecationsInfo: registerApiDeprecationsInfoMock,
--- a/src/core/packages/deprecations/server-internal/src/deprecations_service.test.ts
+++ b/src/core/packages/deprecations/server-internal/src/deprecations_service.test.ts
@ -10,6 +10,7 @@
 import {
  DeprecationsFactoryMock,
  registerConfigDeprecationsInfoMock,
+  loggingMock,
 } from './deprecations_service.test.mocks';
 import { mockCoreContext } from '@kbn/core-base-server-mocks';
 import { httpServerMock, httpServiceMock } from '@kbn/core-http-server-mocks';
@ -18,6 +19,7 @@ import { configServiceMock } from '@kbn/config-mocks';
 import { savedObjectsClientMock } from '@kbn/core-saved-objects-api-server-mocks';
 import { elasticsearchServiceMock } from '@kbn/core-elasticsearch-server-mocks';
 import { DeprecationsService, DeprecationsSetupDeps } from './deprecations_service';
+import { firstValueFrom } from 'rxjs';

 describe('DeprecationsService', () => {
  let coreContext: ReturnType<typeof mockCoreContext.create>;
@ -35,7 +37,7 @@ describe('DeprecationsService', () => {
    coreUsageData = coreUsageDataServiceMock.createSetupContract();
    router = httpServiceMock.createRouter();
    http.createRouter.mockReturnValue(router);
-    deprecationsCoreSetupDeps = { http, coreUsageData };
+    deprecationsCoreSetupDeps = { http, coreUsageData, logging: loggingMock };
  });

  afterEach(() => {
@ -64,6 +66,32 @@ describe('DeprecationsService', () => {
      expect(registerConfigDeprecationsInfoMock).toBeCalledTimes(1);
    });

+    describe('logging.configure tests', () => {
+      it('calls logging.configure without enable_http_debug_logs', async () => {
+        const deprecationsService = new DeprecationsService(coreContext);
+        await deprecationsService.setup(deprecationsCoreSetupDeps);
+        expect(loggingMock.configure).toBeCalledTimes(1);
+        const config$ = loggingMock.configure.mock.calls[0][1];
+        expect(await firstValueFrom(config$)).toStrictEqual({
+          loggers: [{ name: 'http', level: 'off', appenders: [] }],
+        });
+      });
+
+      it('calls logging.configure with enable_http_debug_logs set to true', async () => {
+        const configService = configServiceMock.create({
+          atPath: { enable_http_debug_logs: true },
+        });
+        coreContext = mockCoreContext.create({ configService });
+        const deprecationsService = new DeprecationsService(coreContext);
+        await deprecationsService.setup(deprecationsCoreSetupDeps);
+        expect(loggingMock.configure).toBeCalledTimes(1);
+        const config$ = loggingMock.configure.mock.calls[0][1];
+        expect(await firstValueFrom(config$)).toStrictEqual({
+          loggers: [{ name: 'http', level: 'debug', appenders: [] }],
+        });
+      });
+    });
+
    it('creates DeprecationsFactory with the correct parameters', async () => {
      const deprecationsService = new DeprecationsService(coreContext);
      await deprecationsService.setup(deprecationsCoreSetupDeps);
--- a/src/core/packages/deprecations/server-internal/src/deprecations_service.ts
+++ b/src/core/packages/deprecations/server-internal/src/deprecations_service.ts
@ -7,7 +7,7 @@
 * License v3.0 only", or the "Server Side Public License, v 1".
 */

-import { firstValueFrom } from 'rxjs';
+import { firstValueFrom, map } from 'rxjs';
 import type { Logger } from '@kbn/logging';
 import type { IConfigService } from '@kbn/config';
 import type { CoreContext, CoreService } from '@kbn/core-base-server-internal';
@ -21,6 +21,7 @@ import type {
 } from '@kbn/core-deprecations-server';
 import { InternalCoreUsageDataSetup } from '@kbn/core-usage-data-base-server-internal';
 import type { KibanaRequest } from '@kbn/core-http-server';
+import { type InternalLoggingServiceSetup } from '@kbn/core-logging-server-internal';
 import { DeprecationsFactory } from './deprecations_factory';
 import { registerRoutes } from './routes';
 import { config as deprecationConfig, DeprecationConfigType } from './deprecation_config';
@ -49,6 +50,7 @@ export type InternalDeprecationsServiceSetup = DeprecationRegistryProvider;
 export interface DeprecationsSetupDeps {
  http: InternalHttpServiceSetup;
  coreUsageData: InternalCoreUsageDataSetup;
+  logging: InternalLoggingServiceSetup;
 }

 /** @internal */
@ -67,6 +69,7 @@ export class DeprecationsService
  public async setup({
    http,
    coreUsageData,
+    logging,
  }: DeprecationsSetupDeps): Promise<InternalDeprecationsServiceSetup> {
    this.logger.debug('Setting up Deprecations service');

@ -81,7 +84,18 @@ export class DeprecationsService
      },
    });

-    registerRoutes({ http, coreUsageData });
+    const config$ = this.configService.atPath<DeprecationConfigType>(deprecationConfig.path);
+    logging.configure(
+      ['deprecations-service'],
+      config$.pipe(
+        map((cfg) => {
+          const logLevel = cfg.enable_http_debug_logs ? 'debug' : 'off';
+          return { loggers: [{ name: 'http', level: logLevel, appenders: [] }] };
+        })
+      )
+    );
+
+    registerRoutes({ http, coreUsageData, logger: this.logger.get('http') });

    registerConfigDeprecationsInfo({
      deprecationsFactory: this.deprecationsFactory,
--- a/src/core/packages/deprecations/server-internal/src/routes/index.ts
+++ b/src/core/packages/deprecations/server-internal/src/routes/index.ts
@ -9,6 +9,7 @@

 import type { InternalHttpServiceSetup } from '@kbn/core-http-server-internal';
 import { InternalCoreUsageDataSetup } from '@kbn/core-usage-data-base-server-internal';
+import { Logger } from '@kbn/logging';
 import type { InternalDeprecationRequestHandlerContext } from '../internal_types';
 import { registerGetRoute } from './get';
 import { registerMarkAsResolvedRoute } from './resolve_deprecated_api';
@ -17,13 +18,15 @@ import { registerApiDeprecationsPostValidationHandler } from './post_validation_
 export function registerRoutes({
  http,
  coreUsageData,
+  logger,
 }: {
  http: InternalHttpServiceSetup;
  coreUsageData: InternalCoreUsageDataSetup;
+  logger: Logger;
 }) {
  const router = http.createRouter<InternalDeprecationRequestHandlerContext>('/api/deprecations');
  registerGetRoute(router);

-  registerApiDeprecationsPostValidationHandler({ http, coreUsageData });
+  registerApiDeprecationsPostValidationHandler({ http, coreUsageData, logger });
  registerMarkAsResolvedRoute(router, { coreUsageData });
 }
--- a/src/core/packages/deprecations/server-internal/src/routes/post_validation_handler.ts
+++ b/src/core/packages/deprecations/server-internal/src/routes/post_validation_handler.ts
@ -8,15 +8,18 @@
 */

 import type { InternalCoreUsageDataSetup } from '@kbn/core-usage-data-server-internal';
-import type { CoreKibanaRequest } from '@kbn/core-http-router-server-internal';
+import { ensureRawRequest, type CoreKibanaRequest } from '@kbn/core-http-router-server-internal';
 import type { InternalHttpServiceSetup } from '@kbn/core-http-server-internal';
 import type { PostValidationMetadata } from '@kbn/core-http-server';
+import { Logger } from '@kbn/logging';
+import { getEcsResponseLog } from '@kbn/core-http-server-internal/src/logging';
 import { buildApiDeprecationId } from '../deprecations';
 import { getIsRouteApiDeprecation, getIsAccessApiDeprecation } from '../deprecations';

 interface Dependencies {
  coreUsageData: InternalCoreUsageDataSetup;
  http: InternalHttpServiceSetup;
+  logger: Logger;
 }

 /**
@ -26,14 +29,17 @@ interface Dependencies {
 export const registerApiDeprecationsPostValidationHandler = ({
  coreUsageData,
  http,
+  logger,
 }: Dependencies) => {
-  http.registerOnPostValidation(createRouteDeprecationsHandler({ coreUsageData }));
+  http.registerOnPostValidation(createRouteDeprecationsHandler({ coreUsageData, logger }));
 };

 export function createRouteDeprecationsHandler({
  coreUsageData,
+  logger,
 }: {
  coreUsageData: InternalCoreUsageDataSetup;
+  logger: Logger;
 }) {
  return (req: CoreKibanaRequest, metadata: PostValidationMetadata) => {
    const hasRouteDeprecation = getIsRouteApiDeprecation(metadata);
@ -49,6 +55,11 @@ export function createRouteDeprecationsHandler({
      const client = coreUsageData.getClient();
      // no await we just fire it off.
      void client.incrementDeprecatedApi(counterName, { resolved: false });
+
+      if (logger.isLevelEnabled('debug')) {
+        const { message, meta } = getEcsResponseLog(ensureRawRequest(req), logger);
+        logger.debug(message, meta);
+      }
    }
  };
 }
--- a/src/core/packages/deprecations/server-internal/tsconfig.json
+++ b/src/core/packages/deprecations/server-internal/tsconfig.json
@ -38,6 +38,7 @@
    "@kbn/core-usage-data-server-internal",
    "@kbn/core-usage-data-server-mocks",
    "@kbn/core-http-router-server-internal",
+    "@kbn/core-logging-server-internal",
  ],
  "exclude": [
    "target/**/*",
--- a/src/core/packages/http/server-internal/src/logging/get_response_log.test.ts
+++ b/src/core/packages/http/server-internal/src/logging/get_response_log.test.ts
@ -27,7 +27,7 @@ interface RequestFixtureOptions {
  mime?: string;
  path?: string;
  query?: Record<string, any>;
-  response?: Record<string, any> | Boom.Boom;
+  response?: Record<string, any> | Boom.Boom | null;
  app?: Record<string, any>;
 }

@ -345,4 +345,100 @@ describe('getEcsResponseLog', () => {
      `);
    });
  });
+
+  test('does not return response in meta object if response is not in the request', () => {
+    const req = createMockHapiRequest({
+      response: null,
+    });
+    const result = getEcsResponseLog(req, logger);
+    expect(result).toMatchInlineSnapshot(`
+      Object {
+        "message": "GET /path",
+        "meta": Object {
+          "client": Object {
+            "ip": undefined,
+          },
+          "http": Object {
+            "request": Object {
+              "headers": Object {
+                "user-agent": "",
+              },
+              "method": "GET",
+              "mime_type": "application/json",
+              "referrer": "localhost:5601/app/home",
+            },
+          },
+          "trace": undefined,
+          "url": Object {
+            "path": "/path",
+            "query": "",
+          },
+          "user_agent": Object {
+            "original": "",
+          },
+        },
+      }
+    `);
+  });
+
+  test('handles invalid response time correctly', () => {
+    const req = createMockHapiRequest({
+      info: {
+        completed: 1610660230000,
+        received: 1610660232000, // completed before received
+      },
+    });
+    const result = getEcsResponseLog(req, logger);
+    expect(result.message).toMatchInlineSnapshot(`"GET /path 200 - 1.2KB"`);
+  });
+
+  test('formats large payload sizes correctly', () => {
+    (getResponsePayloadBytes as jest.Mock).mockReturnValueOnce(1024 * 1024 * 5); // 5 MB
+    const req = createMockHapiRequest();
+    const result = getEcsResponseLog(req, logger);
+    expect(result.message).toMatchInlineSnapshot(`"GET /path 200 - 5.0MB"`);
+  });
+
+  test('handles minimal response object without crashing', () => {
+    const req = createMockHapiRequest({
+      response: { statusCode: 204 },
+    });
+    const result = getEcsResponseLog(req, logger);
+    expect(result).toMatchInlineSnapshot(`
+      Object {
+        "message": "GET /path 204 - 1.2KB",
+        "meta": Object {
+          "client": Object {
+            "ip": undefined,
+          },
+          "http": Object {
+            "request": Object {
+              "headers": Object {
+                "user-agent": "",
+              },
+              "method": "GET",
+              "mime_type": "application/json",
+              "referrer": "localhost:5601/app/home",
+            },
+            "response": Object {
+              "body": Object {
+                "bytes": 1234,
+              },
+              "headers": Object {},
+              "responseTime": undefined,
+              "status_code": 204,
+            },
+          },
+          "trace": undefined,
+          "url": Object {
+            "path": "/path",
+            "query": "",
+          },
+          "user_agent": Object {
+            "original": "",
+          },
+        },
+      }
+    `);
+  });
 });
--- a/src/core/packages/http/server-internal/src/logging/get_response_log.ts
+++ b/src/core/packages/http/server-internal/src/logging/get_response_log.ts
@ -59,23 +59,36 @@ export function getEcsResponseLog(request: Request, log: Logger) {
  const query = querystring.stringify(request.query);
  const pathWithQuery = query.length > 0 ? `${path}?${query}` : path;

-  // eslint-disable-next-line @typescript-eslint/naming-convention
-  const status_code = isBoom(response) ? response.output.statusCode : response.statusCode;
-
  const requestHeaders = cloneAndFilterHeaders(request.headers);
-  const responseHeaders = cloneAndFilterHeaders(
-    isBoom(response) ? (response.output.headers as HapiHeaders) : response.headers
-  );

  // borrowed from the hapi/good implementation
  const responseTime = (request.info.completed || request.info.responded) - request.info.received;
-  const responseTimeMsg = !isNaN(responseTime) ? ` ${responseTime}ms` : '';
+  const responseTimeMsg = responseTime >= 0 ? ` ${responseTime}ms` : '';

-  const bytes = getResponsePayloadBytes(response, log);
+  const bytes = response ? getResponsePayloadBytes(response, log) : undefined;
  const bytesMsg = bytes ? ` - ${numeral(bytes).format('0.0b')}` : '';

  const traceId = (request.app as KibanaRequestState).traceId;

+  const responseLogObj = response
+    ? {
+        response: {
+          body: {
+            bytes,
+          },
+          status_code: isBoom(response) ? response.output.statusCode : response.statusCode,
+          headers: cloneAndFilterHeaders(
+            isBoom(response) ? (response.output.headers as HapiHeaders) : response.headers
+          ),
+          responseTime: !isNaN(responseTime) ? responseTime : undefined,
+        },
+      }
+    : {};
+
+  const message = response
+    ? `${method} ${pathWithQuery} ${responseLogObj.response?.status_code}${responseTimeMsg}${bytesMsg}`
+    : `${method} ${pathWithQuery}`;
+
  const meta: LogMeta = {
    client: {
      ip: request.info.remoteAddress,
@ -88,16 +101,7 @@ export function getEcsResponseLog(request: Request, log: Logger) {
        // @ts-expect-error ECS custom field: https://github.com/elastic/ecs/issues/232.
        headers: requestHeaders,
      },
-      response: {
-        body: {
-          bytes,
-        },
-        status_code,
-        // @ts-expect-error ECS custom field: https://github.com/elastic/ecs/issues/232.
-        headers: responseHeaders,
-        // responseTime is a custom non-ECS field
-        responseTime: !isNaN(responseTime) ? responseTime : undefined,
-      },
+      ...responseLogObj,
    },
    url: {
      path,
@ -110,7 +114,7 @@ export function getEcsResponseLog(request: Request, log: Logger) {
  };

  return {
-    message: `${method} ${pathWithQuery} ${status_code}${responseTimeMsg}${bytesMsg}`,
+    message,
    meta,
  };
 }
--- a/src/core/packages/root/server-internal/src/server.ts
+++ b/src/core/packages/root/server-internal/src/server.ts
@ -302,9 +302,12 @@ export class Server {
      changedDeprecatedConfigPath$: this.configService.getDeprecatedConfigPath$(),
    });

+    const loggingSetup = this.logging.setup();
+
    const deprecationsSetup = await this.deprecations.setup({
      http: httpSetup,
      coreUsageData: coreUsageDataSetup,
+      logging: loggingSetup,
    });

    const savedObjectsSetup = await this.savedObjects.setup({
@ -355,8 +358,6 @@ export class Server {
      rendering: renderingSetup,
    });

-    const loggingSetup = this.logging.setup();
-
    const coreSetup: InternalCoreSetup = {
      analytics: analyticsSetup,
      capabilities: capabilitiesSetup,