diff --git a/lib/rackstash/encoder/helper/message.rb b/lib/rackstash/encoder/helper/message.rb index dfe9762..4781d8b 100644 --- a/lib/rackstash/encoder/helper/message.rb +++ b/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 diff --git a/lib/rackstash/encoder/message.rb b/lib/rackstash/encoder/message.rb index 4fc2101..308cdd9 100644 --- a/lib/rackstash/encoder/message.rb +++ b/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 diff --git a/lib/rackstash/formatter.rb b/lib/rackstash/formatter.rb index b65c307..53723ea 100644 --- a/lib/rackstash/formatter.rb +++ b/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 - # the end + # * Strings passed to `msg` are returned as a UTF-8 encoded frozen String # * 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 diff --git a/spec/rackstash/encoder/gelf_spec.rb b/spec/rackstash/encoder/gelf_spec.rb index e1e2fb2..444c4fe 100644 --- a/spec/rackstash/encoder/gelf_spec.rb +++ b/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"])) - .to include '"short_message":"Hello\nWorld\n"' + expect(encoder.encode('message' => ['Hello', 'World'])) + .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 diff --git a/spec/rackstash/encoder/hash_spec.rb b/spec/rackstash/encoder/hash_spec.rb index 6410419..28cdd54 100644 --- a/spec/rackstash/encoder/hash_spec.rb +++ b/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'] } - expect(encoder.encode(event)).to eql 'message' => "hello\nworld\nfoobar" + event = { 'message' => ['hello', 'world'] } + 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 diff --git a/spec/rackstash/encoder/helper/message_spec.rb b/spec/rackstash/encoder/helper/message_spec.rb index b8588de..a2ef9a4 100644 --- a/spec/rackstash/encoder/helper/message_spec.rb +++ b/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 diff --git a/spec/rackstash/encoder/json_spec.rb b/spec/rackstash/encoder/json_spec.rb index 96a0f90..d068495 100644 --- a/spec/rackstash/encoder/json_spec.rb +++ b/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 diff --git a/spec/rackstash/encoder/logstash_spec.rb b/spec/rackstash/encoder/logstash_spec.rb index 79ad454..4d75e67 100644 --- a/spec/rackstash/encoder/logstash_spec.rb +++ b/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 diff --git a/spec/rackstash/encoder/message_spec.rb b/spec/rackstash/encoder/message_spec.rb index 955f8ae..88bfb35 100644 --- a/spec/rackstash/encoder/message_spec.rb +++ b/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] line2\n" - ].join + '[2016-10-17T10:37:00.000000Z] line1', + '[2016-10-17T10:37:00.000000Z] line2' + ].join("\n") end it 'ignores missing fields' do - event = { 'message' => ["line1\n", "line2\n"] } - expect(encoder.encode(event)).to eql "line1\nline2\n" + event = { 'message' => ['line1', 'line2'] } + expect(encoder.encode(event)).to eql "line1\nline2" end it 'adds the prefix to a single string' do diff --git a/spec/rackstash/formatter_spec.rb b/spec/rackstash/formatter_spec.rb index de4e9fb..5bc9cc7 100644 --- a/spec/rackstash/formatter_spec.rb +++ b/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 diff --git a/spec/rackstash/logger_spec.rb b/spec/rackstash/logger_spec.rb index c3c3e0c..fd51bd2 100644 --- a/spec/rackstash/logger_spec.rb +++ b/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 diff --git a/spec/rackstash/rack/middleware_spec.rb b/spec/rackstash/rack/middleware_spec.rb index e315aef..257b5dc 100644 --- a/spec/rackstash/rack/middleware_spec.rb +++ b/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