The Puppet Labs Issue Tracker has Moved: https://tickets.puppetlabs.com

This issue tracker is now in read-only archive mode and automatic ticket export has been disabled. Redmine users will need to create a new JIRA account to file tickets using https://tickets.puppetlabs.com. See the following page for information on filing tickets with JIRA:

Bug #17887

Failure during property sync results in "Puppet::Util::Log requires a message"

Added by Dominic Cleal over 3 years ago. Updated over 2 years ago.

Status:ClosedStart date:
Priority:NormalDue date:
Assignee:Dominic Cleal% Done:

0%

Category:transactions
Target version:3.2.1
Affected Puppet version:development Branch:https://github.com/puppetlabs/puppet/pull/1614
Keywords:resource harness, transaction

We've Moved!

Ticket tracking is now hosted in JIRA: https://tickets.puppetlabs.com


Description

During provider development and testing with rspec+mocha and using a test catalog, an expectation failure can cause the following log message:

Could not evaluate: Puppet::Util::Log requires a message

This occurs if the property sync calls a method that has a mocha expectation set, but has reached the max call count or similar.

When testing a catalog from a test, the Puppet::Transaction::ResourceHarness calls apply_parameter for a given parameter, which then calls property.sync. If the mocha expectation fails inside this sync, the rescue block is never called (it isn’t an exception) but the ensure block is still run. This calls send_log on the event, but the message is uninitialised at that point so the logging fails with the above error.


Related issues

Related to Puppet - Bug #18812: Reuse HTTP connection for duration of pluginsync Accepted
Related to Puppet - Bug #19344: "Error: Could not run: can't convert Puppet::Util::Log in... Needs More Information

History

#1 Updated by Dominic Cleal over 3 years ago

  • Status changed from Unreviewed to In Topic Branch Pending Review
  • Target version set to 3.0.x
  • Branch set to https://github.com/puppetlabs/puppet/pull/1307

#2 Updated by Dominic Cleal over 3 years ago

  • Subject changed from Mocha expectation failure during property sync results in "Puppet::Util::Log requires a message" to Failure during property sync results in "Puppet::Util::Log requires a message"
  • Priority changed from Low to Normal
  • Branch changed from https://github.com/puppetlabs/puppet/pull/1307 to https://github.com/puppetlabs/puppet/pull/1358

This also happens if an exception is raised that isn’t derived from StandardError. The resource harness uses a simple rescue and so core Ruby exceptions (OOMs etc) also get masked by this problem.

Example of a masked SignalException: puppet-dev: Any advice on “Puppet::Util::Log requires a message” failure

#3 Updated by Anonymous over 3 years ago

  • Target version changed from 3.0.x to 3.x

As the 3.0.x line is winding down with the impending release of 3.1.0, I am removing the target at 3.0.x from tickets in the system and targeting them at 3.x instead.

#4 Updated by Josh Cooper over 3 years ago

  • Status changed from In Topic Branch Pending Review to Code Insufficient

I ran into this same error during pluginsync. My windows VM tries to pluginsync from my other VM. This applies a catalog with remote file sources. Each file content request results in a new ssl connection (really it should be reusing the connection) causing the SSL handshake overhead. During the handshake, the Windows VM is blocked in a read, waiting for the master to respond, when the socket times out.. In ruby 1.8, Timeout::Error is not a StandardError (and that results in the issue Andy mentions above). Note in 1.9, Timeout::Error is a StandardError.

Dominic, I’m marking the PR as code as insufficient, because we still want to log the exception that results from the failure to sync the property. Patrick and I were discussing creating a timeout method, e.g. Puppet::Util.timeout, and have that always throw an instance of a standard error.

But in my case, the Timeout::Error is originating in the Net::HTTP code due to read timing out. Perhaps the best thing is to wrap our Puppet::Network::HTTP::Connection#request method to catch Timeout::Error explicitly and raise a Puppet::Error.

#5 Updated by Dominic Cleal over 3 years ago

Josh Cooper wrote:

Dominic, I’m marking the PR as code as insufficient, because we still want to log the exception that results from the failure to sync the property.

Generally, we don’t want to be catching things that aren’t StandardErrors here, they should still be propagating up.

Patrick and I were discussing creating a timeout method, e.g. Puppet::Util.timeout, and have that always throw an instance of a standard error.

But in my case, the Timeout::Error is originating in the Net::HTTP code due to read timing out. Perhaps the best thing is to wrap our Puppet::Network::HTTP::Connection#request method to catch Timeout::Error explicitly and raise a Puppet::Error.

Timeouts are an exception and yes, should be fixed and caught lower down since we can skip to the next task. I don’t think this applies to anything else such as the mocha expectations in this issue, receiving signals, OOMs etc. I’d suggest addressing that separately.

#6 Updated by Dominic Cleal about 3 years ago

Dominic Cleal wrote:

Josh Cooper wrote:

Dominic, I’m marking the PR as code as insufficient, because we still want to log the exception that results from the failure to sync the property.

Generally, we don’t want to be catching things that aren’t StandardErrors here, they should still be propagating up.

It’s still not clear to me what behaviour you’re looking for (network timeout stuff is out of scope IMO, should be another ticket).

I’m wondering if you mean it should catch all exceptions (not just derivatives of StandardError), log in all cases, but then raise non-StandardErrors back again? We definitely don’t want to squash non-StandardErrors, as they could be a variety of things that genuinely should be propagated. I’m also unsure about any side-effects that would come from catching some errors (e.g. OOMs).

#7 Updated by Dominic Cleal about 3 years ago

  • Status changed from Code Insufficient to In Topic Branch Pending Review
  • Branch changed from https://github.com/puppetlabs/puppet/pull/1358 to https://github.com/puppetlabs/puppet/pull/1614

#8 Updated by Josh Cooper almost 3 years ago

  • Status changed from In Topic Branch Pending Review to Merged - Pending Release
  • Target version changed from 3.x to 3.2.1

This was merged into stable and master in 053a743

#9 Updated by Josh Cooper over 2 years ago

  • Status changed from Merged - Pending Release to Closed

Also available in: Atom PDF