Permalink
Browse files

[logging] Refactor formatter, encode user supplied data as ascii

The purpose of this diff is twofold (and could arguably be split into two diffs).
Firstly, the delimited formatter was needlessly complex. This refactors it into a
much simpler implementation. Secondly, the newline escaping regex throws exceptions
when the string attempting to be escaped contains invalid characters for its
encoding. While this behavior is technically correct, it is undesirable. We avoid it
by first converting the user supplied data to ASCII, rreplacing any invalid or
undefined characters with a '?'.

Test plan:
- All spec tests pass.
- Tested on my deployment.

Change-Id: I2547b74005c2a0ebcf0c6f0caeb84775e23f946f
  • Loading branch information...
1 parent 23c0a80 commit 377cae3c1ff3d44bd25662e75c3280960987b8ce mpage committed Mar 1, 2012
@@ -9,24 +9,7 @@
module VCAP
module Logging
- FORMATTER = VCAP::Logging::Formatter::DelimitedFormatter.new do
-
- if defined?(RUBY_VERSION) && RUBY_VERSION >= "1.9.2"
- timestamp '[%F %T.%6N]'
- else
- # Time#strftime on 1.8 doesn't do fractional seconds
- timestamp '[%F %T]'
- end
-
- logger_name
- tags
- process_id
- thread_shortid
- fiber_shortid
- log_level
- text '--'
- data
- end
+ FORMATTER = VCAP::Logging::Formatter::DelimitedFormatter.new
LOG_LEVELS = {
:off => 0,
@@ -6,97 +6,58 @@ module VCAP::Logging::Formatter
# A formatter for creating messages delimited by a given value (e.g. space separated logs)
class DelimitedFormatter < BaseFormatter
- DEFAULT_DELIMITER = ' '
+ DEFAULT_DELIMITER = ' '
- if defined?(RUBY_VERSION) && RUBY_VERSION >= "1.9.2"
- DEFAULT_TIMESTAMP_FORMAT = '%F %T.%6N %z' # YYYY-MM-DD HH:MM:SS.NNNNNN TZ
- else
- # Time#strftime on 1.8 doesn't do fractional seconds
- DEFAULT_TIMESTAMP_FORMAT = '%F %T %z' # YYYY-MM-DD HH:MM:SS TZ
- end
-
- # This provides a tiny DSL for constructing the formatting function. We opt
- # to define the method inline in order to avoid incurring multiple method calls
- # per call to format_record().
- #
- # Usage:
- #
- # formatter = VCAP::Logging::Formatter::DelimitedFormatter.new do
- # timestamp '%s'
- # log_level
- # data
- # end
- #
- # @param delim String Delimiter that will separate fields in the message
- # @param Block Block that defines the log message format
- def initialize(delim=DEFAULT_DELIMITER, &blk)
- @exprs = []
-
- # Collect the expressions we want to use when constructing messages in the
- # order that they should appear.
- instance_eval(&blk)
-
- # Build the format string to that will generate the message along with
- # the arguments
- fmt_chars = @exprs.map {|e| e[0] }
- fmt = fmt_chars.join(delim) + "\n"
- fmt_args = @exprs.map {|e| e[1] }.join(', ')
-
- instance_eval("def format_record(log_record); '#{fmt}' % [#{fmt_args}]; end")
- end
+ attr_reader :timestamp_fmt
- private
-
- def log_level
- @exprs << ['%6s', "log_record.log_level.to_s.upcase"]
- end
-
- def data
- # Not sure of a better way to do this...
- # If we are given an exception, include the class name, string representation, and stacktrace
- snippet = "(log_record.data.kind_of?(Exception) ? " \
- + "log_record.data.class.to_s + '(\"' + log_record.data.to_s + '\", [' + (log_record.data.backtrace ? log_record.data.backtrace.join(',') : '') + '])'" \
- + ": log_record.data.to_s" \
- + ").gsub(/\n/, '\\n')"
- @exprs << ['%s', snippet]
+ def initialize(delim=DEFAULT_DELIMITER)
+ @delim = delim
+ if defined?(RUBY_VERSION) && RUBY_VERSION >= "1.9.2"
+ @timestamp_fmt = '[%F %T.%6N]'
+ else
+ # Time#strftime on 1.8 doesn't do fractional seconds
+ @timestamp_fmt = '[%F %T]'
+ end
end
- def tags
- @exprs << ['%s', "log_record.tags.empty? ? '-': log_record.tags.join(',')"]
- end
+ def format_record(log_record)
+ line = [
+ log_record.timestamp.strftime(@timestamp_fmt), # Timestamp
+ log_record.logger_name, # Logger name
+ log_record.tags.empty? ? '-' : log_record.tags.join(','), # Tags
+ "pid=" + log_record.process_id.to_s, # Process id
+ "tid=" + log_record.thread_shortid.to_s, # Thread id
+ "fid=" + log_record.fiber_shortid.to_s, # Fiber id
+ "%6s" % [log_record.log_level.to_s.upcase], # Log level
+ "--", # Separator
+ format_data(log_record.data)].join(@delim)
- def fiber_id
- @exprs << ['%s', "log_record.fiber_id"]
+ line.gsub(/\n/, '\\n') + "\n"
end
- def fiber_shortid
- @exprs << ['%s', "log_record.fiber_shortid"]
- end
- def process_id
- @exprs << ['%s', "log_record.process_id"]
- end
-
- def thread_id
- @exprs << ['%s', "log_record.thread_id"]
- end
-
- def thread_shortid
- @exprs << ['%s', "log_record.thread_shortid"]
- end
-
- def timestamp(fmt=DEFAULT_TIMESTAMP_FORMAT)
- @exprs << ['%s', "log_record.timestamp.strftime('#{fmt}')"]
- end
-
- def logger_name
- @exprs << ['%s', "log_record.logger_name"]
- end
+ private
- def text(str)
- @exprs << ['%s', "'#{str}'"]
+ def format_data(data)
+ # Include the class name, message, and backtrace if the supplied datum
+ # is an exception.
+ formatted_data = nil
+ if data.kind_of?(Exception)
+ formatted_data = data.class.to_s + "<<" + data.to_s + ":"
+ if backtrace = data.backtrace
+ formatted_data += backtrace.join(',')
+ end
+ formatted_data += ">>"
+ else
+ # Replace invalid and undefined byte sequences so that any subsequent
+ # string operations don't fail with 'invalid byte sequence...'
+ formatted_data = data.to_s.encode('ASCII',
+ :invalid => :replace,
+ :undef => :replace)
+ end
+
+ formatted_data
end
-
end
end
@@ -1,5 +1,5 @@
module VCAP
module Logging
- VERSION = '0.1.6'
+ VERSION = '1.0.0'
end
end
Binary file not shown.
@@ -1,44 +1,46 @@
+# encoding: utf-8
require File.join(File.dirname(__FILE__), '..', 'spec_helper')
-describe VCAP::Logging::Formatter::DelimitedFormatter do
- describe '#initialize' do
-
- it 'should define a format_record' do
- fmt = VCAP::Logging::Formatter::DelimitedFormatter.new {}
- fmt.respond_to?(:format_record).should be_true
- end
- end
+describe VCAP::Logging::Formatter::DelimitedFormatter do
+ let(:logger) { VCAP::Logging::Logger.new('foo', nil) }
+ let(:formatter) { VCAP::Logging::Formatter::DelimitedFormatter.new('.') }
describe '#format_record' do
it 'should return a correctly formatted message' do
- rec = VCAP::Logging::LogRecord.new(:debug, 'foo', VCAP::Logging::Logger.new('foo', nil), ['bar', 'baz'])
- fmt = VCAP::Logging::Formatter::DelimitedFormatter.new('.') do
- timestamp '%s'
- log_level
- tags
- process_id
- thread_id
- data
- end
-
- fmt.format_record(rec).should == [rec.timestamp.strftime('%s'), ' DEBUG', 'bar,baz', rec.process_id.to_s, rec.thread_id.to_s, 'foo'].join('.') + "\n"
+ rec = VCAP::Logging::LogRecord.new(:debug, 'foo', logger, ['bar', 'baz'])
+ line = [rec.timestamp.strftime(formatter.timestamp_fmt),
+ logger.name,
+ 'bar,baz',
+ 'pid=' + rec.process_id.to_s,
+ 'tid=' + rec.thread_shortid.to_s,
+ 'fid=' + rec.fiber_shortid.to_s,
+ ' DEBUG',
+ '--',
+ 'foo'].join('.') + "\n"
+ formatter.format_record(rec).should == line
end
it 'should encode newlines' do
- rec = VCAP::Logging::LogRecord.new(:debug, "test\ning123\n\n", VCAP::Logging::Logger.new('foo', nil), [])
- fmt = VCAP::Logging::Formatter::DelimitedFormatter.new('.') { data }
- fmt.format_record(rec).should == "test\\ning123\\n\\n\n"
+ rec = VCAP::Logging::LogRecord.new(:debug, "test\ning123\n\n", logger)
+ formatter.format_record(rec).should match(/test\\ning123\\n\\n\n/)
end
it 'should format exceptions' do
begin
raise StandardError, "Testing 123"
- rescue => exc
+ rescue => e
end
- rec = VCAP::Logging::LogRecord.new(:error, exc, VCAP::Logging::Logger.new('foo', nil), [])
- fmt = VCAP::Logging::Formatter::DelimitedFormatter.new('.') { data }
- fmt.format_record(rec).should == "StandardError(\"Testing 123\", [#{exc.backtrace.join(',')}])\n"
+ rec = VCAP::Logging::LogRecord.new(:error, e, logger)
+ bt_str = e.backtrace.join(',')
+ match_regex = /StandardError<<Testing 123:/
+ formatter.format_record(rec).should match(match_regex)
end
end
+
+ it 'should convert data to ascii' do
+ data = "HI\u2600"
+ rec = VCAP::Logging::LogRecord.new(:error, data, logger)
+ formatter.format_record(rec).should match(/HI\?\n$/)
+ end
end

0 comments on commit 377cae3

Please sign in to comment.