Closed Bug 1157695 Opened 11 years ago Closed 11 years ago

puppet is broken on buildbot-masters in usw2

Categories

(Release Engineering :: General, defect)

Product:
Release Engineering
Component:
General
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: bhearsum, Assigned: dustin)

Details

Attachments

(1 file, 1 obsolete file)

graphite.mozilla.org.png
40.48 KB, image/png
Details
I noticed this while working on bug 1154423: Apr 23 06:04:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:07:02 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1062]: Enabling Puppet. Apr 23 06:09:09 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1067]: Could not retrieve catalog from remote server: execution expired Apr 23 06:09:09 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1067]: Not using cache on failed catalog Apr 23 06:09:09 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1067]: Could not retrieve catalog; skipping run Apr 23 06:09:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:09:59 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1067]: Could not send report: undefined method `from_data_hash' for Array:Class Apr 23 06:14:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:18:13 buildbot-master72.bb.releng.usw2.mozilla.com dhclient[790]: DHCPREQUEST on eth0 to 10.132.68.1 port 67 (xid=0x766e7b32) Apr 23 06:18:13 buildbot-master72.bb.releng.usw2.mozilla.com dhclient[790]: DHCPACK from 10.132.68.1 (xid=0x766e7b32) Apr 23 06:18:15 buildbot-master72.bb.releng.usw2.mozilla.com dhclient[790]: bound to 10.132.68.24 -- renewal in 1389 seconds. Apr 23 06:19:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:24:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:29:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:34:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:37:03 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1847]: Enabling Puppet. Apr 23 06:39:10 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1852]: Could not retrieve catalog from remote server: execution expired Apr 23 06:39:10 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1852]: Not using cache on failed catalog Apr 23 06:39:10 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1852]: Could not retrieve catalog; skipping run Apr 23 06:39:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0 Apr 23 06:39:56 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[1852]: Could not send report: undefined method `from_data_hash' for Array:Class Apr 23 06:41:24 buildbot-master72.bb.releng.usw2.mozilla.com dhclient[790]: DHCPREQUEST on eth0 to 10.132.68.1 port 67 (xid=0x766e7b32) Apr 23 06:41:24 buildbot-master72.bb.releng.usw2.mozilla.com dhclient[790]: DHCPACK from 10.132.68.1 (xid=0x766e7b32) Apr 23 06:41:26 buildbot-master72.bb.releng.usw2.mozilla.com dhclient[790]: bound to 10.132.68.24 -- renewal in 1383 seconds. Apr 23 06:44:33 buildbot-master72.bb.releng.usw2.mozilla.com collectd[1330]: ethstat plugin: No stats available for eth0
I see the same thing in the logs, but running by hand works just fine: bash-4.1# puppet agent --test Info: Retrieving pluginfacts Info: Retrieving plugin Info: Loading facts Info: Caching catalog for buildbot-master72.bb.releng.usw2.mozilla.com Warning: The package type's allow_virtual parameter will be changing its default value from false to true in a future release. If you do not want to allow virtual packages, please explicitly set allow_virtual to false. (at /usr/lib/ruby/site_ruby/1.8/puppet/type/package.rb:430:in `default') Info: Applying configuration version '5817fca3094a' Notice: /Stage[main]/Toplevel::Server::Buildmaster/Assert[buildmaster-high-security]/ensure: created Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/File[/builds/bbb]/ensure: created Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Exec[virtualenv /builds/bbb]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||amqp==1.4.6]/Exec[pip /builds/bbb||amqp==1.4.6]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||bbb==0.2]/Exec[pip /builds/bbb||bbb==0.2]/returns: executed successfully Notice: /Stage[main]/Selfserve_agent::Install/Python::Virtualenv[/builds/selfserve-agent]/Python::Virtualenv::Package[/builds/selfserve-agent||buildapi==0.3.12]/Exec[pip /builds/selfserve-agent||buildapi==0.3.12]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||PyHawk-with-a-single-extra-commit==0.1.5]/Exec[pip /builds/bbb||PyHawk-with-a-single-extra-commit==0.1.5]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||kombu==3.0.24]/Exec[pip /builds/bbb||kombu==3.0.24]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||six==1.9.0]/Exec[pip /builds/bbb||six==1.9.0]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||requests==2.4.3]/Exec[pip /builds/bbb||requests==2.4.3]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||taskcluster==0.0.16]/Exec[pip /builds/bbb||taskcluster==0.0.16]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||anyjson==0.3.3]/Exec[pip /builds/bbb||anyjson==0.3.3]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||pytz==2015.2]/Exec[pip /builds/bbb||pytz==2015.2]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||mysql-python==1.2.5]/Exec[pip /builds/bbb||mysql-python==1.2.5]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||redo==1.4]/Exec[pip /builds/bbb||redo==1.4]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||arrow==0.5.4]/Exec[pip /builds/bbb||arrow==0.5.4]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||python-dateutil==2.4.2]/Exec[pip /builds/bbb||python-dateutil==2.4.2]/returns: executed successfully Notice: /Stage[main]/Buildbot_bridge/Python::Virtualenv[/builds/bbb]/Python::Virtualenv::Package[/builds/bbb||sqlalchemy==1.0.0]/Exec[pip /builds/bbb||sqlalchemy==1.0.0]/returns: executed successfully Info: Python::Virtualenv[/builds/selfserve-agent]: Scheduling refresh of Exec[restart-selfserve-agent] Notice: /Stage[main]/Selfserve_agent::Services/Exec[restart-selfserve-agent]: Triggered 'refresh' from 1 events Notice: /Stage[main]/Buildbot_bridge::Conf/File[/builds/bbb/config.json]/ensure: defined content as '{md5}278f085b7cbdb4838b47f074de971b03' Notice: /Stage[main]/Buildbot_bridge::Services/Supervisord::Supervise[buildbot_bridge_reflector]/File[/etc/supervisord.d/buildbot_bridge_reflector]/ensure: defined content as '{md5}4067ea56c1c7fd0f07071554c863a7c3' Info: /Stage[main]/Buildbot_bridge::Services/Supervisord::Supervise[buildbot_bridge_reflector]/File[/etc/supervisord.d/buildbot_bridge_reflector]: Scheduling refresh of Service[supervisord] Notice: /Stage[main]/Buildbot_bridge::Services/Supervisord::Supervise[buildbot_bridge_tclistener]/File[/etc/supervisord.d/buildbot_bridge_tclistener]/ensure: defined content as '{md5}07e9828f01488b39fef82cf2d963b488' Info: /Stage[main]/Buildbot_bridge::Services/Supervisord::Supervise[buildbot_bridge_tclistener]/File[/etc/supervisord.d/buildbot_bridge_tclistener]: Scheduling refresh of Service[supervisord] Notice: /Stage[main]/Buildbot_bridge::Services/Supervisord::Supervise[buildbot_bridge_bblistener]/File[/etc/supervisord.d/buildbot_bridge_bblistener]/ensure: defined content as '{md5}8ec93957eb1665b7ec80555cee81c818' Info: /Stage[main]/Buildbot_bridge::Services/Supervisord::Supervise[buildbot_bridge_bblistener]/File[/etc/supervisord.d/buildbot_bridge_bblistener]: Scheduling refresh of Service[supervisord] Notice: /Stage[main]/Supervisord::Base/Service[supervisord]: Triggered 'refresh' from 3 events Notice: Finished catalog run in 230.71 seconds I'll wait to see if it runs successfully from cron.
Assignee: nobody → dustin
It doesn't. But it reliably runs correctly from the command line bash-4.1# date ; . /usr/local/bin/proxy_reset_env.sh && /usr/bin/puppet agent --enable >/dev/null 2>/dev/null && /usr/bin/puppet agent --onetime --no-daemonize ; date Thu Apr 23 14:29:34 PDT 2015 Thu Apr 23 14:31:41 PDT 2015 Apr 23 14:29:35 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[24001]: Enabling Puppet. Apr 23 14:30:12 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[24006]: The package type's allow_virtual parameter will be changing its default value from false to true in a future release. If you do not want to allow virtual packages, please explicitly set allow_virtual to false. Apr 23 14:30:12 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[24006]: (at /usr/lib/ruby/site_ruby/1.8/puppet/type/package.rb:430:in `default') Apr 23 14:30:37 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[24006]: (/Stage[main]/Toplevel::Server::Buildmaster/Assert[buildmaster-high-security]/ensure) created Apr 23 14:31:12 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[24006]: (/Stage[main]/Selfserve_agent::Install/Python::Virtualenv[/builds/selfserve-agent]/Python::Virtualenv::Package[/builds/selfserve-agent||buildapi==0.3.12]/Exec[pip /builds/selfserve-agent||buildapi==0.3.12]/returns) executed successfully Apr 23 14:31:31 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[24006]: (/Stage[main]/Selfserve_agent::Services/Exec[restart-selfserve-agent]) Triggered 'refresh' from 1 events Apr 23 14:31:35 buildbot-master72.bb.releng.usw2.mozilla.com puppet-agent[24006]: Finished catalog run in 77.46 seconds
I see the same logging on buildbot-master73.
..but not on buildbot-master70 or bm71 (use1) nor on bm74 (usw2 like bm72 and bm73)..
In fact, looking in papertrail, the set of affected hosts today is something like buildbot-master04.bb.releng.usw2.mozilla.com buildbot-master118.bb.releng.usw2.mozilla.com buildbot-master68.bb.releng.usw2.mozilla.com buildbot-master72.bb.releng.usw2.mozilla.com buildbot-master73.bb.releng.usw2.mozilla.com buildbot-master79.bb.releng.usw2.mozilla.com releng-puppet1.srv.releng.usw2.mozilla.com Those hosts are all puppetizing at about :08 and :38. Checking some other masters, I see similar numbers -- :10/:40, :05/:35, etc. Which is pretty weird! $minute1 = fqdn_rand(30) $minute2 = $minute1+30 should be selecting a minute randomly between 0 and 30. Here's the distribution from all masters: 0,30 0,30 0,30 0,30 1,31 1,31 3,33 3,33 3,33 4,34 5,35 5,35 6,36 6,36 6,36 6,36 6,36 6,36 7,37 8,38 8,38 8,38 9,39 9,39 10,40 10,40 10,40 11,41 11,41 12,42 13,43 13,43 14,44 14,44 14,44 15,45 16,46 16,46 16,46 16,46 17,47 17,47 18,48 21,51 21,51 22,52 22,52 23,53 23,53 24,54 24,54 25,55 25,55 27,57 28,58 28,58 29,59
viewed a different way: 00 **** 01 ** 02 03 *** 04 * 05 ** 06 ****** 07 * 08 *** 09 ** 10 *** 11 ** 12 * 13 ** 14 *** 15 * 16 **** 17 ** 18 * 19 20 21 ** 22 ** 23 ** 24 ** 25 ** 26 27 * 28 ** 29 * which isn't that bad. I restarted httpd on the usw1 puppetmaster -- let's see if that helps.
Nope. I'll try rebooting.
Nope :(
Summary: puppet is broken on buildbot-master72 → puppet is broken on buildbot-masters in usw2
This is still happening on bm73, but only about 50% of the time. I pushed a change to pin that host to one of the scl3 puppetmasters. If it stops expiring after that point, then we'll know this is a load issue. At that point, we can consider a beefier master or an additional master.
Attached image graphite.mozilla.org.png (obsolete) —
The host seems to max out at ~2G RAM, which is well within its ~3.7G allocation. I can't get any data from graphite on the CPU usage, but the load average has a big spike every 30 minutes (this is a one-hour period, but it's noticeable over the last 24h at least). This really does suggest that the master is simply underpowered.
Four hours' view, with the average user CPU time overlaid. Same pattern. The CPU lags the load average, but I assume that's due to a longer duration for the averaging.
Attachment #8598062 - Attachment is obsolete: true
That seems to have helped for bm73. So I think that the usw2 master (and likely the use1 as well) is underpowered :( rail, how should we fix?
Flags: needinfo?(rail)
let's bump them to m3.large?
Flags: needinfo?(rail)
OK, I upgraded the usw2 puppetmaster to m3.large, and I've reverted the pin of bm73. I'll check back tomorrow to see if it's helped, and if so, upgrade the use1 puppetmaster.
releng-puppet1.srv.releng.use1.mozilla.com is bumped now, too.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Component: General Automation → General
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: