Deprecation log indexing increases JVM pressure on coordinator nodes consuming all heap

[gregolsen]

Elasticsearch Version

7.17.0

Installed Plugins

discovery-ec2,repository-s3

Java Version

17.0.1

OS Version

5.10.102-99.473.amzn2.x86_64

Problem Description

After upgrading to 7.17.0 from 7.9.3 cluster coordinator nodes are experiencing elevated JVM pressure.
This issue manifests across all the cluster we run. However, in one particular case, coordinator nodes were unable to garbage-collect their way out of this. Over a few hours those nodes consumed all the heap and started to breach parent circuit breaker (charts below is JVM memory pressure in percentage of "old" pool used).

We took a heap dump on a running node and it seems like class org.elasticsearch.action.bulk.BulkProcessor @ 0x4322cce48 is consuming most of the heap:

Upon inspecting the objects it seems like heap is full of objects with deprecation logs in a form of events written into the deprecation.elasticsearch data stream:

As a mitigation, we attempted to disable deprecation logs indexing (which seems like was enabled by default in #76292). However, this didn't work and hasn't resulted in any reduction in JVM memory pressure.

      "deprecation_indexing" : {
        "enabled" : "false",
        "x_opaque_id_used" : {
          "enabled" : "false"
        }
      }

Steps to Reproduce

Unfortunately I don't have any generic steps to reproduce this apart from adding a coordinator node using 7.17.0 to one of our clusters.
That said, I was able to easily reproduce this issue so it does seem like a genuine problem and not a fluke.

Logs (if relevant)

No response

[elasticmachine]

Pinging @elastic/es-core-infra (Team:Core/Infra)

[gregolsen]

We managed to disable deprecation logs completely by setting this:

    "logger" : {
      "org" : {
        "elasticsearch" : {
          "deprecation" : "ERROR"
        }
      }
    }

This has solved the problem of the memory leak. However, it is suboptimal as we do want to re-enable deprecation logging back before 8.x upgrade.

[pgomulka]

@gregolsen can you provide use with sample of deprecation logs ? Can you see if they are duplicated/unique?
Also can you share log4j2.properties file? And make sure it is the only log4j2.properties file recursively under config dir?

[gregolsen]

Hey @pgomulka,

I queried all the deprecation logs emitted at the time I was reproducing the issue and they are duplicates of just a few different log lines:

CloudWatch Logs Insights
region: us-east-1
log-group-names: inbox-search/es-client/var/log/elasticsearch/inbox-search_deprecation.log
start-time: 2022-03-31T14:33:13.683Z
end-time: 2022-03-31T16:44:43.618Z
query-string:

fields @message
| parse @message "[*][*][*] [*] [] *" as time, severity, type, node_name, message
| filter node_name = "es-client1.localdomain"
| stats count() by severity, type, message

---

severity	type	message	count()
CRITICAL	o.e.d.r.a.d.RestIndexAction	[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).	1583241
CRITICAL	o.e.d.r.a.s.RestSearchAction	[types removal] Specifying types in search requests is deprecated.	138863
CRITICAL	o.e.d.r.a.d.RestGetAction	[types removal] Specifying types in document get requests is deprecated, use the /{index}/_doc/{id} endpoint instead.	14831
CRITICAL	o.e.d.a.b.BulkRequestParser	[types removal] Specifying types in bulk requests is deprecated.	62932
CRITICAL	o.e.d.r.a.d.RestDeleteAction	[types removal] Specifying types in document index requests is deprecated, use the /{index}/_doc/{id} endpoint instead.	9550
CRITICAL	o.e.d.r.RestController	[POST /_xpack/monitoring/_bulk] is deprecated! Use [POST /_monitoring/bulk] instead.	67
CRITICAL	o.e.d.c.s.Settings	[node.data] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.	3
CRITICAL	o.e.d.c.s.Settings	[discovery.zen.minimum_master_nodes] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.	3
CRITICAL	o.e.d.c.s.Settings	[node.master] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.	3
CRITICAL	o.e.d.c.s.Settings	[xpack.monitoring.enabled] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.	3
CRITICAL	o.e.d.c.r.OperationRouting	searches will not be routed based on awareness attributes starting in version 8.0.0; to opt into this behaviour now please set the system property [es.search.ignore_awareness_attributes] to [true]	2
CRITICAL	o.e.d.c.s.Settings	[discovery.zen.hosts_provider] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.	2
CRITICAL	o.e.d.n.Node	legacy role settings [node.data, node.master] are deprecated, use [node.roles=[remote_cluster_client, ingest]]	2

---

Our log4j2.properties file is as follows:

status = error

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

######## Server JSON ############################
appender.rolling.type = RollingFile
appender.rolling.name = rolling
appender.rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_server.json
appender.rolling.layout.type = ESJsonLayout
appender.rolling.layout.type_name = server

appender.rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}-%d{yyyy-MM-dd}-%i.json.gz
appender.rolling.policies.type = Policies
appender.rolling.policies.time.type = TimeBasedTriggeringPolicy
appender.rolling.policies.time.interval = 1
appender.rolling.policies.time.modulate = true
appender.rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.rolling.policies.size.size = 128MB
appender.rolling.strategy.type = DefaultRolloverStrategy
appender.rolling.strategy.fileIndex = nomax
appender.rolling.strategy.action.type = Delete
appender.rolling.strategy.action.basepath = ${sys:es.logs.base_path}
appender.rolling.strategy.action.condition.type = IfFileName
appender.rolling.strategy.action.condition.glob = ${sys:es.logs.cluster_name}-*
appender.rolling.strategy.action.condition.nested_condition.type = IfAccumulatedFileSize
appender.rolling.strategy.action.condition.nested_condition.exceeds = 2GB
################################################
######## Server -  old style pattern ###########
appender.rolling_old.type = RollingFile
appender.rolling_old.name = rolling_old
appender.rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log
appender.rolling_old.layout.type = PatternLayout
appender.rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %m%n

