Logging changes to support Beats Elasticsearch module (including logging to JSON)

[jasontedor]

This relates to the effort in Beats (filebeat) to build a module for Elasticsearch. To support this effort, we want to make some changes to the logs in Elasticsearch including removing some existing pain points. The main highlight of these changes will be shipping with JSON logging.

• Change the name of the main log file to something like server.log. Today the main log file is <clustername>.log and this creates complexity for Filebeat; it would be simpler for them if they could rely on an include pattern based on a predictable log file name (another possibility here is server-<clustername>.log). Note that this will be a breaking change.
• Each log line should contain the node ID and cluster ID (machine friendly, and serve as unique identifiers), and node name and cluster name (human friendly). Filebeat wants to see these for instances where logs are being collected to a single sink from multiple nodes and multiple clusters.
• Improve logging in the official Docker images. Logging in Docker images traditionally goes to standard output and standard error. We do this with our official Docker images today, but then there is no way to distinguish the server logs from the audit, deprecation, and slow logs. With a single output stream, we need to add a "type" field to the log outputs from the Docker container so the different sources can be parsed from the single standard output stream.
• Enable JSON layout. Today we do not support layout, mainly due to security manager issues. We need to address these. With this effort, we want the logs to remain human friendly, so we will also want to define an ordering of the first few fields in the JSON object (something like timestamp, log_level, component, node_name, index_name, shard_id, message).

[elasticmachine]

Pinging @elastic/es-core-infra

[jasontedor]

Pinging @ruflin; let me know if I missed anything!

[sshling]

In some scenarios, an exception occurs, a large amount of logs will be printed, tens of MB per second, if it can be optimized, the same type exception is suppressed ,as print info :

"2016-07-09 11:01:31 +0430 [warn]: suppressed same stacktrace"

A large number of exception log writes, seriously affecting disk write performance.

[ycombinator]

Now that we have a Logging UI in Kibana, we were hoping to show ES deprecation (and potentially other types of) logs in the UI. The user would discover said logs via the Monitoring UI, filtered down to the context they are in: a cluster, a node within a cluster, etc. In order for this to work correctly, item 2 in the checklist above needs to be implemented:

Each log line should contain the node ID and cluster ID (machine friendly, and serve as unique identifiers), and node name and cluster name (human friendly). Filebeat wants to see these for instances where logs are being collected to a single sink from multiple nodes and multiple clusters.

Any chance this specific item could be prioritized to enable the Monitoring UI use case described above?

[jasontedor]

Any chance this specific item could be prioritized to enable the Monitoring UI use case described above?

We have been meaning to follow-up on this requirement, because as written we can’t meet it. We need to understand more how important and how strong this requirement is. It is simply not possible include the node ID and cluster ID on every log line. We emit log lines before these data are available.

[ycombinator]

We emit log lines before these data are available.

Is this true for all types of logs? For example, would it be possible to emit the node ID and cluster ID on every log line for deprecation logs?

Are there any guarantees about when the data becomes available or, conversely, what types of log messages might not have this data in them since it's not available yet?

[jasontedor]

Yes, it could be true for the deprecation log too. Also, it would be that we are considering combining all the log files into a single log file for all instances, not only for the Docker images.

Are there any guarantees about when the data becomes available or, conversely, what types of log messages might not have this data in them since it's not available yet?

There aren't guarantees per se. They can be categorized as all startup log messages up to the point that we recover node state would not have the node ID, and all startup log messages up to the point that we recover cluster state would not have the cluster ID (superset of those without the node ID).

[ycombinator]

Thanks Jason. Roughly how many log entries are we talking about without cluster UUID or node ID? The reason I ask is: thinking a bit out of the box, would it be silly to re-emit those messages with the IDs in them, once the IDs become available? Just want to consider all possibilities before we say it's okay to "drop" certain messages that don't have IDs.

[jasontedor]

Roughly how many log entries are we talking about without cluster UUID or node ID?

I can not bound it because we can always add more in the future, and if debug or trace logging is enabled (or even only for certain components) it can be quite a lot of log messages.

[ycombinator]

In that case, I'm in favor of doing a best effort here. That is, I'm in favor of ES including the cluster UUID and node ID on every log line as and when that information becomes available.

It would be an improvement over what we can do today in the UI with the logs in terms of correlating them with other information about the node or cluster. And we'd still have the un-correlatable logs (but fewer in number now) around in filebeat indices, in case we later think of some way to display these meaningfully to the user.