Slowlog format different than regular logs

[almiche]

Elasticsearch version (bin/elasticsearch --version): 6.6.0

Plugins installed: []

JVM version (java -version):
http://docker.elastic.co/elasticsearch/elasticsearch:6.6.0 (Unchanged from within the image)

OS version (uname -a if on a Unix-like system): http://docker.elastic.co/elasticsearch/elasticsearch:6.6.0

Description of the problem including expected versus actual behavior:
It seems that slowlogs specifically with elasticsearch have been implemented in such a way which would not allow us to add an extra field in the logs. See below for an explanation.

Below we can see a sample log4j.properties file which is used to specify the pattern layouts used by lo4j. The first appender.console.layout.pattern is used to specify the layout of most logs. The same present pattern is reused below for the pattern that log4j is using for slowlogs. The problem is that the log being output is different in both cases.

appender.console.layout.pattern = {\"source\":\"elasticsearch_log\",\"msg\":\"%m %throwable\"}%n

appender.index_search_slowlog_rolling.layout.pattern = {\"source\":\"slowlog\",\"msg\":\"%m %throwable\"}%n

Taking a look at the raw output we can see that the log produced by the slowlog appender is does not come out as a valid JSON due to the %m field.

{"source":"slowlog","msg":"[twitter][1] took[153.3micros], took_millis[0], total_hits[0], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[3], source[{"size":1}], id[], "}

The same is not true for regular logs which are indeed a valid json:

{"source":"elasticsearch_log","msg":"updating [index.search.slowlog.threshold.fetch.trace] from [200ms] to [0s] "}

Steps to reproduce:

Please include a minimal but complete recreation of the problem, including
(e.g.) index creation, mappings, settings, query etc. The easier you make for
us to reproduce it, the more likely that somebody will take the time to look at it.

1. Adding the following Pattern layouts to appender.index_search_slowlog_rolling.layout.pattern and appender.console.layout.pattern `{"source":"slowlog","msg":"%m %throwable"}%n'
2. Enable slowlogs

Provide logs (if relevant):
See images above ^^

[elasticmachine]

Pinging @elastic/es-core-infra

[pgomulka]

@almiche I am looking into this, can you please provide log samples or screenshots?

[almiche]

@pgomulka I'll be adding those shortly. Thanks.

[almiche]

@pgomulka I have updated the issue with a more accurate description and simpler example. Let me know if you have any further questions I can clarify :)

[pgomulka]

@almiche
Slow logs most of the time have JSON as a message itself. The stacktrace also can be a problem for your pattern as the message in an exception can contain the JSON. This applies to both console and slowlog appenders
You can fix that with escaping the message - sacrificing readability.
appender.index_search_slowlog_rolling.layout.pattern = {\"source\":\"slowlog\",\"msg\":\"%enc{%m}{JSON} %enc{%throwable}{JSON}\"}%n
Let me know if that works

[pgomulka]

you might also find helpful that in version 7 Elasticsearch will use JSON format in logs as well
https://www.elastic.co/guide/en/elasticsearch/reference/7.0/logging.html

#36833

[almiche]

Looks like it's working perfect thanks alot @pgomulka

[almiche]

I will close the issue if that's alright since it's been resolved