Don't add trailing newline in Rackstash::Formatter

Instead, let the encoders (and if necessary the adapters) add newlines
if necessary.

This makes it more straight-forward to filter messages and eventually
allows the encoders to format messages with fewer checks. Finally, we
might avoid the creation a lot of intermediary strings.

lib/rackstash/encoder/helper/message.rb

@@ -47,7 +47,7 @@ module Rackstash
         def normalized_message(message) #:doc:
           case message
           when Array
-            message.map(&:to_s).join
+            message.map(&:to_s).join("\n")
           else
             message.to_s
           end

lib/rackstash/encoder/message.rb

@@ -28,11 +28,11 @@ module Rackstash
     #     event = {
     #       'remote_ip' => '127.0.0.1',
     #       'tags' => ['foo', 123],
-    #       'message' => ["Hello\n", "World\n"],
+    #       'message' => ["Hello", "World"],
     #       'key' => 'value'
     #     }
     #     encoder.encode(event)
-    #     # Logs "[foo,123] [127.0.0.1] Hello\n[foo,123] [127.0.0.1] World\n"
+    #     # => "[foo,123] [127.0.0.1] Hello\n[foo,123] [127.0.0.1] World"
     class Message
       include Rackstash::Utils
       include Rackstash::Encoder::Helper::Message

lib/rackstash/formatter.rb

@@ -5,26 +5,36 @@
 # This software may be modified and distributed under the terms
 # of the MIT license. See the LICENSE.txt file for details.
 
-require 'logger'
-
 module Rackstash
   # The default logging formatter which is responsible for formatting a single
   # {Message} for the final emitted log event.
-  class Formatter < ::Logger::Formatter
+  class Formatter
+    include Rackstash::Utils
+
     # Return the formatted message from the following rules:
-    # * Strings passed to `msg` are returned with an added newline character at
+    # * Strings passed to `msg` are returned as a UTF-8 encoded frozen String
-    #   the end
     # * Exceptions are formatted with their name, message and backtrace,
     #   separated by newline characters.
-    # * All other objects will be `inspect`ed with an added newline.
+    # * All other objects will be `inspect`ed and returned as a UTF-8 encoded
+    #   frozen String.
     #
     # @param _severity [Integer] the log severity, ignored.
     # @param _time [Time] the time of the log message, ignored.
     # @param _progname [String] the program name, ignored.
     # @param msg [String, Exception, #inspect] the log message
-    # @return [String] the formatted message with a final newline character
+    # @return [String] the formatted message
     def call(_severity, _time, _progname, msg)
-      "#{msg2str(msg)}\n".freeze
+      case msg
+      when ::String
+       utf8(msg)
+      when ::Exception
+        lines = ["#{msg.message} (#{msg.class})"]
+        lines.concat(msg.backtrace) if msg.backtrace
+
+        utf8 lines.join("\n").freeze
+      else
+        utf8(msg.inspect)
+      end
     end
   end
 end

spec/rackstash/encoder/gelf_spec.rb

@@ -147,21 +147,21 @@ RSpec.describe Rackstash::Encoder::GELF do
 
   describe 'short_message field' do
     it 'adds the event message to the short_message field by default' do
-      expect(encoder.encode('message' => ["Hello\n", "World\n"]))
+      expect(encoder.encode('message' => ['Hello', 'World']))
-        .to include '"short_message":"Hello\nWorld\n"'
+        .to include '"short_message":"Hello\nWorld"'
     end
 
     it 'uses the configured short_message field' do
       encoder_args[:fields] = { short_message: 'gelf_message' }
 
       event = {
-        'message' => ["Hello\n", "World\n"],
+        'message' => ['Hello', 'World'],
         'gelf_message' => 'Hello GELF'
       }
 
       expect(encoder.encode(event))
         .to include('"short_message":"Hello GELF"')
-        .and include('"_message":"Hello\nWorld\n"')
+        .and include('"_message":"Hello\nWorld"')
     end
 
     it 'sets an empty short_message if the configured field is missing' do

spec/rackstash/encoder/hash_spec.rb

@@ -14,8 +14,8 @@ RSpec.describe Rackstash::Encoder::Hash do
 
   describe '#encode' do
     it 'normalized the message' do
