diff --git a/lib/puppet/transaction/resource_harness.rb b/lib/puppet/transaction/resource_harness.rb index 3f02c1436..a693fbb49 100644 --- a/lib/puppet/transaction/resource_harness.rb +++ b/lib/puppet/transaction/resource_harness.rb @@ -1,238 +1,251 @@ require 'puppet/resource/status' class Puppet::Transaction::ResourceHarness NO_ACTION = Object.new extend Forwardable def_delegators :@transaction, :relationship_graph attr_reader :transaction def initialize(transaction) @transaction = transaction end def evaluate(resource) status = Puppet::Resource::Status.new(resource) begin context = ResourceApplicationContext.from_resource(resource, status) perform_changes(resource, context) if status.changed? && ! resource.noop? cache(resource, :synced, Time.now) resource.flush if resource.respond_to?(:flush) end rescue => detail status.failed_because(detail) ensure status.evaluation_time = Time.now - status.time end status end def scheduled?(resource) return true if Puppet[:ignoreschedules] return true unless schedule = schedule(resource) # We use 'checked' here instead of 'synced' because otherwise we'll # end up checking most resources most times, because they will generally # have been synced a long time ago (e.g., a file only gets updated # once a month on the server and its schedule is daily; the last sync time # will have been a month ago, so we'd end up checking every run). schedule.match?(cached(resource, :checked).to_i) end def schedule(resource) unless resource.catalog resource.warning "Cannot schedule without a schedule-containing catalog" return nil end return nil unless name = resource[:schedule] resource.catalog.resource(:schedule, name) || resource.fail("Could not find schedule #{name}") end # Used mostly for scheduling and auditing at this point. def cached(resource, name) Puppet::Util::Storage.cache(resource)[name] end # Used mostly for scheduling and auditing at this point. def cache(resource, name, value) Puppet::Util::Storage.cache(resource)[name] = value end private def perform_changes(resource, context) cache(resource, :checked, Time.now) return [] if ! allow_changes?(resource) # Record the current state in state.yml. context.audited_params.each do |param| cache(resource, param, context.current_values[param]) end ensure_param = resource.parameter(:ensure) if ensure_param && ensure_param.should ensure_event = sync_if_needed(ensure_param, context) else ensure_event = NO_ACTION end if ensure_event == NO_ACTION if context.resource_present? resource.properties.each do |param| sync_if_needed(param, context) end else resource.debug("Nothing to manage: no ensure and the resource doesn't exist") end end capture_audit_events(resource, context) end def allow_changes?(resource) if resource.purging? and resource.deleting? and deps = relationship_graph.dependents(resource) \ and ! deps.empty? and deps.detect { |d| ! d.deleting? } deplabel = deps.collect { |r| r.ref }.join(",") plurality = deps.length > 1 ? "":"s" resource.warning "#{deplabel} still depend#{plurality} on me -- not purging" false else true end end def sync_if_needed(param, context) historical_value = context.historical_values[param.name] current_value = context.current_values[param.name] do_audit = context.audited_params.include?(param.name) begin if param.should && !param.safe_insync?(current_value) event = create_change_event(param, current_value, historical_value) if do_audit event = audit_event(event, param) end brief_audit_message = audit_message(param, do_audit, historical_value, current_value) if param.noop noop(event, param, current_value, brief_audit_message) else sync(event, param, current_value, brief_audit_message) end event else NO_ACTION end rescue => detail # Execution will continue on StandardErrors, just store the event Puppet.log_exception(detail) event = create_change_event(param, current_value, historical_value) event.status = "failure" event.message = "change from #{param.is_to_s(current_value)} to #{param.should_to_s(param.should)} failed: #{detail}" event rescue Exception => detail # Execution will halt on Exceptions, they get raised to the application event = create_change_event(param, current_value, historical_value) event.status = "failure" event.message = "change from #{param.is_to_s(current_value)} to #{param.should_to_s(param.should)} failed: #{detail}" raise ensure if event context.record(event) event.send_log context.synced_params << param.name end end end def create_change_event(property, current_value, historical_value) event = property.event event.previous_value = current_value event.desired_value = property.should event.historical_value = historical_value event end + # This method is an ugly hack because, given a Time object with nanosecond + # resolution, roundtripped through YAML serialization, the Time object will + # be truncated to microseconds. + # For audit purposes, this code special cases this comparison, and compares + # the two objects by their second and microsecond components. tv_sec is the + # number of seconds since the epoch, and tv_usec is only the microsecond + # portion of time. This compare satisfies compatibility requirements for + # Ruby 1.8.7, where to_r does not exist on the Time class. + def are_audited_values_equal(a, b) + a == b || (a.is_a?(Time) && a.tv_sec == b.tv_sec && a.tv_usec == b.tv_usec) + end + private :are_audited_values_equal + def audit_event(event, property) event.audited = true event.status = "audit" - if event.historical_value != event.previous_value + if !are_audited_values_equal(event.historical_value, event.previous_value) event.message = "audit change: previously recorded value #{property.is_to_s(event.historical_value)} has been changed to #{property.is_to_s(event.previous_value)}" end event end def audit_message(param, do_audit, historical_value, current_value) - if do_audit && historical_value && historical_value != current_value + if do_audit && historical_value && !are_audited_values_equal(historical_value, current_value) " (previously recorded value was #{param.is_to_s(historical_value)})" else "" end end def noop(event, param, current_value, audit_message) event.message = "current_value #{param.is_to_s(current_value)}, should be #{param.should_to_s(param.should)} (noop)#{audit_message}" event.status = "noop" end def sync(event, param, current_value, audit_message) param.sync event.message = "#{param.change_to_s(current_value, param.should)}#{audit_message}" event.status = "success" end def capture_audit_events(resource, context) context.audited_params.each do |param_name| if context.historical_values.include?(param_name) - if context.historical_values[param_name] != context.current_values[param_name] && !context.synced_params.include?(param_name) + if !are_audited_values_equal(context.historical_values[param_name], context.current_values[param_name]) && !context.synced_params.include?(param_name) parameter = resource.parameter(param_name) event = audit_event(create_change_event(parameter, context.current_values[param_name], context.historical_values[param_name]), parameter) event.send_log context.record(event) end else resource.property(param_name).notice "audit change: newly-recorded value #{context.current_values[param_name]}" end end end # @api private ResourceApplicationContext = Struct.new(:resource, :current_values, :historical_values, :audited_params, :synced_params, :status) do def self.from_resource(resource, status) ResourceApplicationContext.new(resource, resource.retrieve_resource.to_hash, Puppet::Util::Storage.cache(resource).dup, (resource[:audit] || []).map { |p| p.to_sym }, [], status) end def resource_present? resource.present?(current_values) end def record(event) status << event end end end diff --git a/spec/unit/transaction/resource_harness_spec.rb b/spec/unit/transaction/resource_harness_spec.rb index 5eeaf0ba4..7d9c6f439 100755 --- a/spec/unit/transaction/resource_harness_spec.rb +++ b/spec/unit/transaction/resource_harness_spec.rb @@ -1,478 +1,542 @@ #! /usr/bin/env ruby require 'spec_helper' require 'puppet/transaction/resource_harness' describe Puppet::Transaction::ResourceHarness do include PuppetSpec::Files before do @mode_750 = Puppet.features.microsoft_windows? ? '644' : '750' @mode_755 = Puppet.features.microsoft_windows? ? '644' : '755' path = make_absolute("/my/file") @transaction = Puppet::Transaction.new(Puppet::Resource::Catalog.new, nil, nil) @resource = Puppet::Type.type(:file).new :path => path @harness = Puppet::Transaction::ResourceHarness.new(@transaction) @current_state = Puppet::Resource.new(:file, path) @resource.stubs(:retrieve).returns @current_state end it "should accept a transaction at initialization" do harness = Puppet::Transaction::ResourceHarness.new(@transaction) harness.transaction.should equal(@transaction) end it "should delegate to the transaction for its relationship graph" do @transaction.expects(:relationship_graph).returns "relgraph" Puppet::Transaction::ResourceHarness.new(@transaction).relationship_graph.should == "relgraph" end describe "when evaluating a resource" do it "produces a resource state that describes what happened with the resource" do status = @harness.evaluate(@resource) status.resource.should == @resource.ref status.should_not be_failed status.events.should be_empty end it "retrieves the current state of the resource" do @resource.expects(:retrieve).returns @current_state @harness.evaluate(@resource) end it "produces a failure status for the resource when an error occurs" do the_message = "retrieve failed in testing" @resource.expects(:retrieve).raises(ArgumentError.new(the_message)) status = @harness.evaluate(@resource) status.should be_failed events_to_hash(status.events).collect do |event| { :@status => event[:@status], :@message => event[:@message] } end.should == [{ :@status => "failure", :@message => the_message }] end it "records the time it took to evaluate the resource" do before = Time.now status = @harness.evaluate(@resource) after = Time.now status.evaluation_time.should be <= after - before end end def events_to_hash(events) events.map do |event| hash = {} event.instance_variables.each do |varname| hash[varname.to_sym] = event.instance_variable_get(varname) end hash end end def make_stub_provider stubProvider = Class.new(Puppet::Type) stubProvider.instance_eval do initvars newparam(:name) do desc "The name var" isnamevar end newproperty(:foo) do desc "A property that can be changed successfully" def sync end def retrieve :absent end def insync?(reference_value) false end end newproperty(:bar) do desc "A property that raises an exception when you try to change it" def sync raise ZeroDivisionError.new('bar') end def retrieve :absent end def insync?(reference_value) false end end newproperty(:baz) do desc "A property that raises an Exception (not StandardError) when you try to change it" def sync raise Exception.new('baz') end def retrieve :absent end def insync?(reference_value) false end end newproperty(:brillig) do desc "A property that raises a StandardError exception when you test if it's insync?" def sync end def retrieve :absent end def insync?(reference_value) raise ZeroDivisionError.new('brillig') end end newproperty(:slithy) do desc "A property that raises an Exception when you test if it's insync?" def sync end def retrieve :absent end def insync?(reference_value) raise Exception.new('slithy') end end end stubProvider end context "interaction of ensure with other properties" do def an_ensurable_resource_reacting_as(behaviors) stub_type = Class.new(Puppet::Type) stub_type.class_eval do initvars ensurable do def sync (@resource.behaviors[:on_ensure] || proc {}).call end def insync?(value) @resource.behaviors[:ensure_insync?] end end newparam(:name) do desc "The name var" isnamevar end newproperty(:prop) do newvalue("new") do #noop end def retrieve "old" end end attr_reader :behaviors def initialize(options) @behaviors = options.delete(:behaviors) super end def exists? @behaviors[:present?] end def present?(resource) @behaviors[:present?] end def self.name "Testing" end end stub_type.new(:behaviors => behaviors, :ensure => :present, :name => "testing", :prop => "new") end it "ensure errors means that the rest doesn't happen" do resource = an_ensurable_resource_reacting_as(:ensure_insync? => false, :on_ensure => proc { raise StandardError }, :present? => true) status = @harness.evaluate(resource) expect(status.events.length).to eq(1) expect(status.events[0].property).to eq('ensure') expect(status.events[0].name.to_s).to eq('Testing_created') expect(status.events[0].status).to eq('failure') end it "ensure fails completely means that the rest doesn't happen" do resource = an_ensurable_resource_reacting_as(:ensure_insync? => false, :on_ensure => proc { raise Exception }, :present? => false) expect do @harness.evaluate(resource) end.to raise_error(Exception) @logs.first.message.should == "change from absent to present failed: Exception" @logs.first.level.should == :err end it "ensure succeeds means that the rest doesn't happen" do resource = an_ensurable_resource_reacting_as(:ensure_insync? => false, :on_ensure => proc { }, :present? => true) status = @harness.evaluate(resource) expect(status.events.length).to eq(1) expect(status.events[0].property).to eq('ensure') expect(status.events[0].name.to_s).to eq('Testing_created') expect(status.events[0].status).to eq('success') end it "ensure is in sync means that the rest *does* happen" do resource = an_ensurable_resource_reacting_as(:ensure_insync? => true, :present? => true) status = @harness.evaluate(resource) expect(status.events.length).to eq(1) expect(status.events[0].property).to eq('prop') expect(status.events[0].name.to_s).to eq('prop_changed') expect(status.events[0].status).to eq('success') end it "ensure is in sync but resource not present, means that the rest doesn't happen" do resource = an_ensurable_resource_reacting_as(:ensure_insync? => true, :present? => false) status = @harness.evaluate(resource) expect(status.events).to be_empty end end describe "when a caught error occurs" do before :each do stub_provider = make_stub_provider resource = stub_provider.new :name => 'name', :foo => 1, :bar => 2 resource.expects(:err).never @status = @harness.evaluate(resource) end it "should record previous successful events" do @status.events[0].property.should == 'foo' @status.events[0].status.should == 'success' end it "should record a failure event" do @status.events[1].property.should == 'bar' @status.events[1].status.should == 'failure' end end describe "when an Exception occurs during sync" do before :each do stub_provider = make_stub_provider @resource = stub_provider.new :name => 'name', :baz => 1 @resource.expects(:err).never end it "should log and pass the exception through" do lambda { @harness.evaluate(@resource) }.should raise_error(Exception, /baz/) @logs.first.message.should == "change from absent to 1 failed: baz" @logs.first.level.should == :err end end describe "when a StandardError exception occurs during insync?" do before :each do stub_provider = make_stub_provider @resource = stub_provider.new :name => 'name', :brillig => 1 @resource.expects(:err).never end it "should record a failure event" do @status = @harness.evaluate(@resource) @status.events[0].name.to_s.should == 'brillig_changed' @status.events[0].property.should == 'brillig' @status.events[0].status.should == 'failure' end end describe "when an Exception occurs during insync?" do before :each do stub_provider = make_stub_provider @resource = stub_provider.new :name => 'name', :slithy => 1 @resource.expects(:err).never end it "should log and pass the exception through" do lambda { @harness.evaluate(@resource) }.should raise_error(Exception, /slithy/) @logs.first.message.should == "change from absent to 1 failed: slithy" @logs.first.level.should == :err end end describe "when auditing" do it "should not call insync? on parameters that are merely audited" do stub_provider = make_stub_provider resource = stub_provider.new :name => 'name', :audit => ['foo'] resource.property(:foo).expects(:insync?).never status = @harness.evaluate(resource) expect(status.events).to be_empty end it "should be able to audit a file's group" do # see bug #5710 test_file = tmpfile('foo') File.open(test_file, 'w').close resource = Puppet::Type.type(:file).new :path => test_file, :audit => ['group'], :backup => false resource.expects(:err).never # make sure no exceptions get swallowed status = @harness.evaluate(resource) status.events.each do |event| event.status.should != 'failure' end end + + it "should not ignore microseconds when auditing a file's mtime" do + test_file = tmpfile('foo') + File.open(test_file, 'w').close + resource = Puppet::Type.type(:file).new :path => test_file, :audit => ['mtime'], :backup => false + + # construct a property hash with nanosecond resolution as would be + # found on an ext4 file system + time_with_nsec_resolution = Time.at(1000, 123456.999) + current_from_filesystem = {:mtime => time_with_nsec_resolution} + + # construct a property hash with a 1 microsecond difference from above + time_with_usec_resolution = Time.at(1000, 123457.000) + historical_from_state_yaml = {:mtime => time_with_usec_resolution} + + # set up the sequence of stubs; yeah, this is pretty + # brittle, so this might need to be adjusted if the + # resource_harness logic changes + resource.expects(:retrieve).returns(current_from_filesystem) + Puppet::Util::Storage.stubs(:cache).with(resource). + returns(historical_from_state_yaml).then. + returns(current_from_filesystem).then. + returns(current_from_filesystem) + + # there should be an audit change recorded, since the two + # timestamps differ by at least 1 microsecond + status = @harness.evaluate(resource) + status.events.should_not be_empty + status.events.each do |event| + event.message.should =~ /audit change: previously recorded/ + end + end + + it "should ignore nanoseconds when auditing a file's mtime" do + test_file = tmpfile('foo') + File.open(test_file, 'w').close + resource = Puppet::Type.type(:file).new :path => test_file, :audit => ['mtime'], :backup => false + + # construct a property hash with nanosecond resolution as would be + # found on an ext4 file system + time_with_nsec_resolution = Time.at(1000, 123456.789) + current_from_filesystem = {:mtime => time_with_nsec_resolution} + + # construct a property hash with the same timestamp as above, + # truncated to microseconds, as would be read back from state.yaml + time_with_usec_resolution = Time.at(1000, 123456.000) + historical_from_state_yaml = {:mtime => time_with_usec_resolution} + + # set up the sequence of stubs; yeah, this is pretty + # brittle, so this might need to be adjusted if the + # resource_harness logic changes + resource.expects(:retrieve).returns(current_from_filesystem) + Puppet::Util::Storage.stubs(:cache).with(resource). + returns(historical_from_state_yaml).then. + returns(current_from_filesystem).then. + returns(current_from_filesystem) + + # there should be no audit change recorded, despite the + # slight difference in the two timestamps + status = @harness.evaluate(resource) + status.events.each do |event| + event.message.should_not =~ /audit change: previously recorded/ + end + end end describe "when applying changes" do it "should not apply changes if allow_changes?() returns false" do test_file = tmpfile('foo') resource = Puppet::Type.type(:file).new :path => test_file, :backup => false, :ensure => :file resource.expects(:err).never # make sure no exceptions get swallowed @harness.expects(:allow_changes?).with(resource).returns false status = @harness.evaluate(resource) Puppet::FileSystem.exist?(test_file).should == false end end describe "when determining whether the resource can be changed" do before do @resource.stubs(:purging?).returns true @resource.stubs(:deleting?).returns true end it "should be true if the resource is not being purged" do @resource.expects(:purging?).returns false @harness.should be_allow_changes(@resource) end it "should be true if the resource is not being deleted" do @resource.expects(:deleting?).returns false @harness.should be_allow_changes(@resource) end it "should be true if the resource has no dependents" do @harness.relationship_graph.expects(:dependents).with(@resource).returns [] @harness.should be_allow_changes(@resource) end it "should be true if all dependents are being deleted" do dep = stub 'dependent', :deleting? => true @harness.relationship_graph.expects(:dependents).with(@resource).returns [dep] @resource.expects(:purging?).returns true @harness.should be_allow_changes(@resource) end it "should be false if the resource's dependents are not being deleted" do dep = stub 'dependent', :deleting? => false, :ref => "myres" @resource.expects(:warning) @harness.relationship_graph.expects(:dependents).with(@resource).returns [dep] @harness.should_not be_allow_changes(@resource) end end describe "when finding the schedule" do before do @catalog = Puppet::Resource::Catalog.new @resource.catalog = @catalog end it "should warn and return nil if the resource has no catalog" do @resource.catalog = nil @resource.expects(:warning) @harness.schedule(@resource).should be_nil end it "should return nil if the resource specifies no schedule" do @harness.schedule(@resource).should be_nil end it "should fail if the named schedule cannot be found" do @resource[:schedule] = "whatever" @resource.expects(:fail) @harness.schedule(@resource) end it "should return the named schedule if it exists" do sched = Puppet::Type.type(:schedule).new(:name => "sched") @catalog.add_resource(sched) @resource[:schedule] = "sched" @harness.schedule(@resource).to_s.should == sched.to_s end end describe "when determining if a resource is scheduled" do before do @catalog = Puppet::Resource::Catalog.new @resource.catalog = @catalog end it "should return true if 'ignoreschedules' is set" do Puppet[:ignoreschedules] = true @resource[:schedule] = "meh" @harness.should be_scheduled(@resource) end it "should return true if the resource has no schedule set" do @harness.should be_scheduled(@resource) end it "should return the result of matching the schedule with the cached 'checked' time if a schedule is set" do t = Time.now @harness.expects(:cached).with(@resource, :checked).returns(t) sched = Puppet::Type.type(:schedule).new(:name => "sched") @catalog.add_resource(sched) @resource[:schedule] = "sched" sched.expects(:match?).with(t.to_i).returns "feh" @harness.scheduled?(@resource).should == "feh" end end it "should be able to cache data in the Storage module" do data = {} Puppet::Util::Storage.expects(:cache).with(@resource).returns data @harness.cache(@resource, :foo, "something") data[:foo].should == "something" end it "should be able to retrieve data from the cache" do data = {:foo => "other"} Puppet::Util::Storage.expects(:cache).with(@resource).returns data @harness.cached(@resource, :foo).should == "other" end end