[HTTP] Log deprecated api usages

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.
 
+|[[allow-http-debug-logs]] `deprecation.allow_http_debug_logs`
+| Optional boolean to log debug messages when a deprecated API is called. Default is `false`.
+
 |===

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 <<allow-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[]

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: [] }),
+  allow_http_debug_logs: schema.boolean({ defaultValue: false }),
 });
 
 export type DeprecationConfigType = TypeOf<typeof configSchema>;

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,

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 allow_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 allow_http_debug_logs set to true', async () => {
+        const configService = configServiceMock.create({
+          atPath: { allow_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);

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.allow_http_debug_logs ? 'debug' : 'off';
+          return { loggers: [{ name: 'http', level: logLevel, appenders: [] }] };
+        })
+      )
+    );
+
+    registerRoutes({ http, coreUsageData, logger: this.logger.get('http') });
 
     registerConfigDeprecationsInfo({
       deprecationsFactory: this.deprecationsFactory,

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 });
 }

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,9 @@ export function createRouteDeprecationsHandler({
       const client = coreUsageData.getClient();
       // no await we just fire it off.
       void client.incrementDeprecatedApi(counterName, { resolved: false });
+
+      const { message, meta } = getEcsResponseLog(ensureRawRequest(req), logger);
+      logger.debug(message, meta);
     }
   };
 }

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/**/*",

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,13 @@ 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.message).toMatchInlineSnapshot(`"GET /path"`);
+    expect(result.meta.http?.response).toBeUndefined();
+  });
 });

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 = !isNaN(responseTime) && 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,
   };
 }

src/core/packages/root/server-internal/src/server.ts

@@ -299,9 +299,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({
@@ -348,8 +351,6 @@ export class Server {
       rendering: renderingSetup,
     });
 
-    const loggingSetup = this.logging.setup();
-
     const coreSetup: InternalCoreSetup = {
       analytics: analyticsSetup,
       capabilities: capabilitiesSetup,