Making trigger logs much clearer -- you now get info logs indicating how many dependencies changed, and debug logs indicating what those dependencies are

git-svn-id: https://reductivelabs.com/svn/puppet/trunk@1178 980ebf18-57e1-0310-9a29-db15c13687c0

3 files changed, 61 insertions, 8 deletions

diff --git a/lib/puppet/event.rb b/lib/puppet/event.rb
index eb17750cc..79f01b65f 100644
--- a/lib/puppet/event.rb
+++ b/lib/puppet/event.rb
@@ -206,7 +206,7 @@ module Puppet
             end
 
             # Trigger a subscription, which basically calls the associated method
-            # on the target object.
+            # on the target object. XXX This is currently unused.
             def trigger(transaction)
                 event = nil
 
diff --git a/lib/puppet/transaction.rb b/lib/puppet/transaction.rb
index 4dfa3913b..23d384b38 100644
--- a/lib/puppet/transaction.rb
+++ b/lib/puppet/transaction.rb
@@ -81,10 +81,13 @@ class Transaction
     def collecttargets(events)
         events.each do |event|
             source = event.source
+            start = source
 
             while source
                 Puppet::Event::Subscription.targets_of(event, source) do |sub|
-                    @targets[sub.target] << sub
+                    start.info "Scheduling %s of %s[%s]" %
+                        [sub.callback, sub.target.class.name, sub.target.name]
+                    @targets[sub.target][event] = sub
                 end
 
                 source = source.parent
@@ -149,7 +152,7 @@ class Transaction
         }
 
         @targets = Hash.new do |hash, key|
-            hash[key] = []
+            hash[key] = {}
         end
 
         # of course, this won't work on the second run
@@ -199,25 +202,48 @@ class Transaction
         }.flatten.reject { |e| e.nil? }
     end
 
-    # Trigger any subscriptions to a child
+    # Trigger any subscriptions to a child.  This does an upwardly recursive
+    # search -- it triggers the passed object, but also the object's parent
+    # and so on up the tree.
     def trigger(child)
         obj = child
+        callbacks = Hash.new { |hash, key| hash[key] = [] }
+        sources = Hash.new { |hash, key| hash[key] = [] }
 
         while obj
             if @targets.include?(obj)
-                @targets[obj].uniq.each do |sub|
+                callbacks.clear
+                sources.clear
+                @targets[obj].each do |event, sub|
+                    # Collect all of the subs for each callback
+                    callbacks[sub.callback] << sub
+
+                    # And collect the sources for logging
+                    sources[event.source] << sub.callback
+                end
+
+                sources.each do |source, callbacklist|
+                    obj.debug "%s[%s] results in triggering %s" %
+                        [source.class.name, source.name, callbacklist.join(", ")]
+                end
+
+                callbacks.each do |callback, subs|
+                    obj.info "Triggering '%s' from %s dependencies" %
+                        [callback, subs.length]
                     # At this point, just log failures, don't try to react
                     # to them in any way.
                     begin
-                        sub.trigger(self)
+                        obj.send(callback)
                     rescue => detail
-                        sub.target.err "Failed to call %s on %s: %s" %
-                            [sub.callback, sub.target, detail]
+                        obj.err "Failed to call %s on %s: %s" %
+                            [callback, obj, detail]
 
                         if Puppet[:debug]
                             puts detail.backtrace
                         end
                     end
+
+                    triggered(obj, callback)
                 end
             end
 
diff --git a/test/other/events.rb b/test/other/events.rb
index a8779743b..4bfb73090 100755
--- a/test/other/events.rb
+++ b/test/other/events.rb
@@ -100,4 +100,31 @@ class TestEvents < Test::Unit::TestCase
         assert(FileTest.exists?(fname), "#{fname} does not exist")
         #assert_equal(events.length, trans.triggered?(objects[:b], :refresh))
     end
+
+    def test_multiplerefreshes
+        files = []
+
+        4.times { |i|
+            files << Puppet.type(:file).create(
+                :name => tempfile(),
+                :ensure => "file"
+            )
+        }
+
+        fname = tempfile()
+        exec = Puppet.type(:exec).create(
+            :name => "touch %s" % fname,
+            :path => "/usr/bin:/bin",
+            :refreshonly => true
+        )
+
+        exec[:subscribe] = files.collect { |f|
+            ["file", f.name]
+        }
+
+        comp = newcomp(exec, *files)
+
+        assert_apply(comp)
+        assert(FileTest.exists?(fname), "Exec file did not get created")
+    end
 end