From 94222a8a0a1cda16d35c8f08c731a3f902449391 Mon Sep 17 00:00:00 2001 From: Thom May Date: Wed, 14 Feb 2018 12:22:41 +0000 Subject: Add the ability to inject log objects meaning that we can have inheritable metadata Signed-off-by: Thom May --- Gemfile | 5 +- Gemfile.lock | 51 ++++++++---------- chef.gemspec | 2 +- lib/chef/application.rb | 63 +++++++++++----------- lib/chef/client.rb | 61 +++++++++++---------- lib/chef/monologger.rb | 88 +------------------------------ lib/chef/node.rb | 22 +++++--- lib/chef/resource.rb | 25 ++++++--- lib/chef/run_context.rb | 28 +++++++--- lib/chef/run_context/cookbook_compiler.rb | 27 ++++++---- spec/functional/root_alias_spec.rb | 2 +- spec/support/platform_helpers.rb | 3 ++ spec/support/shared/context/client.rb | 22 ++++---- spec/unit/client_spec.rb | 6 +-- spec/unit/log/syslog_spec.rb | 6 +-- spec/unit/log/winevt_spec.rb | 5 +- spec/unit/shell/shell_session_spec.rb | 1 - spec/unit/windows_service_spec.rb | 6 ++- 18 files changed, 187 insertions(+), 236 deletions(-) diff --git a/Gemfile b/Gemfile index 81109eb6f5..b699dca975 100644 --- a/Gemfile +++ b/Gemfile @@ -7,11 +7,8 @@ source "https://rubygems.org" # of bundler versions prior to 1.12.0 (https://github.com/bundler/bundler/commit/193a14fe5e0d56294c7b370a0e59f93b2c216eed) gem "chef", path: "." -# @todo before shipping 14.0 we need to switch this over to a gem again -gem "ohai", git: "https://github.com/chef/ohai.git", branch: "master" - gem "chef-config", path: File.expand_path("../chef-config", __FILE__) if File.exist?(File.expand_path("../chef-config", __FILE__)) -gem "cheffish", "~> 13" # required for rspec tests +gem "cheffish", "~> 14" group(:omnibus_package) do gem "appbundler" diff --git a/Gemfile.lock b/Gemfile.lock index 63d4cee2f5..da1da698de 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -6,24 +6,6 @@ GIT chefstyle (0.8.0) rubocop (= 0.52.1) -GIT - remote: https://github.com/chef/ohai.git - revision: 9a6842a19cc9d46ca9cc42af4bda5e9ca31a0dce - branch: master - specs: - ohai (14.0.27) - chef-config (>= 12.8, < 15) - ffi (~> 1.9) - ffi-yajl (~> 2.2) - ipaddress - mixlib-cli - mixlib-config (~> 2.0) - mixlib-log (>= 1.7.1, < 2.0) - mixlib-shellout (~> 2.0) - plist (~> 3.1) - systemu (~> 2.6.4) - wmi-lite (~> 1.0) - PATH remote: . specs: @@ -41,7 +23,7 @@ PATH mixlib-archive (~> 0.4) mixlib-authentication (~> 1.4) mixlib-cli (~> 1.7) - mixlib-log (~> 1.3) + mixlib-log (~> 2.0) mixlib-shellout (~> 2.0) net-sftp (~> 2.1, >= 2.1.2) net-ssh (~> 4.2) @@ -72,7 +54,7 @@ PATH mixlib-archive (~> 0.4) mixlib-authentication (~> 1.4) mixlib-cli (~> 1.7) - mixlib-log (~> 1.3) + mixlib-log (~> 2.0) mixlib-shellout (~> 2.0) net-sftp (~> 2.1, >= 2.1.2) net-ssh (~> 4.2) @@ -126,14 +108,14 @@ GEM thor (~> 0.18) byebug (10.0.0) chef-vault (3.3.0) - chef-zero (13.1.0) + chef-zero (14.0.1) ffi-yajl (~> 2.2) hashie (>= 2.0, < 4.0) - mixlib-log (~> 1.3) + mixlib-log (~> 2) rack (~> 2.0) uuidtools (~> 2.1) - cheffish (13.1.0) - chef-zero (~> 13.0) + cheffish (14.0.0) + chef-zero (~> 14.0) net-ssh coderay (1.1.2) crack (0.4.3) @@ -141,13 +123,13 @@ GEM debug_inspector (0.0.3) diff-lcs (1.3) docile (1.3.0) - docker-api (1.34.1) + docker-api (1.34.2) excon (>= 0.47.0) multi_json erubis (2.7.0) ethon (0.11.0) ffi (>= 1.3.0) - excon (0.60.0) + excon (0.61.0) faraday (0.14.0) multipart-post (>= 1.2, < 3) faraday_middleware (0.12.2) @@ -212,7 +194,7 @@ GEM mixlib-authentication (1.4.2) mixlib-cli (1.7.0) mixlib-config (2.2.5) - mixlib-log (1.7.1) + mixlib-log (2.0.1) mixlib-shellout (2.3.2) mixlib-shellout (2.3.2-universal-mingw32) win32-process (~> 0.8.2) @@ -236,6 +218,18 @@ GEM nori (2.6.0) octokit (4.8.0) sawyer (~> 0.8.0, >= 0.5.3) + ohai (14.0.28) + chef-config (>= 12.8, < 15) + ffi (~> 1.9) + ffi-yajl (~> 2.2) + ipaddress + mixlib-cli + mixlib-config (~> 2.0) + mixlib-log (~> 2.0, >= 2.0.1) + mixlib-shellout (~> 2.0) + plist (~> 3.1) + systemu (~> 2.6.4) + wmi-lite (~> 1.0) parallel (1.12.1) parser (2.5.0.4) ast (~> 2.4.0) @@ -394,12 +388,11 @@ DEPENDENCIES chef! chef-config! chef-vault - cheffish (~> 13) + cheffish (~> 14) chefstyle! inspec (~> 1) netrc octokit - ohai! pry pry-byebug pry-remote diff --git a/chef.gemspec b/chef.gemspec index be35d854df..02815a6d56 100644 --- a/chef.gemspec +++ b/chef.gemspec @@ -18,7 +18,7 @@ Gem::Specification.new do |s| s.add_dependency "chef-config", "= #{Chef::VERSION}" s.add_dependency "mixlib-cli", "~> 1.7" - s.add_dependency "mixlib-log", "~> 1.3" + s.add_dependency "mixlib-log", "~> 2.0" s.add_dependency "mixlib-authentication", "~> 1.4" s.add_dependency "mixlib-shellout", "~> 2.0" s.add_dependency "mixlib-archive", "~> 0.4" 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) diff --git a/spec/functional/root_alias_spec.rb b/spec/functional/root_alias_spec.rb index 7091615d12..a0a63011b4 100644 --- a/spec/functional/root_alias_spec.rb +++ b/spec/functional/root_alias_spec.rb @@ -49,7 +49,7 @@ describe "root aliases" do context "with both an attributes.rb and attributes/default.rb" do it "should log an error and ignore attributes/default.rb" do - expect(Chef::Log).to receive(:error).with("Cookbook dup_attr contains both attributes.rb and and attributes/default.rb, ignoring attributes/default.rb") + expect_any_instance_of(Mixlib::Log::Child).to receive(:error).with("Cookbook dup_attr contains both attributes.rb and and attributes/default.rb, ignoring attributes/default.rb") node.run_list << "dup_attr" run_context.load(node.run_list.expand("_default")) expect(node["aliased"]["attr"]).to eq "value" diff --git a/spec/support/platform_helpers.rb b/spec/support/platform_helpers.rb index 1718632186..8569523e05 100644 --- a/spec/support/platform_helpers.rb +++ b/spec/support/platform_helpers.rb @@ -246,6 +246,9 @@ end class HttpHelper extend Ohai::Mixin::HttpHelper + def self.logger + Chef::Log + end end def gce? diff --git a/spec/support/shared/context/client.rb b/spec/support/shared/context/client.rb index 19ce82fa15..5acae86acf 100644 --- a/spec/support/shared/context/client.rb +++ b/spec/support/shared/context/client.rb @@ -20,7 +20,7 @@ shared_context "client" do end let(:ohai_system) do - ohai = instance_double("Ohai::System", :all_plugins => true, :data => ohai_data) + ohai = instance_double("Ohai::System", :all_plugins => true, :data => ohai_data, logger: logger) allow(ohai).to receive(:[]) do |k| ohai_data[k] end @@ -37,19 +37,24 @@ shared_context "client" do let(:json_attribs) { nil } let(:client_opts) { {} } + let(:stdout) { STDOUT } + let(:stderr) { STDERR } + let(:client) do Chef::Config[:event_loggers] = [] - Chef::Client.new(json_attribs, client_opts).tap do |c| + allow(Ohai::System).to receive(:new).and_return(ohai_system) + opts = client_opts.merge({ logger: logger }) + Chef::Client.new(json_attribs, opts).tap do |c| c.node = node end end - before do - Chef::Log.logger = Logger.new(StringIO.new) + let(:logger) { instance_double("Mixlib::Log::Child", trace: nil, debug: nil, warn: nil, info: nil, error: nil, fatal: nil) } - # Node/Ohai data - #Chef::Config[:node_name] = fqdn - allow(Ohai::System).to receive(:new).and_return(ohai_system) + before do + stub_const("Chef::Client::STDOUT_FD", stdout) + stub_const("Chef::Client::STDERR_FD", stderr) + allow(client).to receive(:logger).and_return(logger) end end @@ -163,9 +168,6 @@ shared_context "a client run" do Chef::Config[:why_run] = false Chef::Config[:audit_mode] = :enabled - stub_const("Chef::Client::STDOUT_FD", stdout) - stub_const("Chef::Client::STDERR_FD", stderr) - stub_rest_clean stub_for_register stub_for_data_collector_init diff --git a/spec/unit/client_spec.rb b/spec/unit/client_spec.rb index 2aff7b2a71..d92b2e2358 100644 --- a/spec/unit/client_spec.rb +++ b/spec/unit/client_spec.rb @@ -448,7 +448,7 @@ EOM end it "should log and continue on" do - expect(Chef::Log).to receive(:debug) + expect(logger).to receive(:trace) client.load_required_recipe(rest, run_context) end end @@ -482,7 +482,7 @@ EOM end it "should not log a warning message" do - expect(Chef::Log).not_to receive(:warn) + expect(logger).not_to receive(:warn) client.do_windows_admin_check end @@ -499,7 +499,7 @@ EOM end it "should log a warning message" do - expect(Chef::Log).to receive(:warn) + expect(logger).to receive(:warn) client.do_windows_admin_check end diff --git a/spec/unit/log/syslog_spec.rb b/spec/unit/log/syslog_spec.rb index ebf1418576..6d56b96575 100644 --- a/spec/unit/log/syslog_spec.rb +++ b/spec/unit/log/syslog_spec.rb @@ -17,11 +17,9 @@ # require "spec_helper" -require "chef" describe "Chef::Log::Syslog", :unix_only => true do let(:syslog) { Chef::Log::Syslog.new } - let(:app) { Chef::Application.new } before do Chef::Log.init(MonoLogger.new(syslog)) @@ -37,12 +35,12 @@ describe "Chef::Log::Syslog", :unix_only => true do end it "should send message with severity info to syslog." do - expect(syslog).to receive(:info).with("*** Chef 12.4.0.dev.0 ***") + expect(syslog).to receive(:add).with(1, "*** Chef 12.4.0.dev.0 ***", nil) Chef::Log.info("*** Chef 12.4.0.dev.0 ***") end it "should send message with severity warning to syslog." do - expect(syslog).to receive(:warn).with("No config file found or specified on command line, using command line options.") + expect(syslog).to receive(:add).with(2, "No config file found or specified on command line, using command line options.", nil) Chef::Log.warn("No config file found or specified on command line, using command line options.") end diff --git a/spec/unit/log/winevt_spec.rb b/spec/unit/log/winevt_spec.rb index d5d452159b..c7cc49f40d 100644 --- a/spec/unit/log/winevt_spec.rb +++ b/spec/unit/log/winevt_spec.rb @@ -25,7 +25,6 @@ describe Chef::Log::WinEvt do let(:app) { Chef::Application.new } before do - Chef::Log.init(MonoLogger.new(winevt)) @old_log_level = Chef::Log.level Chef::Log.level = :info @@ -39,12 +38,12 @@ describe Chef::Log::WinEvt do end it "should send message with severity info to Windows Event Log." do - expect(winevt).to receive(:info).with("*** Chef 12.4.0.dev.0 ***") + expect(winevt).to receive(:add).with(1, "*** Chef 12.4.0.dev.0 ***", nil) Chef::Log.info("*** Chef 12.4.0.dev.0 ***") end it "should send message with severity warning to Windows Event Log." do - expect(winevt).to receive(:warn).with("No config file found or specified on command line, using command line options.") + expect(winevt).to receive(:add).with(2, "No config file found or specified on command line, using command line options.", nil) Chef::Log.warn("No config file found or specified on command line, using command line options.") end diff --git a/spec/unit/shell/shell_session_spec.rb b/spec/unit/shell/shell_session_spec.rb index 7ed372f375..c96453eeae 100644 --- a/spec/unit/shell/shell_session_spec.rb +++ b/spec/unit/shell/shell_session_spec.rb @@ -229,7 +229,6 @@ describe Shell::SoloLegacySession do it "runs chef with a resource collection from the compiled cookbooks" do allow(@session).to receive(:node_built?).and_return(true) - allow(Chef::Log).to receive(:level) chef_runner = double("Chef::Runner.new", :converge => :converged) expect(Chef::Runner).to receive(:new).with(an_instance_of(Chef::RunContext)).and_return(chef_runner) diff --git a/spec/unit/windows_service_spec.rb b/spec/unit/windows_service_spec.rb index 3555b70f1b..71e01a0b6b 100644 --- a/spec/unit/windows_service_spec.rb +++ b/spec/unit/windows_service_spec.rb @@ -38,10 +38,12 @@ describe "Chef::Application::WindowsService", :windows_only do end before do + monologger = instance_double("MonoLogger", :level= => nil, :add => nil, :formatter= => nil, :formatter => nil) + allow(MonoLogger).to receive(:new).and_return(monologger) + Chef::Config.merge!(config_options) allow(subject).to receive(:configure_chef) allow(subject).to receive(:parse_options) - allow(MonoLogger).to receive(:new) allow(subject).to receive(:running?).and_return(true, false) allow(subject).to receive(:state).and_return(4) subject.service_init @@ -98,7 +100,7 @@ describe "Chef::Application::WindowsService", :windows_only do end end - context "configueres a watchdog timeout" do + context "configures a watchdog timeout" do let(:timeout) { 10 } before do -- cgit v1.2.1