appender.rolling_old.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}-%d{yyyy-MM-dd}-%i.log.gz
appender.rolling_old.policies.type = Policies
appender.rolling_old.policies.time.type = TimeBasedTriggeringPolicy
appender.rolling_old.policies.time.interval = 1
appender.rolling_old.policies.time.modulate = true
appender.rolling_old.policies.size.type = SizeBasedTriggeringPolicy
appender.rolling_old.policies.size.size = 128MB
appender.rolling_old.strategy.type = DefaultRolloverStrategy
appender.rolling_old.strategy.fileIndex = nomax
appender.rolling_old.strategy.action.type = Delete
appender.rolling_old.strategy.action.basepath = ${sys:es.logs.base_path}
appender.rolling_old.strategy.action.condition.type = IfFileName
appender.rolling_old.strategy.action.condition.glob = ${sys:es.logs.cluster_name}-*
appender.rolling_old.strategy.action.condition.nested_condition.type = IfAccumulatedFileSize
appender.rolling_old.strategy.action.condition.nested_condition.exceeds = 2GB
################################################

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

######## Deprecation JSON #######################
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.json
appender.deprecation_rolling.layout.type = ESJsonLayout
appender.deprecation_rolling.layout.type_name = deprecation.elasticsearch
appender.deprecation_rolling.layout.esmessagefields=x-opaque-id,key,category,elasticsearch.elastic_product_origin
appender.deprecation_rolling.filter.rate_limit.type = RateLimitingFilter

appender.deprecation_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation-%i.json.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

appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
#################################################
######## Deprecation -  old style pattern #######
appender.deprecation_rolling_old.type = RollingFile
appender.deprecation_rolling_old.name = deprecation_rolling_old
appender.deprecation_rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
appender.deprecation_rolling_old.layout.type = PatternLayout
appender.deprecation_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name] [%product_origin]%marker %m%n
appender.deprecation_rolling_old.filter.rate_limit.type = RateLimitingFilter