-      event = { 'message' => ["hello\n", "world\n", 'foo', 'bar'] }
+      event = { 'message' => ['hello', 'world'] }
-      expect(encoder.encode(event)).to eql 'message' => "hello\nworld\nfoobar"
+      expect(encoder.encode(event)).to eql 'message' => "hello\nworld"
     end
 
     it 'normalizes the timestamp' do
@@ -23,7 +23,7 @@ RSpec.describe Rackstash::Encoder::Hash do
       event = { 'message' => ['foo', 'bar'], '@timestamp' => time }
 
       expect(encoder.encode(event))
-        .to eql 'message' => 'foobar', '@timestamp' => time.getutc.iso8601(6)
+        .to eql 'message' => "foo\nbar", '@timestamp' => time.getutc.iso8601(6)
     end
 
     it 'passes the normalized event hash through' do

spec/rackstash/encoder/helper/message_spec.rb

@@ -23,9 +23,9 @@ RSpec.describe Rackstash::Encoder::Helper::Message do
 
   describe '#normalize_message' do
     it 'concatenates the message array' do
-      event['message'] = ["a\n", "b\n", 42]
+      event['message'] = ["a\n", "b", 42]
 
-      expect(helper.normalize_message(event)).to eql 'message' => "a\nb\n42"
+      expect(helper.normalize_message(event)).to eql 'message' => "a\n\nb\n42"
     end
 
     it 'does not set a missing message' do

spec/rackstash/encoder/json_spec.rb

@@ -14,7 +14,7 @@ RSpec.describe Rackstash::Encoder::JSON do
 
   describe '#encode' do
     it 'formats the passed event hash as a JSON string' do
-      event = { 'hello' => 'world', 'message' => ["hello\n", 'world'] }
+      event = { 'hello' => 'world', 'message' => ['hello', 'world'] }
       expect(encoder.encode(event)).to eql '{"hello":"world","message":"hello\nworld"}'
     end
 
@@ -35,10 +35,10 @@ RSpec.describe Rackstash::Encoder::JSON do
 
     it 'normalizes the timestamp' do
       time = Time.parse('2016-10-17 13:37:00 +03:00')
-      event = { 'message' => ["line1\n", "line2\n"], '@timestamp' => time }
+      event = { 'message' => ['line1', 'line2'], '@timestamp' => time }
 
       expect(encoder.encode(event))
-        .to eql '{"message":"line1\nline2\n","@timestamp":"2016-10-17T10:37:00.000000Z"}'
+        .to eql '{"message":"line1\nline2","@timestamp":"2016-10-17T10:37:00.000000Z"}'
     end
 
     it 'omits a missing timestamp' do

spec/rackstash/encoder/logstash_spec.rb

@@ -14,7 +14,7 @@ RSpec.describe Rackstash::Encoder::Logstash do
 
   describe '#encode' do
     it 'formats the passed event hash as JSON and adds @version and @timstamp' do
-      event = { 'hello' => 'world', 'message' => ["hello\n", 'world'] }
+      event = { 'hello' => 'world', 'message' => ['hello', 'world'] }
       expect(encoder.encode(event))
         .to match(/\A\{"hello":"world","message":"hello\\nworld","@version":"1","@timestamp":"\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d\.\d{6}Z"\}\z/)
     end

spec/rackstash/encoder/message_spec.rb

@@ -16,7 +16,7 @@ RSpec.describe Rackstash::Encoder::Message do
   describe '#encode' do
     it 'gets the message from the event hash' do
       event = { 'hello' => 'world', 'message' => ["\n\t \nline1\n", "line2\n  \n\t\n"] }
-      expect(encoder.encode(event)).to eql "\n\t \nline1\nline2\n  \n\t\n"
+      expect(encoder.encode(event)).to eql "\n\t \nline1\n\nline2\n  \n\t\n"
     end
 
     it 'returns an empty with an empty message' do
@@ -41,37 +41,37 @@ RSpec.describe Rackstash::Encoder::Message do
       end
 
       it 'adds fields to all lines' do
-        event = { 'message' => ["line1\t\n", "line2\nline3\n\t\n"], 'field' => 'BXC' }
+        event = { 'message' => ["line1\t", "line2\nline3\n\t\n"], 'field' => 'BXC' }
         expect(encoder.encode(event))
           .to eql "[BXC] line1\t\n[BXC] line2\n[BXC] line3\n[BXC] \t\n"
       end
 
       it 'uses stringified fields' do
