diff --git a/lib/puppet/parser/ast/node.rb b/lib/puppet/parser/ast/node.rb index f009f20c6..fd6443327 100644 --- a/lib/puppet/parser/ast/node.rb +++ b/lib/puppet/parser/ast/node.rb @@ -1,26 +1,25 @@ require 'puppet/parser/ast/top_level_construct' class Puppet::Parser::AST::Node < Puppet::Parser::AST::TopLevelConstruct attr_accessor :names, :context def initialize(names, context = {}, &ruby_code) raise ArgumentError, "names should be an array" unless names.is_a? Array if context[:parent] msg = "Deprecation notice: Node inheritance is not supported in Puppet >= 4.0.0. See http://links.puppetlabs.com/puppet-node-inheritance-deprecation" - # Cannot use Puppet.deprecation_warning here since it prints gobbledygook stack trace - Puppet.warning(msg) + Puppet.puppet_deprecation_warning(msg, :key => "node-inheritance-#{names.join}", :file => context[:file], :line => context[:line]) end @names = names @context = context @ruby_code = ruby_code end def instantiate(modname) @names.collect do |name| new_node = Puppet::Resource::Type.new(:node, name, @context.merge(:module_name => modname)) new_node.ruby_code = @ruby_code if @ruby_code new_node end end end diff --git a/lib/puppet/util/logging.rb b/lib/puppet/util/logging.rb index 7541b42b0..84a35ddc2 100644 --- a/lib/puppet/util/logging.rb +++ b/lib/puppet/util/logging.rb @@ -1,151 +1,181 @@ # A module to make logging a bit easier. require 'puppet/util/log' require 'puppet/error' module Puppet::Util::Logging def send_log(level, message) Puppet::Util::Log.create({:level => level, :source => log_source, :message => message}.merge(log_metadata)) end # Create a method for each log level. Puppet::Util::Log.eachlevel do |level| define_method(level) do |args| args = args.join(" ") if args.is_a?(Array) send_log(level, args) end end # Log an exception via Puppet.err. Will also log the backtrace if Puppet[:trace] is set. # Parameters: # [exception] an Exception to log # [message] an optional String overriding the message to be logged; by default, we log Exception.message. # If you pass a String here, your string will be logged instead. You may also pass nil if you don't # wish to log a message at all; in this case it is likely that you are only calling this method in order # to take advantage of the backtrace logging. def log_exception(exception, message = :default, options = {}) err(format_exception(exception, message, Puppet[:trace] || options[:trace])) end def format_exception(exception, message = :default, trace = true) arr = [] case message when :default arr << exception.message when nil # don't log anything if they passed a nil; they are just calling for the optional backtrace logging else arr << message end if trace and exception.backtrace arr << Puppet::Util.pretty_backtrace(exception.backtrace) end if exception.respond_to?(:original) and exception.original arr << "Wrapped exception:" arr << format_exception(exception.original, :default, trace) end arr.flatten.join("\n") end def log_and_raise(exception, message) log_exception(exception, message) raise exception, message + "\n" + exception.to_s, exception.backtrace end class DeprecationWarning < Exception; end - # Logs a warning indicating that the code path is deprecated. Note that this - # method keeps track of the offending lines of code that triggered the + # Logs a warning indicating that the Ruby code path is deprecated. Note that + # this method keeps track of the offending lines of code that triggered the # deprecation warning, and will only log a warning once per offending line of # code. It will also stop logging deprecation warnings altogether after 100 - # unique deprecation warnings have been logged. + # unique deprecation warnings have been logged. Finally, if + # Puppet[:disable_warnings] includes 'deprecations', it will squelch all + # warning calls made via this method. # - # @param [String] message The message to log (logs via ) - # @param [String] key Optional key to mark the message as unique. If not + # @param message [String] The message to log (logs via warning) + # @param key [String] Optional key to mark the message as unique. If not # passed in, the originating call line will be used instead. def deprecation_warning(message, key = nil) - return if Puppet[:disable_warnings].include?('deprecations') - $deprecation_warnings ||= {} - if $deprecation_warnings.length < 100 then - key ||= (offender = get_deprecation_offender) - if (! $deprecation_warnings.has_key?(key)) then - $deprecation_warnings[key] = message - warning("#{message}\n (at #{(offender || get_deprecation_offender).join('; ')})") - end - end + issue_deprecation_warning(message, key, nil, nil, true) + end + + # Logs a warning whose origin comes from Puppet source rather than somewhere + # internal within Puppet. Otherwise the same as deprecation_warning() + # + # @param message [String] The message to log (logs via warning) + # @param options [Hash] + # @option options [String] :file File we are warning from + # @option options [Integer] :line Line number we are warning from + # @option options [String] :key (:file + :line) Alternative key used to mark + # warning as unique + # + # Either :file and :line and/or :key must be passed. + def puppet_deprecation_warning(message, options = {}) + key = options[:key] + file = options[:file] + line = options[:line] + raise(Puppet::DevError, "Need either :file and :line, or :key") if (key.nil?) && (file.nil? || line.nil?) + + key ||= "#{file}:#{line}" + issue_deprecation_warning(message, key, file, line, false) end def get_deprecation_offender() # we have to put this in its own method to simplify testing; we need to be able to mock the offender results in # order to test this class, and our framework does not appear to enjoy it if you try to mock Kernel.caller # # let's find the offending line; we need to jump back up the stack a few steps to find the method that called # the deprecated method if Puppet[:trace] caller()[2..-1] else [caller()[2]] end end def clear_deprecation_warnings $deprecation_warnings.clear if $deprecation_warnings end # TODO: determine whether there might be a potential use for adding a puppet configuration option that would # enable this deprecation logging. # utility method that can be called, e.g., from spec_helper config.after, when tracking down calls to deprecated # code. # Parameters: # [deprecations_file] relative or absolute path of a file to log the deprecations to # [pattern] (default nil) if specified, will only log deprecations whose message matches the provided pattern def log_deprecations_to_file(deprecations_file, pattern = nil) # this method may get called lots and lots of times (e.g., from spec_helper config.after) without the global # list of deprecation warnings being cleared out. We don't want to keep logging the same offenders over and over, # so, we need to keep track of what we've logged. # # It'd be nice if we could just clear out the list of deprecation warnings, but then the very next spec might # find the same offender, and we'd end up logging it again. $logged_deprecation_warnings ||= {} File.open(deprecations_file, "a") do |f| if ($deprecation_warnings) then $deprecation_warnings.each do |offender, message| if (! $logged_deprecation_warnings.has_key?(offender)) then $logged_deprecation_warnings[offender] = true if ((pattern.nil?) || (message =~ pattern)) then f.puts(message) f.puts(offender) f.puts() end end end end end end private + def issue_deprecation_warning(message, key, file, line, use_caller) + return if Puppet[:disable_warnings].include?('deprecations') + $deprecation_warnings ||= {} + if $deprecation_warnings.length < 100 then + key ||= (offender = get_deprecation_offender) + if (! $deprecation_warnings.has_key?(key)) then + $deprecation_warnings[key] = message + call_trace = use_caller ? + (offender || get_deprecation_offender).join('; ') : + "#{file || 'unknown'}:#{line || 'unknown'}" + warning("#{message}\n (at #{call_trace})") + end + end + end + def is_resource? defined?(Puppet::Type) && is_a?(Puppet::Type) end def is_resource_parameter? defined?(Puppet::Parameter) && is_a?(Puppet::Parameter) end def log_metadata [:file, :line, :tags].inject({}) do |result, attr| result[attr] = send(attr) if respond_to?(attr) result end end def log_source # We need to guard the existence of the constants, since this module is used by the base Puppet module. (is_resource? or is_resource_parameter?) and respond_to?(:path) and return path.to_s to_s end end diff --git a/spec/unit/util/logging_spec.rb b/spec/unit/util/logging_spec.rb index 7eba80bca..abdae9189 100755 --- a/spec/unit/util/logging_spec.rb +++ b/spec/unit/util/logging_spec.rb @@ -1,167 +1,205 @@ #! /usr/bin/env ruby require 'spec_helper' require 'puppet/util/logging' class LoggingTester include Puppet::Util::Logging end describe Puppet::Util::Logging do before do @logger = LoggingTester.new end Puppet::Util::Log.eachlevel do |level| it "should have a method for sending '#{level}' logs" do @logger.should respond_to(level) end end it "should have a method for sending a log with a specified log level" do @logger.expects(:to_s).returns "I'm a string!" Puppet::Util::Log.expects(:create).with { |args| args[:source] == "I'm a string!" and args[:level] == "loglevel" and args[:message] == "mymessage" } @logger.send_log "loglevel", "mymessage" end describe "when sending a log" do it "should use the Log's 'create' entrance method" do Puppet::Util::Log.expects(:create) @logger.notice "foo" end it "should send itself converted to a string as the log source" do @logger.expects(:to_s).returns "I'm a string!" Puppet::Util::Log.expects(:create).with { |args| args[:source] == "I'm a string!" } @logger.notice "foo" end it "should queue logs sent without a specified destination" do Puppet::Util::Log.close_all Puppet::Util::Log.expects(:queuemessage) @logger.notice "foo" end it "should use the path of any provided resource type" do resource = Puppet::Type.type(:host).new :name => "foo" resource.expects(:path).returns "/path/to/host".to_sym Puppet::Util::Log.expects(:create).with { |args| args[:source] == "/path/to/host" } resource.notice "foo" end it "should use the path of any provided resource parameter" do resource = Puppet::Type.type(:host).new :name => "foo" param = resource.parameter(:name) param.expects(:path).returns "/path/to/param".to_sym Puppet::Util::Log.expects(:create).with { |args| args[:source] == "/path/to/param" } param.notice "foo" end it "should send the provided argument as the log message" do Puppet::Util::Log.expects(:create).with { |args| args[:message] == "foo" } @logger.notice "foo" end it "should join any provided arguments into a single string for the message" do Puppet::Util::Log.expects(:create).with { |args| args[:message] == "foo bar baz" } @logger.notice ["foo", "bar", "baz"] end [:file, :line, :tags].each do |attr| it "should include #{attr} if available" do @logger.singleton_class.send(:attr_accessor, attr) @logger.send(attr.to_s + "=", "myval") Puppet::Util::Log.expects(:create).with { |args| args[attr] == "myval" } @logger.notice "foo" end end end describe "when sending a deprecation warning" do it "does not log a message when deprecation warnings are disabled" do Puppet.expects(:[]).with(:disable_warnings).returns %w[deprecations] @logger.expects(:warning).never @logger.deprecation_warning 'foo' end it "logs the message with warn" do @logger.expects(:warning).with do |msg| msg =~ /^foo\n/ end @logger.deprecation_warning 'foo' end it "only logs each offending line once" do @logger.expects(:warning).with do |msg| msg =~ /^foo\n/ end .once 5.times { @logger.deprecation_warning 'foo' } end it "ensures that deprecations from same origin are logged if their keys differ" do @logger.expects(:warning).with(regexp_matches(/deprecated foo/)).times(5) 5.times { |i| @logger.deprecation_warning('deprecated foo', :key => "foo#{i}") } end it "does not duplicate deprecations for a given key" do @logger.expects(:warning).with(regexp_matches(/deprecated foo/)).once 5.times { @logger.deprecation_warning('deprecated foo', :key => 'foo-msg') } end it "only logs the first 100 messages" do (1..100).each { |i| @logger.expects(:warning).with do |msg| msg =~ /^#{i}\n/ end .once # since the deprecation warning will only log each offending line once, we have to do some tomfoolery # here in order to make it think each of these calls is coming from a unique call stack; we're basically # mocking the method that it would normally use to find the call stack. @logger.expects(:get_deprecation_offender).returns(["deprecation log count test ##{i}"]) @logger.deprecation_warning i } @logger.expects(:warning).with(101).never @logger.deprecation_warning 101 end end + describe "when sending a puppet_deprecation_warning" do + it "requires file and line or key options" do + expect do + @logger.puppet_deprecation_warning("foo") + end.to raise_error(Puppet::DevError, /Need either :file and :line, or :key/) + expect do + @logger.puppet_deprecation_warning("foo", :file => 'bar') + end.to raise_error(Puppet::DevError, /Need either :file and :line, or :key/) + expect do + @logger.puppet_deprecation_warning("foo", :key => 'akey') + @logger.puppet_deprecation_warning("foo", :file => 'afile', :line => 1) + end.to_not raise_error + end + + it "warns with file and line" do + @logger.expects(:warning).with(regexp_matches(/deprecated foo.*afile:5/m)) + @logger.puppet_deprecation_warning("deprecated foo", :file => 'afile', :line => 5) + end + + it "warns keyed from file and line" do + @logger.expects(:warning).with(regexp_matches(/deprecated foo.*afile:5/m)).once + 5.times do + @logger.puppet_deprecation_warning("deprecated foo", :file => 'afile', :line => 5) + end + end + + it "warns with separate key only once regardless of file and line" do + @logger.expects(:warning).with(regexp_matches(/deprecated foo.*afile:5/m)).once + @logger.puppet_deprecation_warning("deprecated foo", :key => 'some_key', :file => 'afile', :line => 5) + @logger.puppet_deprecation_warning("deprecated foo", :key => 'some_key', :file => 'bfile', :line => 3) + end + + it "warns with key but no file and line" do + @logger.expects(:warning).with(regexp_matches(/deprecated foo.*unknown:unknown/m)) + @logger.puppet_deprecation_warning("deprecated foo", :key => 'some_key') + end + end + describe "when formatting exceptions" do it "should be able to format a chain of exceptions" do exc3 = Puppet::Error.new("original") exc3.set_backtrace(["1.rb:4:in `a'","2.rb:2:in `b'","3.rb:1"]) exc2 = Puppet::Error.new("second", exc3) exc2.set_backtrace(["4.rb:8:in `c'","5.rb:1:in `d'","6.rb:3"]) exc1 = Puppet::Error.new("third", exc2) exc1.set_backtrace(["7.rb:31:in `e'","8.rb:22:in `f'","9.rb:9"]) # whoa ugly @logger.format_exception(exc1).should =~ /third .*7\.rb:31:in `e' .*8\.rb:22:in `f' .*9\.rb:9 Wrapped exception: second .*4\.rb:8:in `c' .*5\.rb:1:in `d' .*6\.rb:3 Wrapped exception: original .*1\.rb:4:in `a' .*2\.rb:2:in `b' .*3\.rb:1/ end end end