[PUP-1542] Puppet::Util::Log requires a message Created: 2014/01/29  Updated: 2019/01/15  Resolved: 2018/11/29

Status: Closed
Project: Puppet
Component/s: Types and Providers
Affects Version/s: PUP 3.5.0
Fix Version/s: PUP 5.5.10, PUP 6.0.5

Type: Bug Priority: Normal
Reporter: Gavin Williams Assignee: Kris Bosland
Resolution: Fixed Votes: 0
Labels: resolved-issue-added
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File lib_puppet_type_package_rb.diff    
Issue Links:
Relates
relates to PUP-4386 Windows Group resource reports errors... Closed
relates to PUP-1544 Puppet Logging - `format_exception': ... Closed
relates to PUP-2789 critical bug, windows agent : cant do... Closed
Template: PUP Bug Template
Epic Link: Agent Logging
Team: Coremunity
Sprint: Platform Core KANBAN
Release Notes: Bug Fix
Release Notes Summary: Puppet will provide a minimal log message, instead of no log message and an uninformative error, if there are certain errors during sync.
QA Contact: Narmadha Perumal

 Description   

When trying to add holdable support to the yum package provider under PUP-958, the following error is being thrown when attempting to catch an exception invoking 'provider.hold'.

$ sudo bundle exec puppet resource package bash ensure=held --trace
Error: /Package[bash]: Could not evaluate: Puppet::Util::Log requires a message
/mnt/data/Puppet/lib/puppet/util/log.rb:298:in `message='
/mnt/data/Puppet/lib/puppet/util/log.rb:247:in `initialize'
/mnt/data/Puppet/lib/puppet/util/log.rb:84:in `new'
/mnt/data/Puppet/lib/puppet/util/log.rb:84:in `create'
/mnt/data/Puppet/lib/puppet/util/logging.rb:8:in `send_log'
/mnt/data/Puppet/lib/puppet/transaction/event.rb:78:in `send_log'
/mnt/data/Puppet/lib/puppet/transaction/resource_harness.rb:154:in `ensure in sync_if_needed'
/mnt/data/Puppet/lib/puppet/transaction/resource_harness.rb:155:in `sync_if_needed'
/mnt/data/Puppet/lib/puppet/transaction/resource_harness.rb:107:in `manage_via_ensure_if_possible'
/mnt/data/Puppet/lib/puppet/transaction/resource_harness.rb:77:in `perform_changes'
/mnt/data/Puppet/lib/puppet/transaction/resource_harness.rb:18:in `evaluate'
/mnt/data/Puppet/lib/puppet/transaction.rb:174:in `apply'
/mnt/data/Puppet/lib/puppet/transaction.rb:187:in `eval_resource'
/mnt/data/Puppet/lib/puppet/transaction.rb:117:in `call'
/mnt/data/Puppet/lib/puppet/transaction.rb:117:in `block (2 levels) in evaluate'
/mnt/data/Puppet/lib/puppet/util.rb:327:in `block in thinmark'
/usr/share/ruby/benchmark.rb:296:in `realtime'
/mnt/data/Puppet/lib/puppet/util.rb:326:in `thinmark'
/mnt/data/Puppet/lib/puppet/transaction.rb:117:in `block in evaluate'
/mnt/data/Puppet/lib/puppet/graph/relationship_graph.rb:118:in `traverse'
/mnt/data/Puppet/lib/puppet/transaction.rb:108:in `evaluate'
/mnt/data/Puppet/lib/puppet/resource/catalog.rb:164:in `block in apply'
/mnt/data/Puppet/lib/puppet/util/log.rb:153:in `with_destination'
/mnt/data/Puppet/lib/puppet/transaction/report.rb:107:in `as_logging_destination'
/mnt/data/Puppet/lib/puppet/resource/catalog.rb:163:in `apply'
/mnt/data/Puppet/lib/puppet/indirector/resource/ral.rb:41:in `save'
/mnt/data/Puppet/lib/puppet/indirector/indirection.rb:283:in `save'
/mnt/data/Puppet/lib/puppet/application/resource.rb:219:in `find_or_save_resources'
/mnt/data/Puppet/lib/puppet/application/resource.rb:143:in `main'
/mnt/data/Puppet/lib/puppet/application.rb:376:in `run_command'
/mnt/data/Puppet/lib/puppet/application.rb:367:in `block (3 levels) in run'
/mnt/data/Puppet/lib/puppet/application.rb:474:in `plugin_hook'
/mnt/data/Puppet/lib/puppet/application.rb:367:in `block (2 levels) in run'
/mnt/data/Puppet/lib/puppet/util.rb:479:in `exit_on_fail'
/mnt/data/Puppet/lib/puppet/application.rb:367:in `block in run'
/mnt/data/Puppet/lib/puppet/context.rb:51:in `override'
/mnt/data/Puppet/lib/puppet.rb:224:in `override'
/mnt/data/Puppet/lib/puppet/application.rb:357:in `run'
/mnt/data/Puppet/lib/puppet/util/command_line.rb:137:in `run'
/mnt/data/Puppet/lib/puppet/util/command_line.rb:91:in `execute'
/mnt/data/Puppet/bin/puppet:4:in `<top (required)>'
/usr/local/share/gems/bin/puppet:23:in `load'
/usr/local/share/gems/bin/puppet:23:in `<main>'
package { 'bash':
  ensure => '4.2.45-1.fc19',
}

