Merge pull request #5851 from chef/lcg/chef-13-formatter

Chef-13:  remove magic from the logger/formatter settings

10 files changed, 122 insertions, 111 deletions

diff --git a/RELEASE_NOTES.md b/RELEASE_NOTES.md
index 0ccd86637c..1f5b069d0c 100644
--- a/RELEASE_NOTES.md
+++ b/RELEASE_NOTES.md
@@ -272,3 +272,28 @@ use `recipe.rb` in the root of the cookbook.
 The `use_inline_resources` provider mode is always enabled when using the
 `action :name do ... end` syntax. You can remove the `use_inline_resources`
 line.
+
+### The logger and formatter settings are more predictable
+
+The default now is the formatter.  There is no more automatic switching to the logger when logging or when output
+is sent to a pipe.  The logger needs to be specifically requested with `--force-logger` or it will not show up.
+
+The `--force-formatter` option does still exist, although it will probably be deprecated in the future.
+
+Setting the `log_location` in the config.rb now applies to both daemonized and command-line invocation and there is
+no magic which dups the logger in order to log to STDOUT on the command line in that case.
+
+Setting logger settings in config.rb is most likely no longer appropriate and those settings should be changed to
+command line flags on the config script or cronjob that invokes chef-client daemonized.  In other words:
+
+```
+chef-client -d -L /var/log/client.rb --force-logger
+```
+
+If your logfiles switch to the formatter, you need to include `--force-logger` for your daemonized runs.
+
+If your command line invocations have no output, delete the config.rb setting for the log_location and move that
+to the command line that invokes your daemon process.
+
+Redirecting output to a file with `chef-client > /tmp/chef.out` now captures the same output as invoking it directly on the command
+line with no redirection.
diff --git a/lib/chef/application.rb b/lib/chef/application.rb
index eba0d48e57..005418d184 100644
--- a/lib/chef/application.rb
+++ b/lib/chef/application.rb
@@ -144,22 +144,12 @@ class Chef
     # unattended, the `force_formatter` option is provided.
     #
     # === Auto Log Level
-    # When `log_level` is set to `:auto` (default), the log level will be `:warn`
-    # when the primary output mode is an output formatter (see
-    # +using_output_formatter?+) and `:info` otherwise.
+    # The `log_level` of `:auto` means `:warn` in the formatter and `:info` in
+    # the logger.
     #
-    # === Automatic STDOUT Logging
-    # When `force_logger` is configured (e.g., Chef 10 mode), a second logger
-    # with output on STDOUT is added when running in a console (STDOUT is a tty)
-    # and the configured log_location isn't STDOUT. This accounts for the case
-    # that a user has configured a log_location in client.rb, but is running
-    # chef-client by hand to troubleshoot a problem.
     def configure_logging
       configure_log_location
       Chef::Log.init(MonoLogger.new(Chef::Config[:log_location]))
-      if want_additional_logger?
-        configure_stdout_logger
-      end
       Chef::Log.level = resolve_log_level
     rescue StandardError => error
       Chef::Log.fatal("Failed to open or create log file at #{Chef::Config[:log_location]}: #{error.class} (#{error.message})")
@@ -180,22 +170,9 @@ class Chef
         end
     end
 
-    def configure_stdout_logger
-      stdout_logger = MonoLogger.new(STDOUT)
-      stdout_logger.formatter = Chef::Log.logger.formatter
-      Chef::Log.loggers << stdout_logger
-    end
-
-    # 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] != STDOUT ) && STDOUT.tty? && (!Chef::Config[:daemonize]) && (Chef::Config[:force_logger])
-    end
-
-    # Use of output formatters is assumed if `force_formatter` is set or if
-    # `force_logger` is not set and STDOUT is to a console (tty)
+    # Use of output formatters is assumed if `force_formatter` is set or if `force_logger` is not set
     def using_output_formatter?
-      Chef::Config[:force_formatter] || (!Chef::Config[:force_logger] && STDOUT.tty?)
+      Chef::Config[:force_formatter] || !Chef::Config[:force_logger]
     end
 
     def auto_log_level?
diff --git a/lib/chef/application/windows_service.rb b/lib/chef/application/windows_service.rb
index c30f5d1fe8..5e95c14095 100644
--- a/lib/chef/application/windows_service.rb
+++ b/lib/chef/application/windows_service.rb
@@ -1,6 +1,6 @@
 #
 # Author:: Christopher Maier (<maier@lambda.local>)
