Puppet

puppet.conf on the puppetmaster is very stable – it is rolled out as is from my svn repo by rsync so rarely if ever gets changed. puppet.conf on the clients is rolled out by puppet but again this rarely changes.

My repo rollout makefile doesn’t restart the puppetmaster as I assume it can pick up any changes made to the manifests automatically. A graceful restart of the Apache daemon in front of Mongrel is done though.

So in short, no I don’t believe it has anything to do with updating puppet.conf on either the clients or the master as this is generally not done. Is there any more I can do to get more debugging/trace output that would be useful?

Oh, if it makes any difference, both my staging and live puppetmasters are running on RHEL5 i386.

As indicated, I think this is related to #1143, but that ticket shows the settings losing their values entirely, rather than your case which reverts to the default values.

I’m absolutely stumped, though — I have analyzed the code pretty thoroughly and have no idea how it could ever revert to either no values or default values; at least, I don’t see how it could happen without puppet.conf being involved in some way.

Try this: in puppetmasterd, after startup but before it backgrounds, freeze Puppet.settings. At some point, you should get an exception, and hopefully the stack trace will tell you who was trying to modify it. However, freezing might not quite be enough — try the code here: http://www.semintelligent.com/blog/articles/29/freezing-ruby-data-structures-recursively

OK, I did a simple Puppet.settings.freeze and it did provide a traceback, let me know if you want me to try again with the deep freeze.

In order to reproduce the issue I added a new node config. Here is the traceback and output from puppetmasterd after the next node connected:

notice: Reparsing /etc/puppet/puppet.conf
Tue Oct 28 17:10:48 +1100 2008: Read error: #
/usr/lib/ruby/site_ruby/1.8/puppet/util/settings.rb:107:in `clear'
/usr/lib/ruby/site_ruby/1.8/puppet/util/settings.rb:337:in `parse'
/usr/lib/ruby/site_ruby/1.8/puppet/util/settings.rb:506:in `reparse'
/usr/lib/ruby/1.8/sync.rb:229:in `synchronize'
/usr/lib/ruby/site_ruby/1.8/puppet/util/settings.rb:505:in `reparse'
/usr/lib/ruby/site_ruby/1.8/puppet/util/settings.rb:762:in `value'
/usr/lib/ruby/site_ruby/1.8/puppet/util/settings.rb:19:in `[]'
/usr/lib/ruby/site_ruby/1.8/puppet.rb:92:in `[]'
/usr/lib/ruby/site_ruby/1.8/puppet/network/http_server/mongrel.rb:127:in `client_info'
/usr/lib/ruby/site_ruby/1.8/puppet/network/http_server/mongrel.rb:105:in `process'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:159:in `process_client'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:158:in `each'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:158:in `process_client'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `run'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `initialize'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `new'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `run'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `initialize'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `new'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `run'
/usr/sbin/puppetmasterd:290
debug: Allowing authenticated client client1(127.0.0.1) access to fileserver.describe
info: mount[module]: allowing *.anchor.net.au access
info: mount[host]: allowing *.anchor.net.au access
info: mount[role]: allowing *.anchor.net.au access
info: mount[common]: allowing *.anchor.net.au access
info: mount[facts]: allowing *.anchor.net.au access
debug: No modules mount given; autocreating with default permissions
debug: No plugins mount given; autocreating with default permissions
warning: Could not find facts for client1; you probably have a discrepancy between the node and fact names
info: Caching node for client1
err: Could not call: No such file or directory - /var/puppet/yaml/node
debug: Allowing authenticated client client1(127.0.0.1) access to fileserver.list
warning: Could not find facts for client1; you probably have a discrepancy between the node and fact names
info: Caching node for client1
err: Could not call: No such file or directory - /var/puppet/yaml/node

… and so on.

Ah, ok that makes sense. My rollout procedure actually rsyncs over the puppet.conf from the staging server then uses sed to replace a few values for the live environment, so while the MD5 of the file doesn’t change, the mtime would.

Glad we could get to the bottom of this.

luke wrote:

In looking at the code, I see two things I can do: Either wrap value retrieval in the mutex, or don’t replace the in-memory values until the whole file has been parsed. The latter is the more sensible option, I think.

