Switch to @metadata

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.
 
 ---
 
 </p></details>
 
-<details><summary><strong>Tagging logs</strong></summary><p>
+<details><summary><strong>Tagging</strong></summary><p>
 
-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,30 @@ end
 # My log message @metadata {"level": "info", "tags": ["tag"], "context": {...}}
 ```
 
+---
+
+</p></details>
+
+<details><summary><strong>Timings & Durations</strong></summary><p>
+
+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)
+
+# 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.
+
+---
+
 </p></details>
 
+
 <details><summary><strong>Custom events</strong></summary><p>
 
 1. Log a structured Hash (simplest)
@@ -168,7 +190,8 @@ end
   # 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)
 

lib/timber/log_entry.rb

@@ -3,9 +3,9 @@ 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
+    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

lib/timber/logger.rb

@@ -76,15 +76,24 @@ 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)
+            tags.uniq!
+            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
 
@@ -104,10 +113,10 @@ def extract_active_support_tagged_logging_tags
     #
     # 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)

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
 

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

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,28 +46,43 @@
         message = {message: "payment rejected", payment_rejected: {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.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}}
         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
 

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_server_response":{"status":200,"time_ms":0.0}}}')
           end
         end

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
 

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

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

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