Windows node fails to request certificate (SSL error)

[d...@n-cube.org]

I am mostly using Puppet for Linux nodes, but I have started deploying it on a handful of Windows nodes, but seem to run into SSL problems every time on the initial deployment. I think I have hit this error on all three nodes so far, but currently two are working and one is not. All three nodes are virtually identical servers running Windows Server 2012 R2.

[0;36mDebug: Failed to load library 'syslog' for feature 'syslog' [0m
[0;36mDebug: Failed to load library 'selinux' for feature 'selinux' [0m
[0;36mDebug: Using settings: adding file resource 'confdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'vardir': 'File[C:/ProgramData/PuppetLabs/puppet/var]{:path=>"C:/ProgramData/PuppetLabs/puppet/var", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'logdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/log]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/log", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'statedir': 'File[C:/ProgramData/PuppetLabs/puppet/var/state]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state", :mode=>"1755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'rundir': 'File[C:/ProgramData/PuppetLabs/puppet/var/run]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/run", :mode=>"755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'libdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/lib]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/lib", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'certdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'ssldir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl", :mode=>"771", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'publickeydir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'requestdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'privatekeydir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'privatedir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'hostprivkey': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/testnode1.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/testnode1.pem", :mode=>"600", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'hostpubkey': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/testnode1.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/testnode1.pem", :mode=>"644", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'localcacert': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs/ca.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs/ca.pem", :mode=>"644", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'clientyamldir': 'File[C:/ProgramData/PuppetLabs/puppet/var/client_yaml]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/client_yaml", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'client_datadir': 'File[C:/ProgramData/PuppetLabs/puppet/var/client_data]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/client_data", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'clientbucketdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/clientbucket]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/clientbucket", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'graphdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/state/graphs]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state/graphs", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Puppet::Type::File::ProviderPosix: feature posix is missing [0m
[0;36mDebug: Failed to load library 'shadow' for feature 'libshadow' [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/log]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/state]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/run]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/lib]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/testnode1.pem]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/testnode1.pem]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs/ca.pem]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/client_yaml]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/client_data]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/clientbucket]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/state/graphs]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var/state] [0m
[0;36mDebug: Finishing transaction 36564120 [0m
[0;36mDebug: Using settings: adding file resource 'confdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'vardir': 'File[C:/ProgramData/PuppetLabs/puppet/var]{:path=>"C:/ProgramData/PuppetLabs/puppet/var", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'logdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/log]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/log", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'statedir': 'File[C:/ProgramData/PuppetLabs/puppet/var/state]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state", :mode=>"1755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'rundir': 'File[C:/ProgramData/PuppetLabs/puppet/var/run]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/run", :mode=>"755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'libdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/lib]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/lib", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'certdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'ssldir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl", :mode=>"771", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'publickeydir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'requestdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'privatekeydir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'privatedir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'hostprivkey': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/testnode1.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/testnode1.pem", :mode=>"600", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'hostpubkey': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/testnode1.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/testnode1.pem", :mode=>"644", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: Using settings: adding file resource 'localcacert': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs/ca.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs/ca.pem", :mode=>"644", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/log]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/state]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/run]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/var/lib]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/testnode1.pem]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/testnode1.pem]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys] [0m
[0;36mDebug: /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs/ca.pem]: Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs] [0m
[0;36mDebug: Finishing transaction 37392876 [0m
[0;36mDebug: Using cached certificate for ca [0m
Exiting; failed to retrieve certificate and waitforcert is disabled
Error: Could not request certificate: SSL_connect SYSCALL returned=5 errno=0 state=SSLv2/v3 read server hello A

The puppet master log shows:
[2013-12-05 10:12:08] ERROR RuntimeError: Client disconnected before connection could be established
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/http/webrick.rb:31:in `listen'
        /usr/lib64/ruby/1.8/webrick/server.rb:173:in `call'
        /usr/lib64/ruby/1.8/webrick/server.rb:173:in `start_thread'
        /usr/lib64/ruby/1.8/webrick/server.rb:162:in `start'
        /usr/lib64/ruby/1.8/webrick/server.rb:162:in `start_thread'
        /usr/lib64/ruby/1.8/webrick/server.rb:95:in `start'
        /usr/lib64/ruby/1.8/webrick/server.rb:92:in `each'
        /usr/lib64/ruby/1.8/webrick/server.rb:92:in `start'
        /usr/lib64/ruby/1.8/webrick/server.rb:23:in `start'
        /usr/lib64/ruby/1.8/webrick/server.rb:82:in `start'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/http/webrick.rb:30:in `listen'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/http/webrick.rb:29:in `initialize'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/http/webrick.rb:29:in `new'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/http/webrick.rb:29:in `listen'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/http/webrick.rb:26:in `synchronize'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/http/webrick.rb:26:in `listen'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/server.rb:92:in `listen'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/network/server.rb:104:in `start'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/daemon.rb:136:in `start'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/application/master.rb:207:in `main'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/application/master.rb:157:in `run_command'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/application.rb:364:in `run'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/application.rb:456:in `plugin_hook'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/application.rb:364:in `run'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/util.rb:504:in `exit_on_fail'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/application.rb:364:in `run'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/util/command_line.rb:132:in `run'
        /usr/lib64/ruby/vendor_ruby/1.8/puppet/util/command_line.rb:86:in `execute'
        /usr/bin/puppet:4

I suspected the time being out of sync was an issue, so I tried syncing the time on this server and I then renamed the hostname, uninstalled Puppet, deleted the data in C:\ProgramData, removed the certificate on the puppet master, and tried the whole process over again. I continue to get the exact same error. It does not go away after waiting a while like I have seen sometimes.

I've confirmed that there is no firewall issue here. It is able to connect to the puppet master.

Any idea on what is going on here? Or how to debug? I suppose I could try to debug with an openssl client, but I don't know how to replicate the exact environment that this puppet agent is using.

Thanks,
Dan

[Rob Reynolds]

Dan, 

Thanks for the detailed question. What version of Puppet agent do you have installed?

For posterity, because I think you tried this already:

net stop mpssvc

puppet agent -t --debug --verbose --trace

 

Any idea on what is going on here? Or how to debug? I suppose I could try to debug with an openssl client, but I don't know how to replicate the exact environment that this puppet agent is using.

I've ran into a similar issue before. Apparently it's not a new issue either - https://groups.google.com/forum/#!topic/puppet-users/MLQOB66zero 

Deleting the SSL directory and removing the offending certificates from the puppet master were the solution for me.

Could you try running the agent with the --waitforcert option?

 

Thanks,
Dan

--
You received this message because you are subscribed to the Google Groups "Puppet Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to puppet-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-users/e4bbc251-a50e-4848-93d2-b9b2438d5aae%40googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--

Rob Reynolds

Developer, Puppet Labs

Join us at PuppetConf 2014, September 23-24 in San Francisco

[d...@n-cube.org]

I left the node running overnight with the puppet service enabled. This morning it was working normally, so I did not have a chance to do any further experiments. This is similar to what happened on the other nodes, and leads me back to the suspicion that it has something to do with the time sync of the nodes. The master is synced via NTP, but these nodes do not have an accessible timeserver (that's what puppet is supposed to add...), so they started out with a considerable drift in either direction from the current time (up to 10 minutes). This second attempt that worked after waiting overnight was after a clean install with the time already manually synced.

The master is running 3.1.0. The Windows nodes have agent 3.3.1 I also upgraded to 3.3.2 on this particular node in question.

Dan