#1992 investigation

redheadphones - 14:08:35

2011-06-18 14:08:35-0700 [-] Log opened.
2011-06-18 14:08:35-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.
2011-06-18 14:08:35-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 14:08:35-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 14:08:35-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 14:08:35-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 14:08:35-0700 [-] configuration update started
2011-06-18 14:08:35-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 14:08:35-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 14:08:35-0700 [-] before def thd(engine) in model.is_current
2011-06-18 14:08:35-0700 [-] in try block in model.is_current
2011-06-18 14:11:05-0700 [-] right after model.is_current call in buildbot.master
2011-06-18 14:11:05-0700 [-] just inside check_current
2011-06-18 14:11:05-0700 [-] between loadConfig_Database and loadConfig_Slaves
2011-06-18 14:11:05-0700 [-] in loadConfig_Slaves
2011-06-18 14:11:05-0700 [-] twisted.spread.pb.PBServerFactory starting on 9989
2011-06-18 14:11:05-0700 [-] Starting factory <twisted.spread.pb.PBServerFactory instance at 0x101577fc8>
2011-06-18 14:11:05-0700 [-] adding new builder runtests for category None
2011-06-18 14:11:05-0700 [-] trying to load status pickle from /Users/dustin/current2/master/runtests/builder
2011-06-18 14:11:05-0700 [-] added builder runtests in category None
2011-06-18 14:11:05-0700 [-] setBuilders._add: [<buildbot.process.botmaster.BuildRequestDistributor instance at 0x102b03dd0>, <BuildSlave 'tests', current builders: >] ['runtests']
2011-06-18 14:11:05-0700 [-] adding IStatusReceiver <WebStatus on port tcp:8010 at 0x102b64a28>
2011-06-18 14:11:05-0700 [-] buildbot.status.web.baseweb.RotateLogSite starting on 8010
2011-06-18 14:11:05-0700 [-] Starting factory <buildbot.status.web.baseweb.RotateLogSite instance at 0x10157ee18>
2011-06-18 14:11:05-0700 [-] Setting up http.log rotating 10 files of 10000000 bytes each
2011-06-18 14:11:05-0700 [-] WebStatus using (/Users/dustin/current2/master/public_html)
2011-06-18 14:11:05-0700 [-] removing 0 old schedulers, updating 0, and adding 1
2011-06-18 14:11:05-0700 [-] adding 1 new changesources, removing 0
2011-06-18 14:11:05-0700 [-] configuration update complete

diff at that point:

diff --git a/master/buildbot/db/model.py b/master/buildbot/db/model.py
index b27bbee..4307ba3 100644
--- a/master/buildbot/db/model.py
+++ b/master/buildbot/db/model.py
@@ -378,12 +378,14 @@ class Model(base.DBConnectorComponent):
 
     def is_current(self):
         """Returns true (via deferred) if the database's version is up to date."""
+        log.msg("before def thd(engine) in model.is_current")
         def thd(engine):
             # we don't even have to look at the old version table - if there's
             # no migrate_version, then we're not up to date.
             repo = migrate.versioning.repository.Repository(self.repo_path)
             repo_version = repo.latest
             try:
+                log.msg("in try block in model.is_current")
                 # migrate.api doesn't let us hand in an engine
                 schema = migrate.versioning.schema.ControlledSchema(engine, self.repo_path)
                 db_version = schema.version
diff --git a/master/buildbot/master.py b/master/buildbot/master.py
index 9148248..293a0f6 100644
--- a/master/buildbot/master.py
+++ b/master/buildbot/master.py
@@ -506,6 +506,11 @@ class BuildMaster(service.MultiService):
             d.addCallback(lambda res:
                           self.loadConfig_Database(db_url, db_poll_interval))
 
+            def dbg(r, msg):
+                log.msg(msg)
+                return r
+            d.addCallback(dbg, "between loadConfig_Database and loadConfig_Slaves")
+
             # set up slaves
             d.addCallback(lambda res: self.loadConfig_Slaves(slaves))
 
@@ -574,7 +579,12 @@ class BuildMaster(service.MultiService):
 
         # make sure it's up to date
         d = self.db.model.is_current()
+        def dbg(r, msg):
+            log.msg(msg)
+            return r
+        d.addCallback(dbg, "right after model.is_current call in buildbot.master")
         def check_current(res):
