diff --git a/lib/puppet/transaction/event.rb b/lib/puppet/transaction/event.rb index 64980f1d9..cd695cff8 100644 --- a/lib/puppet/transaction/event.rb +++ b/lib/puppet/transaction/event.rb @@ -1,67 +1,66 @@ require 'puppet/transaction' require 'puppet/util/tagging' require 'puppet/util/logging' # A simple struct for storing what happens on the system. class Puppet::Transaction::Event include Puppet::Util::Tagging include Puppet::Util::Logging ATTRIBUTES = [:name, :resource, :property, :previous_value, :desired_value, :historical_value, :status, :message, :file, :line, :source_description, :audited] YAML_ATTRIBUTES = %w{@audited @property @previous_value @desired_value @historical_value @message @name @status @time} attr_accessor *ATTRIBUTES attr_writer :tags attr_accessor :time attr_reader :default_log_level EVENT_STATUSES = %w{noop success failure audit} - def initialize(*args) + def initialize(options = {}) @audited = false - options = args.last.is_a?(Hash) ? args.pop : ATTRIBUTES.inject({}) { |hash, attr| hash[attr] = args.pop; hash } - options.each { |attr, value| send(attr.to_s + "=", value) unless value.nil? } + options.each { |attr, value| send(attr.to_s + "=", value) } @time = Time.now end def property=(prop) @property = prop.to_s end def resource=(res) if res.respond_to?(:[]) and level = res[:loglevel] @default_log_level = level end @resource = res.to_s end def send_log super(log_level, message) end def status=(value) raise ArgumentError, "Event status can only be #{EVENT_STATUSES.join(', ')}" unless EVENT_STATUSES.include?(value) @status = value end def to_s message end def to_yaml_properties (YAML_ATTRIBUTES & instance_variables).sort end private # If it's a failure, use 'err', else use either the resource's log level (if available) # or 'notice'. def log_level status == "failure" ? :err : (@default_log_level || :notice) end # Used by the Logging module def log_source source_description || property || resource end end diff --git a/lib/puppet/transaction/resource_harness.rb b/lib/puppet/transaction/resource_harness.rb index cb9a193b9..c259d3e05 100644 --- a/lib/puppet/transaction/resource_harness.rb +++ b/lib/puppet/transaction/resource_harness.rb @@ -1,191 +1,193 @@ require 'puppet/resource/status' class Puppet::Transaction::ResourceHarness extend Forwardable def_delegators :@transaction, :relationship_graph attr_reader :transaction 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 # 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 def perform_changes(resource) current = resource.retrieve_resource cache resource, :checked, Time.now return [] if ! allow_changes?(resource) current_values = current.to_hash historical_values = Puppet::Util::Storage.cache(resource).dup desired_values = resource.to_resource.to_hash audited_params = (resource[:audit] || []).map { |p| p.to_sym } synced_params = [] # Record the current state in state.yml. audited_params.each do |param| cache(resource, param, current_values[param]) end # Update the machine state & create logs/events events = [] ensure_param = resource.parameter(:ensure) if desired_values[:ensure] && !ensure_param.insync?(current_values[:ensure]) events << apply_parameter(ensure_param, current_values[:ensure], audited_params.include?(:ensure), historical_values[:ensure]) synced_params << :ensure elsif current_values[:ensure] != :absent work_order = resource.properties # Note: only the resource knows what order to apply changes in work_order.each do |param| if !param.insync?(current_values[param.name]) events << apply_parameter(param, current_values[param.name], audited_params.include?(param.name), historical_values[param.name]) synced_params << param.name end end end # Add more events to capture audit results audited_params.each do |param_name| if historical_values.include?(param_name) if historical_values[param_name] != current_values[param_name] && !synced_params.include?(param_name) event = create_change_event(resource.parameter(param_name), current_values[param_name], true, historical_values[param_name]) event.send_log events << event end else resource.property(param_name).notice "audit change: newly-recorded value #{current_values[param_name]}" end end events end def create_change_event(property, current_value, do_audit, historical_value) event = property.event event.previous_value = current_value event.desired_value = property.should event.historical_value = historical_value - if do_audit and historical_value != current_value - event.message = "audit change: previously recorded value #{property.is_to_s(historical_value)} has been changed to #{property.is_to_s(current_value)}" - event.status = "audit" + if do_audit event.audited = true + event.status = "audit" + if historical_value != current_value + event.message = "audit change: previously recorded value #{property.is_to_s(historical_value)} has been changed to #{property.is_to_s(current_value)}" + end end event end def apply_parameter(property, current_value, do_audit, historical_value) event = create_change_event(property, current_value, do_audit, historical_value) - if event.audited && historical_value + if do_audit && historical_value && historical_value != current_value brief_audit_message = " (previously recorded value was #{property.is_to_s(historical_value)})" else brief_audit_message = "" end if property.noop event.message = "current_value #{property.is_to_s(current_value)}, should be #{property.should_to_s(property.should)} (noop)#{brief_audit_message}" event.status = "noop" else property.sync event.message = [ property.change_to_s(current_value, property.should), brief_audit_message ].join event.status = "success" end event rescue => detail puts detail.backtrace if Puppet[:trace] event.status = "failure" event.message = "change from #{property.is_to_s(current_value)} to #{property.should_to_s(property.should)} failed: #{detail}" event ensure event.send_log end def evaluate(resource) start = Time.now status = Puppet::Resource::Status.new(resource) perform_changes(resource).each do |event| status << event end if status.changed? && ! resource.noop? cache(resource, :synced, Time.now) resource.flush if resource.respond_to?(:flush) end return status rescue => detail resource.fail "Could not create resource status: #{detail}" unless status puts detail.backtrace if Puppet[:trace] resource.err "Could not evaluate: #{detail}" status.failed = true return status ensure (status.evaluation_time = Time.now - start) if status end def initialize(transaction) @transaction = transaction end def scheduled?(status, 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 private def absent_and_not_being_created?(current, param) current[:ensure] == :absent and param.should.nil? end def ensure_is_insync?(current, param) param.insync?(current[:ensure]) end def ensure_should_be_absent?(current, param) param.should == :absent end def param_is_insync?(current, param) param.insync?(current[param.name]) end end diff --git a/spec/unit/transaction/resource_harness_spec.rb b/spec/unit/transaction/resource_harness_spec.rb index 771c7b4b0..65c148a93 100755 --- a/spec/unit/transaction/resource_harness_spec.rb +++ b/spec/unit/transaction/resource_harness_spec.rb @@ -1,348 +1,398 @@ #!/usr/bin/env ruby require File.dirname(__FILE__) + '/../../spec_helper' require 'puppet_spec/files' require 'puppet/transaction/resource_harness' describe Puppet::Transaction::ResourceHarness do include PuppetSpec::Files before do @transaction = Puppet::Transaction.new(Puppet::Resource::Catalog.new) @resource = Puppet::Type.type(:file).new :path => "/my/file" @harness = Puppet::Transaction::ResourceHarness.new(@transaction) @current_state = Puppet::Resource.new(:file, "/my/file") @resource.stubs(:retrieve).returns @current_state @status = Puppet::Resource::Status.new(@resource) Puppet::Resource::Status.stubs(:new).returns @status 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 "should create and return a resource status instance for the resource" do @harness.evaluate(@resource).should be_instance_of(Puppet::Resource::Status) end it "should fail if no status can be created" do Puppet::Resource::Status.expects(:new).raises ArgumentError lambda { @harness.evaluate(@resource) }.should raise_error end it "should retrieve the current state of the resource" do @resource.expects(:retrieve).returns @current_state @harness.evaluate(@resource) end it "should mark the resource as failed and return if the current state cannot be retrieved" do @resource.expects(:retrieve).raises ArgumentError @harness.evaluate(@resource).should be_failed end it "should store the resource's evaluation time in the resource status" do @harness.evaluate(@resource).evaluation_time.should be_instance_of(Float) end end + def events_to_hash(events) + events.map do |event| + hash = {} + event.instance_variables.each do |varname| + hash[varname] = event.instance_variable_get(varname.to_sym) + end + hash + end + end + describe "when applying changes" do [false, true].each do |noop_mode|; describe (noop_mode ? "in noop mode" : "in normal mode") do [nil, '750'].each do |machine_state|; describe (machine_state ? "with a file initially present" : "with no file initially present") do [nil, '750', '755'].each do |yaml_mode| [nil, :file, :absent].each do |yaml_ensure|; describe "with mode=#{yaml_mode.inspect} and ensure=#{yaml_ensure.inspect} stored in state.yml" do [false, true].each do |auditing_ensure| [false, true].each do |auditing_mode| auditing = [] auditing.push(:mode) if auditing_mode auditing.push(:ensure) if auditing_ensure [nil, :file, :absent].each do |ensure_property| # what we set "ensure" to in the manifest [nil, '750', '755'].each do |mode_property| # what we set "mode" to in the manifest manifest_settings = {} manifest_settings[:audit] = auditing if !auditing.empty? manifest_settings[:ensure] = ensure_property if ensure_property manifest_settings[:mode] = mode_property if mode_property describe "with manifest settings #{manifest_settings.inspect}" do; it "should behave properly" do # Set up preconditions test_file = tmpfile('foo') if machine_state File.open(test_file, 'w', machine_state.to_i(8)).close end Puppet[:noop] = noop_mode params = { :path => test_file, :backup => false } params.merge!(manifest_settings) resource = Puppet::Type.type(:file).new params @harness.cache(resource, :mode, yaml_mode) if yaml_mode @harness.cache(resource, :ensure, yaml_ensure) if yaml_ensure + fake_time = Time.utc(2011, 'jan', 3, 12, 24, 0) + Time.stubs(:now).returns(fake_time) # So that Puppet::Resource::Status objects will compare properly + resource.expects(:err).never # make sure no exceptions get swallowed status = @harness.evaluate(resource) # do the thing # check that the state of the machine has been properly updated expected_logs = [] + expected_status_events = [] if auditing_mode @harness.cached(resource, :mode).should == (machine_state || :absent) else @harness.cached(resource, :mode).should == yaml_mode end if auditing_ensure @harness.cached(resource, :ensure).should == (machine_state ? :file : :absent) else @harness.cached(resource, :ensure).should == yaml_ensure end if ensure_property == :file file_would_be_there_if_not_noop = true elsif ensure_property == nil file_would_be_there_if_not_noop = machine_state != nil else # ensure_property == :absent file_would_be_there_if_not_noop = false end file_should_be_there = noop_mode ? machine_state != nil : file_would_be_there_if_not_noop File.exists?(test_file).should == file_should_be_there if file_should_be_there if noop_mode expected_file_mode = machine_state else expected_file_mode = mode_property || machine_state end if !expected_file_mode # we didn't specify a mode and the file was created, so mode comes from umode else file_mode = File.stat(test_file).mode & 0777 file_mode.should == expected_file_mode.to_i(8) end end # Test log output for the "mode" parameter previously_recorded_mode_already_logged = false + mode_status_msg = nil if machine_state && file_would_be_there_if_not_noop && mode_property && machine_state != mode_property if noop_mode what_happened = "current_value #{machine_state}, should be #{mode_property} (noop)" + expected_status = 'noop' else what_happened = "mode changed '#{machine_state}' to '#{mode_property}'" + expected_status = 'success' end if auditing_mode && yaml_mode && yaml_mode != machine_state previously_recorded_mode_already_logged = true - expected_logs << "notice: /#{resource}/mode: #{what_happened} (previously recorded value was #{yaml_mode})" + mode_status_msg = "#{what_happened} (previously recorded value was #{yaml_mode})" else - expected_logs << "notice: /#{resource}/mode: #{what_happened}" + mode_status_msg = what_happened end + expected_logs << "notice: /#{resource}/mode: #{mode_status_msg}" end if @harness.cached(resource, :mode) && @harness.cached(resource, :mode) != yaml_mode if yaml_mode unless previously_recorded_mode_already_logged - expected_logs << "notice: /#{resource}/mode: audit change: previously recorded value #{yaml_mode} has been changed to #{@harness.cached(resource, :mode)}" + mode_status_msg = "audit change: previously recorded value #{yaml_mode} has been changed to #{@harness.cached(resource, :mode)}" + expected_logs << "notice: /#{resource}/mode: #{mode_status_msg}" + expected_status = 'audit' end else expected_logs << "notice: /#{resource}/mode: audit change: newly-recorded value #{@harness.cached(resource, :mode)}" end end + if mode_status_msg + expected_status_events << Puppet::Transaction::Event.new( + :source_description => "/#{resource}/mode", :resource => resource, :file => nil, + :line => nil, :tags => %w{file}, :desired_value => mode_property, + :historical_value => yaml_mode, :message => mode_status_msg, :name => :mode_changed, + :previous_value => machine_state || :absent, :property => :mode, :status => expected_status, + :audited => auditing_mode) + end # Test log output for the "ensure" parameter previously_recorded_ensure_already_logged = false + ensure_status_msg = nil if file_would_be_there_if_not_noop != (machine_state != nil) if noop_mode what_happened = "current_value #{machine_state ? 'file' : 'absent'}, should be #{file_would_be_there_if_not_noop ? 'file' : 'absent'} (noop)" + expected_status = 'noop' else what_happened = file_would_be_there_if_not_noop ? 'created' : 'removed' + expected_status = 'success' end if auditing_ensure && yaml_ensure && yaml_ensure != (machine_state ? :file : :absent) previously_recorded_ensure_already_logged = true - expected_logs << "notice: /#{resource}/ensure: #{what_happened} (previously recorded value was #{yaml_ensure})" + ensure_status_msg = "#{what_happened} (previously recorded value was #{yaml_ensure})" else - expected_logs << "notice: /#{resource}/ensure: #{what_happened}" + ensure_status_msg = "#{what_happened}" end + expected_logs << "notice: /#{resource}/ensure: #{ensure_status_msg}" end if @harness.cached(resource, :ensure) && @harness.cached(resource, :ensure) != yaml_ensure if yaml_ensure unless previously_recorded_ensure_already_logged - expected_logs << "notice: /#{resource}/ensure: audit change: previously recorded value #{yaml_ensure} has been changed to #{@harness.cached(resource, :ensure)}" + ensure_status_msg = "audit change: previously recorded value #{yaml_ensure} has been changed to #{@harness.cached(resource, :ensure)}" + expected_logs << "notice: /#{resource}/ensure: #{ensure_status_msg}" + expected_status = 'audit' end else expected_logs << "notice: /#{resource}/ensure: audit change: newly-recorded value #{@harness.cached(resource, :ensure)}" end end + if ensure_status_msg + if ensure_property == :file + ensure_event_name = :file_created + elsif ensure_property == nil + ensure_event_name = :file_changed + else # ensure_property == :absent + ensure_event_name = :file_removed + end + expected_status_events << Puppet::Transaction::Event.new( + :source_description => "/#{resource}/ensure", :resource => resource, :file => nil, + :line => nil, :tags => %w{file}, :desired_value => ensure_property, + :historical_value => yaml_ensure, :message => ensure_status_msg, :name => ensure_event_name, + :previous_value => machine_state ? :file : :absent, :property => :ensure, + :status => expected_status, :audited => auditing_ensure) + end # Actually check the logs. @logs.map {|l| "#{l.level}: #{l.source}: #{l.message}"}.should =~ expected_logs # All the log messages should show up as events except the "newly-recorded" ones. expected_event_logs = @logs.reject {|l| l.message =~ /newly-recorded/ } status.events.map {|e| e.message}.should =~ expected_event_logs.map {|l| l.message } + events_to_hash(status.events).should =~ events_to_hash(expected_status_events) # Check change count - this is the number of changes that actually occurred. expected_change_count = 0 if (machine_state != nil) != file_should_be_there expected_change_count = 1 elsif machine_state != nil if expected_file_mode != machine_state expected_change_count = 1 end end status.change_count.should == expected_change_count # Check out of sync count - this is the number # of changes that would have occurred in # non-noop mode. expected_out_of_sync_count = 0 if (machine_state != nil) != file_would_be_there_if_not_noop expected_out_of_sync_count = 1 elsif machine_state != nil if mode_property != nil && mode_property != machine_state expected_out_of_sync_count = 1 end end if !noop_mode expected_out_of_sync_count.should == expected_change_count end status.out_of_sync_count.should == expected_out_of_sync_count # Check legacy summary fields status.changed.should == (expected_change_count != 0) status.out_of_sync.should == (expected_out_of_sync_count != 0) # Check the :synced field on state.yml synced_should_be_set = !noop_mode && status.changed (@harness.cached(resource, :synced) != nil).should == synced_should_be_set end; end end end end end end; end end end; end end; end 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) File.exists?(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 @status = Puppet::Resource::Status.new(@resource) end it "should return true if 'ignoreschedules' is set" do Puppet[:ignoreschedules] = true @resource[:schedule] = "meh" @harness.should be_scheduled(@status, @resource) end it "should return true if the resource has no schedule set" do @harness.should be_scheduled(@status, @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?(@status, @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