diff options
| -rw-r--r-- | .travis.yml | 8 | ||||
| -rw-r--r-- | lib/mixlib/log.rb | 54 | ||||
| -rw-r--r-- | lib/mixlib/log/child.rb | 60 | ||||
| -rw-r--r-- | lib/mixlib/log/formatter.rb | 14 | ||||
| -rw-r--r-- | lib/mixlib/log/logger.rb | 106 | ||||
| -rw-r--r-- | lib/mixlib/log/logging.rb | 53 | ||||
| -rw-r--r-- | spec/mixlib/log/child_spec.rb | 99 | ||||
| -rw-r--r-- | spec/mixlib/log/formatter_spec.rb | 13 | ||||
| -rw-r--r-- | spec/mixlib/log_spec.rb | 43 |
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) |