Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

JSON logger always shows a content length of 9 bytes #80544

Closed
jportner opened this issue Oct 14, 2020 · 3 comments · Fixed by #87939
Closed

JSON logger always shows a content length of 9 bytes #80544

jportner opened this issue Oct 14, 2020 · 3 comments · Fixed by #87939
Assignees
Labels
bug Fixes for quality problems that affect the customer experience Feature:Logging Team:Core Core services & architecture: plugins, logging, config, saved objects, http, ES client, i18n, etc

Comments

@jportner
Copy link
Contributor

jportner commented Oct 14, 2020

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
@jportner jportner added bug Fixes for quality problems that affect the customer experience Team:Core Core services & architecture: plugins, logging, config, saved objects, http, ES client, i18n, etc labels Oct 14, 2020
@elasticmachine
Copy link
Contributor

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

@jportner jportner changed the title JSON logger always JSON logger always shows a content length of 9 bytes Oct 14, 2020
@lukeelmers
Copy link
Member

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). 🤦

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:

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 lukeelmers self-assigned this Jan 5, 2021
@lukeelmers
Copy link
Member

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Fixes for quality problems that affect the customer experience Feature:Logging Team:Core Core services & architecture: plugins, logging, config, saved objects, http, ES client, i18n, etc
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants