[core.logging] Add response logs to the KP logging system.

[lukeelmers]

Closes #13241
Also fixes #80544

Summary

This introduces response logging to the new logging system, one of the planned improvements needed to bring us to feature parity with legacy logging.

Legacy response logs are provided by the @hapi/good plugin, but since we are aiming to get rid of that dependency, we need to do some of the work ourselves in the new logging system.

Details

In legacy logging, response logs can be enabled either by setting logging.verbose: true, or by enabling one of the specific event filters which are passed to the @hapi/good configuration:

logging:
  events:
    request: "*"
    response: "*"

This results in a response log like this (when logging to stdout):

server  response [15:51:58.332]  GET /path/to/thing 200 16ms - 9.0B

This PR introduces a new logger context in the http server: http.server.response. All requests/responses are logged at the debug level, meaning that, as in the legacy world, they are not shown by default. To see them, you need to allow debug logs for the logger:

logging:
  loggers:
    - context: http.server.response
      appenders: [console]
      level: debug

The logs look like this (again, logging to console):

[2021-01-20T20:36:51.094Z][DEBUG][http.server.response]{"ecs":{"version":"1.7.0"},"client":{"ip":"127.0.0.1"},"http":{"request":{"method":"GET","mime_type":null,"referrer":"http://localhost:5601/kva/login?next=%2Fzir%2F","headers":{"content-type":"application/json", ...}},"response":{"body":{"bytes":66},"status_code":401,"responseTime":21}},"url":{"path":"/internal/security/me","query":""},"user_agent":{"original":"..."}} GET /internal/security/me 401 21ms - 66.0B

Note that we've added ECS-compatible structured LogMeta, in addition to the log message (which remains the same as legacy).

Changes

• Adds logging to http server using hapi's on('response') event.
• Adds a utility for extracting the payload size from a hapi response.
  • Also introduces a utility for legacy logging, as this fixes JSON logger always shows a content length of 9 bytes #80544
• Adds config deprecations for logging.events.request and logging.events.response & updates docs.
• Disables legacy response logs when logging.verbose: true, as this results in duplicate data with the new http logs.

Plugin API Changes

We are deprecating the legacy response logs which were enabled when logging.verbose: true or when using logging.events.request and logging.events.response. They will be removed completely in 8.0, and have been replaced with new response logs which are provided under the http.server.response context at the debug level:

Before

logging:
  events:
    request: "*"
    response: "*"

After

logging:
  loggers:
    - context: http.server.response
      appenders: [console]
      level: debug

For more information, check out the section on logging config migration in the logging README.

[lukeelmers]

We had discussed doing this as a means of preventing duplicate log entries where possible, however I just wanted to call it out before merging as technically it's a breaking change since the new log format is slightly different from the old one.

Folks using logging.verbose will still get response logs, they'll just look a bit different.

[mshustov]

to call it out before merging as technically it's a breaking change since the new log format is slightly different from the old one.

it is not necessarily so. you can declare a custom pattern for http request / response context so that the format is as close to the old version as possible.

[pgayvallet]

it is not necessarily so

Yea, but that would require manual configuration change from the user, so unsure this is good enough to not consider that breaking?

[lukeelmers]

that would require manual configuration change from the user, so unsure this is good enough to not consider that breaking?

Yeah this is the question I was getting at. Totally agree there are workarounds to minimize disruption (custom pattern, or manually setting logging.events.response) - the question is whether we are okay forcing users to make a manual configuration change to restore the old format (even if the message contents are essentially the same).

Or I guess what we are really asking: Is it worse to inconvenience users with duplicate log messages (which are already quite chatty), or to break a log message format (which they could manually fix)?

[mshustov]

Yea, but that would require manual configuration change from the user

we can leverage logging service API to customize the pattern. WDYT ?

kibana/x-pack/plugins/security/server/audit/audit_service.ts

Lines 222 to 240 in 2b5071f

	export const createLoggingConfig = (config: ConfigType['audit']) =>
	map<Pick<SecurityLicenseFeatures, 'allowAuditLogging'>, LoggerContextConfigInput>((features) => ({
	appenders: {
	auditTrailAppender: config.appender ?? {
	kind: 'console',
	layout: {
	kind: 'pattern',
	highlight: true,
	},
	},
	},
	loggers: [
	{
	context: 'audit.ecs',
	level: config.enabled && config.appender && features.allowAuditLogging ? 'info' : 'off',
	appenders: ['auditTrailAppender'],
	},
	],
	}));

[lukeelmers]

@restrry Just to be clear, you mean apply a custom pattern to the http services response logs to format them in a way that's BWC with legacy logs, but only when using verbose logs & stdout?

I guess the tradeoff would then be that users relying on the new http response logs would suddenly have a different message format when verbose=true, which wouldn't technically be breaking as it is a new set of logs, but might be confusing nonetheless.

FWIW, I don't think introducing duplication would be the end of the world if we needed to go that route... I really could go either way on this.

[elasticmachine]

Pinging @elastic/kibana-core (Team:Core)

[lukeelmers]

@elasticmachine merge upstream

[TinaHeiligers]

Overall, the implementation LGTM and works as expected. We have a few questions to iron out but it's a huge step closer to feature parity!

[lukeelmers]

remove meta property from default pattern

@restrry Agree - I had thought something similar, it feels like having the meta in the default pattern is going to lead to really cluttered logs which will only get worse as time goes on, so we might consider making those opt-in for pattern layout.

pre-populate kibana.yml with defaults for some contexts.

I think this is a viable option too - the only caveat being creating an additional step for support when it comes to debugging problems. ("Can you enable verbose logs, and if you aren't using json, also create a custom console appender with a pattern that includes the meta?").

Not a huge deal if we have examples in kibana.yml, but worth considering.

I guess if someone is enabling debug logs, they have to expect some degree of clutter though. So another alternative might be just moving the default pattern to put the meta at the end of a log line, so at least you see the message first. Doesn't reduce clutter, but makes it easier to scan the logs.

---

EDIT: I misread your comment on this the first time around. I like the approach of having per-context default appenders... I could see this being a good solution as well. 👍

[lukeelmers]

@elasticmachine merge upstream

[lukeelmers]

@elasticmachine merge upstream

[kibanamachine]

💚 Build Succeeded

• continuous-integration/kibana-ci/pull-request
• Commit: 0811e30
• Documentation Changes

Metrics [docs]

✅ unchanged

History

• 💔 Build #103671 failed 871da2d
• 💚 Build #103640 succeeded a41dbd5
• 💔 Build #103623 failed 5d87516
• 💚 Build #102788 succeeded f92cf1b6742589291c6e5e862030d5c6f9593e3f
• 💔 Build #102725 failed 437520875e6117b15229c46eb25f29c86524a08f

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream