Move to mixlib-log 2

This allows us to bubble up a single logging object with metadata
throughout ohai, rather than the current janky way. We also move some
debug output to trace.

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

lib/ohai/application.rb

@@ -93,6 +93,7 @@ def configure_ohai
 
   def run_application
     config[:invoked_from_cli] = true
+    config[:logger] = Ohai::Log.with_child
     ohai = Ohai::System.new(config)
     ohai.all_plugins(@attributes)
 

lib/ohai/dsl/plugin.rb

@@ -80,9 +80,11 @@ class Plugin
 
       attr_reader :data
       attr_reader :failed
+      attr_reader :logger
 
-      def initialize(data)
+      def initialize(data, logger)
         @data = data
+        @logger = logger.with_child({ subsystem: "plugin", plugin: name })
         @has_run = false
         @failed = false
       end
@@ -91,7 +93,7 @@ def run
         @has_run = true
 
         if Ohai.config[:disabled_plugins].include?(name)
-          Ohai::Log.debug("Skipping disabled plugin #{name}")
+          logger.trace("Skipping disabled plugin #{name}")
         else
           run_plugin
         end
@@ -182,8 +184,8 @@ def safe_run
         raise e
       rescue => e
         @failed = true
-        Ohai::Log.debug("Plugin #{name} threw #{e.inspect}")
-        e.backtrace.each { |line| Ohai::Log.debug( line ) }
+        logger.trace("Plugin #{name} threw #{e.inspect}")
+        e.backtrace.each { |line| logger.trace( line ) }
       end
 
       def method_missing(name, *args)

lib/ohai/dsl/plugin/versionvii.rb

@@ -24,8 +24,8 @@ class VersionVII < Plugin
         attr_reader :version
         attr_reader :source
 
-        def initialize(data)
-          super(data)
+        def initialize(data, logger)
+          super(data, logger)
           @source = self.class.sources
           @version = :version7
         end
@@ -97,7 +97,7 @@ def run_plugin
           elsif collector.has_key?(:default)
             instance_eval(&collector[:default])
           else
-            Ohai::Log.debug("Plugin #{name}: No data to collect. Skipping...")
+            logger.trace("Plugin #{name}: No data to collect. Skipping...")
           end
         end
 
@@ -106,11 +106,11 @@ def optional?
         end
 
         def provides(*paths)
-          Ohai::Log.warn("[UNSUPPORTED OPERATION] \'provides\' is no longer supported in a \'collect_data\' context. Please specify \'provides\' before collecting plugin data. Ignoring command \'provides #{paths.join(", ")}")
+          logger.warn("[UNSUPPORTED OPERATION] \'provides\' is no longer supported in a \'collect_data\' context. Please specify \'provides\' before collecting plugin data. Ignoring command \'provides #{paths.join(", ")}")
         end
 
         def require_plugin(*args)
-          Ohai::Log.warn("[UNSUPPORTED OPERATION] \'require_plugin\' is no longer supported. Please use \'depends\' instead.\nIgnoring plugin(s) #{args.join(", ")}")
+          logger.warn("[UNSUPPORTED OPERATION] \'require_plugin\' is no longer supported. Please use \'depends\' instead.\nIgnoring plugin(s) #{args.join(", ")}")
         end
 
         def configuration(option, *options)

lib/ohai/loader.rb

@@ -44,7 +44,7 @@ def self.find_all_in(plugin_dir)
           return []
         end
 
-        Ohai::Log.debug("Searching for Ohai plugins in #{plugin_dir}")
+        Ohai::Log.trace("Searching for Ohai plugins in #{plugin_dir}")
 
         escaped = ChefConfig::PathHelper.escape_glob_dir(plugin_dir)
         Dir[File.join(escaped, "**", "*.rb")].map do |file|
@@ -53,8 +53,10 @@ def self.find_all_in(plugin_dir)
       end
     end
 
+    attr_reader :logger
     def initialize(controller)
       @controller = controller
+      @logger = controller.logger.with_child(subsystem: "loader")
       @v7_plugin_classes = []
     end
 
@@ -77,7 +79,7 @@ def load_all
     def load_additional(from)
       from = [ Ohai.config[:plugin_path], from].flatten
       plugin_files_by_dir(from).collect do |plugin_file|
-        Ohai::Log.debug "Loading additional plugin: #{plugin_file}"
+        logger.trace "Loading additional plugin: #{plugin_file}"
         plugin = load_plugin_class(plugin_file.path, plugin_file.plugin_root)
         load_v7_plugin(plugin)
       end
