Add username to log statements

Elasticsearch version:
7.7.1
Server OS version:
Centos 7
Kibana version (if relevant):

Browser version (if relevant):

Browser OS version (if relevant):

Describe the issue:
I can’t add user to search slow log… I have configured log4j2.properties as describe here https://docs.search-guard.com/latest/troubleshooting-setting-log-level but user is not looged to index_search_slowlog.log
Steps to reproduce:

  1. Update index settings and set level slow search
  2. Add appender.index_search_slowlog_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%{user}] [%x{user}] [%node_name] %marker %m%n to log4j2.properties
  3. Run some searches to generate slow log

Expected behavior:
User added to index_search_slowlog.log

Provide configuration:
/etc/elasticsearch/log4j2.properties

#################################################
#################################################
######## Search slowlog -  old style pattern ####
appender.index_search_slowlog_rolling_old.type = RollingFile
appender.index_search_slowlog_rolling_old.name = index_search_slowlog_rolling_old
appender.index_search_slowlog_rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
  _index_search_slowlog.log
appender.index_search_slowlog_rolling_old.layout.type = PatternLayout
appender.index_search_slowlog_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%{user}] [%x{user}] [%node_name] %marker %m%n

appender.index_search_slowlog_rolling_old.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
  _index_search_slowlog-%i.log.gz
appender.index_search_slowlog_rolling_old.policies.type = Policies
appender.index_search_slowlog_rolling_old.policies.size.type = SizeBasedTriggeringPolicy
appender.index_search_slowlog_rolling_old.policies.size.size = 1GB
appender.index_search_slowlog_rolling_old.strategy.type = DefaultRolloverStrategy
appender.index_search_slowlog_rolling_old.strategy.max = 4
#################################################

index setting
“index.search.slowlog.threshold.query.warn”: “10s”,
index.search.slowlog.threshold.query.info”: “1ms”,
“index.search.slowlog.threshold.query.debug”: “2s”,
“index.search.slowlog.threshold.query.trace”: “500ms”,
“index.search.slowlog.threshold.fetch.warn”: “1s”,
index.search.slowlog.threshold.fetch.info”: “1ms”,
“index.search.slowlog.threshold.fetch.debug”: “500ms”,
“index.search.slowlog.threshold.fetch.trace”: “200ms”,
“index.search.slowlog.level”: “info”

Provide logs:
ndex_search_slowlog.log

[2020-06-29T12:05:56,346][INFO ][i.s.s.query              ] [%{user}] [[]] [esdata1]  [kibana_sample_data_flights][0] took[9.9ms], took_millis[9], total_hits[62 hits], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[1], source[{"size":0,"query":{"bool":{"filter":[{"match_all":{"boost":1.0}},{"range":{"timestamp":{"from":"2020-06-28T12:05:56.258Z","to":"2020-06-29T12:05:56.258Z","include_lower":true,"include_upper":true,"format":"strict_date_optional_time","boost":1.0}}}],"must_not":[{"match_phrase":{"FlightDelayMin":{"query":0,"slop":0,"zero_terms_query":"NONE","boost":1.0}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":[],"excludes":[]},"stored_fields":"*","docvalue_fields":[{"field":"timestamp","format":"date_time"}],"script_fields":{"hour_of_day":{"script":{"source":"doc['timestamp'].value.hourOfDay","lang":"painless"},"ignore_failure":false}},"aggregations":{"2":{"histogram":{"field":"FlightDelayMin","interval":30.0,"offset":0.0,"order":{"_key":"asc"},"keyed":false,"min_doc_count":1}}}}], id[],
[2020-06-29T12:05:56,348][INFO ][i.s.s.fetch              ] [%{user}] [[]] [esdata1]  [kibana_sample_data_flights][0] took[2.2ms], took_millis[2], total_hits[62 hits], types[], stats[], search_type[QUERY_THEN_FETCH], total_shards[1], source[{"size":0,"query":{"bool":{"filter":[{"match_all":{"boost":1.0}},{"range":{"timestamp":{"from":"2020-06-28T12:05:56.258Z","to":"2020-06-29T12:05:56.258Z","include_lower":true,"include_upper":true,"format":"strict_date_optional_time","boost":1.0}}}],"must_not":[{"match_phrase":{"FlightDelayMin":{"query":0,"slop":0,"zero_terms_query":"NONE","boost":1.0}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":[],"excludes":[]},"stored_fields":"*","docvalue_fields":[{"field":"timestamp","format":"date_time"}],"script_fields":{"hour_of_day":{"script":{"source":"doc['timestamp'].value.hourOfDay","lang":"painless"},"ignore_failure":false}},"aggregations":{"2":{"histogram":{"field":"FlightDelayMin","interval":30.0,"offset":0.0,"order":{"_key":"asc"},"keyed":false,"min_doc_count":1}}}}], id[],

I’ll try to reproduce the issue and let you know.

1 Like

Hello, have you try to reproduce issue?

Hi. I tried this today and could reproduce the issue. I add this to the bug queue.

One update to this issue:

log4j patterns are case-sensitive. You need to use %X, not %x.

See also https://logging.apache.org/log4j/2.x/manual/layouts.html

1 Like