Logging consistency fixes.lcg/chef-16-logging-fixed

- The doc formatter is now Chef::Config[:log_location]-aware
  and will log to files as well
- There is now consistency where doc formatter output never
  surprisingly changes to log formatter based on destination
- The "cli" log_location and the "config" log_location are now
  treated separately, so a log_location in the client.rb will
  always force output to a logfile, in addition to output
  to STDOUT if necessary
- The logic around STDOUT is now simplified, if its open we
  log to it, if its closed we don't, if you're daemonized we
  assume you're capturing STDOUT via your process manager
- The log_location variables are now Arrays

Things not done:

- The cli can't specify an array, it would be nice to support
  an accumulator pattern here.  Would also need to support
  disabling STDOUT logging though.

- Using the syslog or winevt logging devices requires the use
  of the logger, which precludes using the formatter.

- Some people may want to have log-formatter style output
  to the log file and doc formatter style output to STDOUT
  which is not very possible right now.  Right now we are
  consistent in that you get either the logger both places
  or the formatter both places.  This use case is complicated
  by the fact that they will want :info level logging for
  the logger, but :warn level logging for the doc formatter
  and that is another global.

- To do that latter thing right would probably require sending
  log messages to the formatter, and supporting a different
  log level in the formatter vs. the logger and then supporting
  the STDOUT/cli loggging being the formatter, while the
  log_location/config logging being the logger.

Those were way out of scope for what I could get done for Chef-16.

Signed-off-by: Lamont Granquist <lamont@scriptkiddie.org>

12 files changed, 56 insertions, 95 deletions

diff --git a/chef-config/.rspec b/chef-config/.rspec
deleted file mode 100644
index eb3ef03653..0000000000
--- a/chef-config/.rspec
+++ /dev/null
@@ -1,2 +0,0 @@
---color
--fd
diff --git a/chef-config/Rakefile b/chef-config/Rakefile
index df2f59e298..4bb4605e0c 100644
--- a/chef-config/Rakefile
+++ b/chef-config/Rakefile
@@ -6,6 +6,7 @@ begin
   require "rspec/core/rake_task"
   desc "Run standard specs"
   RSpec::Core::RakeTask.new(:spec) do |t|
+    t.verbose = false
     t.pattern = FileList["spec/**/*_spec.rb"]
   end
 rescue LoadError
diff --git a/chef-config/lib/chef-config/config.rb b/chef-config/lib/chef-config/config.rb
index d37e8f1104..e7a92c6b6d 100644
--- a/chef-config/lib/chef-config/config.rb
+++ b/chef-config/lib/chef-config/config.rb
@@ -392,7 +392,7 @@ module ChefConfig
     default :log_level, :auto
 
     # Logging location as either an IO stream or string representing log file path
-    default :log_location, STDOUT
+    default :log_location, nil
 
     # Using `force_formatter` causes chef to default to formatter output when STDOUT is not a tty
     default :force_formatter, false
diff --git a/chef-utils/Rakefile b/chef-utils/Rakefile
index df2f59e298..4bb4605e0c 100644
--- a/chef-utils/Rakefile
+++ b/chef-utils/Rakefile
@@ -6,6 +6,7 @@ begin
   require "rspec/core/rake_task"
   desc "Run standard specs"
   RSpec::Core::RakeTask.new(:spec) do |t|
+    t.verbose = false
     t.pattern = FileList["spec/**/*_spec.rb"]
   end
 rescue LoadError
diff --git a/lib/chef/application.rb b/lib/chef/application.rb
index 2599a78156..0d80123bda 100644
--- a/lib/chef/application.rb
+++ b/lib/chef/application.rb
@@ -168,28 +168,11 @@ class Chef
       end
     end
 
-    # Initialize and configure the logger.
-    # === Loggers and Formatters
-    # In Chef 10.x and previous, the Logger was the primary/only way that Chef
-    # communicated information to the user. In Chef 10.14, a new system, "output
-    # formatters" was added, and in Chef 11.0+ it is the default when running
-    # chef in a console (detected by `STDOUT.tty?`). Because output formatters
-    # are more complex than the logger system and users have less experience with
-    # them, the config option `force_logger` is provided to restore the Chef 10.x
-    # behavior.
-    #
-    # Conversely, for users who want formatter output even when chef is running
-    # unattended, the `force_formatter` option is provided.
-    #
-    # === Auto Log Level
-    # The `log_level` of `:auto` means `:warn` in the formatter and `:info` in
-    # the logger.
-    #
     def configure_logging
       configure_log_location
