Forgot to mention the details:

net-mgmt-1# ruby --version
ruby 1.8.7 (2009-12-24 patchlevel 248) [amd64-freebsd8]

net-mgmt-1# puppetd --version
0.25.2

net-mgmt-1# uname -mrsi
FreeBSD 8.0-RELEASE-p2 amd64 GENERIC

Both master and client has the same configuration.

If I downgrade the client to 0.24.8 – no messages appears in the logs and catalog always finished OK, so I assume the problem is on the client side.

Markus – assigned to you for comment – feel free to sling at someone else.

Alexey —

I have been unable to reproduce this and the —trace output does not provide sufficient detail to locate the cause. Could you try again with the attached branch, which will produce additional information when run with —trace, and attach the output?

Thanks, —Markus

We’ve got a clearer case on #3101; I’m closing this one as a duplicate for that reason, even though it chronologically preceded it. If the eventual fix for #3101 does not also resolve this ticket, it should be reopened.

Alexey —

3101 turned out to be a DNS problem, though the message is far from helpful in determining that (see that ticket for details). Can you determine if there may be an analogous problem in your case?

— Markus

Markus,

I think no, it is not the DNS related problem in my case. At least for that reasons:

the debug trace in my case starts from Puppet related sources: “puppet/parameter.rb:401:in fail'", but in #3101 it starts from Ruby related "net/http.rb:1060:inrequest'”.

if I downgrade the puppet client from 0.25.x to 0.24.8 the problem went away.

the problem exists on all my puppet 0.25.x clients, located on a different datacenters and so using different DNS resolvers, which I can’t consider to be problem.

no other application reports about DNS related problems for a years.

Today I will create an output with the branch you provided. Also, I can give you shell access to one of the boxes if you want to see it much closer.

Sorry for a delay, right now I have not enough time.. But I’ll try.

Markus, tell me please, am I correct in what I should do:

git clone git://github.com/MarkusQ/puppet.git cd puppet ruby install.rb

this installs binaries and other suite.. Correct? If so, here is the output:

# puppetd --version
0.25.0

# /usr/local/sbin/puppetd  --trace  --no-daemonize --debug --verbose
debug: Failed to load library 'ldap' for feature 'ldap'
debug: Failed to load library 'shadow' for feature 'libshadow'
debug: /File[/etc/puppet/ssl]: Autorequiring File[/etc/puppet]
debug: /File[/var/puppet/state/classes.txt]: Autorequiring File[/var/puppet/state]
debug: /File[/etc/puppet/ssl/private_keys/puppet.renatasystems.org.pem]: Autorequiring File[/etc/puppet/ssl/private_keys]
debug: /File[/var/puppet/state/graphs]: Autorequiring File[/var/puppet/state]
debug: /File[/var/puppet/facts]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/public_keys/puppet.renatasystems.org.pem]: Autorequiring File[/etc/puppet/ssl/public_keys]
debug: /File[/var/puppet/run]: Autorequiring File[/var/puppet]
debug: /File[/var/puppet/lib]: Autorequiring File[/var/puppet]
debug: /File[/var/puppet/state/state.yaml]: Autorequiring File[/var/puppet/state]
debug: /File[/var/puppet/log]: Autorequiring File[/var/puppet]
debug: /File[/var/puppet/client_yaml]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/certificate_requests]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/etc/puppet/ssl/private_keys]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/etc/puppet/ssl/private]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/var/puppet/clientbucket]: Autorequiring File[/var/puppet]
debug: /File[/var/puppet/state]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/certs]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/etc/puppet/ssl/public_keys]: Autorequiring File[/etc/puppet/ssl]
debug: Finishing transaction 452885940 with 0 changes
/usr/local/lib/ruby/1.8/net/http.rb:1060:in `request': undefined method `closed?' for nil:NilClass (NoMethodError)
        from /usr/local/lib/ruby/1.8/net/http.rb:772:in `get'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/indirector/rest.rb:67:in `find'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/indirector/indirection.rb:198:in `find'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/indirector.rb:51:in `find'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/ssl/host.rb:174:in `certificate'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/ssl/host.rb:238:in `wait_for_cert'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/application/puppetd.rb:243:in `run_setup'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/application.rb:216:in `run'
        from /usr/local/sbin/puppetd:159

Please note, if I downgrade the client to 0.24.8 just before that – everything goes fine:

Feb  1 21:25:51 puppet puppetd[31563]: Reopening log files
Feb  1 21:25:51 puppet puppetd[31563]: Starting Puppet client version 0.24.8
Feb  1 21:25:54 puppet puppetd[31563]: Starting catalog run
Feb  1 21:26:02 puppet puppetd[31563]: Finished catalog run in 7.57 seconds

