From 62c75ad1affed687dbcbf3428b4565eca9e37e1c Mon Sep 17 00:00:00 2001
From: Ben Johnson
+
-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": {...}}
```
+---
+
+
+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.
+
+---
+
+
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}}
Tagging
Timings & Durations
Custom events