-      logger.init(MonoLogger.new(chef_config[:log_location]))
-      if want_additional_logger?
-        configure_stdout_logger
+      logger.init(MonoLogger.new(chef_config[:log_location][0]))
+      chef_config[:log_location][1..-1].each do |log_location|
+        logger.loggers << MonoLogger.new(log_location)
       end
       logger.level = resolve_log_level
     rescue StandardError => error
@@ -197,30 +180,28 @@ class Chef
       Chef::Application.fatal!("Aborting due to invalid 'log_location' configuration", error)
     end
 
-    # Turn `log_location :syslog` and `log_location :win_evt` into the
-    # appropriate loggers.
+    # merge Chef::Config[:log_location] and config[:log_location_cli]
+    #   - the nil default value of log_location_cli means STDOUT
+    #   - the nil default value of log_location is removed
+    #   - Arrays are supported
+    #   - syslog + winevt are converted to those specific logger objects
+    #
     def configure_log_location
-      log_location = chef_config[:log_location]
-      return unless log_location.respond_to?(:to_sym)
-
-      chef_config[:log_location] =
-        case log_location.to_sym
-          when :syslog then logger::Syslog.new
-          when :win_evt then logger::WinEvt.new
-          else log_location # Probably a path; let MonoLogger sort it out
-        end
-    end
+      log_location_cli = [ config[:log_location_cli] ].flatten.map { |log_location| log_location.nil? ? STDOUT : log_location }
 
-    # Based on config and whether or not STDOUT is a tty, should we setup a
-    # secondary logger for stdout?
-    def want_additional_logger?
-      ( Chef::Config[:log_location].class != IO ) && STDOUT.tty? && !Chef::Config[:daemonize]
-    end
+      chef_config[:log_location] = [ chef_config[:log_location], log_location_cli ].flatten.compact.uniq
 
-    def configure_stdout_logger
-      stdout_logger = MonoLogger.new(STDOUT)
-      stdout_logger.formatter = logger.logger.formatter
-      logger.loggers << stdout_logger
+      chef_config[:log_location].map! do |log_location|
+        case log_location
+        when :syslog, "syslog"
+          logger::Syslog.new
+        when :win_evt, "win_evt"
+          logger::WinEvt.new
+        else
+          # should be a path or STDOUT
+          log_location
+        end
+      end
     end
 
     # Use of output formatters is assumed if `force_formatter` is set or if `force_logger` is not set
@@ -228,19 +209,10 @@ class Chef
       chef_config[:force_formatter] || !chef_config[:force_logger]
     end
 
-    def auto_log_level?
-      chef_config[:log_level] == :auto
-    end
-
-    # if log_level is `:auto`, convert it to :warn (when using output formatter)
-    # or :info (no output formatter). See also +using_output_formatter?+
+    # The :auto formatter defaults to :warn with the formatter and :info with the logger
     def resolve_log_level
-      if auto_log_level?
-        if using_output_formatter?
-          :warn
-        else
-          :info
-        end
+      if chef_config[:log_level] == :auto
+        using_output_formatter? ? :warn : :info
       else
         chef_config[:log_level]
       end
@@ -406,6 +378,9 @@ class Chef
 
       # Log a fatal error message to both STDERR and the Logger, exit the application
       def fatal!(msg, err = nil)
+        if Chef::Config[:always_dump_stacktrace]
+          msg << "\n#{err.backtrace.join("\n")}"
+        end
         logger.fatal(msg)
         Process.exit(normalize_exit_code(err))
       end
diff --git a/lib/chef/application/base.rb b/lib/chef/application/base.rb
index 959ab66ea5..382fd3d66b 100644
--- a/lib/chef/application/base.rb
+++ b/lib/chef/application/base.rb
@@ -94,11 +94,10 @@ class Chef::Application::Base < Chef::Application
     description: "Set the log level (auto, trace, debug, info, warn, error, fatal).",
     proc: lambda { |l| l.to_sym }
 
-  option :log_location,
+  option :log_location_cli,
     short: "-L LOGLOCATION",
     long: "--logfile LOGLOCATION",
