Add support for specifying additional log outputs

This will add another configuration block where users can specify a list
of additional log4r outputters to enable

CHANGELOG.mkd

@@ -8,6 +8,7 @@ Unreleased
 - (RK-381) Do not recurse into symlinked dirs when finding files to purge. [#1233](https://github.com/puppetlabs/r10k/pull/1233)
 - Purge should remove unmanaged directories, in addition to unmanaged files. [#1222](https://github.com/puppetlabs/r10k/pull/1222)
 - Rename experimental environment type "bare" to "plain". [#1228](https://github.com/puppetlabs/r10k/pull/1228)
+- Add support for specifying additional logging ouputs. [#1230](https://github.com/puppetlabs/r10k/issues/1230)
 
 3.12.1
 ------

lib/r10k/action/runner.rb

@@ -51,6 +51,12 @@ def setup_settings
           overrides[:deploy][:generate_types] = @opts[:'generate-types'] if @opts.key?(:'generate-types')
           overrides[:deploy][:exclude_spec] = @opts[:'exclude-spec'] if @opts.key?(:'exclude-spec')
         end
+        # If the log level has been given as an argument, ensure that output happens on stderr
+        if @opts.key?(:loglevel)
+          overrides[:logging] = {}
+          overrides[:logging][:level] = @opts[:loglevel]
+          overrides[:logging][:disable_default_stderr] = false
+        end
 
         with_overrides = config_settings.merge(overrides) do |key, oldval, newval|
           newval = oldval.merge(newval) if oldval.is_a? Hash

lib/r10k/initializers.rb

@@ -30,6 +30,8 @@ def call
           logger.warn(_("the purgedirs key in r10k.yaml is deprecated. it is currently ignored."))
         end
 
+        with_setting(:logging) { |value| LoggingInitializer.new(value).call }
+
         with_setting(:deploy) { |value| DeployInitializer.new(value).call }
 
         with_setting(:cachedir) { |value| R10K::Git::Cache.settings[:cache_root] = value }
@@ -41,6 +43,14 @@ def call
       end
     end
 
+    class LoggingInitializer < BaseInitializer
+      def call
+        with_setting(:level) { |value| R10K::Logging.level = value }
+        with_setting(:disable_default_stderr) { |value| R10K::Logging.disable_default_stderr = value }
+        with_setting(:outputs) { |value| R10K::Logging.add_outputters(value) }
+      end
+    end
+
     class DeployInitializer < BaseInitializer
       def call
         with_setting(:puppet_path) { |value| R10K::Settings.puppet_path = value }

lib/r10k/logging.rb

@@ -8,6 +8,16 @@
 module R10K::Logging
 
   LOG_LEVELS = %w{DEBUG2 DEBUG1 DEBUG INFO NOTICE WARN ERROR FATAL}
+  SYSLOG_LEVELS_MAP = {
+    'DEBUG2' => 'DEBUG',
+    'DEBUG1' => 'DEBUG',
+    'DEBUG' => 'DEBUG',
+    'INFO' => 'INFO',
+    'NOTICE' => 'INFO',
+    'WARN' => 'WARN',
+    'ERROR' => 'ERROR',
+    'FATAL' => 'FATAL',
+  }.freeze
 
   def logger_name
     self.class.to_s
@@ -21,6 +31,9 @@ def logger
       else
         @logger = Log4r::Logger.new(name)
         @logger.add(R10K::Logging.outputter)
+        R10K::Logging.outputters.each do |output|
+          @logger.add(output)
+        end
       end
     end
     @logger
@@ -59,7 +72,7 @@ def level=(val)
       if level.nil?
         raise ArgumentError, _("Invalid log level '%{val}'. Valid levels are %{log_levels}") % {val: val, log_levels: LOG_LEVELS.map(&:downcase).inspect}
       end
-      outputter.level = level
+      outputter.level = level unless @disable_default_stderr
       @level = level
 
       if level < Log4r::INFO
@@ -69,6 +82,58 @@ def level=(val)
       end
     end
 
+    def disable_default_stderr=(val)
+      @disable_default_stderr = val
+      outputter.level = val ? Log4r::OFF : @level
+    end
+
+    def add_outputters(outputs)
+      outputs.each do |output|
+        type = output.fetch(:type)
+        # Support specifying both short as well as full names
+        type = type.to_s[0..-10] if type.to_s.downcase.end_with? 'outputter'
+
+        name = output.fetch(:name, 'r10k')
+        if output[:level]
+          level = parse_level(output[:level])
+          if level.nil?
+            raise ArgumentError, _("Invalid log level '%{val}'. Valid levels are %{log_levels}") % { val: output[:level], log_levels: LOG_LEVELS.map(&:downcase).inspect }
+          end
+        else
+          level = self.level
+        end
+        only_at = output[:only_at]
+        only_at&.map! do |val|
+          lv = parse_level(val)
+          if lv.nil?
+            raise ArgumentError, _("Invalid log level '%{val}'. Valid levels are %{log_levels}") % { val: val, log_levels: LOG_LEVELS.map(&:downcase).inspect }
+          end
+
+          lv
+        end
+        parameters = output.fetch(:parameters, {}).merge({ level: level })
+
+        begin
+          # Try to load the outputter file if possible
+          require "log4r/outputter/#{type.to_s.downcase}outputter"
+        rescue LoadError
+          false
+        end
+        outputtertype = Log4r.constants
+                             .select { |klass| klass.to_s.end_with? 'Outputter' }
+                             .find { |klass| klass.to_s.downcase == "#{type.to_s.downcase}outputter" }
+        raise ArgumentError, "Unable to find a #{output[:type]} outputter." unless outputtertype
+
+        outputter = Log4r.const_get(outputtertype).new(name, parameters)
+        outputter.only_at(*only_at) if only_at
+        # Handle log4r's syslog mapping correctly
+        outputter.map_levels_by_name_to_syslog(SYSLOG_LEVELS_MAP) if outputter.respond_to? :map_levels_by_name_to_syslog
+
+        @outputters << outputter
+        Log4r::Logger.global.add outputter
+      end
+    end
+
     extend Forwardable
     def_delegators :@outputter, :use_color, :use_color=
 
@@ -87,6 +152,16 @@ def level=(val)
     #   @return [Log4r::Outputter]
     attr_reader :outputter
 
+    # @!attribute [r] outputters
+    #   @api private
+    #   @return [Array[Log4r::Outputter]]
+    attr_reader :outputters
+
+    # @!attribute [r] disable_default_stderr
+    #   @api private
+    #   @return [Boolean]
+    attr_reader :disable_default_stderr
+
     def default_formatter
       Log4r::PatternFormatter.new(:pattern => '%l\t -> %m')
     end
@@ -106,4 +181,6 @@ def default_outputter
   @level     = Log4r::WARN
   @formatter = default_formatter
   @outputter = default_outputter
+  @outputters = []
+  @disable_default_stderr = false
 end

lib/r10k/settings.rb

@@ -217,6 +217,39 @@ def self.deploy_settings
         })])
     end
 