-        event = { 'message' => ["line1\n", "line2\nline3\n"], 'sym' => 'SYM', 'field' => 123 }
+        event = { 'message' => ['line1', "line2\nline3\n"], 'sym' => 'SYM', 'field' => 123 }
         expect(encoder.encode(event))
           .to eql "[SYM] [123] line1\n[SYM] [123] line2\n[SYM] [123] line3\n"
       end
 
       it 'formats arrays' do
-        event = { 'message' => ["line1\n", "line2\n"], 'tags' => ['foo', 'bar'] }
+        event = { 'message' => ['line1', "line2\n"], 'tags' => ['foo', 'bar'] }
         expect(encoder.encode(event)).to eql "[foo,bar] line1\n[foo,bar] line2\n"
       end
 
       it 'normalizes the timestamp' do
         time = Time.parse('2016-10-17 13:37:00 +03:00')
-        event = { 'message' => ["line1\n", "line2\n"], '@timestamp' => time }
+        event = { 'message' => ['line1', 'line2'], '@timestamp' => time }
 
         tagged << '@timestamp'
 
         expect(encoder.encode(event)).to eql [
-          "[2016-10-17T10:37:00.000000Z] line1\n",
+          '[2016-10-17T10:37:00.000000Z] line1',
-          "[2016-10-17T10:37:00.000000Z] line2\n"
+          '[2016-10-17T10:37:00.000000Z] line2'
-        ].join
+        ].join("\n")
       end
 
       it 'ignores missing fields' do
-        event = { 'message' => ["line1\n", "line2\n"] }
+        event = { 'message' => ['line1', 'line2'] }
-        expect(encoder.encode(event)).to eql "line1\nline2\n"
+        expect(encoder.encode(event)).to eql "line1\nline2"
       end
 
       it 'adds the prefix to a single string' do

spec/rackstash/formatter_spec.rb

@@ -15,19 +15,19 @@ RSpec.describe Rackstash::Formatter do
 
   it 'formats plain strings' do
     expect(formatter.call('ERROR', Time.now, 'progname', 'Hello'))
-      .to eql("Hello\n")
+      .to eql('Hello')
       .and be_frozen
   end
 
   it 'formats stringifiable objects' do
     expect(formatter.call('ERROR', Time.now, 'progname', 123))
-      .to eql("123\n")
+      .to eql('123')
       .and be_frozen
   end
 
   it 'formats Arrays' do
     expect(formatter.call('ERROR', Time.now, 'progname', [1, 'y']))
-      .to eql("[1, \"y\"]\n")
+      .to eql('[1, "y"]')
       .and be_frozen
   end
 
@@ -46,15 +46,16 @@ RSpec.describe Rackstash::Formatter do
     expect(formatter.call('ERROR', Time.now, 'progname', exception))
       .to match(checker)
       .and be_frozen
+      .and end_with("'")
   end
 
   it 'inspects unknown objects' do
     object = Object.new
-    inspected = object.inspect
+    inspected = Object.inspect.freeze
 
-    expect(object).to receive(:inspect).once.and_call_original
+    expect(object).to receive(:inspect).once.and_return(inspected)
     expect(formatter.call('ERROR', Time.now, 'progname', object))
-      .to eql("#{inspected}\n")
+      .to eq(inspected)
       .and be_frozen
   end
 end

spec/rackstash/logger_spec.rb

@@ -261,30 +261,30 @@ RSpec.describe Rackstash::Logger do
 
     it 'sets the provided a severity' do
       logger.log(Rackstash::DEBUG, 'Debug message')
-      expect(messages.last).to include message: "Debug message\n", severity: 0
+      expect(messages.last).to include message: 'Debug message', severity: 0
 
       logger.log(Rackstash::INFO, 'Info message')
-      expect(messages.last).to include message: "Info message\n", severity: 1
+      expect(messages.last).to include message: 'Info message', severity: 1
 
       logger.log(Rackstash::WARN, 'Warn message')
-      expect(messages.last).to include message: "Warn message\n", severity: 2
+      expect(messages.last).to include message: 'Warn message', severity: 2
 
       logger.log(Rackstash::ERROR, 'Error message')
-      expect(messages.last).to include message: "Error message\n", severity: 3
+      expect(messages.last).to include message: 'Error message', severity: 3
 
       logger.log(Rackstash::FATAL, 'Fatal message')
