From 86d999948a36f16e48a7edc2dc0cf7a82bba2de0 Mon Sep 17 00:00:00 2001 From: Tom Beech Date: Tue, 13 Jul 2021 17:16:59 -0700 Subject: [PATCH] (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](https://github.com/puppetlabs/bolt/issues/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. --- .../out/lib/puppet/functions/out/message.rb | 9 +++- .../out/lib/puppet/functions/out/verbose.rb | 9 +++- .../out/spec/functions/out/message_spec.rb | 12 +++++- .../out/spec/functions/out/verbose_spec.rb | 10 +++++ spec/fixtures/modules/output/plans/verbose.pp | 2 +- spec/integration/plan_spec.rb | 42 ++++++++++++------- spec/lib/bolt_spec/integration.rb | 3 +- 7 files changed, 65 insertions(+), 22 deletions(-) diff --git a/bolt-modules/out/lib/puppet/functions/out/message.rb b/bolt-modules/out/lib/puppet/functions/out/message.rb index 7ee3f72b4d..6f49b4579c 100644 --- a/bolt-modules/out/lib/puppet/functions/out/message.rb +++ b/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 diff --git a/bolt-modules/out/lib/puppet/functions/out/verbose.rb b/bolt-modules/out/lib/puppet/functions/out/verbose.rb index 9089809975..bdf5f3e814 100644 --- a/bolt-modules/out/lib/puppet/functions/out/verbose.rb +++ b/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 diff --git a/bolt-modules/out/spec/functions/out/message_spec.rb b/bolt-modules/out/spec/functions/out/message_spec.rb index 1e32069a18..abeede45e3 100644 --- a/bolt-modules/out/spec/functions/out/message_spec.rb +++ b/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') diff --git a/bolt-modules/out/spec/functions/out/verbose_spec.rb b/bolt-modules/out/spec/functions/out/verbose_spec.rb index e7d2da566e..869377fdcf 100644 --- a/bolt-modules/out/spec/functions/out/verbose_spec.rb +++ b/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') diff --git a/spec/fixtures/modules/output/plans/verbose.pp b/spec/fixtures/modules/output/plans/verbose.pp index 29c8db0f51..aee2f48bcd 100644 --- a/spec/fixtures/modules/output/plans/verbose.pp +++ b/spec/fixtures/modules/output/plans/verbose.pp @@ -1,3 +1,3 @@ -plan output::verbose(){ +plan output::verbose() { out::verbose("Hi, I'm Dave") } diff --git a/spec/integration/plan_spec.rb b/spec/integration/plan_spec.rb index 664094361f..c5cc100f92 100644 --- a/spec/integration/plan_spec.rb +++ b/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 diff --git a/spec/lib/bolt_spec/integration.rb b/spec/lib/bolt_spec/integration.rb index 2d76b1278d..9db5345045 100644 --- a/spec/lib/bolt_spec/integration.rb +++ b/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