Structured Logging

.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

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 @@ def init(*opts)
       @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 @@ def configured?
 
     # Sets the level for the Logger object by symbol.  Valid arguments are:
     #
+    #  :trace
     #  :debug
     #  :info
     #  :warn
@@ -101,7 +104,7 @@ def configured?
     # 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 @@ def level(new_level = nil)
       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.

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

lib/mixlib/log/formatter.rb

@@ -42,15 +42,25 @@ def call(severity, time, progname, msg)
       # 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

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

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