logstash-plugins/logstash-output-elasticsearch

DLQ error messages squashed in string instead of keeping structure when logging in json

andsel opened this issue · 1 comments

andsel commented

Logstash information:

Please include the following information:

  1. Logstash version (e.g. bin/logstash --version) >= 8.3.0
  2. Logstash installation source (e.g. built from source, with a package manager: DEB/RPM, expanded from tar or zip archive, docker)
  3. How is Logstash being run (e.g. as a service/service manager: systemd, upstart, etc. Via command line, docker/kubernetes)
  4. How was the Logstash Plugin installed >= 11.9.0

JVM (e.g. java -version):

If the affected version of Logstash is 7.9 (or earlier), or if it is NOT using the bundled JDK or using the 'no-jdk' version in 7.10 (or higher), please provide the following information:

  1. JVM version (java -version)
  2. JVM installation source (e.g. from the Operating System's package manager, from source, etc).
  3. Value of the JAVA_HOME environment variable if set.

OS version (uname -a if on a Unix-like system):

Description of the problem including expected versus actual behavior:

Steps to reproduce:

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

  1. Start en Elasticsearch with a closed test_index to generate http error code 400.
PUT test_index/
POST test_index/_close
  1. Create pipeline with following config
input {
 generator {
   message => '{"name": "Andrea"}'
   count => 1
 }
}

output {
 elasticsearch {
   index => "test_index"
   hosts => "http://localhost:9200"
   user => "elastic"
   password => "changeme"
 }
}
  1. run Logstash with json format with a version 8.3.3 and 8.5.0
> logstash-8.5.3/bin/logstash -f `pwd/`pipeline.conf --log.format json
> logstash-8.3.3/bin/logstash -f `pwd/`pipeline.conf --log.format json

Provide logs (if relevant):

In Logstash 8.3.3the log is still JSON also for hash map carried with the log line

{"level":"WARN","loggerName":"logstash.outputs.elasticsearch","timeMillis":1671637701670,"thread":"[main]>worker0","logEvent":{"message":"Could not index event to Elasticsearch.","status":400,"action":["index",{"_index":"test_index"},{"host":{"name":"kalimera"},"@version":"1","message":"{\"name\": \"Andrea\"}","event":{"sequence":0,"original":"{\"name\": \"Andrea\"}"},"@timestamp":"2022-12-21T15:48:21.402861Z"}],"response":{"index":{"_index":"test_index","_type":"_doc","status":400,"error":{"type":"index_closed_exception","reason":"closed","index_uuid":"OBa2LOiATmW2rFoAtSU0LA","index":"test_index"}}}}}

while in Logstash 8.5.3 it's squashed into a string, loosing the structure

{"level":"WARN","loggerName":"logstash.outputs.elasticsearch","timeMillis":1671637668478,"thread":"[main]>worker3","logEvent":{"message":"Could not index event to Elasticsearch. status: 400, action: [\"index\", {:_id=>nil, :_index=>\"test_index\", :routing=>nil}, {\"message\"=>\"{\\\"name\\\": \\\"Andrea\\\"}\", \"@version\"=>\"1\", \"event\"=>{\"sequence\"=>0, \"original\"=>\"{\\\"name\\\": \\\"Andrea\\\"}\"}, \"@timestamp\"=>2022-12-21T15:47:48.267496238Z, \"host\"=>{\"name\"=>\"kalimera\"}}], response: {\"index\"=>{\"_index\"=>\"test_index\", \"_type\"=>\"_doc\", \"_id\"=>nil, \"status\"=>400, \"error\"=>{\"type\"=>\"index_closed_exception\", \"reason\"=>\"closed\", \"index_uuid\"=>\"OBa2LOiATmW2rFoAtSU0LA\", \"index\"=>\"test_index\"}}}"}}
andsel commented

The error message comes from DLQ error codes handling. This part of the code was touched in ES output 11.9.0 with PR #1084

where essentially a structured log message:

logger.send level, message, status: status, action: action, response: response

to a message that has been sprintf-ed

message = "#{message} status: #{status}, action: #{action_params}, response: #{response}"
@logger.send log_level, message

There is a code comment to improve it.