(puppetlabsGH-2900) Log messages from out::message and out::verbose

This updates the `out::message` plan function to log messages at the
`info` level and the `out::verbose` plan function to log messages at the
`debug` level. Both functions continue to print to the console as
before.

!feature

* **Log messages from `out::message` and `out::verbose`**
  ([puppetlabs#2900](puppetlabs#2900))

  The `out::message` plan function now logs messages at the `info` level
  and the `out::verbose` plan function now logs messages at the `debug`
  level. Both functions continue to print messages to the console.

bolt-modules/out/lib/puppet/functions/out/message.rb

@@ -5,7 +5,9 @@
 # Output a message for the user.
 #
 # This will print a message to stdout when using the human output format,
-# and print to stderr when using the json output format
+# and print to stderr when using the json output format. Messages are
+# also logged at the `info` level. For more information about logs, see
+# [Logs](logs.md).
 #
 # > **Note:** Not available in apply block
 Puppet::Functions.create_function(:'out::message') do
@@ -24,9 +26,12 @@ def output_message(message)
         .from_issue_and_stack(Bolt::PAL::Issues::PLAN_OPERATION_NOT_SUPPORTED_WHEN_COMPILING, action: 'out::message')
     end
 
+    stringified_message = Bolt::Util::Format.stringify(message)
+
     Puppet.lookup(:bolt_executor).tap do |executor|
       executor.report_function_call(self.class.name)
-      executor.publish_event(type: :message, message: Bolt::Util::Format.stringify(message))
+      executor.publish_event(type: :message, message: stringified_message)
+      executor.publish_event(type: :log, level: :info, message: stringified_message)
     end
 
     nil

bolt-modules/out/lib/puppet/functions/out/verbose.rb

@@ -5,7 +5,9 @@
 # Output a message for the user when running in verbose mode.
 #
 # This will print a message to stdout when using the human output format,
-# and print to stderr when using the json output format.
+# and print to stderr when using the json output format. Messages are
+# also logged at the `debug` level. For more information about logs, see
+# [Logs](logs.md).
 #
 # > **Note:** Not available in apply block
 Puppet::Functions.create_function(:'out::verbose') do
@@ -23,9 +25,12 @@ def output_verbose(message)
         .from_issue_and_stack(Bolt::PAL::Issues::PLAN_OPERATION_NOT_SUPPORTED_WHEN_COMPILING, action: 'out::verbose')
     end
 
+    stringified_message = Bolt::Util::Format.stringify(message)
+
     Puppet.lookup(:bolt_executor).tap do |executor|
       executor.report_function_call(self.class.name)
-      executor.publish_event(type: :verbose, message: Bolt::Util::Format.stringify(message))
+      executor.publish_event(type: :verbose, message: stringified_message)
+      executor.publish_event(type: :log, level: :debug, message: stringified_message)
     end
 
     nil

bolt-modules/out/spec/functions/out/message_spec.rb

@@ -14,7 +14,7 @@
     end
   end
 
-  it 'sends a log event to the executor' do
+  it 'sends a message event to the executor' do
     executor.expects(:publish_event).with(
       type:    :message,
       message: 'This is a message'
@@ -23,6 +23,16 @@
     is_expected.to run.with_params('This is a message')
   end
 
+  it 'sends a log event to the executor' do
+    executor.expects(:publish_event).with(
+      type:    :log,
+      level:   :info,
+      message: 'This is a message'
+    )
+
+    is_expected.to run.with_params('This is a message')
+  end
+
   it 'reports function call to analytics' do
     executor.expects(:report_function_call).with('out::message')
     is_expected.to run.with_params('This is a message')

bolt-modules/out/spec/functions/out/verbose_spec.rb

@@ -23,6 +23,16 @@
     is_expected.to run.with_params('This is a message')
   end
 
+  it 'sends a log event to the executor' do
+    executor.expects(:publish_event).with(
+      type:    :log,
+      level:   :debug,
+      message: 'This is a message'
+    )
+
+    is_expected.to run.with_params('This is a message')
+  end
+
   it 'reports function call to analytics' do
     executor.expects(:report_function_call).with('out::verbose')
     is_expected.to run.with_params('This is a message')

documentation/writing_plans.md

@@ -264,21 +264,24 @@ plan mymodule::myplan {
 By default, Bolt does not print verbose logs for each plan execution to stdout.
 However, you can use one of the following methods to investigate a plan
 execution:
+
 - Each time you run a Bolt command, Bolt prints a debug log to a
   `bolt-debug.log` file in the root of your project directory.
 - You can use the `--verbose` CLI option for verbose logging to stdout.
-- You can print a message to stdout using the `out::message` function. 
+- You can print a message to stdout and the `info` log level using the
+  `out::message` function. 
 - You can adjust your log level for detailed information on how Bolt is
   executing your plan.
 
 ### Using `out::message` to debug a plan
 
-You can print a message, or a variable, to stdout using the `out::message`
-function. If the variable contains a valid plan result, Bolt formats the plan
-result using a JSON representation of the result object. If the object is not a
-plan result, Bolt prints the object as a string.
+You can print a message, or a variable, to stdout and to the `info` log level
+using the `out::message` function. If the variable contains a valid plan result,
+Bolt formats the plan result using a JSON representation of the result object.
+If the object is not a plan result, Bolt prints the object as a string.
 
-To print a variable to stdout with `out::message`, use the following syntax:
+To print a variable to stdout and the `info` log level with `out::message`, use
+the following syntax:
 
 ```puppet
 out::message($variable) 
@@ -849,9 +852,9 @@ plan pdb_discover {
 
 ## Plan logging
 
-Print message strings to `STDOUT` using the plan function `out::message`. This
-function always prints messages regardless of the log level and doesn't log them
-to the log file.
+Print message strings to stdout using the `out::message` plan function. This
+function prints messages at the `info` level and always prints messages to
+stdout regardless of the log level.
 
 ### Default action logging
 

spec/fixtures/modules/output/plans/verbose.pp

@@ -1,3 +1,3 @@
-plan output::verbose(){
+plan output::verbose() {
   out::verbose("Hi, I'm Dave")
 }

spec/integration/plan_spec.rb

@@ -77,25 +77,37 @@
 
       let(:config_flags) { ['--no-host-key-check'] }
       let(:opts)         { { outputter: Bolt::Outputter::Human, project: @project } }
+      let(:project)      { @project }
 
       context 'output' do
-        let(:output)    { StringIO.new }
-        let(:outputter) { Bolt::Outputter::Human.new(true, true, true, true, output) }
-
-        before(:each) do
-          allow(Bolt::Outputter::Human).to receive(:new).and_return(outputter)
-        end
-
-        it 'outputs message with verbose flag' do
-          run_cli(%W[plan run output::verbose --targets #{target} --verbose] + config_flags,
-                  outputter: Bolt::Outputter::Human, project: @project)
-          expect(output.string).to match(/Hi, I'm Dave/)
+        context 'out::message' do
+          it 'outputs messages' do
+            result = run_cli(%w[plan run output], outputter: Bolt::Outputter::Human, project: project)
+            expect(result).to match(/Outputting a message/)
+          end
+
+          it 'logs messages at the info level' do
+            run_cli(%w[plan run output], outputter: Bolt::Outputter::Human, project: project)
+            expect(@log_output.readlines).to include(/INFO.*Outputting a message/)
+          end
         end
 
-        it 'doesnt output without verbose flag' do
-          result = run_cli(%W[plan run output::verbose --targets #{target}] + config_flags,
-                           outputter: Bolt::Outputter::Human, project: @project)
-          expect(result).not_to match(/Hi, I'm Dave/)
+        context 'out::verbose' do
+          it 'outputs verbose messages in verbose mode' do
+            result = run_cli(%w[plan run output::verbose --verbose], outputter: Bolt::Outputter::Human,
+                                                                     project: project)
+            expect(result).to match(/Hi, I'm Dave/)
+          end
+
+          it 'does not output verbose messages' do
+            result = run_cli(%w[plan run output::verbose], outputter: Bolt::Outputter::Human, project: project)
+            expect(result).not_to match(/Hi, I'm Dave/)
+          end
+
+          it 'logs verbose messages at the debug level' do
+            run_cli(%w[plan run output::verbose], outputter: Bolt::Outputter::Human, project: project)
+            expect(@log_output.readlines).to include(/DEBUG.*Hi, I'm Dave/)
+          end
         end
       end
 

spec/lib/bolt_spec/integration.rb

@@ -17,8 +17,9 @@ def run_cli(arguments, rescue_exec: false, outputter: Bolt::Outputter::JSON,
       allow(cli).to receive(:puppetdb_client).and_return(pdb_client)
       allow(cli).to receive(:analytics).and_return(Bolt::Analytics::NoopClient.new)
 
+      verbose = arguments.include?('--verbose')
       output =  StringIO.new
-      outputter = outputter.new(false, false, false, false, output)
+      outputter = outputter.new(false, verbose, false, false, output)
       allow(cli).to receive(:outputter).and_return(outputter)
 
       # Don't allow tests to override the captured log config