Bug #2550

to_sym errors from puppetd

Added by Sam Rowe almost 3 years ago. Updated over 2 years ago.

Status:Closed Start date:08/18/2009
Priority:Normal Due date:
Assignee:James Turnbull % Done:

0%
Category:error reporting
Target version:0.25.0
Affected Puppet version:0.25.0rc1 Branch:
Keywords:
Votes: 1

Description

Running a 299eadb7d903d250c8340049bd78611f0c705920 RHEL 5 client against a server running with Markus' branch which fixes #2493 (ffe6bb837b56ecaf5a50f26550c0e11c707345dc) we get lots of to_sym errors like this:

/usr/lib/ruby/site_ruby/1.8/puppet/type/file/content.rb:110:in `retrieve'
/usr/lib/ruby/site_ruby/1.8/puppet/type.rb:810:in `currentpropvalues'
/usr/lib/ruby/site_ruby/1.8/puppet/util/autoload.rb:85:in `inject'
/usr/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `each'
/usr/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `inject'
/usr/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `currentpropvalues'
/usr/lib/ruby/site_ruby/1.8/puppet/type.rb:790:in `retrieve'
/usr/lib/ruby/site_ruby/1.8/puppet/type/file.rb:638:in `retrieve'
/usr/lib/ruby/site_ruby/1.8/puppet/type.rb:719:in `evaluate'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:60:in `apply'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:249:in `eval_children_and_apply_resource'
/usr/lib/ruby/site_ruby/1.8/puppet/util.rb:425:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'
/usr/lib/ruby/1.8/benchmark.rb:307:in `realtime'
/usr/lib/ruby/site_ruby/1.8/puppet/util.rb:424:in `thinmark'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:248:in `eval_children_and_apply_resource'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:205:in `eval_resource'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:294:in `evaluate'
/usr/lib/ruby/site_ruby/1.8/puppet/util.rb:425:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'
/usr/lib/ruby/1.8/benchmark.rb:307:in `realtime'
/usr/lib/ruby/site_ruby/1.8/puppet/util.rb:424:in `thinmark'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:293:in `evaluate'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:287:in `collect'
/usr/lib/ruby/site_ruby/1.8/puppet/transaction.rb:287:in `evaluate'
/usr/lib/ruby/site_ruby/1.8/puppet/resource/catalog.rb:139:in `apply'
/usr/lib/ruby/site_ruby/1.8/puppet/configurer.rb:142:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/util.rb:180:in `benchmark'
/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'
/usr/lib/ruby/1.8/benchmark.rb:307:in `realtime'
/usr/lib/ruby/site_ruby/1.8/puppet/util.rb:179:in `benchmark'
/usr/lib/ruby/site_ruby/1.8/puppet/configurer.rb:141:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/agent/locker.rb:21:in `lock'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/ruby/1.8/sync.rb:229:in `synchronize'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:130:in `with_client'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:51:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/application/puppetd.rb:103:in `onetime'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:226:in `send'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:226:in `run_command'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:306:in `exit_on_fail'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/sbin/puppetd:159
err: //allusers::bjones/Allusers::Userfile[bjones/.less]/File[/home/bjones/.less]: Failed to retrieve current state of resource: Could not read /home/bjones/.less: undefined method `to_sym' for nil:NilClass

FWIW this only happens on files and all of the files that had the problem are scheduled. And we ran with —ignoreschedules.

Related issues

related to Puppet - Bug #2551: File 'content changed to' message is often missing inform... Closed 08/18/2009
related to Puppet - Bug #2511: Sporadic and spurious "invalid parameter" errors Rejected 08/07/2009
related to Puppet - Bug #2578: undefined method _file Duplicate 08/27/2009

History

#1
Updated by Sam Rowe almost 3 years ago

This also happens on Solaris 9 and 10. And HP-UX 11.11.

Also, it doesn’t happen for every file with a schedule, just some of them.

#2
Updated by Sam Rowe almost 3 years ago

Same thing with git master updated a few minutes ago (0ef5f228c20a34a562a1c20b206acf2af0eb41ba).

#3
Updated by Sam Rowe almost 3 years ago

We reported this a month ago as http://projects.reductivelabs.com/issues/2372

#4
Updated by Luke Kanies almost 3 years ago

  • Category set to file
  • Status changed from Unreviewed to Accepted
  • Assignee set to Markus Roberts
  • Target version set to 0.25.0

