Add username to log statements

Search Guard
1

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 Search Guard logging | Security for Elasticsearch | Search Guard 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[],
2

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

1 Like
3

Hello, have you try to reproduce issue?

4

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

5

One update to this issue:

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

See also Log4j – Log4j 2 Layouts

1 Like
6

Hi @cstaley,
when i change log pattern as You wrote it should work as expected?
br,
Mariusz

7

@marwojt Yes, it should. Did you try it?

8

Not yet. I will try and let You know

9

I tried different patterns and it doesn’t help

appender.index_search_slowlog_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%X{user}] [%x{user}] %X{user} %x{user} [%node_name] %marker %m%n

[2020-10-21T12:56:58,171][INFO ][i.s.s.query ] [] [esdata] [kibana_sample_data_logs][0] took[2.7ms], took_millis[2], total_hits[216 hits], types, stats, search_type[QUERY_THEN_FETCH], total_shards[1], source[{“size”:500,“query”:{“bool”:{“filter”:[{“match_all”:{“boost”:1.0}},{“range”:{“timestamp”:{“from”:“2020-10-20T12:56:58.051Z”,“to”:“2020-10-21T12:56:58.051Z”,“include_lower”:true,“include_upper”:true,“format”:“strict_date_optional_time”,“boost”:1.0}}}],“adjust_pure_negative”:true,“boost”:1.0}},“version”:true,“_source”:{“includes”:,“excludes”:},“stored_fields”:““,“docvalue_fields”:[{“field”:”@timestamp",“format”:“date_time”},{“field”:“timestamp”,“format”:“date_time”},{“field”:“utc_time”,“format”:“date_time”}],“script_fields”:{“hour_of_day”:{“script”:{“source”:“doc[‘timestamp’].value.getHour()”,“lang”:“painless”},“ignore_failure”:false}},“sort”:[{“timestamp”:{“order”:“desc”,“unmapped_type”:“boolean”}}],“track_total_hits”:2147483647,“aggregations”:{“2”:{“date_histogram”:{“field”:“timestamp”,“time_zone”:“Europe/Warsaw”,“fixed_interval”:“30m”,“offset”:0,“order”:{“_key”:“asc”},“keyed”:false,“min_doc_count”:1}}},“highlight”:{“pre_tags”:[“@kibana-highlighted-field@”],“post_tags”:[“@/kibana-highlighted-field@”],“fragment_size”:2147483647,“fields”:{"”:{}}}}], id,