Puppet: `rbuf_fill': execution expired (Timeout::Error)

[Dolph Mathews]

2014-07-15 17:28:52.374 | /usr/lib/ruby/1.8/timeout.rb:64:in `rbuf_fill': execution expired (Timeout::Error)
2014-07-15 17:28:52.374 | from /usr/lib/ruby/1.8/net/protocol.rb:134:in `rbuf_fill'
2014-07-15 17:28:52.374 | from /usr/lib/ruby/1.8/net/protocol.rb:116:in `readuntil'
2014-07-15 17:28:52.374 | from /usr/lib/ruby/1.8/net/protocol.rb:126:in `readline'
2014-07-15 17:28:52.374 | from /usr/lib/ruby/1.8/net/http.rb:2028:in `read_status_line'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/net/http.rb:2017:in `read_new'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/net/http.rb:1051:in `request'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:248:in `open_http'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/net/http.rb:543:in `start'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:242:in `open_http'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:616:in `buffer_open'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:164:in `open_loop'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:162:in `catch'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:162:in `open_loop'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:132:in `open_uri'
2014-07-15 17:28:52.375 | from /usr/lib/ruby/1.8/open-uri.rb:518:in `open'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/1.8/open-uri.rb:30:in `open'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/ec2.rb:9:in `metadata'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/ec2.rb:5:in `each'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/ec2.rb:5:in `metadata'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/ec2.rb:33
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/util/loader.rb:95:in `load'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/util/loader.rb:95:in `load_file'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/util/loader.rb:46:in `load_all'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/util/loader.rb:41:in `each'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/util/loader.rb:41:in `load_all'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/util/loader.rb:38:in `each'
2014-07-15 17:28:52.376 | from /usr/lib/ruby/vendor_ruby/facter/util/loader.rb:38:in `load_all'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/vendor_ruby/facter/util/collection.rb:115:in `load_all'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/vendor_ruby/facter.rb:248:in `loadfacts'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/1.8/puppet/indirector/facts/facter.rb:18:in `reload_facter'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/1.8/puppet/indirector/facts/facter.rb:82:in `find'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/1.8/puppet/indirector/indirection.rb:195:in `find'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/1.8/puppet/node.rb:85:in `fact_merge'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/1.8/puppet/indirector/node/plain.rb:16:in `find'
2014-07-15 17:28:52.377 | from /usr/lib/ruby/1.8/puppet/indirector/indirection.rb:195:in `find'
2014-07-15 17:28:52.378 | from /usr/lib/ruby/1.8/puppet/application/apply.rb:196:in `main'
2014-07-15 17:28:52.378 | from /usr/lib/ruby/1.8/puppet/application/apply.rb:149:in `run_command'
2014-07-15 17:28:52.378 | from /usr/lib/ruby/1.8/puppet/application.rb:309:in `run'
2014-07-15 17:28:52.378 | from /usr/lib/ruby/1.8/puppet/application.rb:416:in `hook'
2014-07-15 17:28:52.378 | from /usr/lib/ruby/1.8/puppet/application.rb:309:in `run'
2014-07-15 17:28:52.378 | from /usr/lib/ruby/1.8/puppet/application.rb:407:in `exit_on_fail'
2014-07-15 17:28:52.379 | from /usr/lib/ruby/1.8/puppet/application.rb:309:in `run'
2014-07-15 17:28:52.379 | from /usr/lib/ruby/1.8/puppet/util/command_line.rb:69:in `execute'
2014-07-15 17:28:52.379 | from /usr/bin/puppet:8
2014-07-15 17:30:07.808 | Build step 'Execute shell' marked build as failure

Source: http://logs.openstack.org/09/107109/1/gate/gate-config-puppet-apply-precise/aafd4be/console.html
Source: http://logs.openstack.org/39/102739/2/check/gate-config-puppet-apply-precise/697aa88/console.html.gz

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/107163

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/107163
Committed: https://git.openstack.org/cgit/openstack-infra/elastic-recheck/commit/?id=79af6b58dbc8a5ad6dd9d10abf7e8f1db178f417
Submitter: Jenkins
Branch: master

commit 79af6b58dbc8a5ad6dd9d10abf7e8f1db178f417
Author: Dolph Mathews <email address hidden>
Date: Tue Jul 15 14:53:27 2014 -0500

    add query for timeout in puppet

    Change-Id: I14067fc30b3520c4128d000465f288ebb8c72c08
    Related-Bug: 1342310

[Clark Boylan (cboylan)]

This is the facter bug where being unable to query the metadata server causes facter to fail then puppet to fail. Latest facter with latest puppet still seems to be vulnerable to this.

We can work aroudn this by deleting the ec2 fact files completely but that is a crazy hack. We should probably work with our clouds a bit more to keep metadata servers running and queryable.

[Matt Riedemann (mriedem)]

Doesn't appear to be an issue anymore.