Merge pull request #9751 from chef/lcg/chef-16-logging-fixed

Rework logging to resolve STDOUT / log_location issues

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"]