From d65373d811a690c8e5face478e8b61693a99a1b8 Mon Sep 17 00:00:00 2001 From: Ben Johnson Date: Sat, 18 Feb 2017 17:36:39 -0600 Subject: [PATCH 1/7] Switch to @metadata --- lib/timber/logger.rb | 4 ++-- spec/timber/logger_spec.rb | 12 ++++++------ .../probes/action_controller_log_subscriber_spec.rb | 4 ++-- .../probes/action_dispatch_debug_exceptions_spec.rb | 2 +- .../timber/probes/action_view_log_subscriber_spec.rb | 2 +- .../probes/active_record_log_subscriber_spec.rb | 4 ++-- spec/timber/probes/rails_rack_logger_spec.rb | 2 +- 7 files changed, 15 insertions(+), 15 deletions(-) diff --git a/lib/timber/logger.rb b/lib/timber/logger.rb index c303893a..a915a75e 100644 --- a/lib/timber/logger.rb +++ b/lib/timber/logger.rb @@ -93,10 +93,10 @@ def build_log_entry(severity, time, progname, msg) # # Example message: # - # My log message @timber.io {"level":"info","dt":"2016-09-01T07:00:00.000000-05:00"} + # My log message @metadata {"level":"info","dt":"2016-09-01T07:00:00.000000-05:00"} # class HybridFormatter < Formatter - METADATA_CALLOUT = "@timber.io".freeze + METADATA_CALLOUT = "@metadata".freeze def call(severity, time, progname, msg) log_entry = build_log_entry(severity, time, progname, msg) diff --git a/spec/timber/logger_spec.rb b/spec/timber/logger_spec.rb index ba61a7de..c9e78ee1 100644 --- a/spec/timber/logger_spec.rb +++ b/spec/timber/logger_spec.rb @@ -15,7 +15,7 @@ it "should accept strings" do logger.info("this is a test") - expect(io.string).to start_with("this is a test @timber.io {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") + expect(io.string).to start_with("this is a test @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") end context "with a context" do @@ -37,7 +37,7 @@ it "should snapshot and include the context" do expect(Timber::CurrentContext.instance).to receive(:snapshot).and_call_original logger.info("this is a test") - expect(io.string).to start_with("this is a test @timber.io {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") + expect(io.string).to start_with("this is a test @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") expect(io.string).to include("\"http\":{\"method\":\"POST\",\"path\":\"/checkout\",\"remote_addr\":\"123.456.789.10\",\"request_id\":\"abcd1234\"}") end end @@ -46,14 +46,14 @@ message = {message: "payment rejected", type: :payment_rejected, data: {customer_id: "abcde1234", amount: 100}} expect(Timber::Events).to receive(:build).with(message).and_call_original logger.info(message) - expect(io.string).to start_with("payment rejected @timber.io {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") + expect(io.string).to start_with("payment rejected @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") expect(io.string).to include("\"event\":{\"server_side_app\":{\"custom\":{\"payment_rejected\":{\"customer_id\":\"abcde1234\",\"amount\":100}}}}") end it "should log properly when an event is passed" do message = Timber::Events::SQLQuery.new(sql: "select * from users", time_ms: 56, message: "select * from users") logger.info(message) - expect(io.string).to start_with("select * from users @timber.io {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") + expect(io.string).to start_with("select * from users @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") expect(io.string).to include("\"event\":{\"server_side_app\":{\"sql_query\":{\"sql\":\"select * from users\",\"time_ms\":56}}}") end @@ -61,13 +61,13 @@ logger.info do {message: "payment rejected", type: :payment_rejected, data: {customer_id: "abcde1234", amount: 100}} end - expect(io.string).to start_with("payment rejected @timber.io {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") + expect(io.string).to start_with("payment rejected @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") expect(io.string).to include("\"event\":{\"server_side_app\":{\"custom\":{\"payment_rejected\":{\"customer_id\":\"abcde1234\",\"amount\":100}}}}") end it "should escape new lines" do logger.info "first\nsecond" - expect(io.string).to start_with("first\\nsecond @timber.io") + expect(io.string).to start_with("first\\nsecond @metadata") end end diff --git a/spec/timber/probes/action_controller_log_subscriber_spec.rb b/spec/timber/probes/action_controller_log_subscriber_spec.rb index 75334d9e..8c46a878 100644 --- a/spec/timber/probes/action_controller_log_subscriber_spec.rb +++ b/spec/timber/probes/action_controller_log_subscriber_spec.rb @@ -57,9 +57,9 @@ def method_for_action(action_name) dispatch_rails_request("/log_subscriber") lines = io.string.split("\n") expect(lines.length).to eq(2) - expect(lines[0]).to start_with('Processing by LogSubscriberController#index as HTML @timber.io {"level":"info","dt":"2016-09-01T12:00:00.000000Z"') + expect(lines[0]).to start_with('Processing by LogSubscriberController#index as HTML @metadata {"level":"info","dt":"2016-09-01T12:00:00.000000Z"') expect(lines[0]).to include('"event":{"server_side_app":{"controller_call":{"controller":"LogSubscriberController","action":"index"}}}') - expect(lines[1]).to start_with('Completed 200 OK in 0.0ms (Views: 1.0ms) @timber.io {"level":"info","dt":"2016-09-01T12:00:00.000000Z"') + expect(lines[1]).to start_with('Completed 200 OK in 0.0ms (Views: 1.0ms) @metadata {"level":"info","dt":"2016-09-01T12:00:00.000000Z"') expect(lines[1]).to include('"event":{"server_side_app":{"http_response":{"status":200,"time_ms":0.0}}}') end end diff --git a/spec/timber/probes/action_dispatch_debug_exceptions_spec.rb b/spec/timber/probes/action_dispatch_debug_exceptions_spec.rb index 7c400508..cd046e6f 100644 --- a/spec/timber/probes/action_dispatch_debug_exceptions_spec.rb +++ b/spec/timber/probes/action_dispatch_debug_exceptions_spec.rb @@ -38,7 +38,7 @@ def method_for_action(action_name) dispatch_rails_request("/exception") # Because constantly updating the line numbers sucks :/ expect(io.string).to include("RuntimeError (boom):\\n\\n") - expect(io.string).to include("@timber.io") + expect(io.string).to include("@metadata") expect(io.string).to include("\"event\":{\"server_side_app\":{\"exception\":{\"name\":\"RuntimeError\",\"message\":\"boom\",\"backtrace\":[\"") end diff --git a/spec/timber/probes/action_view_log_subscriber_spec.rb b/spec/timber/probes/action_view_log_subscriber_spec.rb index b207c4e7..bdf0b0e4 100644 --- a/spec/timber/probes/action_view_log_subscriber_spec.rb +++ b/spec/timber/probes/action_view_log_subscriber_spec.rb @@ -51,7 +51,7 @@ def method_for_action(action_name) it "should log the controller call event" do allow_any_instance_of(Timber::Probes::ActionViewLogSubscriber::LogSubscriber).to receive(:logger).and_return(logger) dispatch_rails_request("/action_view_log_subscriber") - expect(io.string).to start_with(" Rendered spec/support/rails/templates/template.html (0.0ms) @timber.io {\"level\":\"info\"") + expect(io.string).to start_with(" Rendered spec/support/rails/templates/template.html (0.0ms) @metadata {\"level\":\"info\"") expect(io.string).to include("\"event\":{\"server_side_app\":{\"template_render\":{\"name\":\"spec/support/rails/templates/template.html\",\"time_ms\":0.0}}},") end end diff --git a/spec/timber/probes/active_record_log_subscriber_spec.rb b/spec/timber/probes/active_record_log_subscriber_spec.rb index 834627ef..d7b0ecfb 100644 --- a/spec/timber/probes/active_record_log_subscriber_spec.rb +++ b/spec/timber/probes/active_record_log_subscriber_spec.rb @@ -36,12 +36,12 @@ it "should log the sql query" do User.order("users.id DESC").all.collect # collect kicks the sql because it is lazily executed - message = " \e[1m\e[36mUser Load (0.0ms)\e[0m \e[1m\e[34mSELECT \"users\".* FROM \"users\" ORDER BY users.id DESC\e[0m @timber.io {\"level\":\"debug\",\"dt\":\"2016-09-01T12:00:00.000000Z\",\"event\":{\"sql_query\":{\"sql\":\"SELECT \\\"users\\\".* FROM \\\"users\\\" ORDER BY users.id DESC\",\"time_ms\":0.0}}}\n" + message = " \e[1m\e[36mUser Load (0.0ms)\e[0m \e[1m\e[34mSELECT \"users\".* FROM \"users\" ORDER BY users.id DESC\e[0m @metadata {\"level\":\"debug\",\"dt\":\"2016-09-01T12:00:00.000000Z\",\"event\":{\"sql_query\":{\"sql\":\"SELECT \\\"users\\\".* FROM \\\"users\\\" ORDER BY users.id DESC\",\"time_ms\":0.0}}}\n" # Rails 4.X adds random spaces :/ string = io.string.gsub(" ORDER BY", " ORDER BY") string = string.gsub(" ORDER BY", " ORDER BY") expect(string).to include("users.id DESC") - expect(string).to include("@timber.io") + expect(string).to include("@metadata") expect(string).to include("\"level\":\"debug\"") expect(string).to include("\"sql\":") end diff --git a/spec/timber/probes/rails_rack_logger_spec.rb b/spec/timber/probes/rails_rack_logger_spec.rb index 30b66bb4..975a4b28 100644 --- a/spec/timber/probes/rails_rack_logger_spec.rb +++ b/spec/timber/probes/rails_rack_logger_spec.rb @@ -38,7 +38,7 @@ def method_for_action(action_name) allow(::Rails).to receive(:logger).and_return(logger) # Rails 3.2.X allow_any_instance_of(::Rails::Rack::Logger).to receive(:logger).and_return(logger) dispatch_rails_request("/rails_rack_logger") - expect(io.string).to start_with("Started GET \"/rails_rack_logger\" for 123.456.789.10 @timber.io {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") + expect(io.string).to start_with("Started GET \"/rails_rack_logger\" for 123.456.789.10 @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") expect(io.string).to include("\"event\":{\"server_side_app\":{\"http_request\":{\"host\":\"example.org\",\"method\":\"GET\",\"path\":\"/rails_rack_logger\",\"port\":80,\"headers\":{\"remote_addr\":\"123.456.789.10\",\"request_id\":\"unique-request-id-1234\"}}}") end end From 62c75ad1affed687dbcbf3428b4565eca9e37e1c Mon Sep 17 00:00:00 2001 From: Ben Johnson Date: Sun, 19 Feb 2017 09:57:36 -0600 Subject: [PATCH 2/7] Support :time_ms --- README.md | 26 +++++++++++++++++++++++--- lib/timber/log_entry.rb | 10 ++++++---- lib/timber/logger.rb | 16 ++++++++++++---- spec/timber/logger_spec.rb | 15 +++++++++++++++ 4 files changed, 56 insertions(+), 11 deletions(-) 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}} From 896753fb3408f7729e9a330d3318fa2d2894ff9d Mon Sep 17 00:00:00 2001 From: Ben Johnson Date: Sun, 19 Feb 2017 10:00:07 -0600 Subject: [PATCH 3/7] Update Readme --- README.md | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index e2454a11..5a5875fb 100644 --- a/README.md +++ b/README.md @@ -160,7 +160,7 @@ end