-    description: "Set the log file location, defaults to STDOUT - recommended for daemonizing.",
-    proc: nil
+    description: "Set the log file location, defaults to STDOUT - recommended for daemonizing."
 
   option :always_dump_stacktrace,
     long: "--[no-]always-dump-stacktrace",
diff --git a/lib/chef/chef_fs/file_system/repository/chef_repository_file_system_root_dir.rb b/lib/chef/chef_fs/file_system/repository/chef_repository_file_system_root_dir.rb
index 43847d666a..431b9ecb22 100644
--- a/lib/chef/chef_fs/file_system/repository/chef_repository_file_system_root_dir.rb
+++ b/lib/chef/chef_fs/file_system/repository/chef_repository_file_system_root_dir.rb
@@ -140,11 +140,11 @@ class Chef
           # Used to print out a human-readable file system description
           def fs_description
             repo_paths = root_paths || [ File.dirname(child_paths["cookbooks"][0]) ]
-            result = "repository at #{repo_paths.join(", ")}\n"
+            result = "repository at #{repo_paths.join(", ")}"
             if versioned_cookbooks
-              result << "  Multiple versions per cookbook\n"
+              result << " (Multiple versions per cookbook)"
             else
-              result << "  One version per cookbook\n"
+              result << " (One version per cookbook)"
             end
             child_paths.each_pair do |name, paths|
               if paths.any? { |path| !repo_paths.include?(File.dirname(path)) }
diff --git a/lib/chef/client.rb b/lib/chef/client.rb
index 769d1a4989..a43740258d 100644
--- a/lib/chef/client.rb
+++ b/lib/chef/client.rb
@@ -353,19 +353,15 @@ class Chef
 
     # @api private
     def formatters_for_run
-      if Chef::Config.formatters.empty?
-        [default_formatter]
-      else
-        Chef::Config.formatters
-      end
-    end
+      return Chef::Config.formatters unless Chef::Config.formatters.empty?
 
-    # @api private
-    def default_formatter
-      if !Chef::Config[:force_logger] || Chef::Config[:force_formatter]
-        [:doc]
-      else
-        [:null]
+      [ Chef::Config[:log_location] ].flatten.map do |log_location|
+        log_location = nil if log_location == STDOUT
+        if !Chef::Config[:force_logger] || Chef::Config[:force_formatter]
+          [:doc, log_location]
+        else
+          [:null]
+        end
       end
     end
 
diff --git a/spec/integration/solo/solo_spec.rb b/spec/integration/solo/solo_spec.rb
index c21bc7d597..3029a1b529 100644
--- a/spec/integration/solo/solo_spec.rb
+++ b/spec/integration/solo/solo_spec.rb
@@ -165,7 +165,7 @@ describe Chef::Dist::SOLOEXEC do
         ruby_block "sleeping" do
           block do
             retries = 200
-            while IO.read(Chef::Config[:log_location]) !~ /.* is running, will wait for it to finish and then run./
+            while IO.read(Chef::Config[:log_location][0]) !~ /.* is running, will wait for it to finish and then run./
               sleep 0.1
               raise "we ran out of retries" if ( retries -= 1 ) <= 0
             end
@@ -189,13 +189,13 @@ describe Chef::Dist::SOLOEXEC do
 
           # Instantiate the first chef-solo run
           threads << Thread.new do
-            s1 = Process.spawn("#{chef_solo} -c \"#{path_to("config/solo.rb")}\" -o 'x::default'  -l debug -L #{path_to("logs/runs.log")}", chdir: chef_dir)
+            s1 = Process.spawn("#{chef_solo} -c \"#{path_to("config/solo.rb")}\" -o 'x::default' -l debug -L #{path_to("logs/runs.log")}", chdir: chef_dir)
             Process.waitpid(s1)
           end
 
           # Instantiate the second chef-solo run
           threads << Thread.new do
-            s2 = Process.spawn("#{chef_solo} -c \"#{path_to("config/solo.rb")}\" -o 'x::default'  -l debug -L #{path_to("logs/runs.log")}", chdir: chef_dir)
+            s2 = Process.spawn("#{chef_solo} -c \"#{path_to("config/solo.rb")}\" -o 'x::default' -l debug -L #{path_to("logs/runs.log")}", chdir: chef_dir)
             Process.waitpid(s2)
           end
 