Before you cloned Markus' repo did you delete all traces of Puppet from your host? i.e. ensured all old puppet files deleted?

OK, to be sure, I delete now all puppet libs and run dirs (except certs in /etc/puppet/ssl):

# pkg_delete -f puppet-0.24.8
# rm -r /usr/local/lib/ruby/site_ruby/1.8/puppet
# rm -r /var/puppet /var/run/puppet
# cd puppet/
# ruby install.rb
install -c -m 0755 ./_tmp /usr/local/sbin/puppetca
install -c -m 0755 ./_tmp /usr/local/sbin/puppetd
install -c -m 0755 ./_tmp /usr/local/sbin/puppetmasterd
install -c -m 0755 ./_tmp /usr/local/sbin/puppetqd

 ...

# find /etc/puppet/ssl/
/etc/puppet/ssl/
/etc/puppet/ssl/certs
/etc/puppet/ssl/private
/etc/puppet/ssl/certificate_requests
/etc/puppet/ssl/public_keys
/etc/puppet/ssl/public_keys/puppet.renatasystems.org.pem
/etc/puppet/ssl/private_keys
/etc/puppet/ssl/private_keys/puppet.renatasystems.org.pem

The trace:

# /usr/local/sbin/puppetd  --trace  --no-daemonize --debug --verbose
debug: Failed to load library 'ldap' for feature 'ldap'
debug: Failed to load library 'shadow' for feature 'libshadow'
debug: /File[/var/puppet/facts]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/public_keys/puppet.renatasystems.org.pem]: Autorequiring File[/etc/puppet/ssl/public_keys]
debug: /File[/etc/puppet/ssl/certs]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/var/puppet/log]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/public_keys]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/etc/puppet/ssl/private_keys]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/var/puppet/run]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/private]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/var/puppet/state/graphs]: Autorequiring File[/var/puppet/state]
debug: /File[/var/puppet/clientbucket]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/certificate_requests]: Autorequiring File[/etc/puppet/ssl]
debug: /File[/etc/puppet/ssl]: Autorequiring File[/etc/puppet]
debug: /File[/var/puppet/lib]: Autorequiring File[/var/puppet]
debug: /File[/etc/puppet/ssl/private_keys/puppet.renatasystems.org.pem]: Autorequiring File[/etc/puppet/ssl/private_keys]
debug: /File[/var/puppet/client_yaml]: Autorequiring File[/var/puppet]
debug: /File[/var/puppet/state]: Autorequiring File[/var/puppet]
debug: /File[/var/puppet]: Changing ensure
debug: /File[/var/puppet]: 1 change(s)
debug: /File[/var/puppet]/ensure: created
debug: /File[/var/puppet/client_yaml]: Changing ensure
debug: /File[/var/puppet/client_yaml]: 1 change(s)
debug: /File[/var/puppet/client_yaml]/ensure: created
debug: /File[/var/puppet/state]: Changing ensure
debug: /File[/var/puppet/state]: 1 change(s)
debug: /File[/var/puppet/state]/ensure: created
debug: /File[/var/puppet/state/graphs]: Changing ensure
debug: /File[/var/puppet/state/graphs]: 1 change(s)
debug: /File[/var/puppet/state/graphs]/ensure: created
debug: /File[/var/puppet/lib]: Changing ensure
debug: /File[/var/puppet/lib]: 1 change(s)
debug: /File[/var/puppet/lib]/ensure: created
debug: /File[/var/puppet/clientbucket]: Changing ensure
debug: /File[/var/puppet/clientbucket]: 1 change(s)
debug: /File[/var/puppet/clientbucket]/ensure: created
debug: /File[/var/puppet/run]: Changing ensure
debug: /File[/var/puppet/run]: 1 change(s)
debug: /File[/var/puppet/run]/ensure: created
debug: /File[/var/puppet/log]: Changing ensure
debug: /File[/var/puppet/log]: 1 change(s)
debug: /File[/var/puppet/log]/ensure: created
debug: /File[/var/puppet/facts]: Changing ensure
debug: /File[/var/puppet/facts]: 1 change(s)
debug: /File[/var/puppet/facts]/ensure: created
debug: Finishing transaction 452924520 with 9 changes
/usr/local/lib/ruby/1.8/net/http.rb:1060:in `request': undefined method `closed?' for nil:NilClass (NoMethodError)
        from /usr/local/lib/ruby/1.8/net/http.rb:772:in `get'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/indirector/rest.rb:67:in `find'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/indirector/indirection.rb:198:in `find'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/indirector.rb:51:in `find'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/ssl/host.rb:174:in `certificate'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/ssl/host.rb:238:in `wait_for_cert'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/application/puppetd.rb:243:in `run_setup'
        from /usr/local/lib/ruby/site_ruby/1.8/puppet/application.rb:216:in `run'
        from /usr/local/sbin/puppetd:159