+    def self.logging_settings
+      R10K::Settings::Collection.new(:logging, [
+        Definition.new(:level, {
+          desc: 'What logging level should R10k run on if not specified at runtime.',
+          validate: lambda do |value|
+            if R10K::Logging.parse_level(value).nil?
+              raise ArgumentError, "`level` must be a valid log level.
+                                    Valid levels are #{R10K::Logging::LOG_LEVELS.map(&:downcase).inspect}"
+            end
+          end
+        }),
+
+        Definition.new(:outputs, {
+          desc: 'Additional log outputs to use.',
+          validate: lambda do |value|
+            unless value.is_a?(Array)
+              raise ArgumentError, "The `outputs` setting should be an array of outputs, not a #{value.class}"
+            end
+          end
+        }),
+
+        Definition.new(:disable_default_stderr, {
+          desc: 'Disable the default stderr logging output',
+          default: false,
+          validate: lambda do |value|
+            unless !!value == value
+              raise ArgumentError, "`disable_default_stderr` can only be a boolean value, not '#{value}'"
+            end
+          end
+        })
+      ])
+    end
+
     def self.global_settings
       R10K::Settings::Collection.new(:global, [
         Definition.new(:sources, {
@@ -271,6 +304,8 @@ def self.global_settings
         R10K::Settings.git_settings,
 
         R10K::Settings.deploy_settings,
+
+        R10K::Settings.logging_settings
       ])
     end
   end

r10k.yaml.example

@@ -110,3 +110,31 @@ forge:
   # The 'baseurl' setting indicates where Forge modules should be installed
   # from. This defaults to 'https://forgeapi.puppetlabs.com'
   #baseurl: 'https://forgemirror.example.com'
+
+# Configuration options on how R10k should log its actions
+logging:
+  # The 'level' setting sets the default log level to run R10k actions at.
+  # This value will be overridden by any value set through the command line.
+  #level: warn
+
+  # Specify additional log outputs here, any log4r outputter can be used.
+  # If no log level is specified then the output will use the global level.
+  #outputs:
+  # - type: file
+  #   level: debug
+  #   parameters:
+  #     filename: /var/log/r10k.log
+  #     trunc: true
+  # - type: syslog
+  # - type: email
+  #   only_at: [fatal]
+  #   parameters:
+  #     from: [email protected]
+  #     to: [email protected]
+  #     server: smtp.example.com
+  #     subject: Fatal R10k error occurred
+
+  # The 'disable_default_stderr' setting specifies if the default output on
+  # stderr should be active or not, in case R10k is to be run entirely
+  # through scripts or cronjobs where console output is unwelcome.
+  #disable_default_stderr: false

spec/fixtures/unit/action/r10k_logging.yaml

@@ -0,0 +1,12 @@
+---
+  logging:
+    level: FATAL
+
+    outputs:
+      - type: file
+        parameters:
+          filename: r10k.log
+
+      - type: syslog
+
+    disable_default_stderr: true

spec/unit/action/runner_spec.rb

@@ -159,10 +159,61 @@ def call
   end
 
   describe "configuring logging" do
+    before(:each) do
+      R10K::Logging.outputters.clear
+    end
+
     it "sets the log level if :loglevel is provided" do
       runner = described_class.new({:opts => :yep, :loglevel => 'FATAL'}, %w[args yes], action_class)
-      expect(R10K::Logging).to receive(:level=).with('FATAL')
+      # The settings/overrides system causes the level to be set twice
+      expect(R10K::Logging).to receive(:level=).with('FATAL').twice
+      runner.call
+    end
+
+    # The logging fixture tests require a platform with syslog
+    if !R10K::Util::Platform.windows?
+      it "sets the log level if the logging.level setting is provided" do
+        runner = described_class.new({ opts: :yep, config: 'spec/fixtures/unit/action/r10k_logging.yaml'}, %w[args yes], action_class)
+        expect(R10K::Logging).to receive(:level=).with('FATAL')
+        runner.call
+      end
+
+      it "sets the outputters if logging.outputs is provided" do
+        runner = described_class.new({ opts: :yep, config: 'spec/fixtures/unit/action/r10k_logging.yaml' }, %w[args yes], action_class)
+        expect(R10K::Logging).to receive(:add_outputters).with([
+          { type: 'file', parameters: { filename: 'r10k.log' } },
+          { type: 'syslog' }
+        ])
+        runner.call
+      end
+
+      it "disables the default outputter if the logging.disable_default_stderr setting is provided" do
+        runner = described_class.new({ opts: :yep, config: 'spec/fixtures/unit/action/r10k_logging.yaml'}, %w[args yes], action_class)
+        expect(R10K::Logging).to receive(:disable_default_stderr=).with(true)
+        runner.call
+      end
+
+      it "adds additional log outputs if the logging.outputs setting is provided" do
+        runner = described_class.new({ opts: :yep, config: 'spec/fixtures/unit/action/r10k_logging.yaml'}, %w[args yes], action_class)
+        runner.call
+        expect(R10K::Logging.outputters).to_not be_empty
+      end
+
+      it "disables the default output if the logging.disable_default_stderr setting is provided" do
+        runner = described_class.new({ opts: :yep, config: 'spec/fixtures/unit/action/r10k_logging.yaml'}, %w[args yes], action_class)
+        runner.call
+        expect(runner.logger.outputters).to satisfy { |outputs| outputs.any? { |output| output.is_a?(R10K::Logging::TerminalOutputter) && output.level == Log4r::OFF } }
+      end
+    end
+
+    it "doesn't add additional log outputs if the logging.outputs setting is not provided" do
+      runner.call
+      expect(R10K::Logging.outputters).to be_empty
+    end
+
+    it "includes the default stderr outputter" do
       runner.call
+      expect(runner.logger.outputters).to satisfy { |outputs| outputs.any? { |output| output.is_a? R10K::Logging::TerminalOutputter } }
     end
 
     it "does not modify the loglevel if :loglevel is not provided" do