Elasticsearch Audit not supported, but still got entries

We're running a cluster on Elasticsearch 7.9.3-1

We have 3 head/master nodes, 14 data nodes, and a kibana index node in the cluster.

I was asked to get audit logging running on our cluster to keep an eye on users, but learned (after quite a bit of fumbling around) that because we run ES with a free license, we don't have auditing available to us.

However, I've spotted entries in our audit logs on one of the nodes during a brief time when our cluster was trying to re-add nodes after restart. [1]

I happened upon this information when I was about to make a post asking why, after doing everything I could find on the technical docs, there were no new entries with our elasticsearch.yml [2] and log4j2.properties [3] set up as I had expected. But some entries had come in at some point.

Any idea how this could've happened? It ended up throwing me off for a while, making me think something was up with our cluster. Of course, had I seen the fact that we needed a gold license, that would've stifled my curiosity and constant barraging that probably broke things into auditing a couple things for us.

[1]

    {"type":"audit", "timestamp":"2020-12-08T10:34:49,415-0600", "node.id":"<node_id>", "event.type":"transport", "event.action":"access_granted", "authentication.type":"REALM", "user.name":"kibana", "user.realm":"reserved", "user.roles":["kibana_system"], "origin.type":"transport", "origin.address":"<head_node3>:54380", "request.id":"DozkmiOES2iRUuIDzZwdhQ", "action":"cluster:monitor/nodes/info[n]", "request.name":"NodeInfoRequest"}
    {"type":"audit", "timestamp":"2020-12-08T10:35:24,495-0600", "node.id":"<node_id>", "event.type":"transport", "event.action":"access_granted", "authentication.type":"REALM", "user.name":"kibana", "user.realm":"reserved", "user.roles":["kibana_system"], "origin.type":"transport", "origin.address":"<head_node2>:45770", "request.id":"nSzmLxZPS1-BZg_n8_WAqA", "action":"cluster:monitor/nodes/info[n]", "request.name":"NodeInfoRequest"}
    {"type":"audit", "timestamp":"2020-12-08T10:35:24,837-0600", "node.id":"<node_id>", "event.type":"transport", "event.action":"access_granted", "authentication.type":"REALM", "user.name":"<My User>", "user.realm":"default_native", "user.roles":["superuser"], "origin.type":"transport", "origin.address":"<head_node2>:45764", "request.id":"Ko9W6SZmTzilixffTrVA3A", "action":"cluster:monitor/nodes/info[n]", "request.name":"NodeInfoRequest", "x_forwarded_for":"10.150.70.82"}
    {"type":"audit", "timestamp":"2020-12-08T10:35:24,842-0600", "node.id":"<node_id>", "event.type":"transport", "event.action":"access_granted", "authentication.type":"REALM", "user.name":"<My User>", "user.realm":"default_native", "user.roles":["superuser"], "origin.type":"transport", "origin.address":"<head_node2:45770", "request.id":"Ko9W6SZmTzilixffTrVA3A", "action":"cluster:monitor/nodes/stats[n]", "request.name":"NodeStatsRequest", "x_forwarded_for":"10.150.70.82"}

[2]

    cluster.max_shards_per_node: 5000
    cluster.name: <cluster_name)
    discovery.seed_hosts:
    - <head_node1>:9300
    - <head_node2>:9300
    - <head_node3>:9300
    network.host: <host_ip>
    node.data: 'true'
    node.master: 'false'
    node.name: <node_name>
    path.data:
    - "/path/to/data1"
    - "/path/to/data2"
    - "/path/to/data2"
    - "/path/to/data4"
    - "/path/to/data5"
    - "/path/to/data6"
    - "/path/to/data7"
    path.logs: "/path/to/logfile.log"
    path.repo:
    - "/repo"
    xpack.graph.enabled: 'false'
    xpack.ml.enabled: 'false'
    xpack.security.audit.enabled: 'true'
    xpack.security.enabled: 'true'
    xpack.security.transport.ssl.enabled: 'true'
    xpack.security.transport.ssl.keystore.path: /path/to/key
    xpack.security.transport.ssl.truststore.path: /path/to/key
    xpack.security.transport.ssl.verification_mode: full
    xpack.watcher.enabled: 'false'

[3]

