Merge pull request #30 from chef/tm/slog

Structured Logging

9 files changed, 405 insertions, 45 deletions

diff --git a/.travis.yml b/.travis.yml
index 4dc0d1a..64cc679 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -2,14 +2,10 @@ language: ruby
 cache: bundler
 sudo: false
 rvm:
-  - 2.2.6
-  - 2.3.3
-  - 2.4.0
+  - 2.4.3
+  - 2.5.0
 branches:
   only:
     - master
-before_install:
-  - bundle --version
-  - gem update --system
 script:
   - bundle exec rake
diff --git a/lib/mixlib/log.rb b/lib/mixlib/log.rb
index 7152a90..7193583 100644
--- a/lib/mixlib/log.rb
+++ b/lib/mixlib/log.rb
@@ -19,15 +19,15 @@
 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
@@ -82,6 +82,8 @@ module Mixlib
       @logger.formatter = Mixlib::Log::Formatter.new() if @logger.respond_to?(:formatter=)
       @logger.level = Logger::WARN
       @configured = true
+      @parent = nil
+      @metadata = {}
       @logger
     end
 
@@ -92,6 +94,7 @@ module Mixlib
 
     # Sets the level for the Logger object by symbol.  Valid arguments are:
     #
+    #  :trace
     #  :debug
     #  :info
     #  :warn
@@ -101,7 +104,7 @@ module Mixlib
     # Throws an ArgumentError if you feed it a bogus log level.
     def level=(new_level)
       level_int = LEVEL_NAMES.key?(new_level) ? new_level : LEVELS[new_level]
-      raise ArgumentError, "Log level must be one of :debug, :info, :warn, :error, or :fatal" if level_int.nil?
+      raise ArgumentError, "Log level must be one of :trace, :debug, :info, :warn, :error, or :fatal" if level_int.nil?
       loggers.each { |l| l.level = level_int }
     end
 
@@ -113,38 +116,45 @@ 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
     # two (or more) loggers at different log levels.
-    [:debug?, :info?, :warn?, :error?, :fatal?].each do |method_name|
-      class_eval(<<-METHOD_DEFN, __FILE__, __LINE__)
-        def #{method_name}
-          logger.#{method_name}
-        end
-      METHOD_DEFN
+    [:trace?, :debug?, :info?, :warn?, :error?, :fatal?].each do |method_name|
+      define_method(method_name) do
+        logger.send(method_name)
+      end
     end
 
     def <<(msg)
       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 metadata.kind_of?(Hash) && data.kind_of?(Hash)
+      loggers.each do |l|
+        # if we don't have any metadata, let's not do the potentially expensive
+        # merging and managing that this call requires
+        if l.respond_to?(:add_data) && !data.nil? && !data.empty?
+          l.add_data(severity, message, progname, data: data)
+        else
+          l.add(severity, message, progname)
+        end
+      end
     end
 
     alias :log :add
 
+    def with_child(metadata = {})
+      child = Child.new(self, metadata)
+      if block_given?
+        yield child
+      else
+        child
+      end
+    end
+
     # Passes any other method calls on directly to the underlying Logger object created with init. If
     # this method gets hit before a call to Mixlib::Logger.init has been made, it will call
     # Mixlib::Logger.init() with no arguments.
