Format the message string in the Logger

Since the Message class now formats the passed message on initialization
anyways, there is no need anymore to retain the formatter there.
Instead, we can just format the message string in the Logger before
creating the Message instance.

This significantly simplifies the Message class and better encapsulates
the knowledge about the line formatter into the Logger class.

lib/rackstash.rb

@@ -17,6 +17,15 @@ module Rackstash
     UNKNOWN = 5
   ].freeze
 
+  SEVERITY_LABELS = [
+    'DEBUG'.freeze,
+    'INFO'.freeze,
+    'WARN'.freeze,
+    'ERROR'.freeze,
+    'FATAL'.freeze,
+    'ANY'.freeze
+  ].freeze
+
   PROGNAME = "rackstash/v#{Rackstash::VERSION}".freeze
 
   EMPTY_STRING = ''.freeze

lib/rackstash/logger.rb

@@ -65,7 +65,9 @@ module Rackstash
     def <<(msg)
       buffer.add_message Message.new(
         msg,
-        time: Time.now.utc.freeze
+        time: Time.now.utc.freeze,
+        progname: @progname,
+        severity: UNKNOWN
       )
       msg
     end
@@ -251,15 +253,21 @@ module Rackstash
         end
       end
 
+      time = Time.now.utc.freeze
+      formatted_msg = formatter.call(
+        severity_label(severity),
+        time,
+        progname,
+        msg
+      )
       buffer.add_message Message.new(
-        msg,
+        formatted_msg,
-        time: Time.now.utc.freeze,
+        time: time,
         progname: progname,
-        severity: severity,
+        severity: severity
-        formatter: formatter
       )
 
-      msg
+      formatted_msg
     end
     alias log add
 
@@ -291,5 +299,9 @@ module Rackstash
     def buffer
       buffer_stack.current
     end
+
+    def severity_label(severity)
+      SEVERITY_LABELS[severity] || SEVERITY_LABELS.last
+    end
   end
 end

lib/rackstash/message.rb

@@ -6,17 +6,6 @@
 module Rackstash
   # This class and all its data are immutable after initialization
   class Message
-    RAW_FORMATTER = RawFormatter.new
-
-    SEVERITY_LABEL = [
-      'DEBUG'.freeze,
-      'INFO'.freeze,
-      'WARN'.freeze,
-      'ERROR'.freeze,
-      'FATAL'.freeze,
-      'ANY'.freeze
-    ].freeze
-
     attr_reader :message
 
     alias as_json message
@@ -30,27 +19,14 @@ module Rackstash
 
     attr_reader :time
 
-    attr_reader :formatter
+    def initialize(message, severity: UNKNOWN, time: Time.now.utc.freeze, progname: PROGNAME)
-
-    def initialize(
-      message,
-      severity: UNKNOWN,
-      time: Time.now.utc.freeze,
-      progname: PROGNAME,
-      formatter: RAW_FORMATTER
-    )
       @severity = Integer(severity)
       @severity = 0 if @severity < 0
 
       @time = dup_freeze(time)
       @progname = dup_freeze(progname)
-      @formatter = formatter
 
-      @message = cleanup @formatter.call(severity_label, @time, @progname, message)
+      @message = cleanup(message)
-    end
-
-    def severity_label
-      SEVERITY_LABEL[@severity] || SEVERITY_LABEL.last
     end
 
     def to_json
@@ -65,6 +41,7 @@ module Rackstash
     # @param msg [#to_s] a message to be added to the buffer
     # @return [String] the sanitized frozen message
     def cleanup(msg)