status = info

    # log action execution errors for easier debugging
    logger.action.name = org.elasticsearch.action
    logger.action.level = debug

    appender.console.type = Console
    appender.console.name = console
    appender.console.layout.type = PatternLayout
    appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker%m%n

    appender.rolling.type = RollingFile
    appender.rolling.name = rolling
    appender.rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log
    appender.rolling.layout.type = PatternLayout
    appender.rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker%.-10000m%n
    appender.rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}-%d{yyyy-MM-dd}-%i.log.gz
    appender.rolling.policies.type = Policies
    appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
    appender.rolling.policies.time.interval = 1
    appender.rolling.policies.time.modulate = true

    rootLogger.level = info
    rootLogger.appenderRef.console.ref = console
    rootLogger.appenderRef.rolling.ref = rolling

    appender.deprecation_rolling.type = RollingFile
    appender.deprecation_rolling.name = deprecation_rolling
    appender.deprecation_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
    appender.deprecation_rolling.layout.type = PatternLayout
    appender.deprecation_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker%.-10000m%n
    appender.deprecation_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation-%i.log.gz
    appender.deprecation_rolling.policies.type = Policies
    appender.deprecation_rolling.policies.size.type = SizeBasedTriggeringPolicy
    appender.deprecation_rolling.policies.size.size = 1GB
    appender.deprecation_rolling.strategy.type = DefaultRolloverStrategy
    appender.deprecation_rolling.strategy.max = 4

    logger.deprecation.name = org.elasticsearch.deprecation
    logger.deprecation.level = warn
    logger.deprecation.appenderRef.deprecation_rolling.ref = deprecation_rolling
    logger.deprecation.additivity = false

    appender.index_search_slowlog_rolling.type = RollingFile
    appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
    appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
    appender.index_search_slowlog_rolling.layout.type = PatternLayout
    appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker%.-10000m%n
    appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog-%d{yyyy-MM-dd}.log
    appender.index_search_slowlog_rolling.policies.type = Policies
    appender.index_search_slowlog_rolling.policies.time.type = TimeBasedTriggeringPolicy
    appender.index_search_slowlog_rolling.policies.time.interval = 1
    appender.index_search_slowlog_rolling.policies.time.modulate = true

    logger.index_search_slowlog_rolling.name = index.search.slowlog
    logger.index_search_slowlog_rolling.level = trace
    logger.index_search_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = index_search_slowlog_rolling
    logger.index_search_slowlog_rolling.additivity = false

    appender.index_indexing_slowlog_rolling.type = RollingFile
    appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
    appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog.log
    appender.index_indexing_slowlog_rolling.layout.type = PatternLayout
    appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker%.-10000m%n
    appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog-%d{yyyy-MM-dd}.log
    appender.index_indexing_slowlog_rolling.policies.type = Policies
    appender.index_indexing_slowlog_rolling.policies.time.type = TimeBasedTriggeringPolicy
    appender.index_indexing_slowlog_rolling.policies.time.interval = 1
    appender.index_indexing_slowlog_rolling.policies.time.modulate = true

    logger.index_indexing_slowlog.name = index.indexing.slowlog.index
    logger.index_indexing_slowlog.level = trace
    logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling.ref = index_indexing_slowlog_rolling
    logger.index_indexing_slowlog.additivity = false

    appender.audit_rolling.type = RollingFile
    appender.audit_rolling.name = audit_rolling
    appender.audit_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_audit.json
    appender.audit_rolling.layout.type = PatternLayout
    appender.audit_rolling.layout.pattern = {\
                    "type":"audit", \
                    "timestamp":"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZ}"\
                    %varsNotEmpty{, "node.name":"%enc{%map{node.name}}{JSON}"}\
                    %varsNotEmpty{, "node.id":"%enc{%map{node.id}}{JSON}"}\
                    %varsNotEmpty{, "host.name":"%enc{%map{host.name}}{JSON}"}\
                    %varsNotEmpty{, "host.ip":"%enc{%map{host.ip}}{JSON}"}\
                    %varsNotEmpty{, "event.type":"%enc{%map{event.type}}{JSON}"}\
                    %varsNotEmpty{, "event.action":"%enc{%map{event.action}}{JSON}"}\
                    %varsNotEmpty{, "authentication.type":"%enc{%map{authentication.type}}{JSON}"}\
                    %varsNotEmpty{, "user.name":"%enc{%map{user.name}}{JSON}"}\
                    %varsNotEmpty{, "user.run_by.name":"%enc{%map{user.run_by.name}}{JSON}"}\
                    %varsNotEmpty{, "user.run_as.name":"%enc{%map{user.run_as.name}}{JSON}"}\
                    %varsNotEmpty{, "user.realm":"%enc{%map{user.realm}}{JSON}"}\
                    %varsNotEmpty{, "user.run_by.realm":"%enc{%map{user.run_by.realm}}{JSON}"}\
                    %varsNotEmpty{, "user.run_as.realm":"%enc{%map{user.run_as.realm}}{JSON}"}\
                    %varsNotEmpty{, "user.roles":%map{user.roles}}\
                    %varsNotEmpty{, "apikey.id":"%enc{%map{apikey.id}}{JSON}"}\
                    %varsNotEmpty{, "apikey.name":"%enc{%map{apikey.name}}{JSON}"}\
                    %varsNotEmpty{, "origin.type":"%enc{%map{origin.type}}{JSON}"}\
                    %varsNotEmpty{, "origin.address":"%enc{%map{origin.address}}{JSON}"}\
                    %varsNotEmpty{, "realm":"%enc{%map{realm}}{JSON}"}\
                    %varsNotEmpty{, "url.path":"%enc{%map{url.path}}{JSON}"}\
                    %varsNotEmpty{, "url.query":"%enc{%map{url.query}}{JSON}"}\
                    %varsNotEmpty{, "request.method":"%enc{%map{request.method}}{JSON}"}\
                    %varsNotEmpty{, "request.body":"%enc{%map{request.body}}{JSON}"}\
                    %varsNotEmpty{, "request.id":"%enc{%map{request.id}}{JSON}"}\
                    %varsNotEmpty{, "action":"%enc{%map{action}}{JSON}"}\
                    %varsNotEmpty{, "request.name":"%enc{%map{request.name}}{JSON}"}\
                    %varsNotEmpty{, "indices":%map{indices}}\
                    %varsNotEmpty{, "opaque_id":"%enc{%map{opaque_id}}{JSON}"}\
                    %varsNotEmpty{, "x_forwarded_for":"%enc{%map{x_forwarded_for}}{JSON}"}\
                    %varsNotEmpty{, "transport.profile":"%enc{%map{transport.profile}}{JSON}"}\
                    %varsNotEmpty{, "rule":"%enc{%map{rule}}{JSON}"}\
                    %varsNotEmpty{, "event.category":"%enc{%map{event.category}}{JSON}"}\
                    }%n

    appender.audit_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_audit-%d{yyyy-MM-dd}.json
    appender.audit_rolling.policies.type = Policies
    appender.audit_rolling.policies.time.type = TimeBasedTriggeringPolicy
    appender.audit_rolling.policies.time.interval = 1
    appender.audit_rolling.policies.time.modulate = true

    logger.xpack_security_audit_logfile.name = org.elasticsearch.xpack.security.audit.logfile.LoggingAuditTrail
    logger.xpack_security_audit_logfile.level = info
    logger.xpack_security_audit_logfile.appenderRef.audit_rolling.ref = audit_rolling
    logger.xpack_security_audit_logfile.additivity = false

    logger.xmlsig.name = org.apache.xml.security.signature.XMLSignature
    logger.xmlsig.level = error
    logger.samlxml_decrypt.name = org.opensaml.xmlsec.encryption.support.Decrypter
    logger.samlxml_decrypt.level = fatal
    logger.saml2_decrypt.name = org.opensaml.saml.saml2.encryption.Decrypter
    logger.saml2_decrypt.level = fatal

At startup a node doesn't know the cluster's license: it only gets that information when it joins the rest of the cluster. I guess it defaulted to a trial license which permits every feature, including auditing. Since you had enabled auditing in your config file it (briefly) trusted that this was going to be permitted by the actual license.

1 Like

I see. Thank you for the prompt response. It was something we were looking into and it threw us off for a little while.

Funnily enough I encountered a similar issue at almost exactly the same time you asked your question. A colleague pointed me to https://github.com/elastic/elasticsearch/pull/65498 which I think would have helped us both.

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.