-# Copyright:: Copyright 2011-2016, Chef Software, Inc.
+# Copyright:: Copyright 2011-2017, Chef Software Inc.
 # License:: Apache License, Version 2.0
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
@@ -241,28 +241,13 @@ class Chef
 
       def configure_logging
         Chef::Log.init(MonoLogger.new(resolve_log_location))
-        if want_additional_logger?
-          configure_stdout_logger
-        end
         Chef::Log.level = resolve_log_level
       end
 
-      def configure_stdout_logger
-        stdout_logger = MonoLogger.new(STDOUT)
-        stdout_logger.formatter = Chef::Log.logger.formatter
-        Chef::Log.loggers << stdout_logger
-      end
-
-      # 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] != STDOUT ) && STDOUT.tty? && (!Chef::Config[:daemonize]) && (Chef::Config[:force_logger])
-      end
-
       # Use of output formatters is assumed if `force_formatter` is set or if
       # `force_logger` is not set and STDOUT is to a console (tty)
       def using_output_formatter?
-        Chef::Config[:force_formatter] || (!Chef::Config[:force_logger] && STDOUT.tty?)
+        Chef::Config[:force_formatter] || !Chef::Config[:force_logger]
       end
 
       def auto_log_level?
diff --git a/lib/chef/client.rb b/lib/chef/client.rb
index b219fdfdd6..c3eaa02bed 100644
--- a/lib/chef/client.rb
+++ b/lib/chef/client.rb
@@ -372,7 +372,7 @@ class Chef
 
     # @api private
     def default_formatter
-      if (STDOUT.tty? && !Chef::Config[:force_logger]) || Chef::Config[:force_formatter]
+      if !Chef::Config[:force_logger] || Chef::Config[:force_formatter]
         [:doc]
       else
         [:null]
diff --git a/lib/chef/knife/configure.rb b/lib/chef/knife/configure.rb
index 48007bbee7..967a18de87 100644
--- a/lib/chef/knife/configure.rb
+++ b/lib/chef/knife/configure.rb
@@ -1,6 +1,6 @@
 #
 # Author:: Adam Jacob (<adam@chef.io>)
-# Copyright:: Copyright 2009-2016, Chef Software Inc.
+# Copyright:: Copyright 2009-2017, Chef Software Inc.
 # License:: Apache License, Version 2.0
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
@@ -75,8 +75,6 @@ class Chef
 
         ::File.open(config[:config_file], "w") do |f|
           f.puts <<-EOH
-log_level                :info
-log_location             STDOUT
 node_name                '#{new_client_name}'
 client_key               '#{new_client_key}'
 validation_client_name   '#{validation_client_name}'
diff --git a/lib/chef/knife/configure_client.rb b/lib/chef/knife/configure_client.rb
index 7d0b3d260d..c015687ac7 100644
--- a/lib/chef/knife/configure_client.rb
+++ b/lib/chef/knife/configure_client.rb
@@ -1,6 +1,6 @@
 #
 # Author:: Adam Jacob (<adam@chef.io>)
-# Copyright:: Copyright 2009-2016, Chef Software Inc.
+# Copyright:: Copyright 2009-2017, Chef Software Inc.
 # License:: Apache License, Version 2.0
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
@@ -34,8 +34,6 @@ class Chef
         FileUtils.mkdir_p(@config_dir)
         ui.info("Writing client.rb")
         File.open(File.join(@config_dir, "client.rb"), "w") do |file|
-          file.puts("log_level        :info")
-          file.puts("log_location     STDOUT")
           file.puts("chef_server_url  '#{Chef::Config[:chef_server_url]}'")
           file.puts("validation_client_name '#{Chef::Config[:validation_client_name]}'")
         end
diff --git a/spec/integration/client/client_spec.rb b/spec/integration/client/client_spec.rb
index 1cd74a6fd1..00086c75ca 100644
--- a/spec/integration/client/client_spec.rb
+++ b/spec/integration/client/client_spec.rb
@@ -294,10 +294,9 @@ chef_server_url 'http://omg.com/blah'
 cookbook_path "#{path_to('cookbooks')}"
 EOM
 
