diff --git a/README.md b/README.md index 2f84b991..e2454a11 100644 --- a/README.md +++ b/README.md @@ -122,15 +122,15 @@ logger.info("My log message") # My log message @metadata {"level": "info", "context": {...}} ``` -Timber will never deviate from the public `::Logger` interface in *any* way. +Timber will *never* deviate from the public `::Logger` interface in *any* way. ---

-
Tagging logs

+

Tagging

-Need a quick and easy way to identify a log? Use tags!: +Need a quick way to identify logs? Use tags!: ```ruby logger.info(message: "My log message", tag: "tag") @@ -156,8 +156,28 @@ end # My log message @metadata {"level": "info", "tags": ["tag"], "context": {...}} ``` +--- +

+
Timings & Durations

+ +Sometimes you need a quick way to add timings to log statements: + +```ruby +start = Time.now +# ...my code to time... +time_ms = (Time.now - start) * 1000 +logger.info(message: "Task complete", time_ms: time_ms) +``` + +* The `:time_ms` attribute is supported by Timber. If present, we will display it in the interface, etc. + +--- + +

+ +
Custom events

1. Log a structured Hash (simplest) diff --git a/lib/timber/log_entry.rb b/lib/timber/log_entry.rb index f9d90635..1d898fca 100644 --- a/lib/timber/log_entry.rb +++ b/lib/timber/log_entry.rb @@ -5,7 +5,7 @@ class LogEntry #:nodoc: DT_PRECISION = 6.freeze SCHEMA = "https://raw.githubusercontent.com/timberio/log-event-json-schema/1.2.3/schema.json".freeze - attr_reader :context_snapshot, :event, :level, :message, :progname, :tags, :time + attr_reader :context_snapshot, :event, :level, :message, :progname, :tags, :time, :time_ms # Creates a log entry suitable to be sent to the Timber API. # @param severity [Integer] the log level / severity @@ -17,12 +17,13 @@ class LogEntry #:nodoc: # @param event [Timber.Event] structured data representing the log line event. This should be # an instance of `Timber.Event`. # @return [LogEntry] the resulting LogEntry object - def initialize(level, time, progname, message, context_snapshot, event, tags) + def initialize(level, time, progname, message, context_snapshot, event, options = {}) @level = level @time = time.utc @progname = progname @message = message - @tags = tags + @tags = options[:tags] + @time_ms = options[:time_ms] context_snapshot = {} if context_snapshot.nil? system_context = Contexts::System.new(pid: Process.pid) @@ -34,7 +35,8 @@ def initialize(level, time, progname, message, context_snapshot, event, tags) def as_json(options = {}) options ||= {} - hash = {:level => level, :dt => formatted_dt, :message => message, :tags => tags} + hash = {:level => level, :dt => formatted_dt, :message => message, :tags => tags, + :time_ms => time_ms} if !event.nil? hash[:event] = event diff --git a/lib/timber/logger.rb b/lib/timber/logger.rb index 0e071377..f9e36224 100644 --- a/lib/timber/logger.rb +++ b/lib/timber/logger.rb @@ -76,15 +76,23 @@ class Formatter def build_log_entry(severity, time, progname, msg) level = SEVERITY_MAP.fetch(severity) context_snapshot = CurrentContext.instance.snapshot + tags = extract_active_support_tagged_logging_tags - tags += [msg.delete(:tag)] if msg.is_a?(Hash) && msg.key?(:tag) - tags += msg.delete(:tags) if msg.is_a?(Hash) && msg.key?(:tags) + time_ms = nil + if msg.is_a?(Hash) + tags << msg.delete(:tag) if msg.key?(:tag) + tags += msg.delete(:tags) if msg.key?(:tags) + time_ms = msg.delete(:time_ms) if msg.key?(:time_ms) + + msg = msg[:message] if msg.length == 1 + end + event = Events.build(msg) if event - LogEntry.new(level, time, progname, event.message, context_snapshot, event, tags) + LogEntry.new(level, time, progname, event.message, context_snapshot, event, tags: tags, time_ms: time_ms) else - LogEntry.new(level, time, progname, msg, context_snapshot, nil, tags) + LogEntry.new(level, time, progname, msg, context_snapshot, nil, tags: tags, time_ms: time_ms) end end diff --git a/spec/timber/logger_spec.rb b/spec/timber/logger_spec.rb index c69e58f0..c63d04be 100644 --- a/spec/timber/logger_spec.rb +++ b/spec/timber/logger_spec.rb @@ -57,6 +57,21 @@ expect(io.string).to include("\"event\":{\"server_side_app\":{\"sql_query\":{\"sql\":\"select * from users\",\"time_ms\":56.0}}}") end + it "should allow :time_ms" do + logger.info(message: "event complete", time_ms: 54.5) + expect(io.string).to include("\"time_ms\":54.5") + end + + it "should allow :tag" do + logger.info(message: "event complete", tag: "tag1") + expect(io.string).to include("\"tags\":[\"tag1\"]") + end + + it "should allow :tags" do + logger.info(message: "event complete", tags: ["tag1", "tag2"]) + expect(io.string).to include("\"tags\":[\"tag1\",\"tag2\"]") + end + it "should allow functions" do logger.info do {message: "payment rejected", payment_rejected: {customer_id: "abcde1234", amount: 100}}