I’ve got this exact same problem. I’m using the latest Ubuntu Lucid Alpha. I wiped the computer and started clean to test and and I still get the problem. What would help? Would traces of dubug logs of the client or server help?

This is my site.pp file

file { “/tmp/puppet_test”:

 ensure => present,
 }

My puppet version is 0.25.4-2ubuntu2_all

I forgot to add two things. I get the same error if I point it to itself or if I point it at a working 0.24.8 server.

I also wiped the computer reinstalled it again and got the same error.

Patrick Mohr wrote:

I forgot to add two things. I get the same error if I point it to itself or if I point it at a working 0.24.8 server.

What do you mean with pointing to itself? Pointing the client to a master running on the same box?

And newer clients are not supposed to work against older masters. Always upgrade the master first.

What would help? Would traces of dubug logs of the client or server help?

Both, send anything you can. :)

I was running the server and the client on the same box.

First I ran rm -Rf /var/lib/puppet

I ran the client with “puppetd —trace —verbose —debug —test ubuntu-testclient-004 | tee puppetd.log I ran the server with "puppetmasterd —no-daemonize —verbose —debug —trace | tee puppetmaster.log

I’m appending both logs and a copy of /etc/puppet, /etc/hosts, and /var/puppet just in case that helps.

I tried running the version of puppetmaster and puppetd on Debian testing (squeeze) and get the same errors.
The puppet version is 0.25.4-1.

Would uninstalling puppet and ruby, installing ruby and gems from source, and then installing puppet using gems help? Should I use Ubuntu or Debian?

After getting a lot of help from deet, I learned what the problem was. As far as I can tell, in 0.25.x the puppetmaster does a reverse lookup on the client’s ipaddress, and I get the above error if the client’s IP doesn’t match the reverse lookup.

This was happening to me in my normal usage because the client connects through a VPN that uses NAT. That makes the reverse lookup fail. That means the client was never able to get it’s certificate.

The discussion is here: http://groups.google.com/group/puppet-users/browse_thread/thread/d31811e3d9f883f4/348e4f48a7fd66e1

Although the reverse lookup is a useful security feature, is there anyway to bypass it?

Also, any chance of getting a better error message.

After getting a lot of help from deet, I learned what the problem was. As far as I can tell, in 0.25.x the puppetmaster does a reverse lookup on the client’s ipaddress, and I get the above error if the client’s IP doesn’t match the reverse lookup. This doesn’t match comment 2.

This was happening to me in my normal usage because the client connects through a VPN that uses NAT. That makes the lookup fail. That means the client was never able to get it’s certificate.

The discussion is here: http://groups.google.com/group/puppet-users/browse_thread/thread/d31811e3d9f883f4/348e4f48a7fd66e1

Although what ever it’s doing is probably a useful security feature, is there anyway to bypass it?

Also, any chance of getting a better error message? It’s really cryptic and breaks backwords comparability.

I’m seeing this problem also on Ubuntu 10.04, but my DNS (forward and reverse) is correct.

I’m seeing the same issue and it’s not DNS.

On the client:

info: Retrieving plugin
debug: Using cached certificate for ca, good until Wed Mar 25 04:57:53 UTC 2015
debug: Using cached certificate for dxul.puppetlabs.com, good until Wed Mar 25 04:57:53 UTC 2015
debug: Using cached certificate_revocation_list for ca, good until 
debug: file_metadata supports formats: b64_zlib_yaml marshal pson raw yaml; using pson
debug: file_metadata supports formats: b64_zlib_yaml marshal pson raw yaml; using pson
/usr/lib/ruby/1.8/puppet/parameter.rb:401:in `fail'
/usr/lib/ruby/1.8/puppet/type/file/source.rb:160:in `init_metadata'
/usr/lib/ruby/1.8/puppet/util/cacher.rb:106:in `send'
/usr/lib/ruby/1.8/puppet/util/cacher.rb:106:in `cached_value'
/usr/lib/ruby/1.8/puppet/util/cacher.rb:46:in `metadata'
/usr/lib/ruby/1.8/puppet/type/file/source.rb:111:in `copy_source_values'
/usr/lib/ruby/1.8/puppet/type/file.rb:630:in `retrieve'
/usr/lib/ruby/1.8/puppet/type.rb:726:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:62:in `apply'
/usr/lib/ruby/1.8/puppet/transaction.rb:251:in `eval_children_and_apply_resource'
/usr/lib/ruby/1.8/puppet/util.rb:418:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:417:in `thinmark'
/usr/lib/ruby/1.8/puppet/transaction.rb:250:in `eval_children_and_apply_resource'
/usr/lib/ruby/1.8/puppet/transaction.rb:207:in `eval_resource'
/usr/lib/ruby/1.8/puppet/transaction.rb:296:in `evaluate'
/usr/lib/ruby/1.8/puppet/util.rb:418:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/1.8/puppet/util.rb:417:in `thinmark'
/usr/lib/ruby/1.8/puppet/transaction.rb:295:in `evaluate'
/usr/lib/ruby/1.8/puppet/transaction.rb:289:in `collect'
/usr/lib/ruby/1.8/puppet/transaction.rb:289:in `evaluate'
/usr/lib/ruby/1.8/puppet/resource/catalog.rb:142:in `apply'
/usr/lib/ruby/1.8/puppet/configurer/downloader.rb:32:in `evaluate'
/usr/lib/ruby/1.8/timeout.rb:62:in `timeout'
/usr/lib/ruby/1.8/puppet/configurer/downloader.rb:31:in `evaluate'
/usr/lib/ruby/1.8/puppet/configurer/plugin_handler.rb:12:in `download_plugins'
/usr/lib/ruby/1.8/puppet/configurer.rb:85:in `prepare'
/usr/lib/ruby/1.8/puppet/configurer.rb:152:in `run'
/usr/lib/ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/ruby/1.8/puppet/agent/locker.rb:21:in `lock'
/usr/lib/ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/ruby/1.8/sync.rb:230:in `synchronize'
/usr/lib/ruby/1.8/puppet/agent.rb:53:in `run'
/usr/lib/ruby/1.8/puppet/agent.rb:134:in `with_client'
/usr/lib/ruby/1.8/puppet/agent.rb:51:in `run'
/usr/lib/ruby/1.8/puppet/agent.rb:106
/usr/lib/ruby/1.8/puppet/external/event-loop/signal-system.rb:97:in `call'
/usr/lib/ruby/1.8/puppet/external/event-loop/signal-system.rb:97:in `__signal__'
/usr/lib/ruby/1.8/puppet/external/event-loop/signal-system.rb:97:in `each'
/usr/lib/ruby/1.8/puppet/external/event-loop/signal-system.rb:97:in `__signal__'
(eval):2:in `signal'
/usr/lib/ruby/1.8/puppet/external/event-loop/event-loop.rb:321:in `sound_alarm'
/usr/lib/ruby/1.8/puppet/agent.rb:110:in `start'
/usr/lib/ruby/1.8/puppet/daemon.rb:127:in `start'
/usr/lib/ruby/1.8/puppet/application/puppetd.rb:116:in `main'
/usr/lib/ruby/1.8/puppet/application.rb:226:in `send'
/usr/lib/ruby/1.8/puppet/application.rb:226:in `run_command'
/usr/lib/ruby/1.8/puppet/application.rb:217:in `run'
/usr/lib/ruby/1.8/puppet/application.rb:306:in `exit_on_fail'
/usr/lib/ruby/1.8/puppet/application.rb:217:in `run'
/usr/sbin/puppetd:159
err: /File[/var/lib/puppet-demo/lib]: Failed to retrieve current state of resource: Could not retrieve information from source(s) puppet://dxul.puppetlabs.com/plugins

On the master:

info: access[^/catalog/([^/]+)$]: allowing 'method' find
info: access[^/catalog/([^/]+)$]: allowing $1 access
info: access[/certificate_revocation_list/ca]: allowing 'method' find
info: access[/certificate_revocation_list/ca]: allowing * access
info: access[/report]: allowing 'method' save
info: access[/report]: allowing * access
info: access[/file]: allowing * access
info: access[/certificate/ca]: adding authentication no
info: access[/certificate/ca]: allowing 'method' find
info: access[/certificate/ca]: allowing * access
info: access[/certificate/]: adding authentication no
info: access[/certificate/]: allowing 'method' find
info: access[/certificate/]: allowing * access
info: access[/certificate_request]: adding authentication no
info: access[/certificate_request]: allowing 'method' find
info: access[/certificate_request]: allowing 'method' save
info: access[/certificate_request]: allowing * access
info: access[/]: adding authentication any
info: Could not find filesystem info for file 'plugins' in environment production
info: Could not find file_metadata for 'plugins'
info: Expiring the node cache of dxul.puppetlabs.com
info: Not using expired node for dxul.puppetlabs.com from cache; expired at Sat Mar 27 05:29:23 +0000 2010
info: Caching node for dxul.puppetlabs.com
notice: Compiled catalog for dxul.puppetlabs.com in 0.00 seconds

Changing:

pluginsync=true

pluginsync=false

Makes the error go away.

Fixes issue for me also + Jesse.

Pushing in commit:“ae0b0bf23e418e8c6665e9dc135148b78bdbd913” in branch 0.25.x