dlq-logging: reintroduce structured payload where possible

Author: yaauie

CHANGELOG.md

@@ -1,3 +1,6 @@
+## 11.15.2
+ - Restores DLQ logging behavior from 11.8.x to include the action-tuple as structured [#1105](https://github.com/logstash-plugins/logstash-output-elasticsearch/pull/1105)
+
 ## 11.15.1
  - Move async finish_register to bottom of register to avoid race condition [#1125](https://github.com/logstash-plugins/logstash-output-elasticsearch/pull/1125)
 

lib/logstash/outputs/elasticsearch.rb

@@ -405,7 +405,7 @@ def handle_event_mapping_errors(event_mapping_errors)
 
     event_mapping_errors.each do |event_mapping_error|
       detailed_message = "#{event_mapping_error.message}; event: `#{event_mapping_error.event.to_hash_with_metadata}`"
-      handle_dlq_status(event_mapping_error.event, :warn, detailed_message)
+      @dlq_writer ? @dlq_writer.write(event_mapping_error.event, detailed_message) : @logger.warn(detailed_message)
     end
     @document_level_metrics.increment(:non_retryable_failures, event_mapping_errors.size)
   end
@@ -422,7 +422,7 @@ def safe_interpolation_map_events(events)
         successful_events << @event_mapper.call(event)
       rescue EventMappingError => ie
         event_mapping_errors << FailedEventMapping.new(event, ie.message)
-       end
+      end
     end
     MapEventsResult.new(successful_events, event_mapping_errors)
   end

lib/logstash/plugin_mixins/elasticsearch/common.rb

@@ -227,22 +227,16 @@ def next_sleep_interval(current_interval)
     end
 
     def handle_dlq_response(message, action, status, response)
-      _, action_params = action.event, [action[0], action[1], action[2]]
+      event, action_params = action.event, [action[0], action[1], action[2]]
 
-      # TODO: Change this to send a map with { :status => status, :action => action } in the future
-      detailed_message = "#{message} status: #{status}, action: #{action_params}, response: #{response}"
-
-      log_level = dig_value(response, 'index', 'error', 'type') == 'invalid_index_name_exception' ? :error : :warn
-
-      handle_dlq_status(action.event, log_level, detailed_message)
-    end
-
-    def handle_dlq_status(event, log_level, message)
-      # To support bwc, we check if DLQ exists. otherwise we log and drop event (previous behavior)
       if @dlq_writer
-        @dlq_writer.write(event, "#{message}")
+        # TODO: Change this to send a map with { :status => status, :action => action } in the future
+        detailed_message = "#{message} status: #{status}, action: #{action_params}, response: #{response}"
+        @dlq_writer.write(event, "#{detailed_message}")
       else
-        @logger.send log_level, message
+        log_level = dig_value(response, 'index', 'error', 'type') == 'invalid_index_name_exception' ? :error : :warn
+
+        @logger.public_send(log_level, message, status: status, action: action_params, response: response)
       end
     end
 

spec/es_spec_helper.rb

@@ -67,19 +67,24 @@ def self.es_version
   end
 
   RSpec::Matchers.define :have_hits do |expected|
+    hits_count_path = ESHelper.es_version_satisfies?(">=7") ? %w(hits total value) : %w(hits total)
+
     match do |actual|
-      if ESHelper.es_version_satisfies?(">=7")
-        expected == actual['hits']['total']['value']
-      else
-        expected == actual['hits']['total']
-      end
+      @actual_hits_count = actual&.dig(*hits_count_path)
+      values_match? expected, @actual_hits_count
+    end
+    failure_message do |actual|
+      "expected that #{actual} with #{@actual_hits_count || "UNKNOWN" } hits would have #{expected} hits"
     end
   end
 
   RSpec::Matchers.define :have_index_pattern do |expected|
     match do |actual|
-      test_against = Array(actual['index_patterns'].nil? ? actual['template'] : actual['index_patterns'])
-      test_against.include?(expected)
+      @actual_index_pattterns = Array(actual['index_patterns'].nil? ? actual['template'] : actual['index_patterns'])
+      @actual_index_pattterns.any? { |v| values_match? expected, v }
+    end
+    failure_message do |actual|
+      "expected that #{actual} with index patterns #{@actual_index_pattterns} would have included `#{expected}`"
     end
   end
 

spec/integration/outputs/templates_spec.rb

@@ -23,7 +23,9 @@
 
     elasticsearch_client.indices.delete_template(:name => '*')
     # This can fail if there are no indexes, ignore failure.
-    elasticsearch_client.indices.delete(:index => '*') rescue nil
+    elasticsearch_client.indices.delete(:index => '*') rescue puts("DELETE INDICES ERROR: #{$!}")
+    # Since we are pinned to ES client 7.x, we need to delete data streams the hard way...
+    elasticsearch_client.perform_request("DELETE", "/_data_stream/*") rescue puts("DELETE DATA STREAMS ERROR: #{$!}")
   end
 
   context 'with ecs_compatibility => disabled' do

spec/unit/outputs/elasticsearch_spec.rb

@@ -1121,41 +1121,63 @@
   end if LOGSTASH_VERSION > '6.0'
 
   context 'handling elasticsearch document-level status meant for the DLQ' do
+    let(:es_api_action) { "CUSTOM_ACTION" }
+    let(:es_api_params) { Hash['_index' => 'MY_INDEX'] }
+
     let(:options) { { "manage_template" => false, "data_stream" => 'false' } }
-    let(:action) { LogStash::Outputs::ElasticSearch::EventActionTuple.new(:action, :params, LogStash::Event.new("foo" => "bar")) }
+    let(:action) { LogStash::Outputs::ElasticSearch::EventActionTuple.new(es_api_action, es_api_params, LogStash::Event.new("foo" => "bar")) }
+
+    let(:logger) { double('logger').as_null_object }
+    before(:each) { subject.instance_variable_set(:@logger, logger) }
 
     context 'when @dlq_writer is nil' do
       before { subject.instance_variable_set '@dlq_writer', nil }
-      let(:action) { LogStash::Outputs::ElasticSearch::EventActionTuple.new(:action, :params, LogStash::Event.new("foo" => "bar")) }
 
       context 'resorting to previous behaviour of logging the error' do
         context 'getting an invalid_index_name_exception' do
           it 'should log at ERROR level' do
-            subject.instance_variable_set(:@logger, double("logger").as_null_object)
+            # logger = double("logger").as_null_object
+            # subject.instance_variable_set(:@logger, logger)
+
             mock_response = { 'index' => { 'error' => { 'type' => 'invalid_index_name_exception' } } }
             subject.handle_dlq_response("Could not index event to Elasticsearch.", action, :some_status, mock_response)
+
+            expect(logger).to have_received(:error).with(a_string_including("Could not index event to Elasticsearch"),
+                                                         a_hash_including(:status => :some_status,
+                                                                          :action => [es_api_action, es_api_params, action.event.to_hash],
+                                                                          :response => mock_response))
           end
         end
 
         context 'when getting any other exception' do
           it 'should log at WARN level' do
-            logger = double("logger").as_null_object
-            subject.instance_variable_set(:@logger, logger)
-            expect(logger).to receive(:warn).with(a_string_including "Could not index event to Elasticsearch. status: some_status, action: [:action, :params, {")
+            # logger = double("logger").as_null_object
+            # subject.instance_variable_set(:@logger, logger)
+
             mock_response = { 'index' => { 'error' => { 'type' => 'illegal_argument_exception' } } }
             subject.handle_dlq_response("Could not index event to Elasticsearch.", action, :some_status, mock_response)
+
+            expect(logger).to have_received(:warn).with(a_string_including("Could not index event to Elasticsearch"),
+                                                        a_hash_including(:status => :some_status,
+                                                                         :action => [es_api_action, es_api_params, action.event.to_hash],
+                                                                         :response => mock_response))
           end
         end
 
         context 'when the response does not include [error]' do
           it 'should not fail, but just log a warning' do
-            logger = double("logger").as_null_object
-            subject.instance_variable_set(:@logger, logger)
-            expect(logger).to receive(:warn).with(a_string_including "Could not index event to Elasticsearch. status: some_status, action: [:action, :params, {")
+            # logger = double("logger").as_null_object
+            # subject.instance_variable_set(:@logger, logger)
+
             mock_response = { 'index' => {} }
             expect do
               subject.handle_dlq_response("Could not index event to Elasticsearch.", action, :some_status, mock_response)
             end.to_not raise_error
+
+            expect(logger).to have_received(:warn).with(a_string_including("Could not index event to Elasticsearch"),
+                                                        a_hash_including(:status => :some_status,
+                                                                         :action => [es_api_action, es_api_params, action.event.to_hash],
+                                                                         :response => mock_response))
           end
         end
       end
@@ -1175,6 +1197,8 @@
         mock_response = { 'index' => { 'error' => { 'type' => 'illegal_argument_exception' } } }
         action = LogStash::Outputs::ElasticSearch::EventActionTuple.new(:action, :params, event)
         subject.handle_dlq_response("Could not index event to Elasticsearch.", action, 404, mock_response)
+
+        expect(logger).to_not have_received(:warn).with(a_string_including("Could not index event to Elasticsearch"))
       end
     end