-      result = shell_out("#{chef_client} -c \"#{path_to('config/client.rb')}\" -r 'x::default' -z", :cwd => chef_dir)
+      result = shell_out("#{chef_client} -c \"#{path_to('config/client.rb')}\" -r 'x::default' -z -l info", :cwd => chef_dir)
       expect(result.stdout).not_to include("Overridden Run List")
       expect(result.stdout).to include("Run List is [recipe[x::default]]")
-      #puts result.stdout
       result.error!
     end
 
@@ -445,7 +444,7 @@ control_group "control group without top level control" do
 end
       RECIPE
 
-      result = shell_out("#{chef_client} -c \"#{path_to('config/client.rb')}\" -o 'audit_test::succeed'", :cwd => chef_dir)
+      result = shell_out("#{chef_client} -c \"#{path_to('config/client.rb')}\" -o 'audit_test::succeed' -l info", :cwd => chef_dir)
       expect(result.error?).to be_falsey
       expect(result.stdout).to include("Successfully executed all `control_group` blocks and contained examples")
     end
@@ -555,4 +554,42 @@ EOM
       command.error!
     end
   end
+
+  when_the_repository "has a cookbook that logs at the info level" do
+    before do
+      file "cookbooks/x/recipes/default.rb", <<EOM
+      log "info level" do
+        level :info
+      end
+EOM
+      file "config/client.rb", <<EOM
+local_mode true
+cookbook_path "#{path_to('cookbooks')}"
+EOM
+    end
+
+    it "a chef client run should not log to info by default" do
+      command = shell_out("#{chef_client} -c \"#{path_to('config/client.rb')}\" -o 'x::default' --no-fork", :cwd => chef_dir)
+      command.error!
+      expect(command.stdout).not_to include("INFO")
+    end
+
+    it "a chef client run to a pipe should not log to info by default" do
+      command = shell_out("#{chef_client} -c \"#{path_to('config/client.rb')}\" -o 'x::default' --no-fork | tee #{path_to('chefrun.out')}", :cwd => chef_dir)
+      command.error!
+      expect(command.stdout).not_to include("INFO")
+    end
+
+    it "a chef solo run should not log to info by default" do
+      command = shell_out("#{chef_solo} -c \"#{path_to('config/client.rb')}\" -o 'x::default' --no-fork", :cwd => chef_dir)
+      command.error!
+      expect(command.stdout).not_to include("INFO")
+    end
+
+    it "a chef solo run to a pipe should not log to info by default" do
+      command = shell_out("#{chef_solo} -c \"#{path_to('config/client.rb')}\" -o 'x::default' --no-fork | tee #{path_to('chefrun.out')}", :cwd => chef_dir)
+      command.error!
+      expect(command.stdout).not_to include("INFO")
+    end
+  end
 end
diff --git a/spec/unit/application_spec.rb b/spec/unit/application_spec.rb
index a12935fa78..72921c90ca 100644
--- a/spec/unit/application_spec.rb
+++ b/spec/unit/application_spec.rb
@@ -1,7 +1,7 @@
 #
 # Author:: AJ Christensen (<aj@junglist.gen.nz>)
 # Author:: Mark Mzyk (mmzyk@chef.io)
-# Copyright:: Copyright 2008-2016, Chef Software Inc.
+# Copyright:: Copyright 2008-2017, Chef Software Inc.
 # License:: Apache License, Version 2.0
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
@@ -192,48 +192,49 @@ describe Chef::Application do
       end
 
       shared_examples_for "log_level_is_auto" do
-        context "when STDOUT is to a tty" do
+        before do
+          allow(STDOUT).to receive(:tty?).and_return(true)
+        end
+
+        it "configures the log level to :warn" do
+          @app.configure_logging
+          expect(Chef::Log.level).to eq(:warn)
+        end
+
+        context "when force_formater is configured" do
           before do
-            allow(STDOUT).to receive(:tty?).and_return(true)
+            Chef::Config[:force_formatter] = true
           end
 
-          it "configures the log level to :warn" do
+          it "configures the log level to warn" do
             @app.configure_logging
             expect(Chef::Log.level).to eq(:warn)
           end
-
-          context "when force_logger is configured" do
-            before do
-              Chef::Config[:force_logger] = true
-            end
-
-            it "configures the log level to info" do
-              @app.configure_logging
-              expect(Chef::Log.level).to eq(:info)
-            end
-          end
         end
 
-        context "when STDOUT is not to a tty" do
+        context "when force_logger is configured" do
           before do