-
Timings & Durations

+

Timings & Performance Tracking

Sometimes you need a quick way to add timings to log statements: @@ -188,7 +188,8 @@ logger.info(message: "Task complete", time_ms: time_ms) # Payment rejected @metadata {"level": "warn", "event": {"payment_rejected": {"customer_id": "abcd1234", "amount": 100, "reason": "Card expired"}}, "context": {...}} ``` - * The hash can *only* have a `:message` and "event type" key, where `:payment_rejected` is the event type in the above example. + * The hash can *only* have 2 keys: `:message` and "event type" key; `:payment_rejected` in this example. + * Timber will keyspace your event data by the event type key passed. 2. Log a Struct (recommended) From 6049ccae74016eb310a9ba7f494a65ef7e6909dc Mon Sep 17 00:00:00 2001 From: Ben Johnson Date: Sun, 19 Feb 2017 10:06:04 -0600 Subject: [PATCH 4/7] Update readme --- README.md | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index 5a5875fb..cbea9938 100644 --- a/README.md +++ b/README.md @@ -160,7 +160,7 @@ end

-
Timings & Performance Tracking

+

Timings & Durations

Sometimes you need a quick way to add timings to log statements: @@ -169,6 +169,8 @@ start = Time.now # ...my code to time... time_ms = (Time.now - start) * 1000 logger.info(message: "Task complete", time_ms: time_ms) + +# My log message @metadata {"level": "info", "time_ms": 54.2132, "context": {...}} ``` * The `:time_ms` attribute is supported by Timber. If present, we will display it in the interface, etc. From c4667cc6991088a1651f91adc5ab2968b96db96a Mon Sep 17 00:00:00 2001 From: Ben Johnson Date: Sun, 19 Feb 2017 10:15:07 -0600 Subject: [PATCH 5/7] Bump schema version --- lib/timber/log_entry.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/timber/log_entry.rb b/lib/timber/log_entry.rb index 1d898fca..cb1d35c6 100644 --- a/lib/timber/log_entry.rb +++ b/lib/timber/log_entry.rb @@ -3,7 +3,7 @@ module Timber # `Logger` and the log device that you set it up with. class LogEntry #:nodoc: DT_PRECISION = 6.freeze - SCHEMA = "https://raw.githubusercontent.com/timberio/log-event-json-schema/1.2.3/schema.json".freeze + SCHEMA = "https://raw.githubusercontent.com/timberio/log-event-json-schema/1.2.4/schema.json".freeze attr_reader :context_snapshot, :event, :level, :message, :progname, :tags, :time, :time_ms From 70c34c3a48fd5d93b2834fb45238c3e759a96a31 Mon Sep 17 00:00:00 2001 From: Ben Johnson Date: Sun, 19 Feb 2017 10:29:56 -0600 Subject: [PATCH 6/7] Fix tests --- spec/timber/log_devices/http_spec.rb | 8 ++++---- spec/timber/log_entry_spec.rb | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/spec/timber/log_devices/http_spec.rb b/spec/timber/log_devices/http_spec.rb index 9837e13f..64de9697 100644 --- a/spec/timber/log_devices/http_spec.rb +++ b/spec/timber/log_devices/http_spec.rb @@ -58,9 +58,9 @@ it "should add a request to the queue" do http = described_class.new("MYKEY", threads: false) - log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 1", nil, nil, []) + log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 1", nil, nil) http.write(log_entry) - log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 2", nil, nil, []) + log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 2", nil, nil) http.write(log_entry) http.send(:flush) request_queue = http.instance_variable_get(:@request_queue) @@ -109,9 +109,9 @@ to_return(:status => 200, :body => "", :headers => {}) http = described_class.new("MYKEY", flush_interval: 0.1) - log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 1", nil, nil, []) + log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 1", nil, nil) http.write(log_entry) - log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 2", nil, nil, []) + log_entry = Timber::LogEntry.new("INFO", time, nil, "test log message 2", nil, nil) http.write(log_entry) sleep 0.3 diff --git a/spec/timber/log_entry_spec.rb b/spec/timber/log_entry_spec.rb index 9fb1743f..e4ff86d6 100644 --- a/spec/timber/log_entry_spec.rb +++ b/spec/timber/log_entry_spec.rb @@ -7,7 +7,7 @@ it "should encode properly with an event and context" do event = Timber::Events::Custom.new(type: :event_type, message: "event_message", data: {a: 1}) context = {custom: Timber::Contexts::Custom.new(type: :context_type, data: {b: 1})} - log_entry = described_class.new("INFO", time, nil, "log message", context, event, []) + log_entry = described_class.new("INFO", time, nil, "log message", context, event) msgpack = log_entry.to_msgpack expect(msgpack).to start_with("\x86\xA5level\xA4INFO\xA2dt\xBB2016-09-01T12:00:00.000000Z".force_encoding("ASCII-8BIT")) end From 9a288644081851eb023e93413a34a6169e89ccd2 Mon Sep 17 00:00:00 2001 From: Ben Johnson Date: Sun, 19 Feb 2017 10:46:01 -0600 Subject: [PATCH 7/7] Make tags unique --- lib/timber/logger.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/timber/logger.rb b/lib/timber/logger.rb index f9e36224..b4d4ee5b 100644 --- a/lib/timber/logger.rb +++ b/lib/timber/logger.rb @@ -82,6 +82,7 @@ def build_log_entry(severity, time, progname, msg) if msg.is_a?(Hash) tags << msg.delete(:tag) if msg.key?(:tag) tags += msg.delete(:tags) if msg.key?(:tags) + tags.uniq! time_ms = msg.delete(:time_ms) if msg.key?(:time_ms) msg = msg[:message] if msg.length == 1