SVNPoller stops after failure

[fgsch]

I arrived today at work and buildbot was not working. Checking the logs I found:

2012-01-20 02:30:28+0000 [-] SVNPoller: Error in  while polling
        Traceback (most recent call last):
        Failure: twisted.internet.utils._UnexpectedErrorOutput: got stderr: "svn: REPORT request failed on '/xxx/!svn/bc/25979/packages/yyy/trunk'
svn: REPORT of '/xxx/!svn/bc/25979/packages/yyy/trunk': Could not read chunk size: Secure connection truncated (https://server)
"

And:

2012-01-20 02:32:25+0000 [-] Unhandled error in Deferred:
2012-01-20 02:32:25+0000 [-] Unhandled Error
        Traceback (most recent call last):
        Failure: twisted.internet.error.ProcessTerminated: A process has ended with a probable error condition: process ended with exit code 1.

And another ocurrence for the second SVNPoller (my change_source polls 2 different locations within the same repo).

After the second error the logs were showing only one polling. Before:

2012-01-20 02:26:23+0000 [-] SVNPoller: polling
2012-01-20 02:26:23+0000 [-] SVNPoller: polling
2012-01-20 02:26:25+0000 [-] SVNPoller: no changes
2012-01-20 02:26:25+0000 [-] SVNPoller: _process_changes 25898 .. 25898
2012-01-20 02:26:25+0000 [-] SVNPoller: finished polling None
2012-01-20 02:26:30+0000 [-] SVNPoller: no changes
2012-01-20 02:26:30+0000 [-] SVNPoller: _process_changes 25979 .. 25979
2012-01-20 02:26:30+0000 [-] SVNPoller: finished polling None

After:

2012-01-23 09:44:23+0000 [-] SVNPoller: polling
2012-01-23 09:44:25+0000 [-] SVNPoller: no changes
2012-01-23 09:44:25+0000 [-] SVNPoller: _process_changes 25898 .. 25898
2012-01-23 09:44:25+0000 [-] SVNPoller: finished polling None

Instance details:

• twistd 11.1.0
• buildbot.version: 0.8.5

[dustin]

I may need some more information here.

The first error is expected -- it's reporting a failure -- but I don't see how that would stop the poller from doing its polling thing. The string "Error in while polling" is from

#! python
        d.addErrback(log.err, 'SVNPoller: Error while polling:') # eat errors
        return d

in poll(). That's an unconditional "if an error occurs, log it and resume normal processing of the deferred". So that deferred's next value is a successful None.

Back in base.py, poll() is called in

#! python
        def do_poll():
            d = defer.maybeDeferred(self.poll)
            d.addErrback(log.err, 'while polling for changes')
            return d

which is *another* unconditional catch-all. And while your log snippets are abbreviated, I assume you would have included this output if it existed. That it doesn't makes sense - that deferred was successful. So the LoopingCall? has no reason to stop looping.

Now, the second error, almost two minutes later:

2012-01-20 02:32:25+0000 [-] Unhandled error in Deferred:

That's clearly not related to the *same* failure as two minutes earlier, and in fact it's not obvious that's related to svn at all. Looking at the invocations of getProcessOutput in the poller, all feed their deferreds back into the main poll deferred, which as we've seen is protected against unhandled errors.

I think the next step is to figure out what that second, unhandled error is about, as that will point us to the bug. Can you tell what was around that in the logs? If not, we may need to add some debugging code.

[fgsch]

Unfortunately there was nothing else between those 2 logs, all the information I had is in this report. Let me know what debugging code I need to add should this happen again.

[dustin]

How often does your poller run?

Try this:

master/buildbot/changes/svnpoller.py

@@ -162 +162 @@
 
     def getProcessOutput(self, args):
         # this exists so we can override it during the unit tests
+        log.msg("svnpoller %s GPO %s" % (self.svnurl, args))
         d = utils.getProcessOutput(self.svnbin, args, self.environ)
+        @d.addBoth
+        def report(x):
+            log.msg("svnpoller %s GPO %s -> %s" % (self.svnurl, args, x))
+            return x
         return d
 
     def get_prefix(self):
+        log.msg("svnpoller %s get_prefix" % (self.svnurl,))
         args = ["info", "--xml", "--non-interactive", self.svnurl]
         if self.svnuser:
             args.extend(["--username=%s" % self.svnuser])
@@ -201 +207 @@
         return d
 
     def get_logs(self, _):
+        log.msg("svnpoller %s get_logs" % (self.svnurl,))
         args = []
         args.extend(["log", "--xml", "--verbose", "--non-interactive"])
         if self.svnuser:
@@ -212 +219 @@
         return d
 
     def parse_logs(self, output):
+        log.msg("svnpoller %s parse_logs" % (self.svnurl,))
         # parse the XML output, return a list of <logentry> nodes
         try:
             doc = xml.dom.minidom.parseString(output)
@@ -223 +231 @@
 
 
     def get_new_logentries(self, logentries):
+        log.msg("svnpoller %s get_new_logentries" % (self.svnurl,))
         last_change = old_last_change = self.last_change
 
         # given a list of logentries, calculate new_last_change, and
@@ -275 +284 @@
         return where
 
     def create_changes(self, new_logentries):
+        log.msg("svnpoller %s create_changes" % (self.svnurl,))
         changes = []
 
         for el in new_logentries:
@@ -348 +358 @@
 
     @defer.deferredGenerator
     def submit_changes(self, changes):
+        log.msg("svnpoller %s submit_changes" % (self.svnurl,))
         for chdict in changes:
             wfd = defer.waitForDeferred(self.master.addChange(src='svn',
                                                               **chdict))
@@ -355 +366 @@
             wfd.getResult()
 
     def finished_ok(self, res):
+        log.msg("svnpoller %s finished_ok" % (self.svnurl,))
         if self.cachepath:
             f = open(self.cachepath, "w")
             f.write(str(self.last_change))

[dustin]

debugging.patch

[fgsch]

Currently it runs every minute but I will apply your diff and change it to 5 minutes on Monday.

[dustin]

Any info?

[fgsch]

I checked the logs today and it has not crashed since this report. This can be closed now. I will open a new ticket should it happen again.

[dustin]

Thanks!