appender.deprecation_rolling_old.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
  _deprecation-%i.log.gz
appender.deprecation_rolling_old.policies.type = Policies
appender.deprecation_rolling_old.policies.size.type = SizeBasedTriggeringPolicy
appender.deprecation_rolling_old.policies.size.size = 1GB
appender.deprecation_rolling_old.strategy.type = DefaultRolloverStrategy
appender.deprecation_rolling_old.strategy.max = 4
#################################################
logger.deprecation.name = org.elasticsearch.deprecation
logger.deprecation.level = WARN
logger.deprecation.appenderRef.deprecation_rolling.ref = deprecation_rolling
logger.deprecation.appenderRef.deprecation_rolling_old.ref = deprecation_rolling_old
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false

######## Search slowlog JSON ####################
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.json
appender.index_search_slowlog_rolling.layout.type = ESJsonLayout
appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog
appender.index_search_slowlog_rolling.layout.esmessagefields=message,took,took_millis,total_hits,types,stats,search_type,total_shards,source,id

appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\
  .cluster_name}_index_search_slowlog-%i.json.gz
appender.index_search_slowlog_rolling.policies.type = Policies
appender.index_search_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.index_search_slowlog_rolling.policies.size.size = 1GB
appender.index_search_slowlog_rolling.strategy.type = DefaultRolloverStrategy
appender.index_search_slowlog_rolling.strategy.max = 4
#################################################
######## 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.}] [%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
#################################################
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.appenderRef.index_search_slowlog_rolling_old.ref = index_search_slowlog_rolling_old
logger.index_search_slowlog_rolling.additivity = false

######## Indexing slowlog JSON ##################
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.json
appender.index_indexing_slowlog_rolling.layout.type = ESJsonLayout
appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog
appender.index_indexing_slowlog_rolling.layout.esmessagefields=message,took,took_millis,doc_type,id,routing,source

appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
  _index_indexing_slowlog-%i.json.gz
appender.index_indexing_slowlog_rolling.policies.type = Policies
appender.index_indexing_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.index_indexing_slowlog_rolling.policies.size.size = 1GB
appender.index_indexing_slowlog_rolling.strategy.type = DefaultRolloverStrategy
appender.index_indexing_slowlog_rolling.strategy.max = 4
#################################################
######## Indexing slowlog -  old style pattern ##
appender.index_indexing_slowlog_rolling_old.type = RollingFile
appender.index_indexing_slowlog_rolling_old.name = index_indexing_slowlog_rolling_old
appender.index_indexing_slowlog_rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
  _index_indexing_slowlog.log
