summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
-rw-r--r--.travis.yml8
-rw-r--r--lib/mixlib/log.rb54
-rw-r--r--lib/mixlib/log/child.rb60
-rw-r--r--lib/mixlib/log/formatter.rb14
-rw-r--r--lib/mixlib/log/logger.rb106
-rw-r--r--lib/mixlib/log/logging.rb53
-rw-r--r--spec/mixlib/log/child_spec.rb99
-rw-r--r--spec/mixlib/log/formatter_spec.rb13
-rw-r--r--spec/mixlib/log_spec.rb43
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)