diff --git a/lib/mixlib/log/child.rb b/lib/mixlib/log/child.rb
new file mode 100644
index 0000000..971c956
--- /dev/null
+++ b/lib/mixlib/log/child.rb
@@ -0,0 +1,60 @@
+#
+# 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 "mixlib/log/logging"
+
+module Mixlib
+  module Log
+    class Child
+      include Mixlib::Log::Logging
+
+      attr_reader :parent
+      def initialize(parent, metadata = {})
+        @parent = parent
+        @metadata = metadata
+      end
+
+      def level
+        parent.level
+      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
+      # two (or more) loggers at different log levels.
+      [:trace?, :debug?, :info?, :warn?, :error?, :fatal?].each do |method_name|
+        define_method(method_name) do
+          parent.send(method_name)
+        end
+      end
+
+      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
+
+      def with_child(metadata = {})
+        child = Child.new(self, metadata)
+        if block_given?
+          yield child
+        else
+          child
+        end
+      end
+
+    end
+  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..abc7bc3
--- /dev/null
+++ b/lib/mixlib/log/logger.rb
@@ -0,0 +1,106 @@
+require "logger"
+require "mixlib/log/logging"
+
+# 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
+
+      include Logging
+      #
+      # === 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
+      alias_method :add, :add_data
+
+      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..537e1de
--- /dev/null
+++ b/lib/mixlib/log/logging.rb
@@ -0,0 +1,53 @@
+#
+# 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"
+
+module Mixlib
+  module Log
+    module Logging
+      include ::Logger::Severity
+
+      TRACE = -1
+
+      SEV_LABEL = %w{TRACE DEBUG INFO WARN ERROR FATAL ANY}.each(&:freeze).freeze
+
+      def to_label(sev)
+        SEV_LABEL[sev + 1] || -"ANY"
+      end
+
+      LEVELS = { :trace => TRACE, :debug => DEBUG, :info => INFO, :warn => WARN, :error => ERROR, :fatal => 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.
+      [:trace, :debug, :info, :warn, :error, :fatal].each do |method_name|
+        level = LEVELS[method_name]
+        define_method(method_name) do |msg = nil, data: {}, &block|
+          pass(level, msg, data: data, &block)
+        end
+      end
+
+    end
+  end
+end
diff --git a/spec/mixlib/log/child_spec.rb b/spec/mixlib/log/child_spec.rb
new file mode 100644
index 0000000..eef2ce9
--- /dev/null
+++ b/spec/mixlib/log/child_spec.rb
@@ -0,0 +1,99 @@
+#
+# 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 "tempfile"
+require "stringio"
+require "spec_helper"
+
+RSpec.describe Mixlib::Log::Child do
+  before do
+    Logit.reset!
+    Logit.init(io)
+    Logit.level = :warn
+  end
+
+  let(:io) { StringIO.new }
+
+  let(:child) { Logit.with_child }
+
+  it "has a parent" do
+    expect(child.parent).to be(Logit)
+  end
+
+  it "accepts a message" do
+    Logit.with_child { |l| l.add(Logger::WARN, "a message") }
+    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(Mixlib::Log::LEVELS[level], "a #{level} message", nil, data: {})
+        Logit.level = level
+        child.send(level, "a #{level} message")
+      end
+    end
+  end
+
+  context "can query the parent's level" do
+    %i{ debug info warn error fatal }.each do |level|
+      it "at #{level}" do
+        query = "#{level}?".to_sym
+        Logit.level = level
+        expect(child.send(query)).to be(true)
+      end
+    end
+  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 277035d..137b557 100644
--- a/spec/mixlib/log_spec.rb
+++ b/spec/mixlib/log_spec.rb
@@ -19,16 +19,26 @@
 
 require "tempfile"
 require "stringio"
-require File.expand_path(File.join(File.dirname(__FILE__), "..", "spec_helper"))
+require "spec_helper"
 
 class LoggerLike
   attr_accessor :level
-  attr_reader :messages
+  attr_reader :messages, :data
   def initialize
     @messages = ""
+    @data = []
   end
 
-  [:debug, :info, :warn, :error, :fatal].each do |method_name|
+  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
+
+  [:trace, :debug, :info, :warn, :error, :fatal].each do |method_name|
     class_eval(<<-E)
       def #{method_name}(message)
         @messages << message
@@ -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
@@ -84,13 +95,14 @@ RSpec.describe Mixlib::Log do
     expect(Logit.configured?).to be true
   end
 
-  it "should set the log level using the binding form,  with :debug, :info, :warn, :error, or :fatal" do
+  it "should set the log level using the binding form,  with :trace, :debug, :info, :warn, :error, or :fatal" do
     levels = {
-      :debug => Logger::DEBUG,
-      :info  => Logger::INFO,
-      :warn  => Logger::WARN,
-      :error => Logger::ERROR,
-      :fatal => Logger::FATAL,
+      :trace => Mixlib::Log::TRACE,
+      :debug => Mixlib::Log::DEBUG,
+      :info  => Mixlib::Log::INFO,
+      :warn  => Mixlib::Log::WARN,
+      :error => Mixlib::Log::ERROR,
+      :fatal => Mixlib::Log::FATAL,
     }
     levels.each do |symbol, constant|
       Logit.level = symbol
@@ -106,13 +118,14 @@ RSpec.describe Mixlib::Log do
     expect(logdev.string).to match(/the_message/)
   end
 
-  it "should set the log level using the method form, with :debug, :info, :warn, :error, or :fatal" do
+  it "should set the log level using the method form, with :trace, :debug, :info, :warn, :error, or :fatal" do
     levels = {
-      :debug => Logger::DEBUG,
-      :info  => Logger::INFO,
-      :warn  => Logger::WARN,
-      :error => Logger::ERROR,
-      :fatal => Logger::FATAL,
+      :trace => Mixlib::Log::TRACE,
+      :debug => Mixlib::Log::DEBUG,
+      :info  => Mixlib::Log::INFO,
+      :warn  => Mixlib::Log::WARN,
+      :error => Mixlib::Log::ERROR,
+      :fatal => Mixlib::Log::FATAL,
     }
     levels.each do |symbol, constant|
       Logit.level(symbol)