appender.index_indexing_slowlog_rolling_old.layout.type = PatternLayout
appender.index_indexing_slowlog_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %m%n

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

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.appenderRef.index_indexing_slowlog_rolling_old.ref = index_indexing_slowlog_rolling_old
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{, "authentication.token.name":"%enc{%map{authentication.token.name}}{JSON}"}\
                %varsNotEmpty{, "authentication.token.type":"%enc{%map{authentication.token.type}}{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{, "trace.id":"%enc{%map{trace.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{, "put":%map{put}}\
                %varsNotEmpty{, "delete":%map{delete}}\
                %varsNotEmpty{, "change":%map{change}}\
                %varsNotEmpty{, "create":%map{create}}\
                %varsNotEmpty{, "invalidate":%map{invalidate}}\
                }%n
# "node.name" node name from the `elasticsearch.yml` settings
# "node.id" node id which should not change between cluster restarts
# "host.name" unresolved hostname of the local node
# "host.ip" the local bound ip (i.e. the ip listening for connections)
# "origin.type" a received REST request is translated into one or more transport requests. This indicates which processing layer generated the event "rest" or "transport" (internal)
# "event.action" the name of the audited event, eg. "authentication_failed", "access_granted", "run_as_granted", etc.
# "authentication.type" one of "realm", "api_key", "token", "anonymous" or "internal"
# "user.name" the subject name as authenticated by a realm
# "user.run_by.name" the original authenticated subject name that is impersonating another one.
# "user.run_as.name" if this "event.action" is of a run_as type, this is the subject name to be impersonated as.
# "user.realm" the name of the realm that authenticated "user.name"
# "user.run_by.realm" the realm name of the impersonating subject ("user.run_by.name")
# "user.run_as.realm" if this "event.action" is of a run_as type, this is the realm name the impersonated user is looked up from
# "user.roles" the roles array of the user; these are the roles that are granting privileges
# "apikey.id" this field is present if and only if the "authentication.type" is "api_key"
# "apikey.name" this field is present if and only if the "authentication.type" is "api_key"
# "authentication.token.name" this field is present if and only if the authenticating credential is a service account token
# "authentication.token.type" this field is present if and only if the authenticating credential is a service account token
# "event.type" informs about what internal system generated the event; possible values are "rest", "transport", "ip_filter" and "security_config_change"
# "origin.address" the remote address and port of the first network hop, i.e. a REST proxy or another cluster node
# "realm" name of a realm that has generated an "authentication_failed" or an "authentication_successful"; the subject is not yet authenticated
# "url.path" the URI component between the port and the query string; it is percent (URL) encoded
# "url.query" the URI component after the path and before the fragment; it is percent (URL) encoded
# "request.method" the method of the HTTP request, i.e. one of GET, POST, PUT, DELETE, OPTIONS, HEAD, PATCH, TRACE, CONNECT
# "request.body" the content of the request body entity, JSON escaped
# "request.id" a synthetic identifier for the incoming request, this is unique per incoming request, and consistent across all audit events generated by that request
# "action" an action is the most granular operation that is authorized and this identifies it in a namespaced way (internal)
# "request.name" if the event is in connection to a transport message this is the name of the request class, similar to how rest requests are identified by the url path (internal)
# "indices" the array of indices that the "action" is acting upon
# "opaque_id" opaque value conveyed by the "X-Opaque-Id" request header
# "trace_id" an identifier conveyed by the part of "traceparent" request header
# "x_forwarded_for" the addresses from the "X-Forwarded-For" request header, as a verbatim string value (not an array)
# "transport.profile" name of the transport profile in case this is a "connection_granted" or "connection_denied" event
# "rule" name of the applied rule if the "origin.type" is "ip_filter"
# the "put", "delete", "change", "create", "invalidate" fields are only present
# when the "event.type" is "security_config_change" and contain the security config change (as an object) taking effect

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

[pgomulka]

@gregolsen the config looks correct.
Can you also send me a your deprecation log in JSON *_deprecation.json ?

[gregolsen]

@pgomulka I'd prefer not to share the whole file - it is over 60MB even in compressed form and I want to make sure I'm not sharing anything private that might be in there.
However, I did a similar aggregation and this is what it looks like:

jq -r '"\(.type) \(.level) \(.component) \(.message)"' inbox-search_deprecation.json | sort | uniq -c | sort -nr
 643708 deprecation WARN o.e.d.r.a.d.RestDeleteAction [types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).
  63231 deprecation WARN o.e.d.r.a.s.RestSearchAction [types removal] Specifying types in search requests is deprecated.
  23011 deprecation WARN o.e.d.a.b.BulkRequestParser [types removal] Specifying types in bulk requests is deprecated.
  12456 deprecation WARN o.e.d.r.a.d.RestGetAction [types removal] Specifying types in document get requests is deprecated, use the /{index}/_doc/{id} endpoint instead.
   7297 deprecation WARN o.e.d.r.a.d.RestDeleteAction [types removal] Specifying types in document index requests is deprecated, use the /{index}/_doc/{id} endpoint instead.
     31 deprecation WARN o.e.d.r.RestController [POST /_xpack/monitoring/_bulk] is deprecated! Use [POST /_monitoring/bulk] instead.
      2 deprecation.elasticsearch CRITICAL o.e.d.n.Node legacy role settings [node.data, node.master] are deprecated, use [node.roles=[remote_cluster_client, ingest]]
      2 deprecation.elasticsearch CRITICAL o.e.d.c.s.Settings [xpack.monitoring.enabled] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      2 deprecation.elasticsearch CRITICAL o.e.d.c.s.Settings [node.master] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      2 deprecation.elasticsearch CRITICAL o.e.d.c.s.Settings [node.data] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      2 deprecation.elasticsearch CRITICAL o.e.d.c.s.Settings [discovery.zen.minimum_master_nodes] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      2 deprecation.elasticsearch CRITICAL o.e.d.c.s.Settings [discovery.zen.hosts_provider] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      2 deprecation.elasticsearch CRITICAL o.e.d.c.r.OperationRouting searches will not be routed based on awareness attributes starting in version 8.0.0; to opt into this behaviour now please set the system property [es.search.ignore_awareness_attributes] to [true]
      1 deprecation WARN o.e.d.c.s.Settings [xpack.monitoring.enabled] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      1 deprecation WARN o.e.d.c.s.Settings [script.max_compilations_rate] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      1 deprecation WARN o.e.d.c.s.Settings [node.master] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      1 deprecation WARN o.e.d.c.s.Settings [node.data] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.
      1 deprecation WARN o.e.d.c.s.Settings [discovery.zen.minimum_master_nodes] setting was deprecated in Elasticsearch and will be removed in a future release! See the breaking changes documentation for the next major version.

So basically the same data as in the plain-text log deprecation log file (different counts because I grepped the logs on a different box).

Hope this is helpful.

[pgomulka]

I suspect that you have unique x-opaque-id on every request which is causing deprecation log deduplication to fail.
Can you confirm that?
Or at least share part of the file with duplicates.
You might also be affected by #82810 as you use 7.17.0
Try upgrading to latest 7.17.3

[gregolsen]

I think you are correct - they are uniqueue:

[root@es-client2 elasticsearch]# jq -r '."x-opaque-id" +  " \(.type) \(.level) \(.component) \(.message)"' inbox-search_deprecation.json | sort | uniq -c | wc -l
749746
[root@es-client2 elasticsearch]# jq -r '" \(.type) \(.level) \(.component) \(.message)"' inbox-search_deprecation.json | sort | uniq -c | wc -l
18
[root@es-client2 elasticsearch]# wc -l inbox-search_deprecation.json
749753 inbox-search_deprecation.json
[root@es-client2 elasticsearch]# head -n20 inbox-search_deprecation.json
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,293Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "746f09ff-4b74-42f6-96de-068cd1ea2544", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,296Z", "level": "WARN", "component": "o.e.d.r.a.s.RestSearchAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in search requests is deprecated.", "x-opaque-id": "90834b42-2e3a-4932-ab44-e474da36ed83", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,296Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "ba417ce3-2593-4988-bedf-d6e35f2052a9", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,293Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "a04c0230-f7dc-432d-991d-bcee443d0b22", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,293Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "0f88c546-35e3-46f8-b4a7-5693ab2ffccb", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,299Z", "level": "WARN", "component": "o.e.d.a.b.BulkRequestParser", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in bulk requests is deprecated.", "x-opaque-id": "f3a65f52-d30d-4de6-8a8e-fff9f2abaa31", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,300Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "434e76ce-d645-4f2d-9311-bd2d456f395e", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,300Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "a1b09ef4-2669-47e0-b98a-f20913fea8b2", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,302Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "fdd9228f-566c-4dca-97dc-b52bf4b23fbe", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,304Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "49010df3-4c71-4570-b4ee-7add52bd6d35", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,308Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "82bc4689-b9e9-47bc-b222-8e8aa5f04552", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,309Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "58cfe85d-2bc6-474a-91cd-b48a1b5e7d4f", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,309Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "5a850cab-1cbc-47a1-9834-e959f41e8f73", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,310Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "6d5b4c10-eccf-4e2f-ac5d-9164a921d5d4", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,311Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "c9a3041d-31ff-457b-8516-6038d203bb30", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,312Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "d9934ae7-1033-4df5-abec-589fff54b3d2", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,313Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "70d7e12d-e297-4920-8306-9546a7ca069b", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,314Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "9f92b004-6ff9-4871-89d3-1c4455e77958", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,314Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "ea32c008-2b36-474c-a658-90857f491887", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }
{"type": "deprecation", "timestamp": "2022-04-01T08:05:34,316Z", "level": "WARN", "component": "o.e.d.r.a.d.RestDeleteAction", "cluster.name": "inbox-search", "node.name": "es-client2.localdomain", "message": "[types removal] Specifying types in document index requests is deprecated, use the typeless endpoints instead (/{index}/_doc/{id}, /{index}/_doc, or /{index}/_create/{id}).", "x-opaque-id": "4864c01c-f78b-43b3-8b94-2a99cc7d6287", "cluster.uuid": "3qEE79i0SHGKZ1iheGtGnQ", "node.id": "BX6nyVVdSRiP4Xjd3Fyasg"  }

[pgomulka]

this looks very much like #82810
please do upgrade to latest 7.17 version and let me know if this helped

[gregolsen]

@pgomulka thank you so much for the investigation!
Unfortunately, we can't go above 7.17.0 at the moment because of this issue #85709

[gregolsen]

@pgomulka Just to make sure I understood you correctly – is the assumption that all of those slow log items were created as a result of a request coming from Kibana?
We had over 2M deprecation log lines produced every 2 hours – given the scale I can hardly understand how Kibana could have generated this many requests. I would expect those to be produced by the regular production traffic.
Or am I missing something?

[pgomulka]

@gregolsen yes, I think they might be originated from different dashboards you have, or just plain discovery search.
@pgayvallet can you confirm this? This x-opaque-id should also be visible in kibana logs?

also given the amount of logs are being produced, I think you should disable the deprecation logs until you can upgrade to latest 7.17.x

PUT /_cluster/settings
{
  "persistent": {
    "logger.org.elasticsearch.deprecation": "OFF"
  }
}

[pgayvallet]

This x-opaque-id should also be visible in kibana logs?

It should be surfaced as trace.id in Kibana audit logs, yes

[gregolsen]

The volume of the deprecation logs followed the daily traffic seasonality. Kibana audit log (excluding ELB health checks) is tiny in comparison with the amount of deprecation logs produced by the cluster (hundreds of millions log lines in just a few days).

[ec2-user@es-kibana2 log]$ grep -v 'ELB-HealthChecker' kibana.log | grep '2022-04' | wc -l
20780

I also checked - we don't have a single dashboard created in Kibana for that cluster. Kibana is used rarely and only for manual queries.

Based on the above I'm still not convinced that Kibana requests generated these deprecation logs. Everything points towards the regular production traffic being responsible for generating these messages. While we upgraded the version to 7.17 we haven't done any work on changing the code to be compatible with 8.x - hence all the deprecation warnings about "Specifying types in document/search"

[pgomulka]

it all comes down to incorrect use of x-opaque-id which is used for deduplication. If you use a unique id per each request then deduplication won't work.
https://www.elastic.co/guide/en/elasticsearch/reference/current/api-conventions.html#x-opaque-id

The X-Opaque-Id header accepts any arbitrary value. However, we recommend you limit these values to a finite set, such as an ID per client. Don’t generate a unique X-Opaque-Id header for every request. Too many unique X-Opaque-Id values can prevent Elasticsearch from deduplicating warnings in the deprecation logs.

[pgomulka]

given this is fixed in 7.17.3 (as per #85582 (comment) )I will close an issue.
Feel free to reopen if you want to give more feedback

[gregolsen]

Sorry for the slow response - I was finally able to find where we indeed were setting a unique X-Opaque-Id (it was in our custom proxy in front of every cluster).
@pgomulka you were absolutely right! Thank you so much for helping out here 🙇🏻