-            allow(STDOUT).to receive(:tty?).and_return(false)
+            Chef::Config[:force_logger] = true
           end
 
-          it "configures the log level to :info" do
+          it "configures the log level to info" do
             @app.configure_logging
             expect(Chef::Log.level).to eq(:info)
           end
+        end
 
-          context "when force_formatter is configured" do
-            before do
-              Chef::Config[:force_formatter] = true
-            end
-            it "sets the log level to :warn" do
-              @app.configure_logging
-              expect(Chef::Log.level).to eq(:warn)
-            end
+        context "when both are is configured" do
+          before do
+            Chef::Config[:force_logger] = true
+            Chef::Config[:force_formatter] = true
+          end
+
+          it "configures the log level to warn" do
+            @app.configure_logging
+            expect(Chef::Log.level).to eq(:warn)
           end
         end
+
       end
 
       context "when log_level is not set" do
diff --git a/spec/unit/client_spec.rb b/spec/unit/client_spec.rb
index 7ffc17c4fc..a2bb573e15 100644
--- a/spec/unit/client_spec.rb
+++ b/spec/unit/client_spec.rb
@@ -2,7 +2,7 @@
 # Author:: Adam Jacob (<adam@chef.io>)
 # Author:: Tim Hinderliter (<tim@chef.io>)
 # Author:: Christopher Walters (<cw@chef.io>)
-# Copyright:: Copyright 2008-2016, Chef Software, Inc.
+# Copyright:: Copyright 2008-2017, Chef Software Inc.
 # License:: Apache License, Version 2.0
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
@@ -71,48 +71,40 @@ describe Chef::Client do
 
   describe "configuring output formatters" do
     context "when no formatter has been configured" do
-      context "and STDOUT is a TTY" do
+      it "configures the :doc formatter" do
+        expect(client.formatters_for_run).to eq([[:doc]])
+      end
+
+      context "and force_logger is set" do
         before do
-          allow(STDOUT).to receive(:tty?).and_return(true)
+          Chef::Config[:force_logger] = true
         end
 
-        it "configures the :doc formatter" do
-          expect(client.formatters_for_run).to eq([[:doc]])
+        it "configures the :null formatter" do
+          expect(client.formatters_for_run).to eq([[:null]])
         end
+      end
 
-        context "and force_logger is set" do
-          before do
-            Chef::Config[:force_logger] = true
-          end
-
-          it "configures the :null formatter" do
-            expect(Chef::Config[:force_logger]).to be_truthy
-            expect(client.formatters_for_run).to eq([[:null]])
-          end
-
+      context "and force_formatter is set" do
+        before do
+          Chef::Config[:force_formatter] = true
         end
 
+        it "configures the :doc formatter" do
+          expect(client.formatters_for_run).to eq([[:doc]])
+        end
       end
 
-      context "and STDOUT is not a TTY" do
+      context "both are set" do
         before do
-          allow(STDOUT).to receive(:tty?).and_return(false)
-        end
-
-        it "configures the :null formatter" do
-          expect(client.formatters_for_run).to eq([[:null]])
+          Chef::Config[:force_formatter] = true
+          Chef::Config[:force_logger] = true
         end
 
-        context "and force_formatter is set" do
-          before do
-            Chef::Config[:force_formatter] = true
-          end
-          it "it configures the :doc formatter" do
-            expect(client.formatters_for_run).to eq([[:doc]])
-          end
+        it "configures the :doc formatter" do
+          expect(client.formatters_for_run).to eq([[:doc]])
         end
       end
-
     end
 
     context "when a formatter is configured" do
diff --git a/spec/unit/knife/configure_client_spec.rb b/spec/unit/knife/configure_client_spec.rb
index 3ecb89f827..0f83897564 100644
--- a/spec/unit/knife/configure_client_spec.rb
+++ b/spec/unit/knife/configure_client_spec.rb
@@ -58,8 +58,6 @@ describe Chef::Knife::ConfigureClient do
       it "should write out the config file" do
         allow(FileUtils).to receive(:mkdir_p)
         @knife.run
-        expect(@client_file.string).to match /log_level\s+\:info/
-        expect(@client_file.string).to match /log_location\s+STDOUT/
         expect(@client_file.string).to match /chef_server_url\s+'https\:\/\/chef\.example\.com'/
         expect(@client_file.string).to match /validation_client_name\s+'chef-validator'/
       end