diff options
Diffstat (limited to 'lib')
| -rw-r--r-- | lib/chef/application.rb | 63 | ||||
| -rw-r--r-- | lib/chef/client.rb | 61 | ||||
| -rw-r--r-- | lib/chef/monologger.rb | 88 | ||||
| -rw-r--r-- | lib/chef/node.rb | 22 | ||||
| -rw-r--r-- | lib/chef/resource.rb | 25 | ||||
| -rw-r--r-- | lib/chef/run_context.rb | 28 | ||||
| -rw-r--r-- | lib/chef/run_context/cookbook_compiler.rb | 27 |
7 files changed, 136 insertions, 178 deletions
diff --git a/lib/chef/application.rb b/lib/chef/application.rb index 0d483fff0c..b8acf41557 100644 --- a/lib/chef/application.rb +++ b/lib/chef/application.rb @@ -75,18 +75,18 @@ class Chef unless Chef::Platform.windows? trap("QUIT") do - log.info("SIGQUIT received, call stack:\n " + caller.join("\n ")) + logger.info("SIGQUIT received, call stack:\n " + caller.join("\n ")) end trap("HUP") do - log.info("SIGHUP received, reconfiguring") + logger.info("SIGHUP received, reconfiguring") reconfigure end end end def emit_warnings - log.warn "chef_config[:zypper_check_gpg] is set to false which disables security checking on zypper packages" unless chef_config[:zypper_check_gpg] + logger.warn "chef_config[:zypper_check_gpg] is set to false which disables security checking on zypper packages" unless chef_config[:zypper_check_gpg] end # Parse configuration (options and config file) @@ -104,11 +104,11 @@ class Chef end # @api private (test injection) - def log + def logger Chef::Log end - def self.log + def self.logger Chef::Log end @@ -130,11 +130,11 @@ class Chef config[:config_file] = config_fetcher.expanded_path if config[:config_file].nil? - log.warn("No config file found or specified on command line, using command line options.") + logger.warn("No config file found or specified on command line, using command line options.") elsif config_fetcher.config_missing? - log.warn("*****************************************") - log.warn("Did not find config file: #{config[:config_file]}, using command line options.") - log.warn("*****************************************") + logger.warn("*****************************************") + logger.warn("Did not find config file: #{config[:config_file]}, using command line options.") + logger.warn("*****************************************") else config_content = config_fetcher.read_config apply_config(config_content, config[:config_file]) @@ -176,13 +176,13 @@ class Chef # def configure_logging configure_log_location - log.init(MonoLogger.new(chef_config[:log_location])) + logger.init(MonoLogger.new(chef_config[:log_location])) if want_additional_logger? configure_stdout_logger end - log.level = resolve_log_level + logger.level = resolve_log_level rescue StandardError => error - log.fatal("Failed to open or create log file at #{chef_config[:log_location]}: #{error.class} (#{error.message})") + logger.fatal("Failed to open or create log file at #{chef_config[:log_location]}: #{error.class} (#{error.message})") Chef::Application.fatal!("Aborting due to invalid 'log_location' configuration", error) end @@ -194,8 +194,8 @@ class Chef chef_config[:log_location] = case log_location.to_sym - when :syslog then log::Syslog.new - when :win_evt then log::WinEvt.new + when :syslog then logger::Syslog.new + when :win_evt then logger::WinEvt.new else log_location # Probably a path; let MonoLogger sort it out end end @@ -208,8 +208,8 @@ class Chef def configure_stdout_logger stdout_logger = MonoLogger.new(STDOUT) - stdout_logger.formatter = log.logger.formatter - log.loggers << stdout_logger + stdout_logger.formatter = logger.logger.formatter + logger.loggers << stdout_logger end # Use of output formatters is assumed if `force_formatter` is set or if `force_logger` is not set @@ -263,7 +263,8 @@ class Chef @chef_client_json, override_runlist: override_runlist, specific_recipes: specific_recipes, - runlist: config[:runlist] + runlist: config[:runlist], + logger: logger ) @chef_client_json = nil @@ -293,7 +294,7 @@ class Chef def run_with_graceful_exit_option # Override the TERM signal. trap("TERM") do - log.debug("SIGTERM received during converge," + + logger.debug("SIGTERM received during converge," + " finishing converge to exit normally (send SIGINT to terminate immediately)") end @@ -302,31 +303,31 @@ class Chef end def fork_chef_client - log.info "Forking chef instance to converge..." + logger.info "Forking chef instance to converge..." pid = fork do # Want to allow forked processes to finish converging when # TERM singal is received (exit gracefully) trap("TERM") do - log.debug("SIGTERM received during converge," + + logger.debug("SIGTERM received during converge," + " finishing converge to exit normally (send SIGINT to terminate immediately)") end client_solo = chef_config[:solo] ? "chef-solo" : "chef-client" $0 = "#{client_solo} worker: ppid=#{Process.ppid};start=#{Time.new.strftime("%R:%S")};" begin - log.debug "Forked instance now converging" + logger.debug "Forked instance now converging" @chef_client.run rescue Exception => e - log.error(e.to_s) + logger.error(e.to_s) exit Chef::Application.normalize_exit_code(e) else exit 0 end end - log.debug "Fork successful. Waiting for new chef pid: #{pid}" + logger.debug "Fork successful. Waiting for new chef pid: #{pid}" result = Process.waitpid2(pid) handle_child_exit(result) - log.debug "Forked instance successfully reaped (pid: #{pid})" + logger.debug "Forked instance successfully reaped (pid: #{pid})" true end @@ -344,9 +345,9 @@ class Chef def apply_config(config_content, config_file_path) chef_config.from_string(config_content, config_file_path) rescue Exception => error - log.fatal("Configuration error #{error.class}: #{error.message}") + logger.fatal("Configuration error #{error.class}: #{error.message}") filtered_trace = error.backtrace.grep(/#{Regexp.escape(config_file_path)}/) - filtered_trace.each { |line| log.fatal(" " + line ) } + filtered_trace.each { |line| logger.fatal(" " + line ) } Chef::Application.fatal!("Aborting due to error in '#{config_file_path}'", error) end @@ -369,9 +370,9 @@ class Chef chef_stacktrace_out += message Chef::FileCache.store("chef-stacktrace.out", chef_stacktrace_out) - log.fatal("Stacktrace dumped to #{Chef::FileCache.load("chef-stacktrace.out", false)}") - log.fatal("Please provide the contents of the stacktrace.out file if you file a bug report") - log.debug(message) + logger.fatal("Stacktrace dumped to #{Chef::FileCache.load("chef-stacktrace.out", false)}") + logger.fatal("Please provide the contents of the stacktrace.out file if you file a bug report") + logger.debug(message) true end @@ -381,12 +382,12 @@ class Chef # Log a fatal error message to both STDERR and the Logger, exit the application def fatal!(msg, err = nil) - log.fatal(msg) + logger.fatal(msg) Process.exit(normalize_exit_code(err)) end def exit!(msg, err = nil) - log.debug(msg) + logger.debug(msg) Process.exit(normalize_exit_code(err)) end end diff --git a/lib/chef/client.rb b/lib/chef/client.rb index 6ff2d78ee6..b7ea92b506 100644 --- a/lib/chef/client.rb +++ b/lib/chef/client.rb @@ -135,6 +135,7 @@ class Chef # attr_reader :events + attr_reader :logger # # Creates a new Chef::Client. # @@ -148,7 +149,9 @@ class Chef # def initialize(json_attribs = nil, args = {}) @json_attribs = json_attribs || {} - @ohai = Ohai::System.new + @logger = args.delete(:logger) || Chef::Log.with_child + + @ohai = Ohai::System.new(logger: logger) event_handlers = configure_formatters + configure_event_loggers event_handlers += Array(Chef::Config[:event_handlers]) @@ -249,10 +252,10 @@ class Chef request_id = Chef::RequestID.instance.request_id run_context = nil events.run_start(Chef::VERSION) - Chef::Log.info("*** Chef #{Chef::VERSION} ***") - Chef::Log.info("Platform: #{RUBY_PLATFORM}") - Chef::Log.info "Chef-client pid: #{Process.pid}" - Chef::Log.debug("Chef-client request_id: #{request_id}") + logger.info("*** Chef #{Chef::VERSION} ***") + logger.info("Platform: #{RUBY_PLATFORM}") + logger.info "Chef-client pid: #{Process.pid}" + logger.debug("Chef-client request_id: #{request_id}") enforce_path_sanity run_ohai @@ -265,7 +268,7 @@ class Chef run_status.run_id = request_id run_status.start_clock - Chef::Log.info("Starting Chef Run for #{node.name}") + logger.info("Starting Chef Run for #{node.name}") run_started do_windows_admin_check @@ -280,7 +283,7 @@ class Chef if Chef::Config[:why_run] == true # why_run should probably be renamed to why_converge - Chef::Log.debug("Not running controls in 'why-run' mode - this mode is used to see potential converge changes") + logger.debug("Not running controls in 'why-run' mode - this mode is used to see potential converge changes") elsif Chef::Config[:audit_mode] != :disabled audit_error = run_audits(run_context) end @@ -289,7 +292,7 @@ class Chef raise converge_error if converge_error run_status.stop_clock - Chef::Log.info("Chef Run complete in #{run_status.elapsed_time} seconds") + logger.info("Chef Run complete in #{run_status.elapsed_time} seconds") run_completed_successfully events.run_completed(node, run_status) @@ -300,7 +303,7 @@ class Chef Chef::Platform::Rebooter.reboot_if_needed!(node) rescue Exception => run_error # CHEF-3336: Send the error first in case something goes wrong below and we don't know why - Chef::Log.debug("Re-raising exception: #{run_error.class} - #{run_error.message}\n#{run_error.backtrace.join("\n ")}") + logger.trace("Re-raising exception: #{run_error.class} - #{run_error.message}\n#{run_error.backtrace.join("\n ")}") # If we failed really early, we may not have a run_status yet. Too early for these to be of much use. if run_status run_status.stop_clock @@ -526,7 +529,7 @@ class Chef # def load_required_recipe(rest, run_context) required_recipe_contents = rest.get("required_recipe") - Chef::Log.info("Required Recipe found, loading it") + logger.info("Required Recipe found, loading it") Chef::FileCache.store("required_recipe", required_recipe_contents) required_recipe_file = Chef::FileCache.load("required_recipe", false) @@ -547,7 +550,7 @@ class Chef rescue Net::HTTPServerException => e case e.response when Net::HTTPNotFound - Chef::Log.debug("Required Recipe not configured on the server, skipping it") + logger.trace("Required Recipe not configured on the server, skipping it") else raise end @@ -578,9 +581,9 @@ class Chef if Chef::Config[:solo_legacy_mode] # nothing to do elsif policy_builder.temporary_policy? - Chef::Log.warn("Skipping final node save because override_runlist was given") + logger.warn("Skipping final node save because override_runlist was given") else - Chef::Log.debug("Saving the current state of node #{node_name}") + logger.debug("Saving the current state of node #{node_name}") node.save end end @@ -600,7 +603,7 @@ class Chef ohai.all_plugins(filter) events.ohai_completed(node) rescue Ohai::Exceptions::CriticalPluginFailure => e - Chef::Log.error("Critical Ohai plugins failed: #{e.message}") + logger.error("Critical Ohai plugins failed: #{e.message}") exit(false) end @@ -653,13 +656,13 @@ class Chef def register(client_name = node_name, config = Chef::Config) if !config[:client_key] events.skipping_registration(client_name, config) - Chef::Log.debug("Client key is unspecified - skipping registration") + logger.trace("Client key is unspecified - skipping registration") elsif File.exists?(config[:client_key]) events.skipping_registration(client_name, config) - Chef::Log.debug("Client key #{config[:client_key]} is present - skipping registration") + logger.trace("Client key #{config[:client_key]} is present - skipping registration") else events.registration_start(node_name, config) - Chef::Log.info("Client key #{config[:client_key]} is not present - registering") + logger.info("Client key #{config[:client_key]} is not present - registering") Chef::ApiClient::Registration.new(node_name, config[:client_key]).run events.registration_completed end @@ -707,7 +710,7 @@ class Chef catch(:end_client_run_early) do begin events.converge_start(run_context) - Chef::Log.debug("Converging node #{node_name}") + logger.debug("Converging node #{node_name}") @runner = Chef::Runner.new(run_context) @runner.converge events.converge_complete @@ -775,7 +778,7 @@ class Chef def run_audits(run_context) begin events.audit_phase_start(run_status) - Chef::Log.info("Starting audit phase") + logger.info("Starting audit phase") auditor = Chef::Audit::Runner.new(run_context) auditor.run if auditor.failed? @@ -785,7 +788,7 @@ class Chef @events.audit_phase_complete(Chef::Audit::Logger.read_buffer) end rescue Exception => e - Chef::Log.error("Audit phase failed with error message: #{e.message}") + logger.error("Audit phase failed with error message: #{e.message}") @events.audit_phase_failed(e, Chef::Audit::Logger.read_buffer) audit_exception = e end @@ -818,19 +821,19 @@ class Chef # def do_windows_admin_check if Chef::Platform.windows? - Chef::Log.debug("Checking for administrator privileges....") + logger.trace("Checking for administrator privileges....") if !has_admin_privileges? message = "chef-client doesn't have administrator privileges on node #{node_name}." if Chef::Config[:fatal_windows_admin_check] - Chef::Log.fatal(message) - Chef::Log.fatal("fatal_windows_admin_check is set to TRUE.") + logger.fatal(message) + logger.fatal("fatal_windows_admin_check is set to TRUE.") raise Chef::Exceptions::WindowsNotAdmin, message else - Chef::Log.warn("#{message} This might cause unexpected resource failures.") + logger.warn("#{message} This might cause unexpected resource failures.") end else - Chef::Log.debug("chef-client has administrator privileges on node #{node_name}.") + logger.trace("chef-client has administrator privileges on node #{node_name}.") end end end @@ -960,7 +963,7 @@ class Chef File.open(path, "w+") do |file| RubyProf::GraphPrinter.new(RubyProf.stop).print(file, {}) end - Chef::Log.warn("Ruby execution profile dumped to #{path}") + logger.warn("Ruby execution profile dumped to #{path}") end def empty_directory?(path) @@ -977,14 +980,14 @@ class Chef # Chef::Config[:cookbook_path] can be a string or an array # if it's an array, go through it and check each one, raise error at the last one if no files are found cookbook_paths = Array(Chef::Config[:cookbook_path]) - Chef::Log.debug "Loading from cookbook_path: #{cookbook_paths.map { |path| File.expand_path(path) }.join(', ')}" + logger.trace "Loading from cookbook_path: #{cookbook_paths.map { |path| File.expand_path(path) }.join(', ')}" if cookbook_paths.all? { |path| empty_directory?(path) } msg = "None of the cookbook paths set in Chef::Config[:cookbook_path], #{cookbook_paths.inspect}, contain any cookbooks" - Chef::Log.fatal(msg) + logger.fatal(msg) raise Chef::Exceptions::CookbookNotFound, msg end else - Chef::Log.warn("Node #{node_name} has an empty run list.") if run_context.node.run_list.empty? + logger.warn("Node #{node_name} has an empty run list.") if run_context.node.run_list.empty? end end diff --git a/lib/chef/monologger.rb b/lib/chef/monologger.rb index 82816e887f..0bd262bd85 100644 --- a/lib/chef/monologger.rb +++ b/lib/chef/monologger.rb @@ -1,88 +1,4 @@ -require "logger" +require "mixlib/log/logger" require "pp" -#== MonoLogger -# A subclass of Ruby's stdlib Logger with all the mutex and logrotation stuff -# ripped out. -class MonoLogger < Logger - - # - # === 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 - - 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 +MonoLogger = Mixlib::Log::Logger diff --git a/lib/chef/node.rb b/lib/chef/node.rb index 496bfedc15..eb0f21ea2e 100644 --- a/lib/chef/node.rb +++ b/lib/chef/node.rb @@ -49,6 +49,8 @@ class Chef attr_accessor :recipe_list, :run_state + attr_reader :logger + # RunContext will set itself as run_context via this setter when # initialized. This is needed so DSL::IncludeAttribute (in particular, # #include_recipe) can access the run_context to determine if an attributes @@ -66,9 +68,10 @@ class Chef NULL_ARG = Object.new # Create a new Chef::Node object. - def initialize(chef_server_rest: nil) + def initialize(chef_server_rest: nil, logger: nil) @chef_server_rest = chef_server_rest @name = nil + @logger = logger || Chef::Log.with_child(subsystem: "node") @chef_environment = "_default" @primary_runlist = Chef::RunList.new @@ -321,13 +324,15 @@ class Chef # Consume data from ohai and Attributes provided as JSON on the command line. def consume_external_attrs(ohai_data, json_cli_attrs) - Chef::Log.debug("Extracting run list from JSON attributes provided on command line") + # FIXME(log): should be trace + logger.debug("Extracting run list from JSON attributes provided on command line") consume_attributes(json_cli_attrs) self.automatic_attrs = ohai_data platform, version = Chef::Platform.find_platform_and_version(self) - Chef::Log.debug("Platform is #{platform} version #{version}") + # FIXME(log): should be trace + logger.debug("Platform is #{platform} version #{version}") automatic[:platform] = platform automatic[:platform_version] = version automatic[:name] = name @@ -342,7 +347,8 @@ class Chef def consume_attributes(attrs) normal_attrs_to_merge = consume_run_list(attrs) normal_attrs_to_merge = consume_chef_environment(normal_attrs_to_merge) - Chef::Log.debug("Applying attributes from json file") + # FIXME(log): should be trace + logger.debug("Applying attributes from json file") self.normal_attrs = Chef::Mixin::DeepMerge.merge(normal_attrs, normal_attrs_to_merge) tags # make sure they're defined end @@ -368,7 +374,7 @@ class Chef if attrs.key?("recipes") || attrs.key?("run_list") raise Chef::Exceptions::AmbiguousRunlistSpecification, "please set the node's run list using the 'run_list' attribute only." end - Chef::Log.info("Setting the run_list to #{new_run_list} from CLI options") + logger.info("Setting the run_list to #{new_run_list} from CLI options") run_list(new_run_list) end attrs @@ -594,7 +600,7 @@ class Chef # so then POST to create. begin if Chef::Config[:why_run] - Chef::Log.warn("In why-run mode, so NOT performing node save.") + logger.warn("In why-run mode, so NOT performing node save.") else chef_server_rest.put("nodes/#{name}", data_for_save) end @@ -663,14 +669,14 @@ class Chef whitelist_config_option = "#{level}_attribute_whitelist".to_sym whitelist = Chef::Config[whitelist_config_option] unless whitelist.nil? # nil => save everything - Chef::Log.info("Whitelisting #{level} node attributes for save.") + logger.info("Whitelisting #{level} node attributes for save.") data[level] = Chef::Whitelist.filter(data[level], whitelist) end blacklist_config_option = "#{level}_attribute_blacklist".to_sym blacklist = Chef::Config[blacklist_config_option] unless blacklist.nil? # nil => remove nothing - Chef::Log.info("Blacklisting #{level} node attributes for save") + logger.info("Blacklisting #{level} node attributes for save") data[level] = Chef::Blacklist.filter(data[level], blacklist) end end diff --git a/lib/chef/resource.rb b/lib/chef/resource.rb index 77e735bbce..26298e5b1d 100644 --- a/lib/chef/resource.rb +++ b/lib/chef/resource.rb @@ -131,6 +131,13 @@ class Chef def initialize(name, run_context = nil) name(name) unless name.nil? @run_context = run_context + + @logger = if run_context + run_context.logger.with_child({ name: name, resource: resource_name }) + else + Chef::Log.with_child({ name: name, resource: resource_name }) + end + @before = nil @params = Hash.new @provider = nil @@ -567,9 +574,9 @@ class Chef resolve_notification_references validate_action(action) - if Chef::Config[:verbose_logging] || Chef::Log.level == :debug + if Chef::Config[:verbose_logging] || logger.level == :debug # This can be noisy - Chef::Log.info("Processing #{self} action #{action} (#{defined_at})") + logger.info("Processing #{self} action #{action} (#{defined_at})") end # ensure that we don't leave @updated_by_last_action set to true @@ -586,12 +593,12 @@ class Chef provider_for_action(action).run_action rescue StandardError => e if ignore_failure - Chef::Log.error("#{custom_exception_message(e)}; ignore_failure is set, continuing") + logger.error("#{custom_exception_message(e)}; ignore_failure is set, continuing") events.resource_failed(self, action, e) elsif remaining_retries > 0 events.resource_failed_retriable(self, action, remaining_retries, e) remaining_retries -= 1 - Chef::Log.info("Retrying execution of #{self}, #{remaining_retries} attempt#{"s" if remaining_retries > 1} left") + logger.info("Retrying execution of #{self}, #{remaining_retries} attempt#{"s" if remaining_retries > 1} left") sleep retry_delay retry else @@ -1174,8 +1181,8 @@ class Chef # Internal Resource Interface (for Chef) # - FORBIDDEN_IVARS = [:@run_context, :@not_if, :@only_if, :@enclosing_provider, :@description, :@introduced, :@examples, :@validation_message] - HIDDEN_IVARS = [:@allowed_actions, :@resource_name, :@source_line, :@run_context, :@name, :@not_if, :@only_if, :@elapsed_time, :@enclosing_provider, :@description, :@introduced, :@examples, :@validation_message] + FORBIDDEN_IVARS = [:@run_context, :@logger, :@not_if, :@only_if, :@enclosing_provider, :@description, :@introduced, :@examples, :@validation_message] + HIDDEN_IVARS = [:@allowed_actions, :@resource_name, :@source_line, :@run_context, :@logger, :@name, :@not_if, :@only_if, :@elapsed_time, :@enclosing_provider, :@description, :@introduced, :@examples, :@validation_message] include Chef::Mixin::ConvertToClassName extend Chef::Mixin::ConvertToClassName @@ -1189,6 +1196,10 @@ class Chef # and the resource collection. attr_accessor :run_context + # @return [Mixlib::Log::Child] The logger for this resources. This is a child + # of the run context's logger, if one exists. + attr_reader :logger + # @return [String] The cookbook this resource was declared in. attr_accessor :cookbook_name @@ -1456,7 +1467,7 @@ class Chef false else events.resource_skipped(self, action, conditional) - Chef::Log.debug("Skipping #{self} due to #{conditional.description}") + logger.debug("Skipping #{self} due to #{conditional.description}") true end end diff --git a/lib/chef/run_context.rb b/lib/chef/run_context.rb index a3dd6cffba..bc676bc27f 100644 --- a/lib/chef/run_context.rb +++ b/lib/chef/run_context.rb @@ -153,6 +153,13 @@ class Chef # attr_reader :delayed_actions + # + # A child of the root Chef::Log logging object. + # + # @return Mixlib::Log::Child A child logger + # + attr_reader :logger + # Creates a new Chef::RunContext object and populates its fields. This object gets # used by the Chef Server to generate a fully compiled recipe list for a node. # @@ -162,10 +169,11 @@ class Chef # @param events [EventDispatch::Dispatcher] The event dispatcher for this # run. # - def initialize(node, cookbook_collection, events) + def initialize(node, cookbook_collection, events, logger = nil) @node = node @cookbook_collection = cookbook_collection @events = events + @logger = logger || Chef::Log.with_child node.run_context = self node.set_cookbook_attribute @@ -244,7 +252,7 @@ class Chef # def add_delayed_action(notification) if delayed_actions.any? { |existing_notification| existing_notification.duplicates?(notification) } - Chef::Log.info( "#{notification.notifying_resource} not queuing delayed action #{notification.action} on #{notification.resource}"\ + logger.info( "#{notification.notifying_resource} not queuing delayed action #{notification.action} on #{notification.resource}"\ " (delayed), as it's already been queued") else delayed_actions << notification @@ -318,12 +326,13 @@ class Chef # @see DSL::IncludeRecipe#load_recipe # def load_recipe(recipe_name, current_cookbook: nil) - Chef::Log.debug("Loading recipe #{recipe_name} via include_recipe") + # FIXME(log): Should be trace + logger.debug("Loading recipe #{recipe_name} via include_recipe") cookbook_name, recipe_short_name = Chef::Recipe.parse_recipe_name(recipe_name, current_cookbook: current_cookbook) if unreachable_cookbook?(cookbook_name) # CHEF-4367 - Chef::Log.warn(<<-ERROR_MESSAGE) + logger.warn(<<-ERROR_MESSAGE) MissingCookbookDependency: Recipe `#{recipe_name}` is not in the run_list, and cookbook '#{cookbook_name}' is not a dependency of any cookbook in the run_list. To load this recipe, @@ -333,7 +342,8 @@ ERROR_MESSAGE end if loaded_fully_qualified_recipe?(cookbook_name, recipe_short_name) - Chef::Log.debug("I am not loading #{recipe_name}, because I have already seen it.") + # FIXME(log): Should be trace + logger.debug("I am not loading #{recipe_name}, because I have already seen it.") false else loaded_recipe(cookbook_name, recipe_short_name) @@ -357,7 +367,8 @@ ERROR_MESSAGE raise Chef::Exceptions::RecipeNotFound, "could not find recipe file #{recipe_file}" end - Chef::Log.debug("Loading recipe file #{recipe_file}") + # FIXME(log): Should be trace + logger.debug("Loading recipe file #{recipe_file}") recipe = Chef::Recipe.new("@recipe_files", recipe_file, self) recipe.from_file(recipe_file) recipe @@ -551,7 +562,7 @@ ERROR_MESSAGE # 5. raise an exception on any second call. # 6. ? def request_reboot(reboot_info) - Chef::Log.info "Changing reboot status from #{self.reboot_info.inspect} to #{reboot_info.inspect}" + logger.info "Changing reboot status from #{self.reboot_info.inspect} to #{reboot_info.inspect}" @reboot_info = reboot_info end @@ -559,7 +570,7 @@ ERROR_MESSAGE # Cancels a pending reboot # def cancel_reboot - Chef::Log.info "Changing reboot status from #{reboot_info.inspect} to {}" + logger.info "Changing reboot status from #{reboot_info.inspect} to {}" @reboot_info = {} end @@ -613,6 +624,7 @@ ERROR_MESSAGE loaded_recipe? loaded_recipes loaded_recipes_hash + logger node open_stream reboot_info diff --git a/lib/chef/run_context/cookbook_compiler.rb b/lib/chef/run_context/cookbook_compiler.rb index f2598a4f27..25d32ea7e2 100644 --- a/lib/chef/run_context/cookbook_compiler.rb +++ b/lib/chef/run_context/cookbook_compiler.rb @@ -31,12 +31,14 @@ class Chef class CookbookCompiler attr_reader :events attr_reader :run_list_expansion + attr_reader :logger def initialize(run_context, run_list_expansion, events) @run_context = run_context @events = events @run_list_expansion = run_list_expansion @cookbook_order = nil + @logger = run_context.logger.with_child(subsystem: "cookbook_compiler") end # Chef::Node object for the current run. @@ -89,7 +91,7 @@ class Chef cookbook = Chef::Recipe.parse_recipe_name(recipe).first add_cookbook_with_deps(ordered_cookbooks, seen_cookbooks, cookbook) end - Chef::Log.debug("Cookbooks to compile: #{ordered_cookbooks.inspect}") + logger.debug("Cookbooks to compile: #{ordered_cookbooks.inspect}") ordered_cookbooks end end @@ -116,6 +118,7 @@ class Chef # Doing a full ohai system check is costly, so only do so if we've loaded additional plugins if ohai_plugin_count > 0 + # FIXME(log): figure out what the ohai logger looks like here ohai = Ohai::System.new.run_additional_plugins(Chef::Config[:ohai_segment_plugin_path]) node.consume_ohai_data(ohai) end @@ -192,7 +195,7 @@ class Chef default_file = list_of_attr_files.find { |path| File.basename(path) == "default.rb" } if root_alias if default_file - Chef::Log.error("Cookbook #{cookbook_name} contains both attributes.rb and and attributes/default.rb, ignoring attributes/default.rb") + logger.error("Cookbook #{cookbook_name} contains both attributes.rb and and attributes/default.rb, ignoring attributes/default.rb") list_of_attr_files.delete(default_file) end # The actual root_alias path decoding is handled in CookbookVersion#attribute_filenames_by_short_filename @@ -208,7 +211,8 @@ class Chef end def load_attribute_file(cookbook_name, filename) - Chef::Log.debug("Node #{node.name} loading cookbook #{cookbook_name}'s attribute file #{filename}") + # FIXME(log): should be trace + logger.debug("Node #{node.name} loading cookbook #{cookbook_name}'s attribute file #{filename}") attr_file_basename = ::File.basename(filename, ".rb") node.include_attribute("#{cookbook_name}::#{attr_file_basename}") rescue Exception => e @@ -220,7 +224,8 @@ class Chef files_in_cookbook_by_segment(cookbook_name, :libraries).each do |filename| next unless File.extname(filename) == ".rb" begin - Chef::Log.debug("Loading cookbook #{cookbook_name}'s library file: #{filename}") + # FIXME(log): should be trace + logger.debug("Loading cookbook #{cookbook_name}'s library file: #{filename}") Kernel.load(filename) @events.library_file_loaded(filename) rescue Exception => e @@ -240,7 +245,8 @@ class Chef end def load_lwrp_provider(cookbook_name, filename) - Chef::Log.debug("Loading cookbook #{cookbook_name}'s providers from #{filename}") + # FIXME(log): should be trace + logger.debug("Loading cookbook #{cookbook_name}'s providers from #{filename}") Chef::Provider::LWRPBase.build_from_file(cookbook_name, filename, self) @events.lwrp_file_loaded(filename) rescue Exception => e @@ -249,7 +255,8 @@ class Chef end def load_lwrp_resource(cookbook_name, filename) - Chef::Log.debug("Loading cookbook #{cookbook_name}'s resources from #{filename}") + # FIXME(log): should be trace + logger.debug("Loading cookbook #{cookbook_name}'s resources from #{filename}") Chef::Resource::LWRPBase.build_from_file(cookbook_name, filename, self) @events.lwrp_file_loaded(filename) rescue Exception => e @@ -262,7 +269,8 @@ class Chef files_in_cookbook_by_segment(cookbook_name, :ohai).each do |filename| next unless File.extname(filename) == ".rb" - Chef::Log.debug "Loading Ohai plugin: #{filename} from #{cookbook_name}" + # FIXME(log): should be trace + logger.debug "Loading Ohai plugin: #{filename} from #{cookbook_name}" target_name = File.join(target, cookbook_name.to_s, File.basename(filename)) FileUtils.mkdir_p(File.dirname(target_name)) @@ -273,11 +281,12 @@ class Chef def load_resource_definitions_from_cookbook(cookbook_name) files_in_cookbook_by_segment(cookbook_name, :definitions).each do |filename| begin - Chef::Log.debug("Loading cookbook #{cookbook_name}'s definitions from #{filename}") + # FIXME(log): should be trace + logger.debug("Loading cookbook #{cookbook_name}'s definitions from #{filename}") resourcelist = Chef::ResourceDefinitionList.new resourcelist.from_file(filename) definitions.merge!(resourcelist.defines) do |key, oldval, newval| - Chef::Log.info("Overriding duplicate definition #{key}, new definition found in #{filename}") + logger.info("Overriding duplicate definition #{key}, new definition found in #{filename}") newval end @events.definition_file_loaded(filename) |