Puppet

jamtur01 wrote:

I don’t see know this could be a Puppet issue? I have never seen this – nor can I replicate it. Has it re-occurred?

I’ve seen it before, usually when connecting to a network where puppet resolves but its not the correct certificate (e.g. were signed by another puppetmaster)

It took me a while to see that puppet is abusing my network (learned it only when my home router cpu increased because of so many dns requests)

ohadlevy wrote:

jamtur01 wrote:

I don’t see know this could be a Puppet issue? I have never seen this – nor can I replicate it. Has it re-occurred?

I’ve seen it before, usually when connecting to a network where puppet resolves but its not the correct certificate (e.g. were signed by another puppetmaster)

It took me a while to see that puppet is abusing my network (learned it only when my home router cpu increased because of so many dns requests)

Since the initial setup i had two occurrences that i know of. I’m 100% sure the certificates were ok, we have only one puppetmaster and we already have a procedure for installation of new nodes so things should be the same on all nodes. Since i opened the ticket i didn’t notice new occurences but as said it’s hard to spot them. I don’t want to leave query log enabled on the dns server as last time it filled up all of the disk space (30GB). On the other side if it happens one way to spot it is by the size of the log files (we do network logging so all logs are in one place to check).

If it’s not a puppet issue than what could it be ? From my point of view i’m sure it’s not the dns system at least as queries are answered by the servers but something happens on the client. It guess it may be Puppet or some component from Ruby.

In the mean time i started to add more clients to the setup (and a second caching dns server to cope with possible problems).

I’ll get back when i have news.

Steps how I reproduce the problem:

Get a working client (e.g. already run puppet once, got certificate etc) against puppet dns alias

changed network (from home to work) where puppet.domain point to another server where the certificate does not work. started puppet as a daemon and the following errors start to apper in syslog:

puppetd[26273]: Did not receive certificate

