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/documentation/writing_plans.md b/documentation/writing_plans.md index ece7635989..0d73ce966c 100644 --- a/documentation/writing_plans.md +++ b/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 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