-      expect(messages.last).to include message: "Fatal message\n", severity: 4
+      expect(messages.last).to include message: 'Fatal message', severity: 4
 
       logger.log(Rackstash::UNKNOWN, 'Unknown message')
-      expect(messages.last).to include message: "Unknown message\n", severity: 5
+      expect(messages.last).to include message: 'Unknown message', severity: 5
 
       # Positive severities are passed along
       logger.log(42, 'The answer')
-      expect(messages.last).to include message: "The answer\n", severity: 42
+      expect(messages.last).to include message: 'The answer', severity: 42
 
       # nil is changed to UNKNOWN
       logger.log(nil, 'Missing')
-      expect(messages.last).to include message: "Missing\n", severity: 5
+      expect(messages.last).to include message: 'Missing', severity: 5
 
       # Non-number arguments result in an error
       expect { logger.log(:debug, 'Missing') }.to raise_error(TypeError)
@@ -329,55 +329,55 @@ RSpec.describe Rackstash::Logger do
       # If there is a message, it will be logged
       logger.add(0, 'Hello', nil)
       expect(messages.last).to include(
-        message: "Hello\n", severity: 0, progname: Rackstash::PROGNAME
+        message: 'Hello', severity: 0, progname: Rackstash::PROGNAME
       )
 
       logger.add(4, 'Hello', 'prog')
       expect(messages.last).to include(
-        message: "Hello\n", severity: 4, progname: 'prog'
+        message: 'Hello', severity: 4, progname: 'prog'
       )
 
       logger.add(5, 'Hello', 'prog') { 'block' }
       expect(messages.last).to include(
-        message: "Hello\n", severity: 5, progname: 'prog'
+        message: 'Hello', severity: 5, progname: 'prog'
       )
 
       logger.add(nil, 'Hello', nil)
       expect(messages.last).to include(
-        message: "Hello\n", severity: 5, progname: Rackstash::PROGNAME
+        message: 'Hello', severity: 5, progname: Rackstash::PROGNAME
       )
 
       # If there is no message, we use the block
       logger.add(1, nil, 'prog') { 'Hello' }
       expect(messages.last).to include(
-        message: "Hello\n", severity: 1, progname: 'prog'
+        message: 'Hello', severity: 1, progname: 'prog'
       )
       logger.add(1, nil, nil) { 'Hello' }
       expect(messages.last).to include(
-        message: "Hello\n", severity: 1, progname: Rackstash::PROGNAME
+        message: 'Hello', severity: 1, progname: Rackstash::PROGNAME
       )
 
       # If there is no block either, we use the progname and pass the default
       # progname to the message
       logger.add(2, nil, 'prog')
       expect(messages.last).to include(
-        message: "prog\n", severity: 2, progname: Rackstash::PROGNAME
+        message: 'prog', severity: 2, progname: Rackstash::PROGNAME
       )
       # ... which defaults to `Rackstash::BufferedLogger::PROGNAME`
       logger.add(3, nil, nil)
       expect(messages.last).to include(
-        message: "#{Rackstash::PROGNAME}\n", severity: 3, progname: Rackstash::PROGNAME
+        message: Rackstash::PROGNAME, severity: 3, progname: Rackstash::PROGNAME
       )
 
       # If we resolve the message to a blank string, we still add it
       logger.add(1, '', nil) { 'Hello' }
       expect(messages.last).to include(
-        message: "\n", severity: 1, progname: Rackstash::PROGNAME
+        message: '', severity: 1, progname: Rackstash::PROGNAME
       )
       # Same with nil which is later inspect'ed by the formatter
       logger.add(0, nil, 'prog') { nil }
       expect(messages.last).to include(
-        message: "nil\n", severity: 0, progname: 'prog'
+        message: 'nil', severity: 0, progname: 'prog'
       )
     end
 
@@ -391,73 +391,73 @@ RSpec.describe Rackstash::Logger do
     it 'can use debug shortcut' do
       expect(logger).to receive(:add).with(0, 'Debug').and_call_original
       logger.debug('Debug')
-      expect(messages.last).to include message: "Debug\n", severity: 0
+      expect(messages.last).to include message: 'Debug', severity: 0
     end
 
     it 'can use debug shortcut with a block' do
       expect(logger).to receive(:add).with(0, nil).and_call_original
       logger.debug { 'Debug' }