diff --git a/spec/unit/application_spec.rb b/spec/unit/application_spec.rb
index f5800e61a9..ea784f1d55 100644
--- a/spec/unit/application_spec.rb
+++ b/spec/unit/application_spec.rb
@@ -194,7 +194,6 @@ describe Chef::Application do
       it "should initialise the chef logger" do
         allow(Chef::Log).to receive(:level=)
         @monologger = double("Monologger")
-        expect(MonoLogger).to receive(:new).with(Chef::Config[:log_location]).and_return(@monologger)
         allow(MonoLogger).to receive(:new).with(STDOUT).and_return(@monologger)
         allow(@monologger).to receive(:formatter=).with(Chef::Log.logger.formatter)
         expect(Chef::Log).to receive(:init).with(@monologger)
@@ -272,7 +271,7 @@ describe Chef::Application do
             it "it sets log_location to an instance of #{expected_class}" do
               expect(expected_class).to receive(:new).with no_args
               @app.configure_logging
-              expect(Chef::Config[:log_location]).to be logger_instance
+              expect(Chef::Config[:log_location]).to eq([ logger_instance, STDOUT ])
             end
           end
         end
diff --git a/spec/unit/client_spec.rb b/spec/unit/client_spec.rb
index 8553c52b79..831fe9c9b6 100644
--- a/spec/unit/client_spec.rb
+++ b/spec/unit/client_spec.rb
@@ -351,7 +351,7 @@ describe Chef::Client do
   describe "configuring output formatters" do
     context "when no formatter has been configured" do
       it "configures the :doc formatter" do
-        expect(client.formatters_for_run).to eq([[:doc]])
+        expect(client.formatters_for_run).to eq([[:doc, nil]])
       end
 
       context "and force_logger is set" do
@@ -370,7 +370,7 @@ describe Chef::Client do
         end
 
         it "configures the :doc formatter" do
-          expect(client.formatters_for_run).to eq([[:doc]])
+          expect(client.formatters_for_run).to eq([[:doc, nil]])
         end
       end
 
@@ -381,7 +381,7 @@ describe Chef::Client do
         end
 
         it "configures the :doc formatter" do
-          expect(client.formatters_for_run).to eq([[:doc]])
+          expect(client.formatters_for_run).to eq([[:doc, nil]])
         end
       end
     end
diff --git a/tasks/rspec.rb b/tasks/rspec.rb
index 03e0b1df05..99b3563788 100644
--- a/tasks/rspec.rb
+++ b/tasks/rspec.rb
@@ -41,39 +41,31 @@ begin
 
   task spec: :component_specs
 
-  desc "Run standard specs (minus long running specs)"
+  desc "Run all specs in spec directory"
   RSpec::Core::RakeTask.new(:spec) do |t|
+    t.verbose = false
     t.rspec_opts = %w{--profile}
-    # right now this just limits to functional + unit, but could also remove
-    # individual tests marked long-running
     t.pattern = FileList["spec/**/*_spec.rb"]
   end
 
   namespace :spec do
-    desc "Run all specs in spec directory with RCov"
-    RSpec::Core::RakeTask.new(:rcov) do |t|
-      t.rspec_opts = %w{--profile}
-      t.pattern = FileList["spec/**/*_spec.rb"]
-      t.rcov = true
-      t.rcov_opts = lambda do
-        IO.readlines("#{CHEF_ROOT}/spec/rcov.opts").map { |l| l.chomp.split " " }.flatten
-      end
-    end
-
     desc "Run all specs in spec directory"
     RSpec::Core::RakeTask.new(:all) do |t|
+      t.verbose = false
       t.rspec_opts = %w{--profile}
       t.pattern = FileList["spec/**/*_spec.rb"]
     end
 
     desc "Print Specdoc for all specs"
     RSpec::Core::RakeTask.new(:doc) do |t|
+      t.verbose = false
       t.rspec_opts = %w{--format specdoc --dry-run --profile}
       t.pattern = FileList["spec/**/*_spec.rb"]
     end
 
     desc "Run the specs under spec/unit with activesupport loaded"
     RSpec::Core::RakeTask.new(:activesupport) do |t|
+      t.verbose = false
       t.rspec_opts = %w{--require active_support/core_ext --profile}
       # Only node_spec and role_spec specifically have issues, target those tests
       t.pattern = FileList["spec/unit/node_spec.rb", "spec/unit/role_spec.rb"]