JSON logger always shows a content length of 9 bytes

[jportner]

Kibana version: 7.10

Describe the bug:

When JSON logging is enabled, every single 'response' object shows a content length of 9 bytes.
Example:

{"type":"response","@timestamp":"2020-10-14T10:24:34-04:00","tags":[],"pid":30092,"method":"get","statusCode":200,"req":{"url":"/internal/spaces/_active_space","method":"get","headers":{"host":"black-box.local:5603","connection":"keep-alive","kbn-version":"8.0.0","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.75 Safari/537.36","content-type":"application/json","accept":"*/*","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"https://black-box.local:5603/joe/app/home","accept-encoding":"gzip, deflate, br","accept-language":"en-US,en;q=0.9"},"remoteAddress":"10.0.0.120","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.75 Safari/537.36","referer":"https://black-box.local:5603/joe/app/home"},"res":{"statusCode":200,"responseTime":16,"contentLength":9},"message":"GET /internal/spaces/_active_space 200 16ms - 9.0B"}

Note the end of the line:

"contentLength":9},"message":"GET /internal/spaces/_active_space 200 16ms - 9.0B"}

However, when viewing that response in my browser's dev tools, it shows a content-length header of 134.

Steps to reproduce:

1. Enable logging.json: true and logging.verbose: true in your kibana.yml and start Kibana
2. Use a web browser to navigate to Kibana and log in
3. Examine the JSON logs

Expected behavior: The JSON logs should reflect the actual content length of the response.

Any additional context:

1. Looking at some older GitHub issues that happen to include JSON log output, it appears this bug has been present since at least as far back as 6.x.

2. It appears that these 'response' objects are not logged at all using the new platform logger's json layout, e.g., they will not show up in the target file if you use this config:

logging:
  appenders:
    file:
      kind: file
      path: data/kibana.log
      layout:
        kind: json
  root:
    appenders: [default, file]
    level: trace

however, they will still show in the console output:

server  respons [11:30:13.496]  GET /internal/spaces/_active_space 200 14ms - 9.0B

[elasticmachine]

Pinging @elastic/kibana-platform (Team:Platform)

[lukeelmers]

Ran across this while looking into #13241.

It turns out the reason the content length is always 9 is because the value we are using to calculate it (event.responsePayload) is always undefined in the legacy logging code ('undefined'.length === 9). 🤦

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

Lines 114 to 117 in ff94674

	const contentLength =
	event.responsePayload === 'object'
	? stringify(event.responsePayload).length
	: String(event.responsePayload).length;

(Also I think there's a typo above where we need to check typeof event.responsePayload === 'object')

It seems we are missing the payload because the legacy logging config needs to also specify response headers & payload to the @hapi/good config, not just request:

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

Lines 84 to 86 in ff94674

	includes: {
	request: ['headers', 'payload'],
	},

I'll make sure this is addressed in the course of working on #13241, and will also go ahead and fix this in the legacy logging config so it is resolved for the remainder of 7.x as well.

[lukeelmers]

It appears that these 'response' objects are not logged at all using the new platform logger's json layout, e.g., they will not show up in the target file if you use this config:

Also in case it isn't obvious from my above comment, this is a known issue and work to implement in the KP logger is tracked by #13241. You'll still see them in the console because the legacy/default appender continues to log to stdout.