Merge pull request #397 from ripienaar/394.2

(#394) improve logging and avoid overloading node

lib/mcollective/util/bolt_support.rb

@@ -47,6 +47,7 @@ def self.init_choria
       def playbook
         @_playbook ||= begin
                          pb = Playbook.new(self.class.loglevel)
+                         pb.logger = Playbook::Puppet_Logger
                          pb.set_logger_level
                          pb
                        end
@@ -58,10 +59,12 @@ def nodes
 
       # Discovers nodes using playbook node sets
       #
+      # @param scope [Puppet::Parser::Scope] scope to log against
       # @param type [String] a known node set type like `terraform`
       # @param properties [Hash] properties valid for the node set type
-      def discover_nodes(type, properties)
+      def discover_nodes(scope, type, properties)
         uses_properties = properties.delete("uses") || {}
+        playbook.logger.scope = scope
         playbook.uses.from_hash(uses_properties)
 
         nodes.from_hash("task_nodes" => properties.merge(
@@ -75,37 +78,43 @@ def discover_nodes(type, properties)
 
       # Retrieves a data item from a data store
       #
+      # @param scope [Puppet::Parser::Scope] scope to log against
       # @param item [String] the item to fetch
       # @param properties [Hash] the data source properties
-      def data_read(item, properties)
+      def data_read(scope, item, properties)
+        playbook.logger.scope = scope
         playbook.data_stores.from_hash("plan_store" => properties)
         playbook.data_stores.prepare
         playbook.data_stores.read("plan_store/%s" % item)
       end
 
       # Writes a value to a data store
       #
+      # @param scope [Puppet::Parser::Scope] scope to log against
       # @param item [String] the item to fetch
       # @param value [String] the item to fetch
       # @param properties [Hash] the data source properties
       # @return [String] the data that was written
-      def data_write(item, value, properties)
+      def data_write(scope, item, value, properties)
         config = {"plan_store" => properties}
 
+        playbook.logger.scope = scope
         playbook.data_stores.from_hash(config)
         playbook.data_stores.prepare
         playbook.data_stores.write("plan_store/%s" % item, value)
       end
 
       # Performs a block within a lock in a data store
       #
+      # @param scope [Puppet::Parser::Scope] scope to log against
       # @param item [String] the lock key
       # @param properties [Hash] the data source properties
-      def data_lock(item, properties, &blk)
+      def data_lock(scope, item, properties, &blk)
         locked = false
         lock_path = "plan_store/%s" % item
         config = {"plan_store" => properties}
 
+        playbook.logger.scope = scope
         playbook.data_stores.from_hash(config)
         playbook.data_stores.prepare
 
@@ -119,11 +128,13 @@ def data_lock(item, properties, &blk)
 
       # Runs a playbook task and return execution results
       #
+      # @param scope [Puppet::Parser::Scope] scope to log against
       # @param type [String] the task type
       # @param properties [Hash] properties passed to the task
       # @return [Hash] formatted for BoltSupport::TaskResults
-      def run_task(type, properties)
+      def run_task(scope, type, properties)
         task_properties = properties.reject {|k, _| k.start_with?("_") }
+        playbook.logger.scope = scope
 
         tasks = playbook.tasks.load_tasks([type => task_properties], "tasks")
 

lib/mcollective/util/bolt_support/task_result.rb

@@ -2,7 +2,7 @@ module MCollective
   module Util
     class BoltSupport
       class TaskResult
-        attr_reader :node, :result
+        attr_reader :host, :result
 
         # Method used by Puppet to create the TaskResult from a hash
         #
@@ -12,20 +12,13 @@ def self.from_asserted_hash(hash)
           new(hash.keys.first, hash.values.first)
         end
 
-        # @param node [String] node name
+        # @param host [String] node name
         # @param result [Hash] result value as produced by execution_result methods
-        def initialize(node, result)
-          @node = node
+        def initialize(host, result)
+          @host = host
           @result = result
         end
 
-        # The name of the node this result belongs to
-        #
-        # @param name [String]
-        def name
-          @node
-        end
-
         # A error object if this represents an error
         #
         # @return [Puppet::DataTypes::Error, nil]

lib/mcollective/util/bolt_support/task_results.rb

@@ -56,8 +56,8 @@ def ok
         # List of node names for all results
         #
         # @return [Array<String>]
-        def nodes
-          @results.map(&:node)
+        def hosts
+          @results.map(&:host)
         end
 
         # First result in the set
@@ -69,10 +69,10 @@ def first
 
         # Finds a result by name
         #
-        # @param node [String] node name
+        # @param host [String] node hostname
         # @return [TaskResult,nil]
-        def find(node)
-          @results.find {|r| r.node == node}
+        def find(host)
+          @results.find {|r| r.host == host}
         end
 
         # Determines if the resultset is empty

lib/mcollective/util/playbook.rb

@@ -1,5 +1,6 @@
 require_relative "playbook/report"
 require_relative "playbook/playbook_logger"
+require_relative "playbook/puppet_logger"
 require_relative "playbook/template_util"
 require_relative "playbook/inputs"
 require_relative "playbook/uses"
@@ -15,7 +16,7 @@ class Playbook
       include TemplateUtil
 
       attr_accessor :input_data, :context
-      attr_reader :metadata, :report, :data_stores, :uses, :tasks
+      attr_reader :metadata, :report, :data_stores, :uses, :tasks, :logger
 
       def initialize(loglevel=nil)
         @loglevel = loglevel
@@ -47,6 +48,13 @@ def initialize(loglevel=nil)
         }
       end
 
+      # Sets a custom logger
+      #
+      # @param logger [Class] the logger instance to configure and use
+      def logger=(logger)
+        @logger = Log.set_logger(logger.new(self))
+      end
+
       # Loads the playbook data and prepare the runner
       #
       # @param data [Hash] playbook data

lib/mcollective/util/playbook/playbook_logger.rb

@@ -4,6 +4,8 @@ module MCollective
   module Util
     class Playbook
       class Playbook_Logger < Logger::Console_logger
+        attr_writer :scope
+
         def initialize(playbook)
           @playbook = playbook
           @report = playbook.report

lib/mcollective/util/playbook/puppet_logger.rb

@@ -0,0 +1,49 @@
+require "mcollective/logger/console_logger"
+
+module MCollective
+  module Util
+    class Playbook
+      class Puppet_Logger < Logger::Console_logger
+        attr_writer :scope
+
+        def initialize(playbook)
+          @playbook = playbook
+          @report = playbook.report
+
+          super()
+        end
+
+        def start
+          set_level(@playbook.loglevel.intern)
+        end
+
+        def log(level, from, msg, normal_output=STDERR, last_resort_output=STDERR)
+          return unless should_show?
+
+          logmethod = case level
+                      when :info
+                        :notice
+                      when :warn
+                        :warning
+                      when :error
+                        :err
+                      when :fatal
+                        :crit
+                      else
+                        :debug
+                      end
+
+          if @scope
+            Puppet::Util::Log.log_func(@scope, logmethod, [msg])
+          else
+            Puppet.send(logmethod, msg)
+          end
+        end
+
+        def should_show?
+          !caller(1..5).grep(/playbook/).empty?
+        end
+      end
+    end
+  end
+end

module/choria/data/plugin.yaml

@@ -37,6 +37,7 @@ mcollective_choria::client_files:
  - util/playbook/nodes/terraform_nodes.rb
  - util/playbook/nodes/yaml_nodes.rb
  - util/playbook/playbook_logger.rb
+ - util/playbook/puppet_logger.rb
  - util/playbook/report.rb
  - util/playbook/task_result.rb
  - util/playbook/tasks.rb

spec/unit/mcollective/util/bolt_support/task_result_spec.rb

@@ -36,18 +36,11 @@ class BoltSupport
         describe ".from_asserted_hash" do
           it "should load the correct data" do
             tr = TaskResult.from_asserted_hash(good_result)
-            expect(tr.node).to eq("good.example")
+            expect(tr.host).to eq("good.example")
             expect(tr.result).to eq(good_result["good.example"])
           end
         end
 
-        describe "#name" do
-          it "should get the correct name" do
-            tr = TaskResult.from_asserted_hash(error_result)
-            expect(tr.name).to eq("error.example")
-          end
-        end
-
         describe "#error" do
           it "should be nil when not an error" do
             expect(TaskResult.from_asserted_hash(good_result).error).to be_nil

spec/unit/mcollective/util/bolt_support/task_results_spec.rb

@@ -26,7 +26,7 @@ class BoltSupport
         describe "#.from_asserted_hash" do
           it "should load the correct data" do
             tr = TaskResults.from_asserted_hash([good_result, error_result])
-            expect(tr.nodes).to eq(["good.example", "error.example"])
+            expect(tr.hosts).to eq(["good.example", "error.example"])
           end
         end
 
@@ -57,21 +57,21 @@ class BoltSupport
             tr = TaskResults.from_asserted_hash([good_result, error_result])
             found = tr.find("error.example")
             expect(found).to be_a(TaskResult)
-            expect(found.name).to eq("error.example")
+            expect(found.host).to eq("error.example")
           end
         end
 
         describe "#first" do
           it "should get the right result" do
             tr = TaskResults.from_asserted_hash([good_result, error_result])
-            expect(tr.first.name).to eq("good.example")
+            expect(tr.first.host).to eq("good.example")
           end
         end
 
         describe "#nodes" do
           it "should get the right nodes" do
             tr = TaskResults.from_asserted_hash([good_result, error_result])
-            expect(tr.nodes).to eq(["good.example", "error.example"])
+            expect(tr.hosts).to eq(["good.example", "error.example"])
           end
         end
 
@@ -91,7 +91,7 @@ class BoltSupport
             tr = TaskResults.from_asserted_hash([good_result, error_result])
 
             seen = []
-            tr.each {|r| seen << r.name}
+            tr.each {|r| seen << r.host}
 
             expect(seen).to eq(["good.example", "error.example"])
           end

spec/unit/mcollective/util/bolt_support_spec.rb

@@ -21,16 +21,16 @@ module Util
           playbook.data_stores.expects(:release).with("plan_store/rspec").twice
 
           expect do
-            support.data_lock("rspec", "type" => "consul") { raise("rspec failure") }
+            support.data_lock(nil, "rspec", "type" => "consul") { raise("rspec failure") }
           end.to raise_error("rspec failure")
 
-          expect(support.data_lock("rspec", "type" => "consul") { "rspec result" }).to eq("rspec result")
+          expect(support.data_lock(nil, "rspec", "type" => "consul") { "rspec result" }).to eq("rspec result")
         end
       end
 
       describe "#run_task" do
         it "should invoke the tasks and return an execution_result" do
-          result = support.run_task("shell", "command" => "/bin/echo 'hello world'")
+          result = support.run_task(nil, "shell", "command" => "/bin/echo 'hello world'")
 
           expect(result).to eq(
             "localhost" => {
@@ -42,11 +42,11 @@ module Util
         end
 
         it "should support fail_ok" do
-          expect { support.run_task("shell", "command" => "/bin/false") }.to raise_error(
+          expect { support.run_task(nil, "shell", "command" => "/bin/false") }.to raise_error(
             "Command failed with code 1"
           )
 
-          result = support.run_task("shell", "command" => "/bin/false", "fail_ok" => true)
+          result = support.run_task(nil, "shell", "command" => "/bin/false", "fail_ok" => true)
 
           expect(result).to eq(
             "localhost" => {
@@ -84,7 +84,7 @@ module Util
       describe "#data_write" do
         it "should write the right data" do
           tf = Tempfile.new("rspec")
-          r = support.data_write("hello", "world",
+          r = support.data_write(nil, "hello", "world",
                                  "type" => "file",
                                  "format" => "yaml",
                                  "file" => tf.path)
@@ -97,7 +97,7 @@ module Util
 
       describe "#data_read" do
         it "should read the right data" do
-          r = support.data_read("hello",
+          r = support.data_read(nil, "hello",
                                 "type" => "file",
                                 "format" => "yaml",
                                 "file" => File.expand_path("spec/fixtures/playbooks/file_data.yaml"))
@@ -111,7 +111,7 @@ module Util
           playbook.stubs(:uses).returns(u = stub)
           u.expects(:from_hash).with({})
 
-          result = support.discover_nodes("yaml",
+          result = support.discover_nodes(nil, "yaml",
                                           "source" => File.expand_path("spec/fixtures/playbooks/nodes.yaml"),
                                           "group" => "uk")
 
@@ -133,7 +133,7 @@ module Util
           n.expects(:prepare)
           n.expects(:[]).with("task_nodes").returns(["n1"])
 
-          result = support.discover_nodes("yaml",
+          result = support.discover_nodes(nil, "yaml",
                                           "source" => File.expand_path("spec/fixtures/playbooks/nodes.yaml"),
                                           "group" => "uk",
                                           "uses" => {"rpcutil" => "1.2.3"})

spec/unit/mcollective/util/federation_broker/stats_spec.rb

@@ -8,6 +8,10 @@ class FederationBroker
         let(:fb) { FederationBroker.new("rspec", "test") }
         let(:stats) { fb.stats }
 
+        before(:each) do
+          stats.stubs(:start_stats_web_server)
+        end
+
         describe "#serve_stats" do
           it "should serve the right stats" do
             res = stub