Gracefully handle json Encoding::UndefinedConversionError

lib/logstash-logger/formatter.rb

@@ -10,19 +10,19 @@ module Formatter
     autoload :Cee, 'logstash-logger/formatter/cee'
     autoload :CeeSyslog, 'logstash-logger/formatter/cee_syslog'
 
-    def self.new(formatter_type, customize_event: nil)
-      build_formatter(formatter_type, customize_event)
+    def self.new(formatter_type, customize_event: nil, error_logger: LogStashLogger.configuration.default_error_logger)
+      build_formatter(formatter_type, customize_event, error_logger)
     end
 
-    def self.build_formatter(formatter_type, customize_event)
+    def self.build_formatter(formatter_type, customize_event, error_logger)
       formatter_type ||= DEFAULT_FORMATTER
 
       formatter = if custom_formatter_instance?(formatter_type)
         formatter_type
       elsif custom_formatter_class?(formatter_type)
         formatter_type.new
       else
-        formatter_klass(formatter_type).new(customize_event: customize_event)
+        formatter_klass(formatter_type).new(customize_event: customize_event, error_logger: error_logger)
       end
 
       formatter.send(:extend, ::LogStashLogger::TaggedLogging::Formatter)

lib/logstash-logger/formatter/base.rb

@@ -7,16 +7,22 @@ module Formatter
     HOST = ::Socket.gethostname
 
     class Base < ::Logger::Formatter
+      FAILED_TO_FORMAT_MSG = 'Failed to format log event'
+      attr_accessor :error_logger
       include ::LogStashLogger::TaggedLogging::Formatter
 
-      def initialize(customize_event: nil)
+      def initialize(customize_event: nil, error_logger: LogStashLogger.configuration.default_error_logger)
         @customize_event = customize_event
+        @error_logger = error_logger
         super()
       end
 
       def call(severity, time, _progname, message)
         event = build_event(message, severity, time)
         format_event(event) unless event.cancelled?
+      rescue StandardError => e
+        log_error(e)
+        FAILED_TO_FORMAT_MSG
       end
 
       private
@@ -68,6 +74,16 @@ def build_event(message, severity, time)
       def format_event(event)
         event
       end
+
+      def force_utf8_encoding(event)
+        original_message = event.instance_variable_get(:@data)['message']
+        event.message = original_message.dup.force_encoding(Encoding::UTF_8).scrub
+        event
+      end
+
+      def log_error(e)
+        error_logger.error "[#{self.class}] #{e.class} - #{e.message}"
+      end
     end
   end
 end

lib/logstash-logger/formatter/json.rb

@@ -5,6 +5,9 @@ class Json < Base
 
       def format_event(event)
         event.to_json
+      rescue Encoding::UndefinedConversionError => e
+        log_error(e)
+        force_utf8_encoding(event).to_json
       end
     end
   end

lib/logstash-logger/formatter/json_lines.rb

@@ -5,6 +5,9 @@ class JsonLines < Base
 
       def format_event(event)
         "#{event.to_json}\n"
+      rescue Encoding::UndefinedConversionError => e
+        log_error(e)
+        "#{force_utf8_encoding(event).to_json}\n"
       end
     end
   end

lib/logstash-logger/logger.rb

@@ -50,7 +50,9 @@ def self.extract_opts(*args)
   end
 
   def self.build_logger(opts)
-    formatter = Formatter.new(opts.delete(:formatter), customize_event: opts.delete(:customize_event))
+    formatter = Formatter.new(opts.delete(:formatter),
+                              customize_event: opts.delete(:customize_event),
+                              error_logger: opts.fetch(:error_logger, LogStashLogger.configuration.default_error_logger))
 
     logger_type = opts[:type].to_s.to_sym
     logger = case logger_type

spec/formatter/base_spec.rb

@@ -23,6 +23,51 @@
         expect(subject.call(severity, time, progname, message)).to be_nil
       end
     end
+
+    context "when exception is raised" do
+      before do
+        allow(subject).to receive(:error_logger).and_return(Logger.new('/dev/null'))
+        allow(subject).to receive(:format_event).and_throw
+      end
+
+      it "logs an exception" do
+        expect(subject).to receive(:log_error)
+        subject.call(severity, time, progname, message)
+      end
+
+      it "returns a failed to format message" do
+        expect(subject.call(severity, time, progname, message)).to eq(LogStashLogger::Formatter::Base::FAILED_TO_FORMAT_MSG)
+      end
+    end
+  end
+
+  describe '#force_utf8_encoding' do
+    let(:message) { "foo x\xc3x".force_encoding('ASCII-8BIT').freeze }
+    let(:event) { LogStash::Event.new("message" => message) }
+
+    it 'returns the same event' do
+      expect(subject.send(:force_utf8_encoding, event)).to eq(event)
+    end
+
+    it 'forces the event message to UTF-8 encoding' do
+      subject.send(:force_utf8_encoding, event)
+      updated_event_data = event.instance_variable_get(:@data)
+      expect(updated_event_data['message'].encoding.name).to eq('UTF-8')
+    end
+
+    context 'frozen message string' do
+      let(:message) { "foo x\xc3x".dup.force_encoding('ASCII-8BIT').freeze }
+
+      it 'returns the same event' do
+        expect(subject.send(:force_utf8_encoding, event)).to eq(event)
+      end
+
+      it 'forces the event message to UTF-8 encoding' do
+        subject.send(:force_utf8_encoding, event)
+        updated_event_data = event.instance_variable_get(:@data)
+        expect(updated_event_data['message'].encoding.name).to eq('UTF-8')
+      end
+    end
   end
 
   describe "#build_event" do

spec/formatter/json_lines_spec.rb

@@ -11,4 +11,27 @@
   it "terminates with a line break" do
     expect(formatted_message[-1]).to eq("\n")
   end
+
+  context 'encoding error is raised' do
+    let(:message) { "foo x\xc3x".force_encoding('ASCII-8BIT') }
+
+    before do
+      allow(subject).to receive(:error_logger).and_return(Logger.new('/dev/null'))
+    end
+
+    it 'logs the error' do
+      expect(subject).to receive(:log_error)
+      formatted_message
+    end
+
+    it 'forces the message encoding to utf8' do
+      expect(subject).to receive(:force_utf8_encoding)
+      formatted_message
+    end
+
+    it "outputs in JSON format with message encoding updated to utf8" do
+      json_message = JSON.parse(formatted_message)
+      expect(json_message["message"]).to eq(message.force_encoding(Encoding::UTF_8).scrub)
+    end
+  end
 end

spec/formatter/json_spec.rb

@@ -7,4 +7,27 @@
     json_message = JSON.parse(formatted_message)
     expect(json_message["message"]).to eq(message)
   end
+
+  context 'encoding error is raised' do
+    let(:message) { "foo x\xc3x".force_encoding('ASCII-8BIT') }
+
+    before do
+      allow(subject).to receive(:error_logger).and_return(Logger.new('/dev/null'))
+    end
+
+    it 'logs the error' do
+      expect(subject).to receive(:log_error)
+      formatted_message
+    end
+
+    it 'forces the message encoding to utf8' do
+      expect(subject).to receive(:force_utf8_encoding)
+      formatted_message
+    end
+
+    it "outputs in JSON format with message encoding updated to utf8" do
+      json_message = JSON.parse(formatted_message)
+      expect(json_message["message"]).to eq(message.force_encoding(Encoding::UTF_8).scrub)
+    end
+  end
 end