@@ -106,10 +108,10 @@ def load_plugin_class(plugin_path, plugin_dir_path = nil)
       # Read the contents of the plugin to understand if it's a V6 or V7 plugin.
       contents = ""
       begin
-        Ohai::Log.debug("Loading plugin at #{plugin_path}")
+        logger.trace("Loading plugin at #{plugin_path}")
         contents << IO.read(plugin_path)
       rescue IOError, Errno::ENOENT
-        Ohai::Log.warn("Unable to open or read plugin at #{plugin_path}")
+        logger.warn("Unable to open or read plugin at #{plugin_path}")
         return nil
       end
 
@@ -148,11 +150,11 @@ def load_v7_plugin_class(contents, plugin_path)
     rescue SystemExit, Interrupt # rubocop: disable Lint/ShadowedException
       raise
     rescue Ohai::Exceptions::InvalidPluginName => e
-      Ohai::Log.warn("Plugin Name Error: <#{plugin_path}>: #{e.message}")
+      logger.warn("Plugin Name Error: <#{plugin_path}>: #{e.message}")
     rescue Ohai::Exceptions::IllegalPluginDefinition => e
-      Ohai::Log.warn("Plugin Definition Error: <#{plugin_path}>: #{e.message}")
+      logger.warn("Plugin Definition Error: <#{plugin_path}>: #{e.message}")
     rescue NoMethodError => e
-      Ohai::Log.warn("Plugin Method Error: <#{plugin_path}>: unsupported operation \'#{e.name}\'")
+      logger.warn("Plugin Method Error: <#{plugin_path}>: unsupported operation \'#{e.name}\'")
     rescue SyntaxError => e
       # split on occurrences of
       #    <env>: syntax error,
@@ -161,15 +163,15 @@ def load_v7_plugin_class(contents, plugin_path)
       parts = e.message.split(/<.*>[:[0-9]+]*: syntax error, /)
       parts.each do |part|
         next if part.length == 0
-        Ohai::Log.warn("Plugin Syntax Error: <#{plugin_path}>: #{part}")
+        logger.warn("Plugin Syntax Error: <#{plugin_path}>: #{part}")
       end
     rescue Exception, Errno::ENOENT => e
-      Ohai::Log.warn("Plugin Error: <#{plugin_path}>: #{e.message}")
-      Ohai::Log.debug("Plugin Error: <#{plugin_path}>: #{e.inspect}, #{e.backtrace.join('\n')}")
+      logger.warn("Plugin Error: <#{plugin_path}>: #{e.message}")
+      logger.trace("Plugin Error: <#{plugin_path}>: #{e.inspect}, #{e.backtrace.join('\n')}")
     end
 
     def load_v7_plugin(plugin_class)
-      plugin = plugin_class.new(@controller.data)
+      plugin = plugin_class.new(@controller.data, @controller.logger)
       collect_provides(plugin)
       plugin
     end

lib/ohai/runner.rb

@@ -23,13 +23,15 @@
 module Ohai
   class Runner
 
-    attr_reader :failed_plugins
+    attr_reader :failed_plugins, :logger
     # safe_run: set to true if this runner will run plugins in
     # safe-mode. default false.
     def initialize(controller, safe_run = false)
       @provides_map = controller.provides_map
       @safe_run = safe_run
       @failed_plugins = []
+      @logger = controller.logger.with_child
+      @logger.metadata = { subsystem: "runner" }
     end
 
     # Runs plugins and any un-run dependencies.
@@ -52,10 +54,10 @@ def run_plugin(plugin)
         rescue SystemExit # abort or exit from plug-in should exit Ohai with failure code
           raise
         rescue Exception, Errno::ENOENT => e
-          Ohai::Log.debug("Plugin #{plugin.name} threw exception #{e.inspect} #{e.backtrace.join("\n")}")
+          logger.trace("Plugin #{plugin.name} threw exception #{e.inspect} #{e.backtrace.join("\n")}")
         end
       end
-      Ohai::Log.debug("Plugin #{plugin.name} took #{elapsed.total} seconds to run.")
+      logger.trace("Plugin #{plugin.name} took #{elapsed.total} seconds to run.")
     end
 
     def run_v7_plugin(plugin)

lib/ohai/system.rb

@@ -37,16 +37,19 @@ class System
     attr_accessor :data
     attr_reader :config
     attr_reader :provides_map
+    attr_reader :logger
 
     # the cli flag is used to determine if we're being constructed by
-    # something like chef-client (which doesn't not set this flag) and
+    # something like chef-client (which doesn't set this flag) and
     # which sets up its own loggers, or if we're coming from Ohai::Application
     # and therefore need to configure Ohai's own logger.
     def initialize(config = {})
       @cli = config[:invoked_from_cli]
       @plugin_path = ""
       @config = config
       @failed_plugins = []