cpu load jumps (on my machine to about 15-20%, and puppetd hammers the puppetmaster and dns for querying…..

ohadlevy wrote:

Steps how I reproduce the problem:

Get a working client (e.g. already run puppet once, got certificate etc) against puppet dns alias

changed network (from home to work) where puppet.domain point to another server where the certificate does not work. started puppet as a daemon and the following errors start to apper in syslog: […]

cpu load jumps (on my machine to about 15-20%, and puppetd hammers the puppetmaster and dns for querying…..

Back with news. Today while installing a new client the problem appeared. It seems that it was triggered immediately after puppetd was launched for the first time (by the Debian scripts, as soon as aptitude finished installing the package) and before i had the chance to edit the config files.

/var/log/aptitude

Aptitude 0.4.4: log report
Fri, Oct 31 2008 08:25:36 +0100

IMPORTANT: this log only lists intended actions; actions which fail due to
dpkg problems may not be completed.

Will install 13 packages, and remove 0 packages.
12.2MB of disk space will be used
===============================================================================
[INSTALL, DEPENDENCIES] facter
[INSTALL, DEPENDENCIES] irb1.8
[INSTALL, DEPENDENCIES] libopenssl-ruby
[INSTALL, DEPENDENCIES] libopenssl-ruby1.8
[INSTALL, DEPENDENCIES] libreadline-ruby1.8
[INSTALL, DEPENDENCIES] libruby1.8
[INSTALL, DEPENDENCIES] libshadow-ruby1.8
[INSTALL, DEPENDENCIES] libxmlrpc-ruby
[INSTALL, DEPENDENCIES] rdoc
[INSTALL, DEPENDENCIES] rdoc1.8
[INSTALL, DEPENDENCIES] ruby
[INSTALL, DEPENDENCIES] ruby1.8
[HOLD] libpq4
[HOLD] linux-image-2.6.18-6-686
[HOLD] linux-image-2.6.18-6-686-bigmem
[HOLD] openssh-client
[HOLD] openssh-server
[HOLD] postfix
[HOLD] smart
[HOLD] ssh
[HOLD] tzdata
[INSTALL] puppet
===============================================================================

/var/log/messages

Oct 31 08:25:42 node1 puppetd[11724]: Reopening log files
Oct 31 08:25:42 node1 puppetd[11724]: Could not find server puppet: getaddrinfo: Name or service not known
Oct 31 08:25:42 node1 puppetd[11724]: Could not request certificate: Certificate retrieval failed: Could not find server puppet
Oct 31 08:25:42 node1 puppetd[11724]: Could not find server puppet: getaddrinfo: Name or service not known
Oct 31 08:25:42 node1 puppetd[11724]: Could not request certificate: Certificate retrieval failed: Could not find server puppet
Oct 31 08:25:42 node1 puppetd[11724]: Could not find server puppet: getaddrinfo: Name or service not known
Oct 31 08:25:42 node1 puppetd[11724]: Could not request certificate: Certificate retrieval failed: Could not find server puppet

thousand of lines down the line of /var/log/messages

Oct 31 08:26:15 node1 puppetd[11724]: Could not request certificate: Certificate retrieval failed: Could not find server puppet
Oct 31 08:26:15 node1 puppetd[11724]: Could not find server puppet: getaddrinfo: Name or service not known
Oct 31 08:26:15 node1 puppetd[11724]: Could not request certificate: Certificate retrieval failed: Could not find server puppet
Oct 31 08:26:21 node1 puppetd[11741]: Creating default schedules
Oct 31 08:26:21 node1 puppetd[11741]: Failed to load library 'ldap' for feature 'ldap'
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/etc/puppet/namespaceauth.conf]) Autorequiring File[/etc/puppet]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/etc/puppet/ssl]) Autorequiring File[/etc/puppet]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/var/lib/puppet/state]) Autorequiring File[/var/lib/puppet]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/var/lib/puppet/lib]) Autorequiring File[/var/lib/puppet]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/certs]) Autorequiring File[/etc/puppet/ssl]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/public_keys]) Autorequiring File[/etc/puppet/ssl]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private]) Autorequiring File[/etc/puppet/ssl]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[puppetd]/File[/etc/puppet/puppet.conf]) Autorequiring File[/etc/puppet]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private_keys]) Autorequiring File[/etc/puppet/ssl]
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/etc/puppet/ssl]) File does not exist
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/etc/puppet/ssl]) Changing ensure
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/etc/puppet/ssl]) 1 change(s)
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[main]/File[/etc/puppet/ssl]/ensure) created
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private_keys]) File does not exist
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private_keys]) Changing ensure
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private_keys]) 1 change(s)
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private_keys]/ensure) created
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private]) File does not exist
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private]) Changing ensure
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private]) 1 change(s)
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/private]/ensure) created
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/public_keys]) File does not exist
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/public_keys]) Changing ensure
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/public_keys]) 1 change(s)
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/public_keys]/ensure) created
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/certs]) File does not exist
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/certs]) Changing ensure
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/certs]) 1 change(s)
Oct 31 08:26:21 node1 puppetd[11741]: (/Settings[/etc/puppet/puppetd.conf]/Settings[ssl]/File[/etc/puppet/ssl/certs]/ensure) created
Oct 31 08:26:21 node1 puppetd[11741]: Finishing transaction -606709178 with 5 changes
Oct 31 08:26:21 node1 puppetd[11741]: Creating a new certificate request for node1.foo.bar.com
Oct 31 08:26:21 node1 puppetd[11741]: Creating a new SSL key at /etc/puppet/ssl/private_keys/node1.foo.bar.com
Oct 31 08:26:22 node1 puppetd[11741]: Calling puppetca.getcert
Oct 31 08:26:22 node1 puppetd[11741]: Did not receive certificate
Oct 31 08:26:22 node1 puppetd[11741]: Set to run 'one time'; exiting with no certificate

So it seems that it’s looking by default for the server with the name puppet , this is not the problem that the name does not exist but the fact that is hammering the dns server and the machine itself.

Unfortunately for the other two occurrences i don’t have the logfile any more to check and see if the problems were at the first run but i think the first run was the problem. I’m going to install more clients today and check the behave our .

