add metadata to log messages

Signed-off-by: Thom May <thom@chef.io>

8 files changed, 258 insertions, 51 deletions

diff --git a/lib/mixlib/log.rb b/lib/mixlib/log.rb
index c6dc839..2161568 100644
--- a/lib/mixlib/log.rb
+++ b/lib/mixlib/log.rb
@@ -20,15 +20,14 @@ require "logger"
 require "mixlib/log/version"
 require "mixlib/log/formatter"
 require "mixlib/log/child"
+require "mixlib/log/logging"
 
 module Mixlib
   module Log
 
+    include Logging
     @logger, @loggers = nil
 
-    LEVELS = { :debug => Logger::DEBUG, :info => Logger::INFO, :warn => Logger::WARN, :error => Logger::ERROR, :fatal => Logger::FATAL }.freeze
-    LEVEL_NAMES = LEVELS.invert.freeze
-
     def reset!
       close!
       @logger, @loggers = nil, nil
@@ -70,19 +69,6 @@ module Mixlib
       @configured = true
     end
 
-    def with_child
-      child = Child.new(self)
-      if block_given?
-        yield child
-      else
-        child
-      end
-    end
-
-    def pass(severity, args, progname = nil, &block)
-      add(severity, args, progname, &block)
-    end
-
     # Use Mixlib::Log.init when you want to set up the logger manually.  Arguments to this method
     # get passed directly to Logger.new, so check out the documentation for the standard Logger class
     # to understand what to do here.
@@ -97,6 +83,7 @@ module Mixlib
       @logger.level = Logger::WARN
       @configured = true
       @parent = nil
+      @metadata = {}
       @logger
     end
 
@@ -128,16 +115,6 @@ module Mixlib
       end
     end
 
