[HTTP] Log deprecated api usages (#207904)

## Summary

Resolves https://github.com/elastic/kibana/issues/199616

Added a debug logger when calling deprecated APIs. This logger is
disabled by default, to enable it you have to set
`deprecation.enable_http_debug_logs: true`.

To test this you can play with the config value and do a request like
this to a deprecated endpoint:

```shell
#!/bin/bash
API_KEY=""
curl -X GET "http://localhost:5601/api/cases/status" -i \
-H "Content-Type: application/json" \
-H "Authorization: ApiKey $API_KEY"
``` 


### Checklist

Check the PR satisfies following conditions. 

Reviewers should verify this PR satisfies this list as well.

- [x]
[Documentation](https://www.elastic.co/guide/en/kibana/master/development-documentation.html)
was added for features that require explanation or tutorials
- [x] [Unit or functional
tests](https://www.elastic.co/guide/en/kibana/master/development-tests.html)
were updated or added to match the most common scenarios
- [x] The PR description includes the appropriate Release Notes section,
and the correct `release_note:*` label is applied per the
[guidelines](https://www.elastic.co/guide/en/kibana/master/contributing.html#kibana-release-notes-process)

### Identify risks

Does this PR introduce any risks? For example, consider risks like hard
to test bugs, performance regression, potential of data loss.

Describe the risk, its severity, and mitigation for each identified
risk. Invite stakeholders and evaluate how to proceed before merging.

---------

Co-authored-by: Elastic Machine <elasticmachine@users.noreply.github.com>
Co-authored-by: kibanamachine <42973632+kibanamachine@users.noreply.github.com>
Co-authored-by: florent-leborgne <florent.leborgne@elastic.co>
Co-authored-by: Jean-Louis Leysens <jloleysens@gmail.com>

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`.
+
 |===

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

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

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

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,

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

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,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": "",
+          },
+        },
+      }
+    `);
+  });
 });

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

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,