More sensible, but not practical. There’s at least three instance variables in a Settings object that need updating, and I can’t see a way of doing that atomically, so all variable accesses will have to be locked anyway.

It might be easier to wrap all accesses to @@settings in the Puppet class and do the ol' switcheroo there.

mpalmer wrote:

luke wrote:

In looking at the code, I see two things I can do: Either wrap value retrieval in the mutex, or don’t replace the in-memory values until the whole file has been parsed. The latter is the more sensible option, I think.

More sensible, but not practical. There’s at least three instance variables in a Settings object that need updating, and I can’t see a way of doing that atomically, so all variable accesses will have to be locked anyway.

It might be easier to wrap all accesses to @@settings in the Puppet class and do the ol' switcheroo there.

What are the three instance variables that need updating? Seems like you could just swap out the @values hash in the ‘parse’ method; what am I missing?

I’m less comfortable wrapping Puppet.settings, because I really think the responsibility should lie with the Settings class, and I don’t think you could wrap it successfully for cases where Puppet.settings[:foo] is used.

luke wrote:

mpalmer wrote:

luke wrote:

In looking at the code, I see two things I can do: Either wrap value retrieval in the mutex, or don’t replace the in-memory values until the whole file has been parsed. The latter is the more sensible option, I think.

More sensible, but not practical. There’s at least three instance variables in a Settings object that need updating, and I can’t see a way of doing that atomically, so all variable accesses will have to be locked anyway.

It might be easier to wrap all accesses to @@settings in the Puppet class and do the ol' switcheroo there.

What are the three instance variables that need updating? Seems like you could just swap out the @values hash in the ‘parse’ method; what am I missing?

There’s also @cache that needs dealing with, and I can’t find the third variable now, but when I started adding locks everywhere there was definitely something else that needed love.

I’m less comfortable wrapping Puppet.settings, because I really think the responsibility should lie with the Settings class, and I don’t think you could wrap it successfully for cases where Puppet.settings[:foo] is used.

Yeah, it’s probably going to be at least as ugly going that way. It would have been an awfully minimal solution, though.

• Matt

mpalmer wrote:

luke wrote:

mpalmer wrote:

luke wrote:

In looking at the code, I see two things I can do: Either wrap value retrieval in the mutex, or don’t replace the in-memory values until the whole file has been parsed. The latter is the more sensible option, I think.

More sensible, but not practical. There’s at least three instance variables in a Settings object that need updating, and I can’t see a way of doing that atomically, so all variable accesses will have to be locked anyway.

It might be easier to wrap all accesses to @@settings in the Puppet class and do the ol' switcheroo there.

What are the three instance variables that need updating? Seems like you could just swap out the @values hash in the ‘parse’ method; what am I missing?

There’s also @cache that needs dealing with, and I can’t find the third variable now, but when I started adding locks everywhere there was definitely something else that needed love.

Actually, you shouldn’t have to touch @cache, at least until you replace the @values hash.

All I’m talking about is building up the replacement hash in a separate variable, and only reassigning @values once the whole parsing or whatever has succeeded. This is a technique I’ve used in many other parts of the system to avoid race conditions, including in the language parser. Once you replace @values, of course, you’d want to clear the cache.

Try as I might, I can’t reproduce the problem in my staging environment so a safe testing of the patch was impossible. I did however deploy the patch on my live puppetmaster and the problem hasn’t recurred since the patch has been in place. I haven’t noticed anything additional breaking due to the patch.

Not sure if this is related still to this bug but I was trying to diagnose another error and got this traceback from the puppetmaster:

/usr/lib/ruby/1.8/sync.rb:57:in `Fail'
/usr/lib/ruby/1.8/sync.rb:63:in `Fail'
/usr/lib/ruby/1.8/sync.rb:183:in `sync_unlock'
/usr/lib/ruby/1.8/sync.rb:231:in `synchronize'
/usr/lib/ruby/site_ruby/1.8/puppet/util.rb:385:in `threadlock'
/usr/lib/ruby/site_ruby/1.8/puppet/util/log.rb:437:in `newmessage'
/usr/lib/ruby/site_ruby/1.8/puppet/util/log.rb:436:in `each'
/usr/lib/ruby/site_ruby/1.8/puppet/util/log.rb:436:in `newmessage'
/usr/lib/ruby/site_ruby/1.8/puppet/util/log.rb:505:in `initialize'
/usr/lib/ruby/site_ruby/1.8/puppet/util/log.rb:126:in `new'
/usr/lib/ruby/site_ruby/1.8/puppet/util/log.rb:126:in `create'
/usr/lib/ruby/site_ruby/1.8/puppet.rb:59:in `info'
/usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:152:in `send'
/usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:151:in `each'
/usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:151:in `send'
/usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:126:in `fork'
/usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:126:in `send'
/usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:121:in `process'
/usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:66:in `process'
/usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:59:in `each'
/usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:59:in `process'
/usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:33:in `report'
/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `to_proc'
/usr/lib/ruby/site_ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `call'
/usr/lib/ruby/site_ruby/1.8/puppet/network/xmlrpc/processor.rb:52:in `protect_service'
/usr/lib/ruby/site_ruby/1.8/puppet/network/xmlrpc/processor.rb:85:in `setup_processor'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `call'
/usr/lib/ruby/1.8/xmlrpc/server.rb:336:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `each'
/usr/lib/ruby/1.8/xmlrpc/server.rb:323:in `dispatch'
/usr/lib/ruby/1.8/xmlrpc/server.rb:366:in `call_method'
/usr/lib/ruby/1.8/xmlrpc/server.rb:378:in `handle'
/usr/lib/ruby/site_ruby/1.8/puppet/network/xmlrpc/processor.rb:44:in `process'
/usr/lib/ruby/site_ruby/1.8/puppet/network/http_server/mongrel.rb:111:in `process'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel/http_response.rb:65:in `start'
/usr/lib/ruby/site_ruby/1.8/puppet/network/http_server/mongrel.rb:108:in `process'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:159:in `process_client'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:158:in `each'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:158:in `process_client'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `run'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `initialize'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `new'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:285:in `run'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `initialize'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `new'
/usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `run'
/usr/sbin/puppetmasterd:287
debug: File[/etc/puppet/puppet.conf]: Adding default for backup/usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:166:in `send': Could not send report emails via sendmail: Thread(#) not locked. (Puppet::Error)
        from /usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:126:in `fork'
        from /usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:126:in `send'
        from /usr/lib/ruby/site_ruby/1.8/puppet/reports/tagmail.rb:121:in `process'
        from /usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:66:in `process'
        from /usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:59:in `each'
        from /usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:59:in `process'
        from /usr/lib/ruby/site_ruby/1.8/puppet/network/handler/report.rb:33:in `report'
        from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `to_proc'
         ... 20 levels...
        from /usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `initialize'
        from /usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `new'
        from /usr/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb:268:in `run'
        from /usr/sbin/puppetmasterd:287

After it occurred the first time after quite a few clients had already connected then disconnected, it progressively happened more and more frequently in each of the puppetmasters I had running.

ohookins wrote:

Not sure if this is related still to this bug but I was trying to diagnose another error and got this traceback from the puppetmaster:

[…]

After it occurred the first time after quite a few clients had already connected then disconnected, it progressively happened more and more frequently in each of the puppetmasters I had running.

That’s a different and already-filed bug.

mpalmer wrote:

I have this sneaking suspicion that “avoid” might actually mean “make less likely” rather than “make impossible”…

The problem with trying to replace @values and clear @cache without a mutex is that the race condition still exists, it’s just a smaller target. So when you’re updating @values you need to also clear @cache in the same lock — which means that we still need explicit locking on every access to @values. Since this bug is causing pain in the day job, I’ve whipped up the attached patch to do just that. It doesn’t break anything else, but it hasn’t been tested enough to have a reasonable guarantee that it definitely fixes the bug, since it can’t be reproduced with 100% reliability. The patch is a bit of a monster, as there’s a few bits of dodgy code I gutted while I was in there.

Also, I found the other place that (I thought) needed locking — @config. Turns out that @config is just diving back into the Settings object, so it kinda-sorta doesn’t need locking (although I get the feeling there’s still going to be pain and suffering down the line).

• Matt

The patch looks good to me.

I’d still like the atomic value replacement, though; I’ll hopefully get to it, but it should be easy to do with the mutex in this patch.