-    # Define the standard logger methods on this class programmatically.
-    # No need to incur method_missing overhead on every log call.
-    [:debug, :info, :warn, :error, :fatal].each do |method_name|
-      class_eval(<<-METHOD_DEFN, __FILE__, __LINE__)
-        def #{method_name}(msg=nil, &block)
-          loggers.each {|l| l.#{method_name}(msg, &block) }
-        end
-      METHOD_DEFN
-    end
-
     # Define the methods to interrogate the logger for the current log level.
     # Note that we *only* query the default logger (@logger) and not any other
     # loggers that may have been added, even though it is possible to configure
@@ -154,8 +131,16 @@ module Mixlib
       loggers.each { |l| l << msg }
     end
 
-    def add(severity, message = nil, progname = nil, &block)
-      loggers.each { |l| l.add(severity, message, progname, &block) }
+    def add(severity, message = nil, progname = nil, data: {}, &block)
+      message, progname, data = yield if block_given?
+      data = metadata.merge(data) if data.kind_of?(Hash)
+      loggers.each do |l|
+        if l.respond_to?(:add_data)
+          l.add_data(severity, message, progname, data: data)
+        else
+          l.add(severity, message, progname)
+        end
+      end
     end
 
     alias :log :add
diff --git a/lib/mixlib/log/child.rb b/lib/mixlib/log/child.rb
index 2676b69..7234043 100644
--- a/lib/mixlib/log/child.rb
+++ b/lib/mixlib/log/child.rb
@@ -14,24 +14,23 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+require "mixlib/log/logging"
+
 module Mixlib
   module Log
     class Child
-      # include Mixlib::Log
+      include Mixlib::Log::Logging
 
       attr_reader :parent
-      def initialize(parent)
+      def initialize(parent, metadata = {})
         @parent = parent
+        @metadata = metadata
       end
 
       def level
         parent.level
       end
 
-      def pass(severity, args, progname = nil, &block)
-        parent.pass(severity, args, progname, &block)
-      end
-
       # Define the methods to interrogate the logger for the current log level.
       # Note that we *only* query the default logger (@logger) and not any other
       # loggers that may have been added, even though it is possible to configure
@@ -39,23 +38,14 @@ module Mixlib
       [:debug?, :info?, :warn?, :error?, :fatal?].each do |method_name|
         class_eval(<<-METHOD_DEFN, __FILE__, __LINE__)
           def #{method_name}
-            parent.#{method_name}
+            parent.send(:#{method_name})
           end
         METHOD_DEFN
       end
 
-      # Define the standard logger methods on this class programmatically.
-      # No need to incur method_missing overhead on every log call.
-      [:debug, :info, :warn, :error, :fatal].each do |method_name|
-        class_eval(<<-METHOD_DEFN, __FILE__, __LINE__)
-        def #{method_name}(msg=nil, &block)
-          pass(:#{method_name}, msg, &block)
-        end
-        METHOD_DEFN
-      end
-
-      def add(severity, message = nil, progname = nil, &block)
-        parent.pass(severity, message, progname, &block)
+      def add(severity, message = nil, progname = nil, data: {}, &block)
+        data = metadata.merge(data) if data.kind_of?(Hash)
+        parent.send(:pass, severity, message, progname, data: data, &block)
       end
 
     end
diff --git a/lib/mixlib/log/formatter.rb b/lib/mixlib/log/formatter.rb
index c8f1efa..1727452 100644
--- a/lib/mixlib/log/formatter.rb
+++ b/lib/mixlib/log/formatter.rb
@@ -42,15 +42,25 @@ module Mixlib
       # put through "object.inspect"
       def msg2str(msg)
         case msg
+        when ::Hash
+          if msg.has_key?(:err)
+            format_exception(msg[:err])
+          else
+            msg[:msg]
+          end
         when ::String
           msg
         when ::Exception
-          "#{msg.message} (#{msg.class})\n" <<
-            (msg.backtrace || []).join("\n")
+          format_exception(msg)
         else
           msg.inspect
         end
       end
+
+      def format_exception(msg)
+        "#{msg.message} (#{msg.class})\n" <<
+          (msg.backtrace || []).join("\n")
+      end
     end
   end
 end
diff --git a/lib/mixlib/log/logger.rb b/lib/mixlib/log/logger.rb
new file mode 100644
index 0000000..c97be8e
--- /dev/null
+++ b/lib/mixlib/log/logger.rb
@@ -0,0 +1,103 @@
+require "logger"
+
+# A subclass of Ruby's stdlib Logger with all the mutex and logrotation stuff
+# ripped out, and metadata added in.
+module Mixlib
+  module Log
+    class Logger < ::Logger
+
+      #
+      # === Synopsis
+      #
+      #   Logger.new(name, shift_age = 7, shift_size = 1048576)
+      #   Logger.new(name, shift_age = 'weekly')
+      #
+      # === Args
+      #
+      # +logdev+::
+      #   The log device.  This is a filename (String) or IO object (typically
+      #   +STDOUT+, +STDERR+, or an open file).
+      # +shift_age+::
+      #   Number of old log files to keep, *or* frequency of rotation (+daily+,
+      #   +weekly+ or +monthly+).
+      # +shift_size+::
+      #   Maximum logfile size (only applies when +shift_age+ is a number).
+      #
+      # === Description
+      #
+      # Create an instance.
+      #
+      def initialize(logdev)
+        @progname = nil
+        @level = DEBUG
+        @default_formatter = Formatter.new
+        @formatter = nil
+        @logdev = nil
+        if logdev
+          @logdev = LocklessLogDevice.new(logdev)
+        end
+      end
+
+      def add_data(severity, message, progname, data: {})
+        return true if @logdev.nil? || severity < @level
+        data ||= {}
+        if message.kind_of?(::Exception)
+          data[:err] = message
+        else
+          data[:msg] = message
+        end
+        @logdev.write(
+          format_message(format_severity(severity), Time.now, progname, data))
+        true
+      end
+
+      class LocklessLogDevice < LogDevice
+
+        def initialize(log = nil)
+          @dev = @filename = @shift_age = @shift_size = nil
+          if log.respond_to?(:write) && log.respond_to?(:close)
+            @dev = log
+          else
+            @dev = open_logfile(log)
+            @filename = log
+          end
+          @dev.sync = true
+        end
+
+        def write(message)
+          @dev.write(message)
+        rescue Exception => ignored
+          warn("log writing failed. #{ignored}")
+        end
+
+        def close
+          @dev.close rescue nil
+        end
+
+        private
+
+        def open_logfile(filename)
+          if FileTest.exist?(filename)
+            open(filename, (File::WRONLY | File::APPEND))
+          else
+            create_logfile(filename)
+          end
+        end
+
+        def create_logfile(filename)
+          logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT))
+          add_log_header(logdev)
+          logdev
+        end
+
+        def add_log_header(file)
+          file.write(
+            "# Logfile created on %s by %s\n" % [Time.now.to_s, Logger::ProgName]
+          )
+        end
+
+      end
+
+    end
+  end
+end
diff --git a/lib/mixlib/log/logging.rb b/lib/mixlib/log/logging.rb
new file mode 100644
index 0000000..0e8aed9
--- /dev/null
+++ b/lib/mixlib/log/logging.rb
@@ -0,0 +1,56 @@
+#
+# Copyright:: Copyright (c) 2018 Chef Software, Inc.
+# License:: Apache License, Version 2.0
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+require "logger"
+require "mixlib/log/child"
+
+module Mixlib
+  module Log
+    module Logging
+
+      LEVELS = { :debug => Logger::DEBUG, :info => Logger::INFO, :warn => Logger::WARN, :error => Logger::ERROR, :fatal => Logger::FATAL }.freeze
+      LEVEL_NAMES = LEVELS.invert.freeze
+
+      attr_accessor :metadata
+
+      def pass(severity, args, progname = nil, data: {}, &block)
+        args, progname, data = yield if block_given?
+        add(severity, args, progname, data: data)
+      end
+
+      # Define the standard logger methods on this class programmatically.
+      # No need to incur method_missing overhead on every log call.
+      [:debug, :info, :warn, :error, :fatal].each do |method_name|
+        level = LEVELS[method_name]
+        class_eval(<<-METHOD_DEFN, __FILE__, __LINE__)
+        def #{method_name}(msg=nil, data: {}, &block)
+          pass(#{level}, msg, data: data, &block)
+        end
+        METHOD_DEFN
+      end
+
+      def with_child(metadata = {})
+        child = Child.new(self, metadata)
+        if block_given?
+          yield child
+        else
+          child
+        end
+      end
+
+    end
+  end
+end
diff --git a/spec/mixlib/log/child_spec.rb b/spec/mixlib/log/child_spec.rb
index daf3734..eef2ce9 100644
--- a/spec/mixlib/log/child_spec.rb
+++ b/spec/mixlib/log/child_spec.rb
@@ -39,10 +39,49 @@ RSpec.describe Mixlib::Log::Child do
     expect(io.string).to match(/a message$/)
   end
 
+  context "with structured data" do
+    it "can be created with metadata" do
+      expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true" })
+      Logit.with_child({ child: "true" }) { |l| l.warn("a message") }
+    end
+
+    it "a message can be logged" do
+      expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true" })
+      Logit.with_child { |l| l.warn("a message", data: { child: "true" }) }
+    end
+
+    context "merges properly" do
+      it "in the simple case" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", meta: "data" })
+        Logit.with_child(meta: "data") { |l| l.warn("a message", data: { child: "true" }) }
+      end
+
+      it "when overwriting" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", meta: "overwritten" })
+        Logit.with_child(meta: "data") { |l| l.warn("a message", data: { child: "true", meta: "overwritten" }) }
+      end
+    end
+
+    context "when receiving a message from a child" do
+      it "passes data on" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", parent: "first" })
+        child.metadata = { parent: "first" }
+        child.with_child { |l| l.warn("a message", data: { child: "true" }) }
+      end
+
+      it "merges its own data" do
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[:warn], "a message", nil, data: { child: "true", parent: "second" })
+        child.metadata = { parent: "first" }
+        child.with_child { |l| l.warn("a message", data: { child: "true", parent: "second" }) }
+      end
+    end
+  end
+
   context "sends a message to the parent" do
     %i{ debug info warn error fatal }.each do |level|
       it "at #{level}" do
-        expect(Logit).to receive(:pass).with(level, "a #{level} message", nil)
+        expect(Logit).to receive(:pass).with(Mixlib::Log::LEVELS[level], "a #{level} message", nil, data: {})
+        Logit.level = level
         child.send(level, "a #{level} message")
       end
     end
diff --git a/spec/mixlib/log/formatter_spec.rb b/spec/mixlib/log/formatter_spec.rb
index dd3ce25..16e45af 100644
--- a/spec/mixlib/log/formatter_spec.rb
+++ b/spec/mixlib/log/formatter_spec.rb
@@ -48,4 +48,17 @@ RSpec.describe Mixlib::Log::Formatter do
     expect(@formatter.call("monkey", Time.new, "test", "mos def")).to eq("monkey: mos def\n")
   end
 
+  context "with structured data" do
+    let(:data) { {} }
+
+    it "should format a message" do
+      data[:msg] = "nuthin new"
+      expect(@formatter.msg2str(data)).to eq("nuthin new")
+    end
+
+    it "should format an exception" do
+      data[:err] = IOError.new("legendary roots crew")
+      expect(@formatter.msg2str(data)).to eq("legendary roots crew (IOError)\n")
+    end
+  end
 end
diff --git a/spec/mixlib/log_spec.rb b/spec/mixlib/log_spec.rb
index 69eebd5..ac4932d 100644
--- a/spec/mixlib/log_spec.rb
+++ b/spec/mixlib/log_spec.rb
@@ -23,9 +23,19 @@ require "spec_helper"
 
 class LoggerLike
   attr_accessor :level
-  attr_reader :messages
+  attr_reader :messages, :data
   def initialize
     @messages = ""
+    @data = []
+  end
+
+  def add_data(severity, message = nil, progname = nil, data: {})
+    @messages << message
+    @data << data
+  end
+
+  def add(severity, message = nil, progname = nil, data: {})
+    @messages << message
   end
 
   [:debug, :info, :warn, :error, :fatal].each do |method_name|
@@ -64,6 +74,7 @@ RSpec.describe Mixlib::Log do
   it "uses the logger provided when initialized with a logger like object" do
     logger = LoggerLike.new
     Logit.init(logger)
+    Logit.level = :debug
     Logit.debug "qux"
     expect(logger.messages).to match(/qux/)
   end