(GH-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`**
  ([#2900](#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')

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