Move ohai to structured logging

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/hints.rb

@@ -41,11 +41,11 @@ def self.hint?(name)
       Ohai.config[:hints_path].each do |path|
         filename = File.join(path, "#{name}.json")
         next unless File.exist?(filename)
-        Ohai::Log.debug("Found hint #{name}.json at #{filename}")
+        Ohai::Log.trace("Found hint #{name}.json at #{filename}")
         @hints[name] = parse_hint_file(filename)
       end
 
-      Ohai::Log.debug("Did not find hint #{name}.json in the hint path(s): #{Ohai.config[:hints_path].join(', ')} ") unless @hints.key?(name)
+      Ohai::Log.trace("Did not find hint #{name}.json in the hint path(s): #{Ohai.config[:hints_path].join(', ')} ") unless @hints.key?(name)
       @hints[name]
     end
   end

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/mixin/azure_metadata.rb

@@ -32,19 +32,19 @@ def http_get(uri)
       end
 
       def fetch_metadata
-        Ohai::Log.debug("Mixin AzureMetadata: Fetching metadata from host #{AZURE_METADATA_ADDR} at #{AZURE_METADATA_URL}")
+        logger.trace("Mixin AzureMetadata: Fetching metadata from host #{AZURE_METADATA_ADDR} at #{AZURE_METADATA_URL}")
         response = http_get(AZURE_METADATA_URL)
         if response.code == "200"
           begin
             data = StringIO.new(response.body)
             parser = FFI_Yajl::Parser.new
             parser.parse(data)
           rescue FFI_Yajl::ParseError
-            Ohai::Log.warn("Mixin AzureMetadata: Metadata response is NOT valid JSON")
+            logger.warn("Mixin AzureMetadata: Metadata response is NOT valid JSON")
             nil
           end
         else
-          Ohai::Log.warn("Mixin AzureMetadata: Received response code #{response.code} requesting metadata")
+          logger.warn("Mixin AzureMetadata: Received response code #{response.code} requesting metadata")
           nil
         end
       end

lib/ohai/mixin/command.rb

@@ -37,13 +37,13 @@ def shell_out(cmd, **options)
         so = Mixlib::ShellOut.new(cmd, options)
         begin
           so.run_command
-          Ohai::Log.debug("Plugin #{name}: ran '#{cmd}' and returned #{so.exitstatus}")
+          logger.trace("Plugin #{name}: ran '#{cmd}' and returned #{so.exitstatus}")
           so
         rescue Errno::ENOENT => e
-          Ohai::Log.debug("Plugin #{name}: ran '#{cmd}' and failed #{e.inspect}")
+          logger.trace("Plugin #{name}: ran '#{cmd}' and failed #{e.inspect}")
           raise Ohai::Exceptions::Exec, e
         rescue Mixlib::ShellOut::CommandTimeout => e
-          Ohai::Log.debug("Plugin #{name}: ran '#{cmd}' and timed out after #{options[:timeout]} seconds")
+          logger.trace("Plugin #{name}: ran '#{cmd}' and timed out after #{options[:timeout]} seconds")
           raise Ohai::Exceptions::Exec, e
         end
       end

lib/ohai/mixin/do_metadata.rb

@@ -35,7 +35,7 @@ def fetch_metadata
           parser = FFI_Yajl::Parser.new
           parser.parse(response.body)
         when "404"
-          Ohai::Log.debug("Mixin DOMetadata: Encountered 404 response retrieving Digital Ocean metadata: #{uri} ; continuing.")
+          logger.trace("Mixin DOMetadata: Encountered 404 response retrieving Digital Ocean metadata: #{uri} ; continuing.")
           {}
         else
           raise "Mixin DOMetadata: Encountered error retrieving Digital Ocean metadata (#{uri} returned #{response.code} response)"

lib/ohai/mixin/ec2_metadata.rb

@@ -49,10 +49,10 @@ module Ec2Metadata
 
       def best_api_version
         @api_version ||= begin
-          Ohai::Log.debug("Mixin EC2: Fetching http://#{EC2_METADATA_ADDR}/ to determine the latest supported metadata release")
+          logger.trace("Mixin EC2: Fetching http://#{EC2_METADATA_ADDR}/ to determine the latest supported metadata release")
           response = http_client.get("/")
           if response.code == "404"
-            Ohai::Log.debug("Mixin EC2: Received HTTP 404 from metadata server while determining API version, assuming 'latest'")
+            logger.trace("Mixin EC2: Received HTTP 404 from metadata server while determining API version, assuming 'latest'")
             return "latest"
           elsif response.code != "200"
             raise "Mixin EC2: Unable to determine EC2 metadata version (returned #{response.code} response)"
@@ -62,9 +62,9 @@ def best_api_version
           versions = response.body.split("\n").sort
           until versions.empty? || EC2_SUPPORTED_VERSIONS.include?(versions.last)
             pv = versions.pop
-            Ohai::Log.debug("Mixin EC2: EC2 lists metadata version: #{pv} not yet supported by Ohai") unless pv == "latest"
+            logger.trace("Mixin EC2: EC2 lists metadata version: #{pv} not yet supported by Ohai") unless pv == "latest"
           end
-          Ohai::Log.debug("Mixin EC2: Latest supported EC2 metadata version: #{versions.last}")
+          logger.trace("Mixin EC2: Latest supported EC2 metadata version: #{versions.last}")
           if versions.empty?
             raise "Mixin EC2: Unable to determine EC2 metadata version (no supported entries found)"
           end
@@ -88,13 +88,13 @@ def http_client
       #   `nil` and continue the run instead of failing it.
       def metadata_get(id, api_version)
         path = "/#{api_version}/meta-data/#{id}"