+      @logger = config[:logger] || Ohai::Log.with_child
+      @logger.metadata = { system: "ohai", version: Ohai::VERSION }
       reset_system
     end
 
@@ -90,14 +93,14 @@ def run_plugins(safe = false, attribute_filter = nil)
           @runner.run_plugin(plugin)
         end
       rescue Ohai::Exceptions::AttributeNotFound, Ohai::Exceptions::DependencyCycle => e
-        Ohai::Log.error("Encountered error while running plugins: #{e.inspect}")
+        logger.error("Encountered error while running plugins: #{e.inspect}")
         raise
       end
       critical_failed = Ohai::Config.ohai[:critical_plugins] & @runner.failed_plugins
       unless critical_failed.empty?
         msg = "The following Ohai plugins marked as critical failed: #{critical_failed}"
         if @cli
-          Ohai::Log.error(msg)
+          logger.error(msg)
           exit(true)
         else
           raise Ohai::Exceptions::CriticalPluginFailure, "#{msg}. Failing Chef run."
@@ -110,7 +113,7 @@ def run_plugins(safe = false, attribute_filter = nil)
 
     def run_additional_plugins(plugin_path)
       @loader.load_additional(plugin_path).each do |plugin|
-        Ohai::Log.debug "Running plugin #{plugin}"
+        logger.trace "Running plugin #{plugin}"
         @runner.run_plugin(plugin)
       end
 
@@ -178,7 +181,7 @@ def configure_ohai
         Ohai.config[:plugin_path] << Ohai.config[:directory]
       end
 
-      Ohai::Log.debug("Running Ohai with the following configuration: #{Ohai.config.configuration}")
+      logger.debug("Running Ohai with the following configuration: #{Ohai.config.configuration}")
     end
 
     def configure_logging

ohai.gemspec

@@ -19,7 +19,7 @@ Gem::Specification.new do |s|
   s.add_dependency "ffi-yajl", "~> 2.2"
   s.add_dependency "mixlib-cli"
   s.add_dependency "mixlib-config", "~> 2.0"
-  s.add_dependency "mixlib-log", ">= 1.7.1", "< 2.0"
+  s.add_dependency "mixlib-log", "~> 2.0", ">= 2.0.1"
   s.add_dependency "mixlib-shellout", "~> 2.0"
   s.add_dependency "plist", "~> 3.1"
   s.add_dependency "ipaddress"

spec/unit/dsl/plugin_spec.rb

@@ -62,8 +62,8 @@
         plugin.run
       end
 
-      it "logs a message to debug" do
-        expect(Ohai::Log).to receive(:debug).with(/Skipping disabled plugin TestPlugin/)
+      it "logs a message to trace" do
+        expect(plugin.logger).to receive(:trace).with(/Skipping disabled plugin TestPlugin/)
         plugin.run
       end
 
@@ -382,8 +382,9 @@
 end
 
 describe Ohai::DSL::Plugin::VersionVII do
+  let(:logger) { Ohai::Log }
   it "does not modify the plugin name when the plugin is named correctly" do
-    plugin = Ohai.plugin(:FunkyVALIDpluginName) {}.new({})
+    plugin = Ohai.plugin(:FunkyVALIDpluginName) {}.new({}, logger)
     expect(plugin.name).to eql(:FunkyVALIDpluginName)
   end
 
@@ -538,24 +539,24 @@
 
   describe "#provides (deprecated)" do
     it "logs a warning" do
-      plugin = Ohai::DSL::Plugin::VersionVII.new(Mash.new)
-      expect(Ohai::Log).to receive(:warn).with(/\[UNSUPPORTED OPERATION\]/)
+      plugin = Ohai.plugin(:Test).new(Mash.new, logger)
+      expect_any_instance_of(Mixlib::Log::Child).to receive(:warn).with(/\[UNSUPPORTED OPERATION\]/)
       plugin.provides("attribute")
     end
   end
 
   describe "#require_plugin (deprecated)" do
     it "logs a warning" do
-      plugin = Ohai::DSL::Plugin::VersionVII.new(Mash.new)
-      expect(Ohai::Log).to receive(:warn).with(/\[UNSUPPORTED OPERATION\]/)
+      plugin = Ohai.plugin(:Test).new(Mash.new, logger)
+      expect_any_instance_of(Mixlib::Log::Child).to receive(:warn).with(/\[UNSUPPORTED OPERATION\]/)
       plugin.require_plugin("plugin")
     end
   end
 
   describe "#configuration" do
     let(:plugin) do
       klass = Ohai.plugin(camel_name) {}
