Puppet-like logging for apply blocks in Bolt

[vlastim...@gmail.com]

Hello,

I'm not sure if it's possible (I haven't seen it) to provide Puppet-like logging of changed / error resources in apply blocks without any additional code. Puppet Agent gives great visibility with default logging level about what has changed and what has failed. Unfortunately, the Bolt apply logs nothing except the failure.

Example:

  apply($workers) {

    exec { '/usr/bin/uptime': }

    exec { '/usr/bin/missing': }

    file { '/tmp/hey': content => 'hey', }

  }

Result:

  Starting: apply catalog on 147.251.255.50, 147.251.255.51, 147.251.255.56

  Finished: apply catalog with 3 failures in 12.41 sec

  Finished: plan profiles::test in 24.21 sec

  Resources failed to apply for 147.251.255.50

    Exec[/usr/bin/missing]: change from 'notrun' to ['0'] failed: Could not find command '/usr/bin/missing'

  Resources failed to apply for 147.251.255.51

    Exec[/usr/bin/missing]: change from 'notrun' to ['0'] failed: Could not find command '/usr/bin/missing'

  Resources failed to apply for 147.251.255.56

    Exec[/usr/bin/missing]: change from 'notrun' to ['0'] failed: Could not find command '/usr/bin/missing'

For the user who is writing the plan, debugging the Puppet modules / classes, running it several times... he doesn't see that uptime is running every time or when the file has changed.

Yes, the workaround is to catch the result of apply call... but you would have to do it for the very apply block.

Example:

  $results = apply($workers, _catch_errors => true) {

    exec { '/usr/bin/uptime': }

    exec { '/usr/bin/missing': }

    file { '/tmp/hey': content => 'hey', }

  }

  $results.each |$result| {

    $result.report['logs'].each |$log| {

      $_level = $log['level'] ? {

        'notice'  => 'Notice',

        'err'     => 'Error',

        default   => 'Unknown',

      }

      $_msg = sprintf(

        '%s: %s: %s: %s',

        $result.target.name,

        $_level,

        $log['source'],

        $log['message']

      )

      case $log['level'] {

        err:      { err($_msg) }

        default:  { notice($_msg) }

      }

    }

  }

Result:

  Starting: apply catalog on 147.251.255.50, 147.251.255.51, 147.251.255.56

  Finished: apply catalog with 3 failures in 12.26 sec

  147.251.255.50: Notice: /Stage[main]/Main/Exec[/usr/bin/uptime]/returns: executed successfully

  147.251.255.50: Error: Puppet: Could not find command '/usr/bin/missing'

  147.251.255.50: Error: /Stage[main]/Main/Exec[/usr/bin/missing]/returns: change from 'notrun' to ['0'] failed: Could not find command '/usr/bin/missing'

  147.251.255.50: Notice: /Stage[main]/Main/File[/tmp/hey]/content: content changed '{md5}79c2b46ce2594ecbcb5b73e928345492' to '{md5}6057f13c496ecf7fd777ceb9e79ae285'

  147.251.255.50: Notice: Puppet: Applied catalog in 0.11 seconds

  147.251.255.51: Notice: /Stage[main]/Main/Exec[/usr/bin/uptime]/returns: executed successfully

  147.251.255.51: Error: Puppet: Could not find command '/usr/bin/missing'

  147.251.255.51: Error: /Stage[main]/Main/Exec[/usr/bin/missing]/returns: change from 'notrun' to ['0'] failed: Could not find command '/usr/bin/missing'

  147.251.255.51: Notice: /Stage[main]/Main/File[/tmp/hey]/content: content changed '{md5}79c2b46ce2594ecbcb5b73e928345492' to '{md5}6057f13c496ecf7fd777ceb9e79ae285'

  147.251.255.51: Notice: Puppet: Applied catalog in 0.09 seconds

  147.251.255.56: Notice: /Stage[main]/Main/Exec[/usr/bin/uptime]/returns: executed successfully

  147.251.255.56: Error: Puppet: Could not find command '/usr/bin/missing'

  147.251.255.56: Error: /Stage[main]/Main/Exec[/usr/bin/missing]/returns: change from 'notrun' to ['0'] failed: Could not find command '/usr/bin/missing'

  147.251.255.56: Notice: /Stage[main]/Main/File[/tmp/hey]/content: content changed '{md5}79c2b46ce2594ecbcb5b73e928345492' to '{md5}6057f13c496ecf7fd777ceb9e79ae285'

  147.251.255.56: Notice: Puppet: Applied catalog in 0.07 seconds

  Finished: plan profiles::test in 24.7 sec

I would love to see the above logging style for apply blocks integrated into the Bolt so that it's not necessary to always catch the results to get reasonable logs. It provides the helpful (I would more say necessary) visibility into what's happening on the targets.

Thanks for any comments.

Best regards,

Vlastimil Holer

[Alex Dreyer]

Thanks, I agree this output should be available when you're debugging apply statements in plans and I did a spike on implementing this type of logging a few months ago. After some testing it became apparent that this is too much output for the default log level. When running on many nodes it overwhelms any other output from the plan. Would logging it at verbose level solve your debugging problem? 

Fixing this issue is ticketed as part of https://tickets.puppetlabs.com/browse/BOLT-901

--
You received this message because you are subscribed to the Google Groups "Puppet Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to puppet-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-users/45c0f2a2-4cf9-4993-9c2c-b89b910a8f5c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Vlastimil Holer]

Maybe it shouldn't be related to the existing Bolt log levels? In --verbose, I can see too much noise to follow the apply messages there. I would like to have a separate parameter, e.g. --log-apply=verbose (and be able to set the logging level in the configuration). Or, I could imagine even a standard library function for now (something similar to without_default_logging), still better than nothing...

Thank you, Alex.

Vlastimil