-        Ohai::Log.debug("Mixin EC2: Fetching http://#{EC2_METADATA_ADDR}#{path}")
+        logger.trace("Mixin EC2: Fetching http://#{EC2_METADATA_ADDR}#{path}")
         response = http_client.get(path)
         case response.code
         when "200"
           response.body
         when "404"
-          Ohai::Log.debug("Mixin EC2: Encountered 404 response retrieving EC2 metadata path: #{path} ; continuing.")
+          logger.trace("Mixin EC2: Encountered 404 response retrieving EC2 metadata path: #{path} ; continuing.")
           nil
         else
           raise "Mixin EC2: Encountered error retrieving EC2 metadata (#{path} returned #{response.code} response)"
@@ -169,7 +169,7 @@ def fetch_json_dir_metadata(id, api_version)
       end
 
       def fetch_userdata
-        Ohai::Log.debug("Mixin EC2: Fetching http://#{EC2_METADATA_ADDR}/#{best_api_version}/user-data/")
+        logger.trace("Mixin EC2: Fetching http://#{EC2_METADATA_ADDR}/#{best_api_version}/user-data/")
         response = http_client.get("/#{best_api_version}/user-data/")
         response.code == "200" ? response.body : nil
       end

lib/ohai/mixin/http_helper.rb

@@ -25,7 +25,7 @@ def can_socket_connect?(addr, port, timeout = 2)
         begin
           saddr = Socket.pack_sockaddr_in(port, addr)
         rescue SocketError => e # generally means dns resolution error
-          Ohai::Log.debug("Mixin HttpHelper: can_socket_connect? failed setting up socket connection: #{e}")
+          logger.trace("Mixin HttpHelper: can_socket_connect? failed setting up socket connection: #{e}")
           return false
         end
 
@@ -48,7 +48,7 @@ def can_socket_connect?(addr, port, timeout = 2)
           end
         rescue SystemCallError
         end
-        Ohai::Log.debug("Mixin HttpHelper: can_socket_connect? == #{connected}")
+        logger.trace("Mixin HttpHelper: can_socket_connect? == #{connected}")
         connected
       end
     end

lib/ohai/mixin/scaleway_metadata.rb

@@ -35,7 +35,7 @@ def fetch_metadata
           parser = FFI_Yajl::Parser.new
           parser.parse(response.body)
         when "404"
-          Ohai::Log.debug("Mixin ScalewayMetadata: Encountered 404 response retrieving Scaleway metadata: #{uri} ; continuing.")
+          logger.trace("Mixin ScalewayMetadata: Encountered 404 response retrieving Scaleway metadata: #{uri} ; continuing.")
           {}
         else
           raise "Mixin ScalewayMetadata: Encountered error retrieving Scaleway metadata (#{uri} returned #{response.code} response)"

lib/ohai/mixin/softlayer_metadata.rb

@@ -54,11 +54,11 @@ def fetch_metadata_item(item)
     if res.code.to_i.between?(200, 299)
       res.body
     else
-      ::Ohai::Log.error("Mixin Softlayer: Unable to fetch item #{full_url}: status (#{res.code}) body (#{res.body})")
+      logger.error("Mixin Softlayer: Unable to fetch item #{full_url}: status (#{res.code}) body (#{res.body})")
       nil
     end
   rescue => e
-    ::Ohai::Log.error("Mixin Softlayer: Unable to fetch softlayer metadata from #{u}: #{e.class}: #{e.message}")
+    logger.error("Mixin Softlayer: Unable to fetch softlayer metadata from #{u}: #{e.class}: #{e.message}")
     raise e
   end
 end

lib/ohai/plugins/azure.rb

@@ -30,16 +30,16 @@
     # project for details
     azure_metadata_from_hints = hint?("azure")
     if azure_metadata_from_hints
-      Ohai::Log.debug("Plugin Azure: Azure hint is present. Parsing any hint data.")
+      logger.trace("Plugin Azure: Azure hint is present. Parsing any hint data.")
       azure Mash.new
       azure_metadata_from_hints.each { |k, v| azure[k] = v }
       azure["metadata"] = parse_metadata
     elsif has_waagent? || has_dhcp_option_245?
-      Ohai::Log.debug("Plugin Azure: No hints present, but system appears to be on Azure.")
+      logger.trace("Plugin Azure: No hints present, but system appears to be on Azure.")
       azure Mash.new
       azure["metadata"] = parse_metadata
     else
-      Ohai::Log.debug("Plugin Azure: No hints present and doesn't appear to be on Azure.")
+      logger.trace("Plugin Azure: No hints present and doesn't appear to be on Azure.")
       false
     end
   end
@@ -48,7 +48,7 @@
   # http://blog.mszcool.com/index.php/2015/04/detecting-if-a-virtual-machine-runs-in-microsoft-azure-linux-windows-to-protect-your-software-when-distributed-via-the-azure-marketplace/
   def has_waagent?
     if File.exist?("/usr/sbin/waagent") || Dir.exist?('C:\WindowsAzure')
-      Ohai::Log.debug("Plugin Azure: Found waagent used by Azure.")
+      logger.trace("Plugin Azure: Found waagent used by Azure.")
       true
     end
   end
@@ -58,7 +58,7 @@ def has_dhcp_option_245?
     if File.exist?("/var/lib/dhcp/dhclient.eth0.leases")
       File.open("/var/lib/dhcp/dhclient.eth0.leases").each do |line|
         if line =~ /unknown-245/
-          Ohai::Log.debug("Plugin Azure: Found unknown-245 DHCP option used by Azure.")
+          logger.trace("Plugin Azure: Found unknown-245 DHCP option used by Azure.")
           has_245 = true
           break
         end