I think the checksum_type is somehow throwing this to_sym exception, either on the client or server side. It should be straightforward to figure out how that can happen, even if we can’t reproduce it.

#5
Updated by Markus Roberts almost 3 years ago

  • Status changed from Accepted to In Topic Branch Pending Review

As Luke suspected, the checksum_type was assuming that if the source was present its metadata was as well and throwing a to_sym exception trying to extract the type of the checksum from the (nil) result.

Branch which should fix this specific problem up on http://github.com/MarkusQ/puppet/tree/ticket/master/2550; there may be other problems if the absence of metadata is caused by some other underlying problem.

#6
Updated by Markus Roberts almost 3 years ago

After looking at #2551 a little I believe they are both symptoms of the same underlying issue.

#7
Updated by Sam Rowe almost 3 years ago

We tested and it seems to fail randomly. We’ve seen errors like this before your fix, but they weren’t consistent or reproducible, so we didn’t report them, so it’s possible they’re unrelated. However, we can’t get a catalog to run because of them now.

Here’s a run:

puppetd -t --ignoresc --trace                                                                                                                                                                                               
err: State got corrupted
info: Loading facts in hardwareisa_overrides
info: Loading facts in hardwaremodel_overrides
info: Loading facts in tww_ssh_version
info: Loading facts in fc
info: Loading facts in serialnumber
info: Loading facts in hardwareisa_overrides
info: Loading facts in hardwaremodel_overrides
info: Loading facts in tww_ssh_version
info: Loading facts in fc
info: Loading facts in serialnumber
info: Caching catalog for uptime.bor.usg.edu
/usr/lib/site_ruby/1.8/puppet/type.rb:530:in `newattr'
/usr/lib/site_ruby/1.8/puppet/type.rb:455:in `[]='
/usr/lib/site_ruby/1.8/puppet/type.rb:1919:in `set_name'
/usr/lib/site_ruby/1.8/puppet/type.rb:1905:in `initialize'
/usr/lib/site_ruby/1.8/puppet/type/file.rb:400:in `initialize'
/usr/lib/site_ruby/1.8/puppet/resource.rb:177:in `new'
/usr/lib/site_ruby/1.8/puppet/resource.rb:177:in `to_ral'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:565:in `send'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:565:in `to_catalog'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:543:in `each'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:543:in `to_catalog'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:463:in `to_ral'
/usr/lib/site_ruby/1.8/puppet/configurer.rb:120:in `convert_catalog'
/usr/lib/site_ruby/1.8/puppet/configurer.rb:115:in `retrieve_catalog'
/usr/lib/site_ruby/1.8/puppet/configurer.rb:135:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `lock'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `synchronize'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:51:in `with_client'
/usr/lib/site_ruby/1.8/puppet/agent.rb:58:in `run'
/usr/lib/site_ruby/1.8/puppet/application/puppetd.rb:103:in `onetime'
/usr/lib/site_ruby/1.8/puppet/application/puppetd.rb:94:in `onetime'
/usr/lib/site_ruby/1.8/puppet/application.rb:226:in `send'
/usr/lib/site_ruby/1.8/puppet/application.rb:226:in `run_command'
/usr/lib/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/lib/site_ruby/1.8/puppet/application.rb:217:in `exit_on_fail'
/usr/lib/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/sbin/puppetd:159
err: Could not run Puppet configuration client: Parameter path failed: File paths must be fully qualified, not 'tss_posix_funcs'

and another run:

puppetd -t --ignoresc --trace                                                                                                                                                                                               
err: State got corrupted
info: Loading facts in hardwareisa_overrides
info: Loading facts in hardwaremodel_overrides
info: Loading facts in tww_ssh_version
info: Loading facts in fc
info: Loading facts in serialnumber
info: Loading facts in hardwareisa_overrides
info: Loading facts in hardwaremodel_overrides
info: Loading facts in tww_ssh_version
info: Loading facts in fc
info: Loading facts in serialnumber
info: Caching catalog for uptime.bor.usg.edu
/usr/lib/site_ruby/1.8/puppet/util/errors.rb:51:in `fail'
/usr/lib/site_ruby/1.8/puppet/type.rb:441:in `[]='
/usr/lib/site_ruby/1.8/puppet/type.rb:1935:in `set_parameters'
/usr/lib/site_ruby/1.8/puppet/type.rb:1929:in `each'
/usr/lib/site_ruby/1.8/puppet/type.rb:1929:in `set_parameters'
/usr/lib/site_ruby/1.8/puppet/type.rb:1909:in `initialize'
/usr/lib/site_ruby/1.8/puppet/type/file.rb:400:in `initialize'
/usr/lib/site_ruby/1.8/puppet/resource.rb:177:in `new'
/usr/lib/site_ruby/1.8/puppet/resource.rb:177:in `to_ral'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:565:in `send'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:565:in `to_catalog'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:543:in `each'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:543:in `to_catalog'
/usr/lib/site_ruby/1.8/puppet/resource/catalog.rb:463:in `to_ral'
/usr/lib/site_ruby/1.8/puppet/configurer.rb:120:in `convert_catalog'
/usr/lib/site_ruby/1.8/puppet/configurer.rb:115:in `retrieve_catalog'
/usr/lib/site_ruby/1.8/puppet/configurer.rb:135:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `lock'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `synchronize'
/usr/lib/site_ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/site_ruby/1.8/puppet/agent.rb:51:in `with_client'
/usr/lib/site_ruby/1.8/puppet/agent.rb:58:in `run'
/usr/lib/site_ruby/1.8/puppet/application/puppetd.rb:103:in `onetime'
/usr/lib/site_ruby/1.8/puppet/application/puppetd.rb:94:in `onetime'
/usr/lib/site_ruby/1.8/puppet/application.rb:226:in `send'
/usr/lib/site_ruby/1.8/puppet/application.rb:226:in `run_command'
/usr/lib/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/lib/site_ruby/1.8/puppet/application.rb:217:in `exit_on_fail'
/usr/lib/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/sbin/puppetd:159
err: Could not run Puppet configuration client: Invalid parameter :ignore at /etc/puppet/modules/allusers/manifests/init.pp:23

Running over and over it has similar stack traces on random parameters.

#8
Updated by Markus Roberts almost 3 years ago

  • Status changed from In Topic Branch Pending Review to Ready For Checkin

Sam —

Thanks for the information. The second trace at least looks very like #2511, and I’ve copied it to that ticket. I’m not sure if we’ve seen an example of the first before; I’ll look into it and possibly open a new ticket for it.

Based on these results I believe this patch fixes the specific issue at hand but leaves open the very related/root cause #2551, the possibly related, possibly unrelated #2511, and perhaps one other issue TBD.

#9
Updated by Sam Rowe almost 3 years ago

Markus Roberts wrote:

Based on these results I believe this patch fixes the specific issue at hand but leaves open the very related/root cause #2551, the possibly related, possibly unrelated #2511, and perhaps one other issue TBD.

Which results? When we had the to_sym errors, we were able to complete (although possibly incomplete) catalog runs. Now we can’t. The problem is worse from our perspective.

#10
Updated by Markus Roberts almost 3 years ago

  • Assignee changed from Markus Roberts to James Turnbull

#11
Updated by James Turnbull almost 3 years ago

Is this ready to be committed? From what Sam said this makes things worse?

#12
Updated by Markus Roberts almost 3 years ago

James Turnbull wrote:

Is this ready to be committed? From what Sam said this makes things worse?

I suppose it depends on your perspective. Without this patch the underlying error(s) are ignored and thing “go along further” but, as Sam notes, the results are probably incomplete/incorrect. My perspective is that this patch makes the situation slightly better by causing it to fail in a more appropriate manner. To that end, I’m actually wondering why it continues past the “err: State got corrupted” point (see the top of Sam’s listing) with no more remediation that assuming that there was no state.

So:

  • There is at least one, possibly as many as three underlying errors here (see related tickets). This patch does not fix them.
  • The relationship was not at first apparent because the failure was resulting in a nil being returned where it was not expected, and this caused a less then useful “undefined method `to_sym' for nil” message the first time the value was used.
  • This patch changes the data flow in that one particular place so that missing metadata does not produce the cryptic message.

If you’d prefer, we could hold this and combine it with one of the other tickets, but I’d see this as something that needs to be dealt with in any case and which is only circumstantially related to the more serious underlying issues.

#13
Updated by Markus Roberts almost 3 years ago

  • Category changed from file to error reporting

#14
Updated by James Turnbull over 2 years ago

  • Status changed from Ready For Checkin to Closed

I’ve pushed this in commit:ff39bc707e7f37ddeb28203a9e1bfaddcb9dc641 in branch master. Not convinced about some of the logic of pushing it but…

Also available in: Atom PDF