-      expect(messages.last).to include message: "Debug\n", severity: 0
+      expect(messages.last).to include message: 'Debug', severity: 0
     end
 
     it 'can use info shortcut' do
       expect(logger).to receive(:add).with(1, 'Info').and_call_original
       logger.info('Info')
-      expect(messages.last).to include message: "Info\n", severity: 1
+      expect(messages.last).to include message: 'Info', severity: 1
     end
 
     it 'can use info shortcut with a block' do
       expect(logger).to receive(:add).with(1, nil).and_call_original
       logger.info { 'Info' }
-      expect(messages.last).to include message: "Info\n", severity: 1
+      expect(messages.last).to include message: 'Info', severity: 1
     end
 
     it 'can use warn shortcut' do
       expect(logger).to receive(:add).with(2, 'Warn').and_call_original
       logger.warn('Warn')
-      expect(messages.last).to include message: "Warn\n", severity: 2
+      expect(messages.last).to include message: 'Warn', severity: 2
     end
 
     it 'can use warn shortcut with a block' do
       expect(logger).to receive(:add).with(2, nil).and_call_original
       logger.warn { 'Warn' }
-      expect(messages.last).to include message: "Warn\n", severity: 2
+      expect(messages.last).to include message: 'Warn', severity: 2
     end
 
     it 'can use error shortcut' do
       expect(logger).to receive(:add).with(3, 'Error').and_call_original
       logger.error('Error')
-      expect(messages.last).to include message: "Error\n", severity: 3
+      expect(messages.last).to include message: 'Error', severity: 3
     end
 
     it 'can use error shortcut with a block' do
       expect(logger).to receive(:add).with(3, nil).and_call_original
       logger.error { 'Error' }
-      expect(messages.last).to include message: "Error\n", severity: 3
+      expect(messages.last).to include message: 'Error', severity: 3
     end
 
     it 'can use fatal shortcut' do
       expect(logger).to receive(:add).with(4, 'Fatal').and_call_original
       logger.fatal('Fatal')
-      expect(messages.last).to include message: "Fatal\n", severity: 4
+      expect(messages.last).to include message: 'Fatal', severity: 4
     end
 
     it 'can use fatal shortcut with a block' do
       expect(logger).to receive(:add).with(4, nil).and_call_original
       logger.fatal { 'Fatal' }
-      expect(messages.last).to include message: "Fatal\n", severity: 4
+      expect(messages.last).to include message: 'Fatal', severity: 4
     end
 
     it 'can use unknown shortcut' do
       expect(logger).to receive(:add).with(5, 'Unknown').and_call_original
       logger.unknown('Unknown')
-      expect(messages.last).to include message: "Unknown\n", severity: 5
+      expect(messages.last).to include message: 'Unknown', severity: 5
     end
 
     it 'can use unknown shortcut with a block' do
       expect(logger).to receive(:add).with(5, nil).and_call_original
       logger.unknown { 'Unknown' }
-      expect(messages.last).to include message: "Unknown\n", severity: 5
+      expect(messages.last).to include message: 'Unknown', severity: 5
     end
 
     it 'can add a raw message with <<' do

spec/rackstash/rack/middleware_spec.rb

@@ -111,7 +111,7 @@ RSpec.describe Rackstash::Rack::Middleware do
       'path' => '/demo',
       'status' => 200,
       'duration' => be_a(Float).and(be > 0),
-      'message' => "Request started\nNothing to do...\n",
+      'message' => "Request started\nNothing to do...",
       '@timestamp' => /\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d.\d{6}Z/,
       'tags' => []
     )
@@ -308,7 +308,7 @@ RSpec.describe Rackstash::Rack::Middleware do
         'error_message' => 'kaputt',
         'error_trace' => %r{\A#{__FILE__}:#{__LINE__ - 8}:in},
         # The app did its thing
-        'message' => "Request started\nNothing to do...\n",
+        'message' => "Request started\nNothing to do...",
         # We explicitly override the logged status, even if the app returned a
         # successful response earlier
         'status' => 500
@@ -333,7 +333,7 @@ RSpec.describe Rackstash::Rack::Middleware do
 
       expect(log.last).to include(
         'path' => '/foo',
-        'message' => "Request started\nNothing to do...\n"
+        'message' => "Request started\nNothing to do..."
       )
       expect(log.last).to_not include('error', 'error_message', 'error_trace')
     end