Bug #17942
closedTimeout during Puppet class import, slow re-initialization of Puppet 3
Description
I'm not able to import Puppet classes or environments from foreman-proxy. The foreman-proxy is running on the puppetmaster, and plugins "puppet" and "puppetca" have been enabled on this smart proxy. There is a timeout. I tried to query the proxy directly with curl with a tcpdump running and nothing but Keepalive messages are seen on the wire.
For example :
URL=puppet/environments
PORT=8000
time curl http://vmctldeploy10.rsvgnw.local:${PORT}/${URL}
["admybr","testing","production","lab"]
But if my URL is this, I never get an answer :
URL=puppet/environments/production/classes
In the Foreman WebUI, it's just waiting when I try either to import classes, import environnments, or query the foreman-proxy.
In the example above, I switched to HTTP on port 8000 instead of HTTPS/8443 in the hope of eliminating SSL issues, so the proxy is listening on both protocols, but the behaviour is the same.
I've spent quite some time on this and I can't find the error, it seems I'm the only one to have this.
Some other errors appears in the foreman server log as well, for example ERF50-5345 :
2017-01-05 07:43:09 4382433b [app] [I] Redirected to https://vmctldeploy30.rsvgnw.local/environments
2017-01-05 07:43:09 4382433b [app] [W] ProxyAPI operation FAILED
| ProxyAPI::ProxyException: ERF12-4115 [ProxyAPI::ProxyException]: Unable to get classes from Puppet for lab ([RestClient::RequestTimeout]: Request Timeout) for proxy https://vmctldeploy10.rsvgnw.local:8443/puppet
| /usr/share/foreman/lib/proxy_api/puppet.rb:27:in `rescue in classes'
| /usr/share/foreman/lib/proxy_api/puppet.rb:21:in `classes'
| /usr/share/foreman/app/services/puppet_class_importer.rb:153:in `actual_classes'
| /usr/share/foreman/app/services/puppet_class_importer.rb:77:in `new_classes_for'
| /usr/share/foreman/app/services/puppet_class_importer.rb:24:in `block in changes'
--
2017-01-05 14:00:34 f8013754 [app] [I] Completed 200 OK in 31964ms (Views: 33.8ms | ActiveRecord: 27.0ms)
2017-01-05 14:00:34 f8013754 [app] [W] Failed to counts
| Foreman::WrappedException: ERF50-5345 [Foreman::WrappedException]: Unable to connect ([ProxyAPI::ProxyException]: ERF12-5356 [ProxyAPI::ProxyException]: Unable to get PuppetCA certificates ([RestClient...)
| /usr/share/foreman/app/services/proxy_status/base.rb:55:in `rescue in fetch_proxy_data'
| /usr/share/foreman/app/services/proxy_status/base.rb:47:in `fetch_proxy_data'
| /usr/share/foreman/app/services/proxy_status/puppetca.rb:4:in `certs'
| /usr/share/foreman/app/controllers/puppetca_controller.rb:12:in `counts'
| /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
--
2017-01-05 14:00:35 f8013754 [app] [I] Completed 200 OK in 29380ms (Views: 607.0ms | ActiveRecord: 9.1ms)
2017-01-05 14:20:14 f8013754 [app] [W] Failed to puppet_environments
| Foreman::WrappedException: ERF50-5345 [Foreman::WrappedException]: Unable to connect ([ProxyAPI::ProxyException]: ERF12-4115 [ProxyAPI::ProxyException]: Unable to get classes from Puppet for admybr ([R...)
| /usr/share/foreman/app/services/proxy_status/base.rb:55:in `rescue in fetch_proxy_data'
| /usr/share/foreman/app/services/proxy_status/base.rb:47:in `fetch_proxy_data'
| /usr/share/foreman/app/services/proxy_status/puppet.rb:4:in `environment_stats'
| /usr/share/foreman/app/controllers/smart_proxies_controller.rb:59:in `puppet_environments'
| /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
--
2017-01-05 16:34:44 f8013754 [app] [I] Redirected to https://vmctldeploy30.rsvgnw.local/environments
2017-01-05 16:34:44 f8013754 [app] [W] ProxyAPI operation FAILED
| ProxyAPI::ProxyException: ERF12-4115 [ProxyAPI::ProxyException]: Unable to get classes from Puppet for admybr ([RestClient::RequestTimeout]: Request Timeout) for proxy https://vmctldeploy10.rsvgnw.local:8443/puppet
| /usr/share/foreman/lib/proxy_api/puppet.rb:27:in `rescue in classes'
| /usr/share/foreman/lib/proxy_api/puppet.rb:21:in `classes'
| /usr/share/foreman/app/services/puppet_class_importer.rb:153:in `actual_classes'
| /usr/share/foreman/app/services/puppet_class_importer.rb:77:in `new_classes_for'
| /usr/share/foreman/app/services/puppet_class_importer.rb:38:in `changes'
Files
Updated by Yvan Broccard almost 8 years ago
Error: ERF12-4115 [ProxyAPI::ProxyException]: Unable to get classes from Puppet for admybr ([RestClient::RequestTimeout]: Request Timeout) for proxy https://vmctldeploy10.rsvgnw.local:8443/puppet
Updated by Dominic Cleal almost 8 years ago
proxy.log shows very slow iteration over manifests across multiple environments, measured in minutes per manifest. It's unclear from the log if this is during a request (which would explain timeouts) or from the startup process.
D, [2017-01-05T03:42:44.276364 #113893] DEBUG -- : Scanning oradb classes in /etc/puppet/environments/production/modules/oradb/manifests/listener.pp D, [2017-01-05T03:42:44.276805 #113893] DEBUG -- : Initializing from Puppet config file: /etc/puppet/puppet.conf D, [2017-01-05T03:46:23.462033 #113893] DEBUG -- : Scanning oradb classes in /etc/puppet/environments/production/modules/oradb/manifests/installem_agent.pp D, [2017-01-05T03:46:23.462328 #113893] DEBUG -- : Initializing from Puppet config file: /etc/puppet/puppet.conf
Superficially similar to #14266, which I've not confirmed has been fully resolved in the smart proxy.
Note that this only affects Puppet 3, which is now EOL. With Puppet 4 the API should make this obsolete, and since 4.4+ caching is also supported.
Updated by Tim Meusel almost 8 years ago
Hi.
I get the same issues in my Puppet 4 environment. The Webinterface says:
Error: ERF12-4115 [ProxyAPI::ProxyException]: Unable to get classes from Puppet for puppet4 ([RestClient::ServiceUnavailable]: 503 Service Unavailable) for proxy https://*.de:8443/puppet
The foreman-proxy.log:
D, [2017-01-20T18:28:25.102324 ] DEBUG -- : accept: 10.111.2.251:55644 D, [2017-01-20T18:28:25.103942 ] DEBUG -- : Rack::Handler::WEBrick is invoked. D, [2017-01-20T18:28:25.104827 ] DEBUG -- : verifying remote client 10.111.2.251 against trusted_hosts ["*.de"] E, [2017-01-20T18:28:40.106095 ] ERROR -- : Puppet is taking too long to respond, please try again later. D, [2017-01-20T18:28:40.106214 ] DEBUG -- : Puppet is taking too long to respond, please try again later. I, [2017-01-20T18:28:40.106599 ] INFO -- : 10.111.2.251 - - [20/Jan/2017:18:28:40 +0100] "GET /puppet/environments/puppet4/classes HTTP/1.1" 503 61 15.0020
99% of the requests fail, just a few work. I digged around with curl and time, working and nonworking requests run around 15s. I'm running foreman 1.14.0
Updated by Anonymous almost 8 years ago
When puppet 4 and puppet environment-classes api are used, smart-proxy will attempt to initialize puppet classes cache on startup. Should that fail, it will skip cache initialization and attempt to fetch classes on next request. It will return a time-out error to the client after waiting for puppet's response for 15 seconds. After that, smart-proxy will continue to await the response for another 285 seconds in the background. Could you try repeating your query again after a minute or two? Could you also check smart-proxy logs to see if there are any errors there?
I would also check how fast puppet server responds and if there are any errors in puppet logs.
Updated by Tim Meusel almost 8 years ago
The cache is created during startup:
I, [2017-01-20T17:58:58.281767 ] INFO -- : Started puppet class cache initialization D, [2017-01-20T17:59:00.408362 ] DEBUG -- : Initializing puppet class cache for 'puppet4' environment D, [2017-01-20T17:59:00.408857 ] DEBUG -- : Initializing puppet class cache for 'production' environment D, [2017-01-20T17:59:00.409331 ] DEBUG -- : Initializing puppet class cache for 'puppet4fabricdev' environment D, [2017-01-20T17:59:00.409610 ] DEBUG -- : Initializing puppet class cache for 'common' environment I, [2017-01-20T17:59:26.025801 ] INFO -- : Finished puppet class cache initialization
I've a lot of stdlib deprecation warnings in my puppetserver logs, but I can't spot anything related to this. The foreman-proxy only throws the timeouts I pasted in my first comment. I'm able to get the list via curl from https://localhost:8443/puppet/environments/puppet4/classes after a bit of time, but unable via the webinterface. Tried it for 10 minutes - no luck. Is it possible to increase the timeouts somewhere?
Updated by Anonymous almost 8 years ago
This is quite odd -- it looks like your puppet server responses are very slow: it should return classes pretty quickly once its classes cache is initialized (which, I think, happens on first request). The fact that even repeated requests that should just return 304s time-out (they should come back pretty much instantaneously) also makes me think that there might be a problem with puppet setup. Even more strange is that it only takes 26 seconds to retrieve classes for all environments on startup.
Could you try to use curl to retrieve classes from puppet directly and note the response times?
Updated by Tim Meusel almost 8 years ago
yeah very strange. I would expect that the puppetserver caches it and further calls are fast and working if one ever suceeded, but thats not the case. I've no idea how Puppet implemented the API. I will see if I can increase the debug output for the puppetserver, maybe I will find some errors there.
Updated by Anonymous almost 8 years ago
Could you try using curl with GET method to puppet/v3/environment_classes?environment=<environment_name> to retrieve classes from puppet server directly and note the response times?
Updated by Tim Meusel almost 8 years ago
Did 4 calls, all needed 21s for the same env
Updated by Anonymous almost 8 years ago
You should be getting an ETAG with each response. What are the response times if you add "If-None-Match" header with a value appropriate for the environment you are querying?
Updated by Dominic Cleal almost 8 years ago
Caching must be enabled (via environment-class-cache-enabled in puppetserver.conf) for ETAG and caching support in Puppet Server, it isn't the default.
I don't think this is related to the original bug report which was on Puppet 3, please file a new issue or open a thread on foreman-users.
Updated by Tim Meusel almost 8 years ago
Thanks Dominic, I enabled the caching and everything is working now \o/
Updated by Slagian Momirovici almost 8 years ago
- Related to Bug #18369: Foreman-proxy timeout - Error: ERF12-4115 [ProxyAPI::ProxyException] added
Updated by Dominic Cleal almost 8 years ago
- Subject changed from Foreman-proxy timeout with ERF12-4115 when trying to import classes from Puppet to Timeout during Puppet class import, slow re-initialization of Puppet 3
Updated by Dominic Cleal almost 8 years ago
- Related to Bug #18290: "Puppet is taking too long to respond" during class import with Puppet 4.x added
Updated by Dominic Cleal almost 8 years ago
#18290 covers a similar problem (possibly as described in comments above) when using Puppet 4. The two are otherwise not related.
Updated by Anonymous over 7 years ago
- Status changed from New to Rejected
Puppet 3 is EOL and the Puppet 4 problem is fixed.