[Buildbot] #3066: buildbot.test.integration.test_master.RunMaster.test_master1 become flaky
Buildbot trac
trac at buildbot.net
Sun Nov 30 18:12:43 UTC 2014
#3066: buildbot.test.integration.test_master.RunMaster.test_master1 become flaky
---------------------+--------------------
Reporter: Ben | Owner:
Type: defect | Status: new
Priority: critical | Milestone: 0.9.0
Version: master | Resolution:
Keywords: |
---------------------+--------------------
Comment (by dustin):
Here's some log output. I've hacked up Twisted's `Service.startService`
and `Service.stopService` to print what's stopping and starting.
{{{
2014-11-30 12:28:59-0500 [-] Log opened.
2014-11-30 12:28:59-0500 [-] -->
buildbot.test.integration.test_master.RunMaster.test_master1 <--
2014-11-30 12:28:59-0500 [-] Loading configuration from
'/A/trialtemp/basdir/master.cfg'
2014-11-30 12:28:59-0500 [-] Setting up database with URL
'sqlite:/state.sqlite'
2014-11-30 12:28:59-0500 [-] setting database journal mode to 'wal'
2014-11-30 12:28:59-0500 [-] using SQLAlchemy-Migrate version 0.7.2
2014-11-30 12:28:59-0500 [-] Initializing empty database
2014-11-30 12:28:59-0500 [-] Starting BuildMaster -- buildbot.version:
0.8.9
2014-11-30 12:28:59-0500 [-] Loading configuration from
'/A/trialtemp/basdir/master.cfg'
2014-11-30 12:28:59-0500 [-] starting %r <buildbot.master.BuildMaster
instance at 0x7f0ebc64b3b0>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.process.metrics.MetricLogObserver instance at 0x7f0ebc64b200>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.process.cache.CacheManager instance at 0x7f0ebc64b170>
2014-11-30 12:28:59-0500 [-] starting %r <buildbot.pbmanager.PBManager
instance at 0x7f0ebf3ee1b8>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.buildslave.manager.BuildslaveManager instance at 0x7f0ebc77b950>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.buildslave.protocols.pb.Listener instance at 0x7f0ebc5cd7e8>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.changes.manager.ChangeManager instance at 0x7f0ebc7ed5a8>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.process.botmaster.BotMaster instance at 0x7f0ebf43e8c0>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.process.buildrequestdistributor.BuildRequestDistributor instance
at 0x7f0ebf43ea28>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.schedulers.manager.SchedulerManager instance at 0x7f0ebf43e320>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.process.users.manager.UserManagerManager instance at
0x7f0ebc56b710>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.db.connector.DBConnector instance at 0x7f0ebc56b098>
2014-11-30 12:28:59-0500 [-] starting %r
<twisted.application.internet.TimerService instance at 0x7f0ebc56b128>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.mq.connector.MQConnector instance at 0x7f0ebf44c5f0>
2014-11-30 12:28:59-0500 [-] starting %r <buildbot.mq.simple.SimpleMQ
instance at 0x7f0ebc57ffc8>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.data.connector.DataConnector instance at 0x7f0ebc6a1fc8>
2014-11-30 12:28:59-0500 [-] starting %r <buildbot.www.service.WWWService
instance at 0x7f0ebf5bf290>
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.process.debug.DebugServices instance at 0x7f0ebc8438c0>
2014-11-30 12:28:59-0500 [-] starting %r <buildbot.status.master.Status
instance at 0x7f0ec1d21488>
2014-11-30 12:28:59-0500 [-] adding 1 new changesources, removing 0
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.changes.pb.PBChangeSource object at 0x7f0ebf3c23d0>
2014-11-30 12:28:59-0500 [-] adding 1 new builders, removing 0
2014-11-30 12:28:59-0500 [-] starting %r <Builder 'u'testy'' at
139701265874888>
2014-11-30 12:28:59-0500 [-] starting %r
<twisted.application.internet.TimerService instance at 0x7f0ebf47ee18>
2014-11-30 12:28:59-0500 [-] starting %r
<twisted.application.internet.TimerService instance at 0x7f0ebf47ef80>
2014-11-30 12:28:59-0500 [-] PBServerFactory starting on 51418
2014-11-30 12:28:59-0500 [-] Starting factory
<twisted.spread.pb.PBServerFactory instance at 0x7f0ebc574c68>
2014-11-30 12:28:59-0500 [-] starting %r <pbmanager.Dispatcher for on
tcp:0>
2014-11-30 12:28:59-0500 [-] trying to load status pickle from
/A/trialtemp/basdir/testy/builder
2014-11-30 12:28:59-0500 [-] no saved status pickle, creating a new one
2014-11-30 12:28:59-0500 [-] added builder testy with tags []
2014-11-30 12:28:59-0500 [-] adding scheduler 'all'
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.schedulers.basic.AnyBranchScheduler object at 0x7f0ebf3c2450>
2014-11-30 12:28:59-0500 [-] adding scheduler 'force'
2014-11-30 12:28:59-0500 [-] starting %r
<buildbot.schedulers.forcesched.ForceScheduler object at 0x7f0ebf3c2550>
2014-11-30 12:28:59-0500 [-] adding 1 new slaves, removing 0
2014-11-30 12:28:59-0500 [-] BuildMaster is running
2014-11-30 12:28:59-0500 [-] stopping %r <buildbot.master.BuildMaster
instance at 0x7f0ebc64b3b0>
2014-11-30 12:28:59-0500 [-] stopping %r <buildbot.status.master.Status
instance at 0x7f0ec1d21488>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.process.debug.DebugServices instance at 0x7f0ebc8438c0>
2014-11-30 12:28:59-0500 [-] stopping %r <buildbot.www.service.WWWService
instance at 0x7f0ebf5bf290>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.data.connector.DataConnector instance at 0x7f0ebc6a1fc8>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.mq.connector.MQConnector instance at 0x7f0ebf44c5f0>
2014-11-30 12:28:59-0500 [-] stopping %r <buildbot.mq.simple.SimpleMQ
instance at 0x7f0ebc57ffc8>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.db.connector.DBConnector instance at 0x7f0ebc56b098>
2014-11-30 12:28:59-0500 [-] stopping %r
<twisted.application.internet.TimerService instance at 0x7f0ebc56b128>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.process.users.manager.UserManagerManager instance at
0x7f0ebc56b710>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.schedulers.manager.SchedulerManager instance at 0x7f0ebf43e320>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.process.botmaster.BotMaster instance at 0x7f0ebf43e8c0>
2014-11-30 12:28:59-0500 [-] stopping %r <Builder 'u'testy'' at
139701265874888>
2014-11-30 12:28:59-0500 [-] stopping %r
<twisted.application.internet.TimerService instance at 0x7f0ebf47ef80>
2014-11-30 12:28:59-0500 [-] stopping %r
<twisted.application.internet.TimerService instance at 0x7f0ebf47ee18>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.process.buildrequestdistributor.BuildRequestDistributor instance
at 0x7f0ebf43ea28>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.changes.manager.ChangeManager instance at 0x7f0ebc7ed5a8>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.buildslave.manager.BuildslaveManager instance at 0x7f0ebc77b950>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.buildslave.protocols.pb.Listener instance at 0x7f0ebc5cd7e8>
2014-11-30 12:28:59-0500 [-] stopping %r <buildbot.pbmanager.PBManager
instance at 0x7f0ebf3ee1b8>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.process.cache.CacheManager instance at 0x7f0ebc64b170>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.process.metrics.MetricLogObserver instance at 0x7f0ebc64b200>
2014-11-30 12:28:59-0500 [-] (TCP Port 51418 Closed)
2014-11-30 12:28:59-0500 [-] Stopping factory
<twisted.spread.pb.PBServerFactory instance at 0x7f0ebc574c68>
2014-11-30 12:28:59-0500 [-] stopping %r <pbmanager.Dispatcher for on
tcp:0>
2014-11-30 12:28:59-0500 [-] starting %r <BuildSlave u'local1'>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.changes.pb.PBChangeSource object at 0x7f0ebf3c23d0>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.schedulers.forcesched.ForceScheduler object at 0x7f0ebf3c2550>
2014-11-30 12:28:59-0500 [-] stopping %r
<buildbot.schedulers.basic.AnyBranchScheduler object at 0x7f0ebf3c2450>
2014-11-30 12:28:59-0500 [-] Unhandled error in Deferred:
2014-11-30 12:28:59-0500 [-] Unhandled Error
▷⋅⋅⋅Traceback (most recent call last):
▷⋅⋅⋅ File "/home/dustin/code/buildbot/t/buildbot/sandbox/lib/python2.7
/site-packages/twisted/internet/defer.py", line 382, in callback
▷⋅⋅⋅ self._startRunCallbacks(result)
▷⋅⋅⋅ File "/home/dustin/code/buildbot/t/buildbot/sandbox/lib/python2.7
/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
▷⋅⋅⋅ self._runCallbacks()
▷⋅⋅⋅ File "/home/dustin/code/buildbot/t/buildbot/sandbox/lib/python2.7
/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
▷⋅⋅⋅ current.result = callback(current.result, *args, **kw)
▷⋅⋅⋅ File "/home/dustin/code/buildbot/t/buildbot/sandbox/lib/python2.7
/site-packages/twisted/internet/defer.py", line 1155, in gotResult
▷⋅⋅⋅ _inlineCallbacks(r, g, deferred)
▷⋅⋅⋅--- <exception caught here> ---
▷⋅⋅⋅ File "/home/dustin/code/buildbot/t/buildbot/sandbox/lib/python2.7
/site-packages/twisted/internet/defer.py", line 1099, in _inlineCallbacks
▷⋅⋅⋅ result = g.send(result)
▷⋅⋅⋅ File
"/home/dustin/code/buildbot/t/buildbot/master/buildbot/buildslave/base.py",
line 262, in stopService
▷⋅⋅⋅ yield service.AsyncMultiService.stopService(self)
▷⋅⋅⋅ File
"/home/dustin/code/buildbot/t/buildbot/master/buildbot/util/service.py",
line 204, in stopService
▷⋅⋅⋅ service.Service.stopService(self)
▷⋅⋅⋅ File
"/home/dustin/code/buildbot/t/buildbot/master/buildbot/monkeypatches/servicechecks.py",
line 33, in stopService
▷⋅⋅⋅ assert self.running, "%r already stopped" % (self,)
▷⋅⋅⋅exceptions.AssertionError: <BuildSlave u'local1'> already stopped
▷⋅⋅⋅
2014-11-30 12:28:59-0500 [-] BuildMaster is stopped
2014-11-30 12:28:59-0500 [-] Main loop terminated.
}}}
The interesting bit there is that `<BuildSlave u'local1'>` only gets
started after everything has begun shutting down. What's even weirder,
though, is that the assertion is failing because `self.running` is 0, but
the `starting %r <BuildSlave u'local1'>` log is written just before
setting `self.running = 1`.
--
Ticket URL: <http://trac.buildbot.net/ticket/3066#comment:11>
Buildbot <http://buildbot.net/>
Buildbot: build/test automation
More information about the bugs
mailing list