-      klass.new({})
+      klass.new({}, logger)
     end
 
     shared_examples_for "plugin config lookup" do
@@ -627,7 +628,7 @@
 
   it_behaves_like "Ohai::DSL::Plugin" do
     let(:ohai) { Ohai::System.new }
-    let(:plugin) { Ohai::DSL::Plugin::VersionVII.new(ohai.data) }
+    let(:plugin) { Ohai.plugin(:Test).new(ohai.data, ohai.logger) }
     let(:version) { :version7 }
   end
 end

spec/unit/loader_spec.rb

@@ -23,7 +23,7 @@
   extend IntegrationSupport
 
   let(:loader) { Ohai::Loader.new(ohai) }
-  let(:ohai) { double("Ohai::System", :data => Mash.new, :provides_map => provides_map) }
+  let(:ohai) { double("Ohai::System", :data => Mash.new, :provides_map => provides_map, logger: Ohai::Log) }
   let(:provides_map) { Ohai::ProvidesMap.new }
 
   describe "#initialize" do
@@ -108,7 +108,7 @@
     describe "load_plugin() method" do
       describe "when the plugin uses Ohai.plugin instead of Ohai.plugins" do
         it "logs an unsupported operation warning" do
-          expect(Ohai::Log).to receive(:warn).with(/Plugin Method Error: <#{path_to("extra_s.rb")}>:/)
+          expect(loader.logger).to receive(:warn).with(/Plugin Method Error: <#{path_to("extra_s.rb")}>:/)
           loader.load_plugin(path_to("extra_s.rb"))
         end
 
@@ -119,7 +119,7 @@
 
       describe "when the plugin tries to call an unexisting method" do
         it "shoud log an unsupported operation warning" do
-          expect(Ohai::Log).to receive(:warn).with(/Plugin Method Error: <#{path_to("no_method.rb")}>:/)
+          expect(loader.logger).to receive(:warn).with(/Plugin Method Error: <#{path_to("no_method.rb")}>:/)
           loader.load_plugin(path_to("no_method.rb"))
         end
 
@@ -130,7 +130,7 @@
 
       describe "when the plugin defines collect_data on the same platform more than once" do
         it "shoud log an illegal plugin definition warning" do
-          expect(Ohai::Log).to receive(:warn).with(/Plugin Definition Error: <#{path_to("illegal_def.rb")}>:/)
+          expect(loader.logger).to receive(:warn).with(/Plugin Definition Error: <#{path_to("illegal_def.rb")}>:/)
           loader.load_plugin(path_to("illegal_def.rb"))
         end
 
@@ -141,7 +141,7 @@
 
       describe "when an unexpected error is encountered" do
         it "logs a warning" do
-          expect(Ohai::Log).to receive(:warn).with(/Plugin Error: <#{path_to("unexpected_error.rb")}>:/)
+          expect(loader.logger).to receive(:warn).with(/Plugin Error: <#{path_to("unexpected_error.rb")}>:/)
           loader.load_plugin(path_to("unexpected_error.rb"))
         end
 
@@ -152,7 +152,7 @@
 
       describe "when the plugin name symbol has bad syntax" do
         it "logs a syntax error warning" do
-          expect(Ohai::Log).to receive(:warn).with(/Plugin Syntax Error: <#{path_to("bad_symbol.rb")}>:/)
+          expect(loader.logger).to receive(:warn).with(/Plugin Syntax Error: <#{path_to("bad_symbol.rb")}>:/)
           loader.load_plugin(path_to("bad_symbol.rb"))
         end
 
@@ -163,7 +163,7 @@
 
       describe "when the plugin forgets an 'end'" do
         it "logs a syntax error warning" do
-          expect(Ohai::Log).to receive(:warn).with(/Plugin Syntax Error: <#{path_to("no_end.rb")}>:/)
+          expect(loader.logger).to receive(:warn).with(/Plugin Syntax Error: <#{path_to("no_end.rb")}>:/)
           loader.load_plugin(path_to("no_end.rb"))
         end
 
@@ -174,7 +174,7 @@
 
       describe "when the plugin has an invalid name" do
         it "logs an invalid plugin name warning" do
-          expect(Ohai::Log).to receive(:warn).with(/Plugin Name Error: <#{path_to("bad_name.rb")}>:/)
+          expect(loader.logger).to receive(:warn).with(/Plugin Name Error: <#{path_to("bad_name.rb")}>:/)
           loader.load_plugin(path_to("bad_name.rb"))
         end