puppet/puppetmaster randomly corrupts file{} resources, seemingly after leaking RAM for some time

I expect the only real solution here is to verify the md5 sum on the client side, to make sure the file being sent is the same file we asked for.

Found an IRC log containing the contents of one of the files:

[2008/01/11 22:55:04] <fujin> where it grows to ridiculous ram usage
[2008/01/11 22:55:13] <fujin> and starts overwriting file{} resources
[2008/01/11 22:55:28] <fujin> < 420 file 0 0 {md5}55e72f92f1075842e36dfe449fb9edae
[2008/01/11 22:55:30] <fujin> with stuff like that

We just saw the same thing. In addition to replacing some files with those hash values, it also replaced some files with empty directories (/etc/crontab on one system, /etc/resolv.conf on another system -- that caused interesting problems).

We luckily killed puppetmaster before it could corrupt files, because we get munin errors before it goes really bad. It this time, we resorted to not permanently running puppetmaster, but only run it and puppetd when there are changes made. I have no idea how to go about debugging this... Any tips?

We were having as well the same problem. authorized_keys file was filled with this sort of md5-hash stuff.

I haven't been able to find the source of these issues, but I'm hoping the fix in [b06767ee2d7c22c27d746d3e8d1b6effa37deaa6] will be close enough.

This commit adds a client-side checksum verification, so that the content written to disk is the same as the content on the server, which should at least get you failures instead of bad data written to disk.

See #1131. There is at least one report of similar conditions, where the file resource gets corrupted into creating a directory that appears to be slipping past the checksum fix. I have trouble imagining a more critical bug in puppet.

Is anyone in a position to help debug the problem? Can anyone reproduce it and give me access to the system? Can anyone give me traces from the server and/or client when there are problems?

I can provide an EC2 node running a copy of the manifests that we know trigger the bug, if it would be helpful.

I can provice a ubuntu 7.04 system w/ 0.24.1-2 from Debian which exhibits this behaviour (when puppetmaster isn't restarted regularly) if an NDA is signed.

This problem is clearly triggered by something specific on the server, and it involves significant confusion on the server. Until I can trigger that confusion on demand, I can't reproduce the problem.

I've already spent a couple of days doing what I could to shore up the situation, and I've decided that it's unreasonable for me to spend my time on someone else's servers trying further to reproduce the problem. Based on the days I've already spent, I can't imagine that I'd fix the problem in less than 3-5 days, especially since it would require me learning the local environment.

I've provided all the resources you need in #1131 to reproduce the problem on a test system. If you're a customer, we already have a relationship and I clearly am expected to help you. If you're not a customer, you've decided that you're comfortable with community support and my own best-effort; well, I've already put out my best effort in this case, and it's time for someone else to provide some help.

Okay!

There is some more data needed for tracking down this bug. We have thought for a while now that 1010 and #1131 are related, since we tend to see the corruption happen as memory consumption increases. Several times today, while spending a lot of time on Fujin's magically repeatable system, we saw a few things that seem to contradict this hypothesis:

1. We saw 1010 events happen when memory consumption was relatively low, and nowhere near the large scale spikes we sometimes see. 1. We saw objects in memory that seemed to be displaying quite a bit of growth, but they weren't obviously related to the file objects at all. 1. The objects most reported to be leaking had nothing to do with file resources.

At this point, having spent a lot of time poking around inside a running puppet master exhibiting 1010 and #1131, my working hypothesis is that 1010 and #1031 are *not* related.

What we need to do now is prove it, and anyone with a 1010 system can help.

We need you to figure out which resource is affected by 1010. The best way to get this is to grab the debug/trace output that shows the bad comparison. We'll be happy with just a File/i/got/hit/by/1010? style resource designation.

Next, we need you to go over to #1131, and follow the instructions to get gdb running against your puppetmaster.

Once you have it running, and you've redirected_stdout, we need you to run:

(gdb) eval "total = ObjectSpace.each_object {|x| if x.class.to_s =~ /Puppet/; puts '---'; puts x.inspect; end }; puts \"---\nTotal Objects: #{total}\""

This is going to take a very long time to complete, and generate a really, really large amount of data. What we're looking for is the proverbial needle in the haystack -- we want to find the corrupted file resource.

If we can't find it, that means it's not being persisted within a single puppetmasterd process. Which raises the question: if it's not being persisted, and it's related to the leak, why do we garbage collect it *after it's corrupted by the leak*?

This bug is starting to smell more and more like thread saftey to me, but I would like to get the leak relationship proven or disproven first.

Once you have that dump, send it to adam at hjksolutions.com. It'll be in /tmp/ruby-debug.PID, where PID is the PID of your running puppet master.

Adam

After much debugging and hypothesizing, lak, fujin, shadoi and I have figured this out.

Shadoi had an incident today where an 0.23.2 client was accidentally upgraded to 0.24.1. This client then 1010'ed, but the 0.23.2 puppet master showed no signs of either memory leaking or of spreading the 1010 activity beyond this single node.

That started a conversation with Luke around where in the client code things could be at fault. He pointed out the http pooling code in network/http_pool.rb, and suggested we eliminate the caching altogether. I put together a patch, Fujin built and distributed it to his clients, and his otherwise very reliable 1010 causing infrastructure has not seen a recurrence since. (With load essentially identical to conditions we could trigger this bug in regularly.)

The patch is at:

git://junglist.gen.nz/puppet.upstream bug1010

Now, a few caveats:

1. This causes lots of "Other end went away" errors on the client. This appears to be lines 68-75 of network/xmlrpc/client.rb. I'm pretty sure that it can just be silenced. The best thing to do is explicitly tear down the HTTP connection, but I'm not sure where that should be done. I imagine lak is the man to carry this over the finish line in that regard.

2. The memory leaking being tracked in #1131 is greatly exacerbated by this issue. We saw much faster growth than we had previously, and when we finally killed the puppetmaster it was at nearly 1.5GB of VSS. If you are being plagued by #1010, and you don't want to wait for some fixes to #1131, make sure you stick a cronjob in there to restart your mongrels before they eat you alive.

Fujin should get special thanks here -- if it wasn't for him, and his willingness to allow us to trample all over his puppetmaster, this bug would have lingered even longer.

Shadoi, gets the "good eye" award. Thanks for pointing us in the right direction.

As always, Luke's guidance was the key to putting a fix in place.

See you at the next 0.24.x release with a no longer occurring #1010 once we fix the chattering.

Replying to adamhjk:

After much debugging and hypothesizing, lak, fujin, shadoi and I have figured this out.

Great work!

That started a conversation with Luke around where in the client code things could be at fault. He pointed out the http pooling code in network/http_pool.rb, and suggested we eliminate the caching altogether.

Is everyone who is seeing this problem using Mongrel? We're using Webrick and haven't seen any file corruption. We are seeing the memory leak from #1131 though.

Is everyone who is seeing this problem using Mongrel? We're using Webrick and haven't seen any file corruption. We are seeing the memory leak from #1131 though.

we are seeing issues with #1010 (#1131 not yet observed) and are using Webrick.

At this point, my plan is to provide an option to enable http pooling, leaving it off by default. This will result in slowness, but we all would obviously rather be slow than have corrupt files.

Sounds good to me.

I've disabled keep-alive in [273c7ec]. Note that this will result in a speed hit, but that's better than file corruption.

If you want to re-enable it, just edit the network/http_pool.rb file. We decided not to make it a run-time option, given its danger.

I'd still love to know why this corruption is happening, such that at a later date we could re-enable it.