[BOLT-901] Improve Plan Logging with apply Created: 2018/10/04  Updated: 2019/05/13  Resolved: 2019/05/09

Status: Resolved
Project: Puppet Task Runner
Component/s: None
Affects Version/s: None
Fix Version/s: BOLT 1.20.0

Type: New Feature Priority: Normal
Reporter: Alex Dreyer Assignee: Cas Donoghue
Resolution: Fixed Votes: 2
Labels: docs_reviewed
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Template:
Sprint: Bolt Kanban
Release Notes: Enhancement
Release Notes Summary: `bolt apply` and the `apply` function from plans will now show log messages for changes and failures that happened while applying the Puppet code.
QA Risk Assessment: Needs Assessment

 Description   

Problem
I want useful human readable output showing the events from each targets apply during a plan. This is especially useful when debugging an apply statement in a plan.

Refactor logging and outputting

  • All actions (plan start/finish, step start/finish, node start/result) are handed to the outputter as an event stream.
  • --verbose becomes an option for the outputter not the logger.
  • "verbose" is now defined to mean node-level results are included in the output when using the human format. "verbose" has no meaning for the JSON format.
  • Plans default to non-verbose, everything else defaults to verbose. -no-verbose is accepted as an addition to -verbose
  • "plan logging" becomes an outputter concept, rather than an executor concept
  • without_default_logging becomes state tracked on the outputter that causes it to simply ignore action events.

Human outputter

  • Human outputter without verbose prints starting action and summary for action messages.
  • Human outputter prints full node-level result with --verbose
  • For bolt apply without verbose, human outputter only prints a summary of the run
  • For bolt apply with verbose, human outputter prints logs from each report showing at least changes. This is probably notice level messages and above, maybe excluding messages where the source is "Puppet".
  • All output from this outputter can go to stdout (currently messages go to stderr for plans)

JSON outputter:

  • When in non-plan mode behaves as it does currently.
  • Logs entire JSON format of apply result on stderr for each node at --verbose
  • This outputter can show intermediate results on stderr in human format, but doesn't have to for this ticket

Log output:

  • The default console log level is now "warn". No "human-oriented" output should come from the logger except for warnings and errors.
  • Log files still default to "info".
  • --debug still sets debug level for console logger, --verbose does not affect the logger at all
  • A "logger outputter" should consume the event stream and translate each event to appropriate log messages that are passed to the logger

Puppet log functions:

  • Eventually these should be handled by the outputter rather than the logger directly, but this is left to a later ticket.

apply_prep/get_resources:

  • These probably need to have specific events the outputter can handle. That is out of scope for this ticket. For now just rely on without_default_logging


 Comments   
Comment by Reid Vandewiele [ 2019/01/24 ]

Ended up throwing this function together for now.

function pe_xl::print_apply_result(ApplyResult $apply) {
  $apply.report['logs'].each |$log| {
    # TODO: include file and line number, if present
    notice("${log['time']} ${log['level'].upcase} ${log['source']} ${log['message']}")
  }
 
  $status = $apply.report['status']
  $message = $apply.message
  $target = $apply.target.name
  notice("\"${status}\" on ${target}: ${message}")
}

Looks something like this when running.

plan pe_xl::test(
  TargetSpec $nodes,
) {
 
  apply($nodes) {
    notify { 'foobar': }
  }.each |$result| {
    pe_xl::print_apply_result($result)
  }
 
}

[reidmv@halcyon:~/src/reidmv-pe_xl/] % bolt --modulepath ~/modules plan run pe_xl::test -n localhost
Starting: plan pe_xl::test
Starting: apply catalog on localhost
Finished: apply catalog with 0 failures in 9.04 sec
2019-01-24T10:02:59.684536000-08:00 NOTICE Puppet foobar
2019-01-24T10:02:59.686271000-08:00 NOTICE /Stage[main]/Main/Notify[foobar]/message defined 'message' as 'foobar'
2019-01-24T10:02:59.692682000-08:00 NOTICE Puppet Applied catalog in 0.01 seconds
changed: 1, failed: 0, unchanged: 0 skipped: 0, noop: 0 on localhost
Finished: plan pe_xl::test in 9.11 sec
Plan completed successfully with no result

Generated at Wed Aug 21 01:04:27 PDT 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.