aionica wrote:

Unfortunately for the other two occurrences i don’t have the logfile any more to check and see if the problems were at the first run but i think the first run was the problem. I’m going to install more clients today and check the behave our .

Checked with a new install, same thing happens so this is clearly occuring when the package is installed and before puppet is configured. I don’t know though if this issue is Debian specific but i guess so, i have some CentOS clients too, and probably today i’m going to install on them too , to see if this happens.

ohadlevy – you have similar platform, versions (Puppet, Ruby, etc)?

aionica wrote:

aionica wrote:

Unfortunately for the other two occurrences i don’t have the logfile any more to check and see if the problems were at the first run but i think the first run was the problem. I’m going to install more clients today and check the behave our .

Checked with a new install, same thing happens so this is clearly occuring when the package is installed and before puppet is configured. I don’t know though if this issue is Debian specific but i guess so, i have some CentOS clients too, and probably today i’m going to install on them too , to see if this happens.

Hello, Sorry for not being able to reply sooner. So, on a fresh CentOS 5.1 i installed puppet 0.24.5 from the EPEL repository (http://fedoraproject.org/wiki/EPEL). puppet 0.24.5-1.el5 (epel) facter 1.5.2-1.el5 (epel) ruby 1.8.5-5.el5_2.5 (centos) I started puppet without configuring anything and in /var/log/messages i can see

Nov 20 13:16:09 test2 puppetd[2126]: Reopening log files
Nov 20 13:16:09 test2 puppetd[2126]: Could not find server puppet: getaddrinfo: Name or service not known
Nov 20 13:16:09 test2 puppetd[2126]: Could not request certificate: Certificate retrieval failed: Could not find server puppet
Nov 20 13:18:09 test2 puppetd[2126]: Could not find server puppet: getaddrinfo: Name or service not known
Nov 20 13:18:09 test2 puppetd[2126]: Could not request certificate: Certificate retrieval failed: Could not find server puppet
Nov 20 13:20:09 test2 puppetd[2126]: Could not find server puppet: getaddrinfo: Name or service not known
Nov 20 13:20:09 test2 puppetd[2126]: Could not request certificate: Certificate retrieval failed: Could not find server puppet

The same error but its occurrence is once in 2 minutes which seems the normal thing so probably the issue described is only specific to Debian.

On fresh Debian Etch install with puppet installed from Debian Etch Repository (and not Testin/Lenny or Unstable) the problem doesn’t appear but puppet version is 0.20.1-1 in Debian Etch (stable package).

I built from sources(taken from reductive labs, not the source debian package) puppet version 0.24.5 and i had the same behaveour with the errors. I also tried and build puppet 0.24.6 and facter 1.5.2 and i still had the same errors. It seems like a Debian issue but how can i track it down and find the source of the problem? Please give me some hints about what i should do from here.

I’m pretty clueless as to what’s going on here. The only thing I can think to do is add debugging to the point where those errors are being printed to see if you can get something like a useful stack trace. There’s obviously a DNS problem here, but you’ve also got the issue as to why failure is causing a retry.

I just looked through the code base for where we might be calling ‘retry’, and it’s only in restricted cases.

If you can reproduce this after editing code, I recommend editing network/client/xmlrpc.rb and see if you can figure out why something is retrying.

just got by this one again.

steps to repreduce: on Ubuntu 8.10

I already have a working puppet setup on my laptop against company A. moving to company B, where the dns alias puppet points to another server. (in another company..)

at this point in time, puppet goes into a never ending loop. in the log files:

 puppetd[7603]: Did not receive certificate

this message repeats approx 5 times per minute, every 5 minutes.

Does it make sense for puppet to request a certificate if it already has one?

I think there might be two separate issues here, but to zoom in on the hammering: I’ve also seen puppetd continously hammer the puppetmaster when puppetd requests a new certificate from puppetmaster, but for whichever reason doesn’t get one. After a while the log got filled with thousands of lines, and the server became unresponsive. I had to forcibly kill the puppet client to get things back to normal.

The reason this happened for me was because puppetd was run with ‘-w 0’ as one of the command line arguments, which is apparently what the Debian package for Puppet does by default (see /etc/default/puppet.) Passing -w 0 does not seem to cause puppetd to exit when it doesn’t get a certificate on the first try (which is the behaviour I would expect); instead it waits for 0 seconds, and then tries again, effectively DoS'ing the server.

I’ve only tested this with Puppet 0.24.5 and 0.24.6, so I don’t know if that behaviour still stands for 0.24.7.

bart wrote:

I think there might be two separate issues here, but to zoom in on the hammering: I’ve also seen puppetd continously hammer the puppetmaster when puppetd requests a new certificate from puppetmaster, but for whichever reason doesn’t get one. After a while the log got filled with thousands of lines, and the server became unresponsive. I had to forcibly kill the puppet client to get things back to normal.

The reason this happened for me was because puppetd was run with ‘-w 0’ as one of the command line arguments, which is apparently what the Debian package for Puppet does by default (see /etc/default/puppet.) Passing -w 0 does not seem to cause puppetd to exit when it doesn’t get a certificate on the first try (which is the behaviour I would expect); instead it waits for 0 seconds, and then tries again, effectively DoS'ing the server.

I’ve only tested this with Puppet 0.24.5 and 0.24.6, so I don’t know if that behaviour still stands for 0.24.7.

Looks like the behaviour is still the same in 0.24.7, but it’s not in the master branch.

Can you modify your client to break its loop if waitforcert < 1 and see if that affects the problem?

luke wrote:

Can you modify your client to break its loop if waitforcert < 1 and see if that affects the problem?

Yes, that fixes the hammering:

$ diff -u /usr/lib/ruby/1.8/puppet/executables/client/certhandler.rb{.orig,}
--- /usr/lib/ruby/1.8/puppet/executables/client/certhandler.rb.orig 2009-01-19 18:56:46.000000000 +0100
+++ /usr/lib/ruby/1.8/puppet/executables/client/certhandler.rb  2009-01-19 19:11:51.000000000 +0100
@@ -49,6 +49,10 @@
                           exit(23) if @one_time
                        end
 
+                       if @wait_for_cert < 1
+                           Puppet.notice "waitforcert below 1; not retrying to request a certificate"
+                           break
+                       end
                        sleep @wait_for_cert 
                     end
                 end
$ sudo rm -r /var/lib/puppet/ssl
$ sudo /usr/sbin/puppetd -w 0 --no-daemonize --logdest console
warning: peer certificate won't be verified in this SSL session
notice: Did not receive certificate
notice: waitforcert below 1; not retrying to request a certificate
notice: Starting Puppet client version 0.24.5
err: State got corrupted
warning: peer certificate won't be verified in this SSL session
err: Could not call fileserver.list: #
[ ... ]

luke wrote:

It might be worth the package managers putting out a new package with a slight fix.

I just noticed that the Debian package recently (as of Jan 7) changed the default for -w from 0 to 5. Assuming the packages for other distros do not set the value to 0 by default either, I think it should be safe to postone getting a fix in until some other issues justify a new 0.24.x release. After all, to trigger this behaviour with the latest Debian packages, it would require someone to intentionally set —waitforcert to 0, and in that case it would probably be fairly obvious to that person what causes the load.

bart wrote:

luke wrote:

It might be worth the package managers putting out a new package with a slight fix.

I just noticed that the Debian package recently (as of Jan 7) changed the default for -w from 0 to 5. Assuming the packages for other distros do not set the value to 0 by default either, I think it should be safe to postone getting a fix in until some other issues justify a new 0.24.x release. After all, to trigger this behaviour with the latest Debian packages, it would require someone to intentionally set —waitforcert to 0, and in that case it would probably be fairly obvious to that person what causes the load.

Good to hear, although note that the unit is seconds, so waiting 5 seconds isn’t a huge amount of time, of course.