+            log.msg("just inside check_current")
             if res:
                 return # good to go!
             raise exceptions.DatabaseNotReadyError, textwrap.dedent("""
@@ -611,7 +621,8 @@ class BuildMaster(service.MultiService):
         self.db_poll_interval = db_poll_interval
         return self.loadDatabase(db_url, db_poll_interval)
 
-    def loadConfig_Slaves(self, new_slaves):
+    def loadConfig_Slaves(self, new_slaves):        
+        log.msg("in loadConfig_Slaves")
         return self.botmaster.loadConfig_Slaves(new_slaves)
 
     def loadConfig_Sources(self, sources):

redheadphones - 14:41:06

2011-06-18 14:41:06-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.
2011-06-18 14:41:06-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 14:41:06-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 14:41:06-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 14:41:06-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 14:41:06-0700 [-] configuration update started
2011-06-18 14:41:07-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 14:41:07-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 14:41:07-0700 [-] before def thd(engine) in model.is_current
2011-06-18 14:41:07-0700 [-] in try block in model.is_current

(gdb) info threads
  2                         0x00007fff82895f8a in __semwait_signal ()
* 1 "com.apple.main-thread" 0x00007fff8289ee52 in select$DARWIN_EXTSN ()

blocked until exactly when I exited gdb, which sends a signal to the process and will wake select():

2011-06-18 14:56:54-0700 [-] right after model.is_current call in buildbot.master
2011-06-18 14:56:54-0700 [-] just inside check_current
2011-06-18 14:56:54-0700 [-] between loadConfig_Database and loadConfig_Slaves
2011-06-18 14:56:54-0700 [-] in loadConfig_Slaves
2011-06-18 14:56:54-0700 [-] twisted.spread.pb.PBServerFactory starting on 9989
2011-06-18 14:56:54-0700 [-] Starting factory <twisted.spread.pb.PBServerFactory instance at 0x101e54fc8>
2011-06-18 14:56:54-0700 [-] adding new builder runtests for category None
2011-06-18 14:56:54-0700 [-] trying to load status pickle from /Users/dustin/current2/master/runtests/builder
2011-06-18 14:56:54-0700 [-] added builder runtests in category None
2011-06-18 14:56:54-0700 [-] setBuilders._add: [<buildbot.process.botmaster.BuildRequestDistributor instance at 0x1027c3dd0>, <BuildSlave 'tests', current builders: >] ['runtests']
2011-06-18 14:56:54-0700 [-] adding IStatusReceiver <WebStatus on port tcp:8010 at 0x102b25a28>
2011-06-18 14:56:54-0700 [-] buildbot.status.web.baseweb.RotateLogSite starting on 8010
2011-06-18 14:56:54-0700 [-] Starting factory <buildbot.status.web.baseweb.RotateLogSite instance at 0x101e65290>
2011-06-18 14:56:54-0700 [-] Setting up http.log rotating 10 files of 10000000 bytes each
2011-06-18 14:56:54-0700 [-] WebStatus using (/Users/dustin/current2/master/public_html)
2011-06-18 14:56:54-0700 [-] removing 0 old schedulers, updating 0, and adding 1
2011-06-18 14:56:54-0700 [-] adding 1 new changesources, removing 0
2011-06-18 14:56:54-0700 [-] configuration update complete

diff this time (model.py only):

--- a/master/buildbot/db/model.py
+++ b/master/buildbot/db/model.py
@@ -378,15 +378,19 @@ class Model(base.DBConnectorComponent):
 
     def is_current(self):
         """Returns true (via deferred) if the database's version is up to date."""
+        log.msg("before def thd(engine) in model.is_current")
         def thd(engine):
             # we don't even have to look at the old version table - if there's
             # no migrate_version, then we're not up to date.
             repo = migrate.versioning.repository.Repository(self.repo_path)
             repo_version = repo.latest
             try:
+                log.msg("in try block in model.is_current")
                 # migrate.api doesn't let us hand in an engine
                 schema = migrate.versioning.schema.ControlledSchema(engine, self.repo_path)
+                log.msg("ControlledSchema loaded")
                 db_version = schema.version
+                log.msg("db_version: %s" % (schema.version,))
             except exceptions.DatabaseNotControlledError:
                 return False
 
so the ControlledSchema constructor is throwing DatabaseNotControlledError, which makes sense:

sqlite> select * from migrate_version;
Buildbot|/Users/derekhurley/Documents/Dropbox/gsoc/bbot/src/master/buildbot/db/migrate|10

whereas the path migrate is looking for will be /Users/dustin/...

redheadphones - 15:10:02

2011-06-18 15:10:02-0700 [-] Log opened.
2011-06-18 15:10:02-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.
2011-06-18 15:10:02-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.2011-06-18 15:10:02-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 15:10:02-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 15:10:02-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 15:10:02-0700 [-] configuration update started
2011-06-18 15:10:02-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 15:10:02-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 15:10:02-0700 [-] before def thd(engine) in model.is_current
2011-06-18 15:10:02-0700 [-] in try block in model.is_current DJM..
2011-06-18 15:10:02-0700 [-] ControlledSchema loaded
2011-06-18 15:10:02-0700 [-] db_version: 10

with

--- a/master/buildbot/db/model.py
+++ b/master/buildbot/db/model.py
@@ -378,16 +378,21 @@ class Model(base.DBConnectorComponent):
 
     def is_current(self):
         """Returns true (via deferred) if the database's version is up to date."""
+        log.msg("before def thd(engine) in model.is_current")
         def thd(engine):
             # we don't even have to look at the old version table - if there's
             # no migrate_version, then we're not up to date.
             repo = migrate.versioning.repository.Repository(self.repo_path)
             repo_version = repo.latest
             try:
+                log.msg("in try block in model.is_current DJM..")
                 # migrate.api doesn't let us hand in an engine
                 schema = migrate.versioning.schema.ControlledSchema(engine, self.repo_path)
+                log.msg("ControlledSchema loaded")
                 db_version = schema.version
+                log.msg("db_version: %s" % (schema.version,))
             except exceptions.DatabaseNotControlledError:
+                log.msg("DatabaseNotControlledError")
                 return False
 
             return db_version == repo_version
diff --git a/master/buildbot/master.py b/master/buildbot/master.py
index 9148248..293a0f6 100644
--- a/master/buildbot/master.py
+++ b/master/buildbot/master.py
@@ -506,6 +506,11 @@ class BuildMaster(service.MultiService):
             d.addCallback(lambda res:
                           self.loadConfig_Database(db_url, db_poll_interval))
 
+            def dbg(r, msg):
+                log.msg(msg)
+                return r
+            d.addCallback(dbg, "between loadConfig_Database and loadConfig_Slaves")
+
             # set up slaves
             d.addCallback(lambda res: self.loadConfig_Slaves(slaves))
 
@@ -574,7 +579,12 @@ class BuildMaster(service.MultiService):
 
         # make sure it's up to date
         d = self.db.model.is_current()
+        def dbg(r, msg):
+            log.msg(msg)
+            return r
+        d.addCallback(dbg, "right after model.is_current call in buildbot.master")
         def check_current(res):
+            log.msg("just inside check_current")
             if res:
                 return # good to go!
             raise exceptions.DatabaseNotReadyError, textwrap.dedent("""
@@ -611,7 +621,8 @@ class BuildMaster(service.MultiService):
         self.db_poll_interval = db_poll_interval
         return self.loadDatabase(db_url, db_poll_interval)
 
-    def loadConfig_Slaves(self, new_slaves):
+    def loadConfig_Slaves(self, new_slaves):        
+        log.msg("in loadConfig_Slaves")
         return self.botmaster.loadConfig_Slaves(new_slaves)
 
     def loadConfig_Sources(self, sources):

so the db_version was returned before the hang.  Looking more and more like a thread pool problem!

redheadphones - 15:13:22

2011-06-18 15:13:22-0700 [-] Log opened.
2011-06-18 15:13:22-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.
2011-06-18 15:13:22-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 15:13:23-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 15:13:23-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 15:13:23-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 15:13:23-0700 [-] configuration update started
2011-06-18 15:13:23-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 15:13:23-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 15:13:23-0700 [-] before def thd(engine) in model.is_current
2011-06-18 15:13:23-0700 [-] dwe: <function thd at 0x101476b18>
2011-06-18 15:13:23-0700 [-] start thd
2011-06-18 15:13:23-0700 [-] in try block in model.is_current DJM..
2011-06-18 15:13:23-0700 [-] ControlledSchema loaded
2011-06-18 15:13:23-0700 [-] db_version: 10
2011-06-18 15:13:23-0700 [-] stop thd (return)

This time with 

diff --git a/master/buildbot/db/model.py b/master/buildbot/db/model.py
index b27bbee..d84ccd4 100644
--- a/master/buildbot/db/model.py
+++ b/master/buildbot/db/model.py
@@ -378,16 +378,21 @@ class Model(base.DBConnectorComponent):
 
     def is_current(self):
         """Returns true (via deferred) if the database's version is up to date."""
+        log.msg("before def thd(engine) in model.is_current")
         def thd(engine):
             # we don't even have to look at the old version table - if there's
             # no migrate_version, then we're not up to date.
             repo = migrate.versioning.repository.Repository(self.repo_path)
             repo_version = repo.latest
             try:
+                log.msg("in try block in model.is_current DJM..")
                 # migrate.api doesn't let us hand in an engine
                 schema = migrate.versioning.schema.ControlledSchema(engine, self.repo_path)
+                log.msg("ControlledSchema loaded")
                 db_version = schema.version
+                log.msg("db_version: %s" % (schema.version,))
             except exceptions.DatabaseNotControlledError:
+                log.msg("DatabaseNotControlledError")
                 return False
 
             return db_version == repo_version
diff --git a/master/buildbot/db/pool.py b/master/buildbot/db/pool.py
index 0c38660..0af79fd 100644
--- a/master/buildbot/db/pool.py
+++ b/master/buildbot/db/pool.py
@@ -102,12 +102,15 @@ class DBThreadPool(threadpool.ThreadPool):
         is only used for schema manipulation, and is not used at master
         runtime.
         """
+        print "dwe:", callable
         def thd():
+            print "start thd"
             if self.__broken_sqlite: # see bug #1810
                 self.engine.execute("select * from sqlite_master")
             rv = callable(self.engine, *args, **kwargs)
             assert not isinstance(rv, sa.engine.ResultProxy), \
                     "do not return ResultProxy objects!"
+            print "stop thd (return)"
             return rv
         return threads.deferToThreadPool(reactor, self, thd)
 
diff --git a/master/buildbot/master.py b/master/buildbot/master.py
index 9148248..293a0f6 100644
--- a/master/buildbot/master.py
+++ b/master/buildbot/master.py
@@ -506,6 +506,11 @@ class BuildMaster(service.MultiService):
             d.addCallback(lambda res:
                           self.loadConfig_Database(db_url, db_poll_interval))
 
+            def dbg(r, msg):
+                log.msg(msg)
+                return r
+            d.addCallback(dbg, "between loadConfig_Database and loadConfig_Slaves")
+
             # set up slaves
             d.addCallback(lambda res: self.loadConfig_Slaves(slaves))
 
@@ -574,7 +579,12 @@ class BuildMaster(service.MultiService):
 
         # make sure it's up to date
         d = self.db.model.is_current()
+        def dbg(r, msg):
+            log.msg(msg)
+            return r
+        d.addCallback(dbg, "right after model.is_current call in buildbot.master")
         def check_current(res):
+            log.msg("just inside check_current")
             if res:
                 return # good to go!
             raise exceptions.DatabaseNotReadyError, textwrap.dedent("""
@@ -611,7 +621,8 @@ class BuildMaster(service.MultiService):
         self.db_poll_interval = db_poll_interval
         return self.loadDatabase(db_url, db_poll_interval)
 
-    def loadConfig_Slaves(self, new_slaves):
+    def loadConfig_Slaves(self, new_slaves):        
+        log.msg("in loadConfig_Slaves")
         return self.botmaster.loadConfig_Slaves(new_slaves)
 
     def loadConfig_Sources(self, sources):

so on to investigate deferToThreadPool.

redheadphones - 15:17:25

2011-06-18 15:17:25-0700 [-] Log opened.
2011-06-18 15:17:25-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.
2011-06-18 15:17:25-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 15:17:26-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 15:17:26-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 15:17:26-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 15:17:26-0700 [-] configuration update started
2011-06-18 15:17:26-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 15:17:26-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 15:17:26-0700 [-] before def thd(engine) in model.is_current
2011-06-18 15:17:26-0700 [-] in try block in model.is_current DJM..
2011-06-18 15:17:26-0700 [-] ControlledSchema loaded
2011-06-18 15:17:26-0700 [-] db_version: 10
2011-06-18 15:17:26-0700 [-] cft (<bound method Deferred.callback of <Deferred at 0x101c77170>>, True)

important part of the diff here being

diff --git a/master/buildbot/db/pool.py b/master/buildbot/db/pool.py
index 0c38660..a7155e7 100644
--- a/master/buildbot/db/pool.py
+++ b/master/buildbot/db/pool.py
@@ -144,12 +144,15 @@ class DBThreadPool(threadpool.ThreadPool):
                 rv = callable(conn, *args, **kwargs)
                 assert not isinstance(rv, sa.engine.ResultProxy), \
                         "do not return ResultProxy objects!"
+               print "cft", (d.callback, rv)
                 reactor.callFromThread(d.callback, rv)
             except:
-                reactor.callFromThread(d.errback, failure.Failure())
+               f = failure.Failure()
+               print "cft", (d.errback, f)
+                reactor.callFromThread(d.errback, f)
         self.callInThread(thd)
         return d
-    if twisted.version < versions.Version('twisted', 8, 2, 0):
+    if twisted.version < versions.Version('twisted', 8, 3, 0):
         do = do_081
         do_with_engine = do_with_engine_081

so it's a normal completion of the callable, and callFromThread is being invoked, but is that ever being run in the main thread?

redheadphones - 15:29:07

Two runs here, the first without a hang, and the second with a hang, to show what the expected behavior is

2011-06-18 15:29:07-0700 [-] Log opened.
2011-06-18 15:29:07-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.
2011-06-18 15:29:07-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 15:29:07-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 15:29:07-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 15:29:07-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 15:29:07-0700 [-] configuration update started
2011-06-18 15:29:07-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 15:29:07-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 15:29:07-0700 [-] before def thd(engine) in model.is_current
2011-06-18 15:29:07-0700 [-] in try block in model.is_current DJM..
2011-06-18 15:29:07-0700 [-] ControlledSchema loaded
2011-06-18 15:29:07-0700 [-] db_version: 10
2011-06-18 15:29:07-0700 [-] cft (<function do_cb at 0x1016518c0>, True)
2011-06-18 15:29:07-0700 [-] do_cb (True,) {} <_MainThread(MainThread, started 140735078296736)>
2011-06-18 15:29:07-0700 [-] right after model.is_current call in buildbot.master
2011-06-18 15:29:07-0700 [-] just inside check_current
2011-06-18 15:29:07-0700 [-] between loadConfig_Database and loadConfig_Slaves
2011-06-18 15:29:07-0700 [-] in loadConfig_Slaves
2011-06-18 15:29:07-0700 [-] twisted.spread.pb.PBServerFactory starting on 9989
2011-06-18 15:29:07-0700 [-] Starting factory <twisted.spread.pb.PBServerFactory instance at 0x101654e18>
2011-06-18 15:29:07-0700 [-] adding new builder runtests for category None
2011-06-18 15:29:07-0700 [-] trying to load status pickle from /Users/dustin/current2/master/runtests/builder
2011-06-18 15:29:07-0700 [-] added builder runtests in category None
2011-06-18 15:29:07-0700 [-] setBuilders._add: [<buildbot.process.botmaster.BuildRequestDistributor instance at 0x1027c4c20>, <BuildSlave 'tests', current builders: >] ['runtests']
2011-06-18 15:29:07-0700 [-] adding IStatusReceiver <WebStatus on port tcp:8010 at 0x102ba5878>
2011-06-18 15:29:07-0700 [-] buildbot.status.web.baseweb.RotateLogSite starting on 8010
2011-06-18 15:29:07-0700 [-] Starting factory <buildbot.status.web.baseweb.RotateLogSite instance at 0x101664200>
2011-06-18 15:29:07-0700 [-] Setting up http.log rotating 10 files of 10000000 bytes each
2011-06-18 15:29:07-0700 [-] WebStatus using (/Users/dustin/current2/master/public_html)
2011-06-18 15:29:07-0700 [-] removing 0 old schedulers, updating 0, and adding 1
2011-06-18 15:29:07-0700 [-] adding 1 new changesources, removing 0
2011-06-18 15:29:07-0700 [-] configuration update complete
2011-06-18 15:29:08-0700 [-] Received SIGTERM, shutting down.
2011-06-18 15:29:08-0700 [-] (Port 8010 Closed)
2011-06-18 15:29:08-0700 [-] Stopping factory <buildbot.status.web.baseweb.RotateLogSite instance at 0x101664200>
2011-06-18 15:29:08-0700 [-] (Port 9989 Closed)
2011-06-18 15:29:08-0700 [-] Stopping factory <twisted.spread.pb.PBServerFactory instance at 0x101654e18>
2011-06-18 15:29:08-0700 [-] Main loop terminated.
2011-06-18 15:29:08-0700 [-] Server Shut Down.
2011-06-18 15:29:09-0700 [-] Log opened.
2011-06-18 15:29:09-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.
2011-06-18 15:29:09-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 15:29:09-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 15:29:09-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 15:29:09-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 15:29:09-0700 [-] configuration update started
2011-06-18 15:29:09-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 15:29:10-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 15:29:10-0700 [-] before def thd(engine) in model.is_current
2011-06-18 15:29:10-0700 [-] in try block in model.is_current DJM..
2011-06-18 15:29:10-0700 [-] ControlledSchema loaded
2011-06-18 15:29:10-0700 [-] db_version: 10
2011-06-18 15:29:10-0700 [-] cft (<function do_cb at 0x1014748c0>, True)

pool.py diff is

diff --git a/master/buildbot/db/pool.py b/master/buildbot/db/pool.py
index 0c38660..7401075 100644
--- a/master/buildbot/db/pool.py+++ b/master/buildbot/db/pool.py
@@ -16,6 +16,7 @@
 import os
 import sqlalchemy as sa
 import twisted
+import threading
 from twisted.internet import reactor, threads, defer
 from twisted.python import threadpool, failure, versions, log
 
@@ -136,6 +137,9 @@ class DBThreadPool(threadpool.ThreadPool):
         return d
     def do_with_engine_081(self, callable, *args, **kwargs): # pragma: no cover
         d = defer.Deferred()
+       def do_cb(*args, **kwargs):
+               print "do_cb", args, kwargs, threading.current_thread()
+               return d.callback(*args, **kwargs)
         def thd():
             try:
                 conn = self.engine
@@ -144,12 +148,15 @@ class DBThreadPool(threadpool.ThreadPool):
                 rv = callable(conn, *args, **kwargs)
                 assert not isinstance(rv, sa.engine.ResultProxy), \
                         "do not return ResultProxy objects!"
-                reactor.callFromThread(d.callback, rv)
+               print "cft", (do_cb, rv)
+                reactor.callFromThread(do_cb, rv)
             except:
-                reactor.callFromThread(d.errback, failure.Failure())+               f = failure.Failure()
+               print "cft", (d.errback, f)
+                reactor.callFromThread(d.errback, f)
         self.callInThread(thd)
         return d
-    if twisted.version < versions.Version('twisted', 8, 2, 0):
+    if twisted.version < versions.Version('twisted', 8, 3, 0):
         do = do_081
         do_with_engine = do_with_engine_081
 
so, basically, callFromThread is broken.

redheadphones - 16:44:25

Another double-run, showing that in fact it's select that's not working:

2011-06-18 16:44:25-0700 [-] Log opened.
2011-06-18 16:44:25-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.2011-06-18 16:44:25-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 16:44:25-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 16:44:25-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 16:44:25-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 16:44:25-0700 [-] configuration update started
2011-06-18 16:44:25-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 16:44:25-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 16:44:25-0700 [-] before def thd(engine) in model.is_current2011-06-18 16:44:25-0700 [-] calling select
2011-06-18 16:44:25-0700 [-] in try block in model.is_current DJM..
2011-06-18 16:44:25-0700 [-] ControlledSchema loaded
2011-06-18 16:44:25-0700 [-] db_version: 10
2011-06-18 16:44:25-0700 [-] cft (<function do_cb at 0x101df2938>, True)
2011-06-18 16:44:25-0700 [-] cft done reactor._reads={<twisted.internet.posixbase._UnixWaker instance at 0x1020e9050>: 1} [(<function do_cb at 0x101df2938>, (True,), {})] <twisted.internet.posixbase._UnixWaker instance at 0x1020e9050>
2011-06-18 16:44:25-0700 [-] called select
2011-06-18 16:44:25-0700 [-] <twisted.internet.posixbase._UnixWaker instance at 0x1020e9050>
2011-06-18 16:44:25-0700 [-] doRead
2011-06-18 16:44:25-0700 [-] do_cb (True,) {} <_MainThread(MainThread, started 140735078296736)>
2011-06-18 16:44:25-0700 [-] right after model.is_current call in buildbot.master
2011-06-18 16:44:25-0700 [-] just inside check_current
2011-06-18 16:44:25-0700 [-] between loadConfig_Database and loadConfig_Slaves
2011-06-18 16:44:25-0700 [-] in loadConfig_Slaves
2011-06-18 16:44:25-0700 [-] twisted.spread.pb.PBServerFactory starting on 9989
2011-06-18 16:44:25-0700 [-] Starting factory <twisted.spread.pb.PBServerFactory instance at 0x101df6f38>
2011-06-18 16:44:25-0700 [-] adding new builder runtests for category None
2011-06-18 16:44:25-0700 [-] trying to load status pickle from /Users/dustin/current2/master/runtests/builder
2011-06-18 16:44:25-0700 [-] added builder runtests in category None
2011-06-18 16:44:25-0700 [-] setBuilders._add: [<buildbot.process.botmaster.BuildRequestDistributor instance at 0x1028c2d40>, <BuildSlave 'tests', current builders: >] ['runtests']
2011-06-18 16:44:25-0700 [-] adding IStatusReceiver <WebStatus on port tcp:8010 at 0x102ba4998>
2011-06-18 16:44:25-0700 [-] buildbot.status.web.baseweb.RotateLogSite starting on 8010
2011-06-18 16:44:25-0700 [-] Starting factory <buildbot.status.web.baseweb.RotateLogSite instance at 0x101e06320>
2011-06-18 16:44:25-0700 [-] Setting up http.log rotating 10 files of 10000000 bytes each
2011-06-18 16:44:25-0700 [-] WebStatus using (/Users/dustin/current2/master/public_html)
2011-06-18 16:44:25-0700 [-] removing 0 old schedulers, updating 0, and adding 1
2011-06-18 16:44:25-0700 [-] calling select
2011-06-18 16:44:25-0700 [-] called select
2011-06-18 16:44:25-0700 [-] <twisted.internet.posixbase._UnixWaker instance at 0x1020e9050>
2011-06-18 16:44:25-0700 [-] doRead
2011-06-18 16:44:25-0700 [-] adding 1 new changesources, removing 0
2011-06-18 16:44:25-0700 [-] configuration update complete
2011-06-18 16:44:25-0700 [-] calling select
2011-06-18 16:44:25-0700 [-] called select
2011-06-18 16:44:25-0700 [-] <twisted.internet.posixbase._UnixWaker instance at 0x1020e9050>
2011-06-18 16:44:25-0700 [-] doRead
2011-06-18 16:44:25-0700 [-] calling select
2011-06-18 16:44:26-0700 [-] called select
2011-06-18 16:44:26-0700 [-] calling select
2011-06-18 16:44:26-0700 [-] Received SIGTERM, shutting down.
2011-06-18 16:44:26-0700 [-] exc select 3
2011-06-18 16:44:26-0700 [-] calling select
2011-06-18 16:44:26-0700 [-] called select
2011-06-18 16:44:26-0700 [-] (Port 8010 Closed)
2011-06-18 16:44:26-0700 [-] Stopping factory <buildbot.status.web.baseweb.RotateLogSite instance at 0x101e06320>
2011-06-18 16:44:26-0700 [-] (Port 9989 Closed)
2011-06-18 16:44:26-0700 [-] Stopping factory <twisted.spread.pb.PBServerFactory instance at 0x101df6f38>
2011-06-18 16:44:26-0700 [-] calling select
2011-06-18 16:44:26-0700 [-] called select
2011-06-18 16:44:26-0700 [-] Main loop terminated.
2011-06-18 16:44:26-0700 [-] Server Shut Down.
2011-06-18 16:44:29-0700 [-] Log opened.
2011-06-18 16:44:29-0700 [-] twistd 8.2.0 (/Users/dustin/ve/bin/python 2.6.1) starting up.2011-06-18 16:44:29-0700 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-06-18 16:44:29-0700 [-] Applying patch for http://twistedmatrix.com/trac/ticket/5079
2011-06-18 16:44:29-0700 [-] Creating BuildMaster -- buildbot.version: latest
2011-06-18 16:44:29-0700 [-] loading configuration from /Users/dustin/current2/master/master.cfg
2011-06-18 16:44:29-0700 [-] configuration update started
2011-06-18 16:44:29-0700 [-] /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/mail/smtp.py:10: exceptions.DeprecationWarning: the MimeWriter module is deprecated; use the email package instead
2011-06-18 16:44:29-0700 [-] applying SQLite workaround from Buildbot bug #1810
2011-06-18 16:44:29-0700 [-] before def thd(engine) in model.is_current2011-06-18 16:44:29-0700 [-] calling select
2011-06-18 16:44:29-0700 [-] in try block in model.is_current DJM..
2011-06-18 16:44:29-0700 [-] ControlledSchema loaded
2011-06-18 16:44:29-0700 [-] db_version: 10
2011-06-18 16:44:29-0700 [-] cft (<function do_cb at 0x101e4f938>, True)
2011-06-18 16:44:29-0700 [-] cft done reactor._reads={<twisted.internet.posixbase._UnixWaker instance at 0x101fea050>: 1} [(<function do_cb at 0x101e4f938>, (True,), {})] <twisted.internet.posixbase._UnixWaker instance at 0x101fea050>

pool.py diff:

diff --git a/master/buildbot/db/pool.py b/master/buildbot/db/pool.py
index 0c38660..914f4ae 100644
--- a/master/buildbot/db/pool.py
+++ b/master/buildbot/db/pool.py
@@ -16,6 +16,7 @@
 import os
 import sqlalchemy as sa
 import twisted
+import threading
 from twisted.internet import reactor, threads, defer
 from twisted.python import threadpool, failure, versions, log
 
@@ -136,6 +137,9 @@ class DBThreadPool(threadpool.ThreadPool):
         return d
     def do_with_engine_081(self, callable, *args, **kwargs): # pragma: no cover
         d = defer.Deferred()
+       def do_cb(*args, **kwargs):
+               print "do_cb", args, kwargs, threading.current_thread()
+               return d.callback(*args, **kwargs)
         def thd():
             try:
                 conn = self.engine
@@ -144,12 +148,22 @@ class DBThreadPool(threadpool.ThreadPool):
                 rv = callable(conn, *args, **kwargs)
                 assert not isinstance(rv, sa.engine.ResultProxy), \
                         "do not return ResultProxy objects!"
-                reactor.callFromThread(d.callback, rv)
+               print "cft", (do_cb, rv)
+                reactor.callFromThread(do_cb, rv)
             except:
-                reactor.callFromThread(d.errback, failure.Failure())
+               f = failure.Failure()
+               print "cft", (d.errback, f)
+                reactor.callFromThread(d.errback, f)
+           print "cft done", "reactor._reads=%s" % (reactor._reads,), reactor.threadCallQueue, reactor.waker
+       old = reactor.waker.doRead
+       def doRead():
+               print "doRead"
+               old()
+       reactor.waker.doRead = doRead
+
         self.callInThread(thd)
         return d
-    if twisted.version < versions.Version('twisted', 8, 2, 0):
+    if twisted.version < versions.Version('twisted', 8, 3, 0):
         do = do_081
         do_with_engine = do_with_engine_081
 
@@ -190,3 +204,65 @@ class DBThreadPool(threadpool.ThreadPool):
         # but this version should not fail..
         test(select_from_sqlite_master=True)
         return False # not broken - no workaround required
+
+import twisted.internet.selectreactor
+from twisted.internet.selectreactor import SelectReactor
+
+def doSelect(self, timeout):
+    """
+    Run one iteration of the I/O monitor loop.
+
+    This will run all selectables who had input or output readiness
+    waiting for them.
+    """
+    while 1:
+       try:
+           print "calling select"
+           r, w, ignored = twisted.internet.selectreactor._select(self._reads.keys(),
+                                   self._writes.keys(),
+                                   [], timeout)
+           print "called select"
+           break
+       except ValueError, ve:
+           print "exc select 1"
+           # Possibly a file descriptor has gone negative?
+           twisted.internet.selectreactor.log.err()
+           self._preenDescriptors()
+       except TypeError, te:
+           print "exc select 2"
+           # Something *totally* invalid (object w/o fileno, non-integral
+           # result) was passed
+           twisted.internet.selectreactor.log.err()
+           self._preenDescriptors()
+       except (twisted.internet.selectreactor.select.error, IOError), se:
+           print "exc select 3"
+           # select(2) encountered an error
+           if se.args[0] in (0, 2):
+               # windows does this if it got an empty list
+               if (not self._reads) and (not self._writes):
+                   return
+               else:
+                   raise
+           elif se.args[0] == twisted.internet.selectreactor.EINTR:
+               return
+           elif se.args[0] == twisted.internet.selectreactor.EBADF:
+               self._preenDescriptors()
+           else:
+               # OK, I really don't know what's going on.  Blow up.
+               raise
+    _drdw = self._doReadOrWrite
+    _logrun = twisted.internet.selectreactor.log.callWithLogger
+    for selectables, method, fdset in ((r, "doRead", self._reads),
+                                      (w,"doWrite", self._writes)):
+       for selectable in selectables:
+           print selectable
+           # if this was disconnected in another thread, kill it.
+           # ^^^^ --- what the !@#*?  serious!  -exarkun
+           if selectable not in fdset:
+               continue
+           # This for pausing input when we're not ready for more.
+           _logrun(selectable, _drdw, selectable, method, dict)
+
+
+SelectReactor.doSelect = doSelect
+SelectReactor.doIteration = doSelect

redheadphones - master config.py

# -*- python -*-
# ex: set syntax=python:

# This is a sample buildmaster config file. It must be installed as
# 'master.cfg' in your buildmaster's base directory.

# This is the dictionary that the buildmaster pays attention to. We also use
# a shorter alias to save typing.
c = BuildmasterConfig = {}

####### BUILDSLAVES

# The 'slaves' list defines the set of recognized buildslaves. Each element is
# a BuildSlave object, specifying a unique slave name and password.  The same
# slave name and password must be configured on the slave.
from buildbot.buildslave import BuildSlave
c['slaves'] = [BuildSlave("tests", "pass")]

# 'slavePortnum' defines the TCP port to listen on for connections from slaves.
# This must match the value configured into the buildslaves (with their
# --master option)
c['slavePortnum'] = 9989

####### CHANGESOURCES

# the 'change_source' setting tells the buildmaster how it should find out
# about source code changes.  Here we point to the buildbot clone of pyflakes.

#from buildbot.changes.gitpoller import GitPoller
#c['change_source'] = GitPoller(
#        '/Users/derekhurley/Documents/Dropbox/gsoc/bbot/current/repo',
#        workdir='gitpoller-workdir', branch='master',
#        pollinterval=30)

from buildbot.changes.pb import PBChangeSource
c['change_source'] = PBChangeSource()

####### SCHEDULERS

# Configure the Schedulers, which decide how to react to incoming changes.  In this
# case, just kick off a 'runtests' build

from buildbot.schedulers.basic import SingleBranchScheduler
c['schedulers'] = []
c['schedulers'].append(SingleBranchScheduler(
                            name="all",
                            branch='master',
                            treeStableTimer=None,
                            builderNames=["runtests"]))



####### BUILDERS

# The 'builders' list defines the Builders, which tell Buildbot how to perform a build:
# what steps, and which slaves can execute them.  Note that any particular build will
# only take place on one slave.

from buildbot.process.factory import BuildFactory
from buildbot.steps.source import Git
from buildbot.steps.shell import ShellCommand

factory = BuildFactory()
# check out the source
factory.addStep(Git(repourl='/Users/derekhurley/Documents/Dropbox/gsoc/bbot/current/repo', mode='copy'))
# run the tests (note that this will require that 'trial' is installed)
factory.addStep(ShellCommand(command=["echo", "'done'"]))

from buildbot.config import BuilderConfig

c['builders'] = []
c['builders'].append(
    BuilderConfig(name="runtests",
      slavenames=["tests"],
      factory=factory))

####### STATUS TARGETS

# 'status' is a list of Status Targets. The results of each build will be
# pushed to these targets. buildbot/status/*.py has a variety to choose from,
# including web pages, email senders, and IRC bots.

c['status'] = []

from buildbot.status import html
from buildbot.status.web import auth, authz
authz_cfg=authz.Authz(
    # change any of these to True to enable; see the manual for more
    # options
    gracefulShutdown = False,
    forceBuild = True, # use this to test your slave once it is set up
    forceAllBuilds = True,
    pingBuilder = False,
    stopBuild = False,
    stopAllBuilds = False,
    cancelPendingBuild = False,
)
c['status'].append(html.WebStatus(http_port=8010, authz=authz_cfg))

####### PROJECT IDENTITY

# the 'title' string will appear at the top of this buildbot
# installation's html.WebStatus home page (linked to the
# 'titleURL') and is embedded in the title of the waterfall HTML page.

c['title'] = "User Objects"
c['titleURL'] = "https://github.com/dzhurley"

# the 'buildbotURL' string should point to the location where the buildbot's
# internal web server (usually the html.WebStatus page) is visible. This
# typically uses the port number set in the Waterfall 'status' entry, but
# with an externally-visible host name which the buildbot cannot figure out
# without some help.

c['buildbotURL'] = "http://localhost:8010/"

####### DB URL

# This specifies what database buildbot uses to store change and scheduler
# state.  You can leave this at its default for all but the largest
# installations.
c['db_url'] = "sqlite:///state.sqlite"

redheadphones - system info

bash-3.2$ sqlite3 --version
3.6.12

bash-3.2$ ve/bin/pip freeze
Jinja2==2.5.5
PyRSS2Gen==1.0.0
SQLAlchemy==0.7.1
Tempita==0.5.1
Twisted==8.2.0
altgraph==0.6.8.dev
bdist-mpkg==0.4.3.dev
bonjour-py==0.3
buildbot==0.8.4-pre-778-g1ba74c5
decorator==3.3.1
macholib==1.2.1.dev
modulegraph==0.7.2.dev
numpy==1.2.1
py2app==0.4.2
pyOpenSSL==0.7
pyobjc-core==2.2b3
pyobjc-framework-AddressBook==2.2b3
pyobjc-framework-AppleScriptKit==2.2b3
pyobjc-framework-Automator==2.2b3
pyobjc-framework-CFNetwork==2.2b3
pyobjc-framework-CalendarStore==2.2b3
pyobjc-framework-Cocoa==2.2b3
pyobjc-framework-Collaboration==2.2b3
pyobjc-framework-CoreData==2.2b3
pyobjc-framework-CoreText==2.2b3
pyobjc-framework-DictionaryServices==2.2b3
pyobjc-framework-ExceptionHandling==2.2b3
pyobjc-framework-FSEvents==2.2b3
pyobjc-framework-InputMethodKit==2.2b3
pyobjc-framework-InstallerPlugins==2.2b3
pyobjc-framework-InstantMessage==2.2b3
pyobjc-framework-InterfaceBuilderKit==2.2b3
pyobjc-framework-LatentSemanticMapping==2.2b3
pyobjc-framework-LaunchServices==2.2b3
pyobjc-framework-Message==2.2b3
pyobjc-framework-PreferencePanes==2.2b3
pyobjc-framework-PubSub==2.2b3
pyobjc-framework-QTKit==2.2b3
pyobjc-framework-Quartz==2.2b3
pyobjc-framework-ScreenSaver==2.2b3
pyobjc-framework-ScriptingBridge==2.2b3
pyobjc-framework-SearchKit==2.2b3
pyobjc-framework-SyncServices==2.2b3
pyobjc-framework-SystemConfiguration==2.2b3
pyobjc-framework-WebKit==2.2b3
pyobjc-framework-XgridFoundation==2.2b3
python-dateutil==1.2
python-irclib==0.4.6
sqlalchemy-migrate==0.6
vboxapi==1.0
wsgiref==0.1.2
wxPython==2.8.8.1
wxPython-common==2.8.8.1
wxaddons==2.8.8.1
xattr==0.5
zope.interface==3.5.1

bash-3.2$ ls -alh current2//master/state.sqlite 
-rw-r--r--  1 dustin  staff   104K Jun 18 14:08 current2//master/state.sqlite