+      msg = msg.inspect unless msg.is_a?(String)
       msg = utf8_encode(msg)
       # remove useless ANSI color codes
       msg.gsub!(/\e\[[0-9;]*m/, EMPTY_STRING)

spec/rackstash/logger_spec.rb

@@ -166,30 +166,30 @@ 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', severity: 0
+      expect(messages.last).to include message: "Debug message\n", severity: 0
 
       logger.log(Rackstash::INFO, 'Info message')
-      expect(messages.last).to include message: 'Info message', severity: 1
+      expect(messages.last).to include message: "Info message\n", severity: 1
 
       logger.log(Rackstash::WARN, 'Warn message')
-      expect(messages.last).to include message: 'Warn message', severity: 2
+      expect(messages.last).to include message: "Warn message\n", severity: 2
 
       logger.log(Rackstash::ERROR, 'Error message')
-      expect(messages.last).to include message: 'Error message', severity: 3
+      expect(messages.last).to include message: "Error message\n", severity: 3
 
       logger.log(Rackstash::FATAL, 'Fatal message')
-      expect(messages.last).to include message: 'Fatal message', severity: 4
+      expect(messages.last).to include message: "Fatal message\n", severity: 4
 
       logger.log(Rackstash::UNKNOWN, 'Unknown message')
-      expect(messages.last).to include message: 'Unknown message', severity: 5
+      expect(messages.last).to include message: "Unknown message\n", severity: 5
 
       # Positive severities are passed along
       logger.log(42, 'The answer')
-      expect(messages.last).to include message: 'The answer', severity: 42
+      expect(messages.last).to include message: "The answer\n", severity: 42
 
       # nil is changed to UNKNOWN
       logger.log(nil, 'Missing')
-      expect(messages.last).to include message: 'Missing', severity: 5
+      expect(messages.last).to include message: "Missing\n", severity: 5
 
       # Non-number arguments result in an error
       expect { logger.log(:debug, 'Missing') }.to raise_error(TypeError)
@@ -201,9 +201,16 @@ describe Rackstash::Logger do
       expect(messages.last).to include severity: 5
     end
 
-    it 'adds the current formatter to the message' do
+    it 'formats the message' do
-      logger.add(0, 'test')
+      time = Time.now
-      expect(messages.last).to include formatter: logger.formatter
+      formatter = double('formatter')
+
+      logger.formatter = formatter
+
+      expect(formatter).to receive(:call)
+        .with('DEBUG', instance_of(Time), Rackstash::PROGNAME, 'Hello World')
+
+      logger.add(0, 'Hello World')
     end
 
     it 'calls the block if message is nil' do
@@ -230,134 +237,137 @@ 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', severity: 0, progname: Rackstash::PROGNAME
+        message: "Hello\n", severity: 0, progname: Rackstash::PROGNAME
       )
 
       logger.add(4, 'Hello', 'prog')
       expect(messages.last).to include(
-        message: 'Hello', severity: 4, progname: 'prog'
+        message: "Hello\n", severity: 4, progname: 'prog'
       )
 
       logger.add(5, 'Hello', 'prog') { 'block' }
       expect(messages.last).to include(
-        message: 'Hello', severity: 5, progname: 'prog'
+        message: "Hello\n", severity: 5, progname: 'prog'
       )
 
       logger.add(nil, 'Hello', nil)
       expect(messages.last).to include(
-        message: 'Hello', severity: 5, progname: Rackstash::PROGNAME
+        message: "Hello\n", 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', severity: 1, progname: 'prog'
+        message: "Hello\n", severity: 1, progname: 'prog'
       )
       logger.add(1, nil, nil) { 'Hello' }
       expect(messages.last).to include(
-        message: 'Hello', severity: 1, progname: Rackstash::PROGNAME
+        message: "Hello\n", 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', severity: 2, progname: Rackstash::PROGNAME
+        message: "prog\n", severity: 2, progname: Rackstash::PROGNAME
       )
       # ... which defaults to `Rackstash::BufferedLogger::PROGNAME`
       logger.add(3, nil, nil)
       expect(messages.last).to include(
-        message: Rackstash::PROGNAME, severity: 3, progname: Rackstash::PROGNAME
+        message: "#{Rackstash::PROGNAME}\n", 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: '', severity: 1, progname: Rackstash::PROGNAME
+        message: "\n", 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, severity: 0, progname: 'prog'
+        message: "nil\n", severity: 0, progname: 'prog'
       )
     end
 
     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', severity: 0
+      expect(messages.last).to include message: "Debug\n", 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', severity: 0
+      expect(messages.last).to include message: "Debug\n", 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', severity: 1
+      expect(messages.last).to include message: "Info\n", 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', severity: 1
+      expect(messages.last).to include message: "Info\n", 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', severity: 2
+      expect(messages.last).to include message: "Warn\n", 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', severity: 2
+      expect(messages.last).to include message: "Warn\n", 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', severity: 3
+      expect(messages.last).to include message: "Error\n", 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', severity: 3
+      expect(messages.last).to include message: "Error\n", 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', severity: 4
+      expect(messages.last).to include message: "Fatal\n", 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', severity: 4
+      expect(messages.last).to include message: "Fatal\n", 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', severity: 5
+      expect(messages.last).to include message: "Unknown\n", 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', severity: 5
+      expect(messages.last).to include message: "Unknown\n", severity: 5
     end
 
     it 'can add a raw message with <<' do
       logger << :raw_value
-      expect(messages.last).to include message: :raw_value
+      expect(messages.last).to include(
-      expect(messages.last).not_to include :formatter, :severity
+        message: :raw_value,
+        severity: 5,
+        time: instance_of(Time)
+      )
     end
   end
 

spec/rackstash/message_spec.rb

@@ -11,25 +11,6 @@ require 'rackstash/message'
 
 describe Rackstash::Message do
   describe '#initialize' do
-    it 'immediately formats the message' do
-      severity = 0
-      time = Time.now
-      progname = 'ProgramName'
-      message = 'Hello World'
-
-      formatter = double('formatter')
-      expect(formatter).to receive(:call)
-        .with('DEBUG', time, progname, message)
-
-      message = Rackstash::Message.new(
-        message,
-        severity: severity,
-        time: time,
-        progname: progname,
-        formatter: formatter
-      )
-    end
-
     it 'cleans the message' do
       messages = [
         ["First\r\nSecond",         "First\nSecond"],
@@ -126,18 +107,6 @@ describe Rackstash::Message do
     end
   end
 
-  describe '#severity_label' do
-    it 'formats the given severity as a string' do
-      %w[DEBUG INFO WARN ERROR FATAL ANY].each_with_index do |label, severity|
-        expect(Rackstash::Message.new('', severity: severity).severity_label).to eql label
-      end
-    end
-
-    it 'returns ANY for unknown severities' do
-      expect(Rackstash::Message.new('', severity: 42).severity_label).to eql 'ANY'
-    end
-  end
-
   describe 'progname' do
     it 'dups the progname' do
       progname = 'a message'
@@ -172,16 +141,6 @@ describe Rackstash::Message do
     end
   end
 
-  describe 'formatter' do
-    it 'defaults to RAW_FORMATTER' do
-      expect(Rackstash::Message.new('').formatter).to equal Rackstash::Message::RAW_FORMATTER
-
-      message = Rackstash::Message.new('Beep boop')
-      expect(message.to_s).to eql 'Beep boop'
-    end
-  end
-
-
   describe '#to_json' do
     it 'formats the message as JSON' do
       message = Rackstash::Message.new('hello world')