[core.logging] Add response logs to the KP logging system. (#87939)

Author: lukeelmers

docs/migration/migrate_8_0.asciidoc

@@ -58,7 +58,16 @@ for example, `logstash-*`.
 ==== Responses are never logged by default
 *Details:* Previously responses would be logged if either `logging.json` was true, `logging.dest` was specified, or a `TTY` was detected.
 
-*Impact:* To restore the previous behavior, in kibana.yml set `logging.events.response=*`.
+*Impact:* To restore the previous behavior, in kibana.yml enable `debug` logs for the `http.server.response` context under `logging.loggers`:
+[source,yaml]
+-------------------
+logging:
+  loggers:
+    - context: http.server.response
+      appenders: [console]
+      level: debug
+-------------------
+See https://github.com/elastic/kibana/pull/87939 for more details.
 
 [float]
 ==== `xpack.security.authProviders` is no longer valid

packages/kbn-legacy-logging/src/get_logging_config.ts

@@ -27,14 +27,14 @@ export function getLoggingConfiguration(config: LegacyLoggingConfig, opsInterval
     });
   } else if (config.verbose) {
     _.defaults(events, {
+      error: '*',
       log: '*',
-      // To avoid duplicate logs, we explicitly disable this in verbose
-      // mode as it is already provided by the new logging config under
-      // the `metrics.ops` context.
+      // To avoid duplicate logs, we explicitly disable these in verbose
+      // mode as they are already provided by the new logging config under
+      // the `http.server.response` and `metrics.ops` contexts.
       ops: '!',
-      request: '*',
-      response: '*',
-      error: '*',
+      request: '!',
+      response: '!',
     });
   } else {
     _.defaults(events, {
@@ -75,6 +75,7 @@ export function getLoggingConfiguration(config: LegacyLoggingConfig, opsInterval
     },
     includes: {
       request: ['headers', 'payload'],
+      response: ['headers', 'payload'],
     },
     reporters: {
       logReporter: [loggerStream],

packages/kbn-legacy-logging/src/log_events.ts

@@ -6,6 +6,7 @@
  * Side Public License, v 1.
  */
 
+import type { ResponseObject } from '@hapi/hapi';
 import { EventData, isEventData } from './metadata';
 
 export interface BaseEvent {
@@ -21,7 +22,8 @@ export interface ResponseEvent extends BaseEvent {
   statusCode: number;
   path: string;
   headers: Record<string, string | string[]>;
-  responsePayload: string;
+  responseHeaders: Record<string, string | string[]>;
+  responsePayload: ResponseObject['source'];
   responseTime: string;
   query: Record<string, any>;
 }

packages/kbn-legacy-logging/src/log_format.ts

@@ -12,15 +12,14 @@ import _ from 'lodash';
 import queryString from 'query-string';
 import numeral from '@elastic/numeral';
 import chalk from 'chalk';
-// @ts-expect-error missing type def
-import stringify from 'json-stringify-safe';
 import { inspect } from 'util';
 
-import { applyFiltersToKeys } from './utils';
+import { applyFiltersToKeys, getResponsePayloadBytes } from './utils';
 import { getLogEventData } from './metadata';
 import { LegacyLoggingConfig } from './schema';
 import {
   AnyEvent,
+  ResponseEvent,
   isResponseEvent,
   isOpsEvent,
   isErrorEvent,
@@ -70,6 +69,23 @@ export abstract class BaseLogFormat extends Stream.Transform {
     next();
   }
 
+  getContentLength({ responsePayload, responseHeaders }: ResponseEvent): number | undefined {
+    try {
+      return getResponsePayloadBytes(responsePayload, responseHeaders);
+    } catch (e) {
+      // We intentionally swallow any errors as this information is
+      // only a nicety for logging purposes, and should not cause the
+      // server to crash if it cannot be determined.
+      this.push(
+        this.format({
+          type: 'log',
+          tags: ['warning', 'logging'],
+          message: `Failed to calculate response payload bytes. [${e}]`,
+        }) + '\n'
+      );
+    }
+  }
+
   extractAndFormatTimestamp(data: Record<string, any>, format?: string) {
     const { timezone } = this.config;
     const date = moment(data['@timestamp']);
@@ -100,15 +116,10 @@ export abstract class BaseLogFormat extends Stream.Transform {
         referer: source.referer,
       };
 
-      const contentLength =
-        event.responsePayload === 'object'
-          ? stringify(event.responsePayload).length
-          : String(event.responsePayload).length;
-
       data.res = {
         statusCode: event.statusCode,
         responseTime: event.responseTime,
-        contentLength,
+        contentLength: this.getContentLength(event),
       };
 
       const query = queryString.stringify(event.query, { sort: false });
@@ -122,7 +133,9 @@ export abstract class BaseLogFormat extends Stream.Transform {
       data.message += levelColor(data.res.statusCode);
       data.message += ' ';
       data.message += chalk.gray(data.res.responseTime + 'ms');
-      data.message += chalk.gray(' - ' + numeral(contentLength).format('0.0b'));
+      if (data.res.contentLength) {
+        data.message += chalk.gray(' - ' + numeral(data.res.contentLength).format('0.0b'));
+      }
     } else if (isOpsEvent(event)) {
       _.defaults(data, _.pick(event, ['pid', 'os', 'proc', 'load']));
       data.message = chalk.gray('memory: ');

packages/kbn-legacy-logging/src/log_format_json.test.ts

@@ -39,30 +39,45 @@ describe('KbnLoggerJsonFormat', () => {
       expect(message).toBe('undefined');
     });
 
-    it('response', async () => {
-      const event = {
-        ...makeEvent('response'),
-        statusCode: 200,
-        contentLength: 800,
-        responseTime: 12000,
-        method: 'GET',
-        path: '/path/to/resource',
-        responsePayload: '1234567879890',
-        source: {
-          remoteAddress: '127.0.0.1',
-          userAgent: 'Test Thing',
-          referer: 'elastic.co',
-        },
-      };
-      const result = await createPromiseFromStreams<string>([createListStream([event]), format]);
-      const { type, method, statusCode, message, req } = JSON.parse(result);
-
-      expect(type).toBe('response');
-      expect(method).toBe('GET');
-      expect(statusCode).toBe(200);
-      expect(message).toBe('GET /path/to/resource 200 12000ms - 13.0B');
-      expect(req.remoteAddress).toBe('127.0.0.1');
-      expect(req.userAgent).toBe('Test Thing');
+    describe('response', () => {
+      it('handles a response object', async () => {
+        const event = {
+          ...makeEvent('response'),
+          statusCode: 200,
+          contentLength: 800,
+          responseTime: 12000,
+          method: 'GET',
+          path: '/path/to/resource',
+          responsePayload: '1234567879890',
+          source: {
+            remoteAddress: '127.0.0.1',
+            userAgent: 'Test Thing',
+            referer: 'elastic.co',
+          },
+        };
+        const result = await createPromiseFromStreams<string>([createListStream([event]), format]);
+        const { type, method, statusCode, message, req } = JSON.parse(result);
+
+        expect(type).toBe('response');
+        expect(method).toBe('GET');
+        expect(statusCode).toBe(200);
+        expect(message).toBe('GET /path/to/resource 200 12000ms - 13.0B');
+        expect(req.remoteAddress).toBe('127.0.0.1');
+        expect(req.userAgent).toBe('Test Thing');
+      });
+
+      it('leaves payload size empty if not available', async () => {
+        const event = {
+          ...makeEvent('response'),
+          statusCode: 200,
+          responseTime: 12000,
+          method: 'GET',
+          path: '/path/to/resource',
+          responsePayload: null,
+        };
+        const result = await createPromiseFromStreams<string>([createListStream([event]), format]);
+        expect(JSON.parse(result).message).toBe('GET /path/to/resource 200 12000ms');
+      });
     });
 
     it('ops', async () => {

packages/kbn-legacy-logging/src/utils/get_payload_size.test.ts

@@ -0,0 +1,101 @@
+/*
+ * 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 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 or the Server
+ * Side Public License, v 1.
+ */
+
+import mockFs from 'mock-fs';
+import { createReadStream } from 'fs';
+
+import { getResponsePayloadBytes } from './get_payload_size';
+
+describe('getPayloadSize', () => {
+  describe('handles Buffers', () => {
+    test('with ascii characters', () => {
+      const payload = 'heya';
+      const result = getResponsePayloadBytes(Buffer.from(payload));
+      expect(result).toBe(4);
+    });
+
+    test('with special characters', () => {
+      const payload = '¡hola!';
+      const result = getResponsePayloadBytes(Buffer.from(payload));
+      expect(result).toBe(7);
+    });
+  });
+
+  describe('handles fs streams', () => {
+    afterEach(() => mockFs.restore());
+
+    test('with ascii characters', async () => {
+      mockFs({ 'test.txt': 'heya' });
+      const readStream = createReadStream('test.txt');
+
+      let data = '';
+      for await (const chunk of readStream) {
+        data += chunk;
+      }
+
+      const result = getResponsePayloadBytes(readStream);
+      expect(result).toBe(Buffer.byteLength(data));
+    });
+
+    test('with special characters', async () => {
+      mockFs({ 'test.txt': '¡hola!' });
+      const readStream = createReadStream('test.txt');
+
+      let data = '';
+      for await (const chunk of readStream) {
+        data += chunk;
+      }
+
+      const result = getResponsePayloadBytes(readStream);
+      expect(result).toBe(Buffer.byteLength(data));
+    });
+  });
+
+  describe('handles plain responses', () => {
+    test('when source is text', () => {
+      const result = getResponsePayloadBytes('heya');
+      expect(result).toBe(4);
+    });
+
+    test('when source contains special characters', () => {
+      const result = getResponsePayloadBytes('¡hola!');
+      expect(result).toBe(7);
+    });
+
+    test('when source is object', () => {
+      const payload = { message: 'heya' };
+      const result = getResponsePayloadBytes(payload);
+      expect(result).toBe(JSON.stringify(payload).length);
+    });
+  });
+
+  describe('handles content-length header', () => {
+    test('always provides content-length header if available', () => {
+      const headers = { 'content-length': '123' };
+      const result = getResponsePayloadBytes('heya', headers);
+      expect(result).toBe(123);
+    });
+
+    test('uses first value when hapi header is an array', () => {
+      const headers = { 'content-length': ['123', '456'] };
+      const result = getResponsePayloadBytes(null, headers);
+      expect(result).toBe(123);
+    });
+
+    test('returns undefined if length is NaN', () => {
+      const headers = { 'content-length': 'oops' };
+      const result = getResponsePayloadBytes(null, headers);
+      expect(result).toBeUndefined();
+    });
+  });
+
+  test('defaults to undefined', () => {
+    const result = getResponsePayloadBytes(null);
+    expect(result).toBeUndefined();
+  });
+});

packages/kbn-legacy-logging/src/utils/get_payload_size.ts

@@ -0,0 +1,64 @@
+/*
+ * 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 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 or the Server
+ * Side Public License, v 1.
+ */
+
+import type { ReadStream } from 'fs';
+import type { ResponseObject } from '@hapi/hapi';
+
+const isBuffer = (obj: unknown): obj is Buffer => Buffer.isBuffer(obj);
+const isObject = (obj: unknown): obj is Record<string, unknown> =>
+  typeof obj === 'object' && obj !== null;
+const isFsReadStream = (obj: unknown): obj is ReadStream =>
+  typeof obj === 'object' && obj !== null && 'bytesRead' in obj;
+const isString = (obj: unknown): obj is string => typeof obj === 'string';
+
+/**
+ * Attempts to determine the size (in bytes) of a hapi/good
+ * responsePayload based on the payload type. Falls back to
+ * `undefined` if the size cannot be determined.
+ *
+ * This is similar to the implementation in `core/server/http/logging`,
+ * however it uses more duck typing as we do not have access to the
+ * entire hapi request object like we do in the HttpServer.
+ *
+ * @param headers responseHeaders from hapi/good event
+ * @param payload responsePayload from hapi/good event
+ *
+ * @internal
+ */
+export function getResponsePayloadBytes(
+  payload: ResponseObject['source'],
+  headers: Record<string, any> = {}
+): number | undefined {
+  const contentLength = headers['content-length'];
+  if (contentLength) {
+    const val = parseInt(
+      // hapi response headers can be `string | string[]`, so we need to handle both cases
+      Array.isArray(contentLength) ? String(contentLength) : contentLength,
+      10
+    );
+    return !isNaN(val) ? val : undefined;
+  }
+
+  if (isBuffer(payload)) {
+    return payload.byteLength;
+  }
+
+  if (isFsReadStream(payload)) {
+    return payload.bytesRead;
+  }
+
+  if (isString(payload)) {
+    return Buffer.byteLength(payload);
+  }
+
+  if (isObject(payload)) {
+    return Buffer.byteLength(JSON.stringify(payload));
+  }
+
+  return undefined;
+}

packages/kbn-legacy-logging/src/utils/index.ts

@@ -7,3 +7,4 @@
  */
 
 export { applyFiltersToKeys } from './apply_filters_to_keys';
+export { getResponsePayloadBytes } from './get_payload_size';