This is with the following patch applied:
Edit: Added patch as attachment as formatting was breaking it.



 Comments   
Comment by Gavin Williams [ 2014/01/30 ]

Patch file for package type to add catch block around provider.hold.

Comment by Gavin Williams [ 2014/01/30 ]

Tried to do some ruby-debug tracing of this issue - Not sure if it's of any value...

Output is: https://gist.github.com/fatmcgav/8689846#file-ruby-debug-output

Comment by Ethan Brown [ 2014/12/04 ]

I have confirmed under other circumstances on Windows that the original fix for issue 17887 is incomplete.

This particular message is unfortunate, because it masks the propagation of the real error information.

Comment by Russell Mull [ 2017/05/12 ]

Was just reading some of this code with Rob Browning. It looks like there must be an exception being thrown in ResourceHarness.sync_if_needed, sometime after the event object was created but before its status was set. Then, if that exception manages to have a nil message, the Puppet.log_exception(detail) will throw an exception. Then the ensure block happens, which records the event which doesn't yet have a status. Finally, the logger exception bubbles up to the rescue block in ResourceHarness.evaluate, which writes down the "requires a message" text into a newly created event via "failed_because".

Comment by Russell Mull [ 2017/05/16 ]

We've put a workaround for this in the pdb terminus; we should take it out when this is resolved.

Comment by Melissa Stone [ 2018/10/19 ]

The code from the patch uploaded by the reporter

 

diff --git a/lib/puppet/type/package.rb b/lib/puppet/type/package.rb
index 9438716..eb1e59a 100644
--- a/lib/puppet/type/package.rb
+++ b/lib/puppet/type/package.rb
@@ -81,7 +81,11 @@ module Puppet
       end
 
       newvalue(:held, :event => :package_held, :required_features => :holdable) do
-        provider.hold
+        begin
+          provider.hold
+        rescue => detail
+          self.fail Puppet::Error, "Could not hold: #{detail}", detail.backtrace
+        end
       end
 
       # Alias the 'present' value. 

Comment by Jorie Tappa [ 2018/10/19 ]

Grooming session:

We need to reproduce, but the behavior of requiring a message is correct. We may have to find places where we're calling log or raising exceptions in Puppet code and not providing a message.

Comment by Jorie Tappa [ 2018/11/27 ]

Merged to 5.5.x at 2702cbf247b33dbdad4221607ab12ca6e9d1a168

Generated at Mon Sep 23 13:12:18 PDT 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.