Implement compatibility for read-only log methods in old-style steps

Including
 * log.getText, log.readlines, etc.
 * step.getLog returns an instance with those methods in old-style
   steps

master/buildbot/process/buildstep.py

@@ -13,6 +13,12 @@
 #
 # Copyright Buildbot Team Members
 
+try:
+    import cStringIO as StringIO
+    assert StringIO
+except ImportError:
+    import StringIO
+
 from twisted.internet import defer
 from twisted.internet import error
 from twisted.python import components
@@ -32,6 +38,9 @@
 from buildbot.process import properties
 from buildbot.process import remotecommand
 from buildbot.status import progress
+from buildbot.status.logfile import HEADER
+from buildbot.status.logfile import STDERR
+from buildbot.status.logfile import STDOUT
 from buildbot.status.results import CANCELLED
 from buildbot.status.results import EXCEPTION
 from buildbot.status.results import FAILURE
@@ -96,18 +105,22 @@ def wrap(self, *args, **kwargs):
     return wrap
 
 
-class SyncWriteOnlyLogFileWrapper(object):
+class SyncLogFileWrapper(logobserver.LogObserver):
 
     # A temporary wrapper around process.log.Log to emulate *synchronous*
     # writes to the logfile by handling the Deferred from each add* operation
     # as part of the step's _start_unhandled_deferreds.  This has to handle
     # the tricky case of adding data to a log *before* addLog has returned!
+    # this also adds the read-only methods such as getText
 
     def __init__(self, step, name, addLogDeferred):
         self.step = step
         self.name = name
         self.delayedOperations = []
         self.asyncLogfile = None
+        self.chunks = []
+        self.finished = False
+        self.finishDeferreds = []
 
         @addLogDeferred.addCallback
         def gotAsync(log):
@@ -143,27 +156,67 @@ def _delay(self, op):
         if len(self.delayedOperations) == 1:
             self._catchup()
 
-    def getName(self):
-        # useLog uses this
-        return self.name
+    def _maybeFinished(self):
+        if self.finished and self.finishDeferreds:
+            pending = self.finishDeferreds
+            self.finishDeferreds = []
+            for d in pending:
+                d.callback(self)
+
+    # write methods
 
     def addStdout(self, data):
+        self.chunks.append((STDOUT, data))
         self._delay(lambda: self.asyncLogfile.addStdout(data))
 
     def addStderr(self, data):
+        self.chunks.append((STDERR, data))
         self._delay(lambda: self.asyncLogfile.addStderr(data))
 
     def addHeader(self, data):
+        self.chunks.append((HEADER, data))
         self._delay(lambda: self.asyncLogfile.addHeader(data))
 
     def finish(self):
+        self.finished = True
+        self._maybeFinished()
         self._delay(lambda: self.asyncLogfile.finish())
 
     def unwrap(self):
         d = defer.Deferred()
         self._delay(lambda: d.callback(self.asyncLogfile))
         return d
 
+    # read-only methods
+
+    def getName(self):
+        return self.name
+
+    def getText(self):
+        return "".join(self.getChunks([STDOUT, STDERR], onlyText=True))
+
+    def readlines(self):
+        alltext = "".join(self.getChunks([STDOUT], onlyText=True))
+        io = StringIO.StringIO(alltext)
+        return io.readlines()
+
+    def getChunks(self, channels=[], onlyText=False):
+        chunks = self.chunks
+        if channels:
+            channels = set(channels)
+            chunks = ((c, t) for (c, t) in chunks if c in channels)
+        if onlyText:
+            chunks = (t for (c, t) in chunks)
+        return chunks
+
+    def isFinished(self):
+        return self.finished
+
+    def waitUntilFinished(self):
+        d = defer.Deferred()
+        self.finishDefereds.append(d)
+        self._maybeFinished()
+
 
 class BuildStep(object, properties.PropertiesMixin):
 
@@ -455,18 +508,30 @@ def run(self):
         self._start_deferred = defer.Deferred()
         unhandled = self._start_unhandled_deferreds = []
         try:
+            # here's where we set things up for backward compatibility for
+            # old-style tests, using monkey patches so that new-style tests
+            # aren't bothered by any of this equipment
+
             # monkey-patch self.step_status.{setText,setText2} back into
             # existence for old steps; when these write to the data API,
             # the monkey patches will stash their deferreds on the unhandled
             # list
             self.step_status.setText = self.step_status.old_setText
             self.step_status.setText2 = self.step_status.old_setText2
 
-            # and monkey-patch in support for old statistics functions
+            # monkey-patch in support for old statistics functions
             self.step_status.setStatistic = self.setStatistic
             self.step_status.getStatistic = self.getStatistic
             self.step_status.hasStatistic = self.hasStatistic
 
+            # monkey-patch an addLog that returns an write-only, sync log
+            self.addLog = self.addLog_oldStyle
+            self._logFileWrappers = {}
+
+            # and a getLog that returns a read-only, sync log, captured by
+            # LogObservers installed by addLog_oldStyle
+            self.getLog = self.getLog_oldStyle
+
             results = yield self.start()
             if results == SKIPPED:
                 yield self.setStateStrings(self.describe(True) + ['skipped'])
@@ -541,28 +606,32 @@ def getSlaveName(self):
         return self.build.getSlaveName()
 
     def addLog(self, name, type='s', logEncoding=None):
-        @defer.inlineCallbacks
-        def _addLog():
-            logid = yield self.master.data.updates.newLog(self.stepid,
-                                                          util.ascii2unicode(name), unicode(type))
-            defer.returnValue(self._newLog(name, type, logid, logEncoding))
-
-        # This method implements a smooth transition for nine
-        # it returns a synchronous version of logfile, so that steps can safely
-        # start writting into logfile, without waiting for log creation in db
-        loog_d = _addLog()
-        if self._start_unhandled_deferreds is None:
-            # This is a new-style step, so we can return the deferred
-            return loog_d
+        d = self.master.data.updates.newLog(self.stepid,
+                                            util.ascii2unicode(name),
+                                            unicode(type))
 
+        @d.addCallback
+        def newLog(logid):
+            return self._newLog(name, type, logid, logEncoding)
+        return d
+    addLog_newStyle = addLog
+
+    def addLog_oldStyle(self, name, type='s', logEncoding=None):
+        # create a logfile instance that acts like old-style status logfiles
+        # begin to create a new-style logfile
+        loog_d = self.addLog_newStyle(name, type, logEncoding)
         self._start_unhandled_deferreds.append(loog_d)
-        return SyncWriteOnlyLogFileWrapper(self, name, loog_d)
+        # and wrap the deferred that will eventually fire with that logfile
+        # into a write-only logfile instance
+        wrapper = SyncLogFileWrapper(self, name, loog_d)
+        self._logFileWrappers[name] = wrapper
+        return wrapper
 
     def getLog(self, name):
-        for l in self.step_status.getLogs():
-            if l.getName() == name:
-                return l
-        raise KeyError("no log named '%s'" % (name,))
+        return self.logs[name]
+
+    def getLog_oldStyle(self, name):
+        return self._logFileWrappers[name]
 
     @_maybeUnhandled
     @defer.inlineCallbacks
@@ -710,6 +779,8 @@ def startCommand(self, cmd, errorMessages=[]):
 
         def _gotResults(results):
             self.setStatus(cmd, results)
+            # finish off the stdio logfile
+            stdio_log.finish()
             return results
         d.addCallback(_gotResults)  # returns results
         d.addCallbacks(self.finished, self.checkDisconnect)

master/buildbot/test/fake/logfile.py

@@ -39,6 +39,7 @@ def getName(self):
         return self.name
 
     def subscribe(self, callback):
+        log.msg("NOTE: fake logfile subscription never produces anything")
         return self.subPoint.subscribe(callback)
 
     def _getLbf(self, stream, meth):
@@ -59,16 +60,19 @@ def addHeader(self, text):
         self.header += text
         self.chunks.append((HEADER, text))
         self._getLbf('h', 'headerReceived').append(text)
+        return defer.succeed(None)
 
     def addStdout(self, text):
         self.stdout += text
         self.chunks.append((STDOUT, text))
         self._getLbf('o', 'outReceived').append(text)
+        return defer.succeed(None)
 
     def addStderr(self, text):
         self.stderr += text
         self.chunks.append((STDERR, text))
         self._getLbf('e', 'errReceived').append(text)
+        return defer.succeed(None)
 
     def isFinished(self):
         return self.finished

master/buildbot/test/fake/remotecommand.py

@@ -182,8 +182,11 @@ def runBehavior(self, behavior, args, command):
         """
         if behavior == 'rc':
             command.rc = args[0]
-            for l in command.logs.values():
-                l.flushFakeLogfile()
+            d = defer.succeed(None)
+            for wrapper in command.logs.values():
+                d.addCallback(lambda _: wrapper.unwrap())
+                d.addCallback(lambda l: l.flushFakeLogfile())
+            return d
         elif behavior == 'err':
             return defer.fail(args[0])
         elif behavior == 'update':

master/buildbot/test/integration/test_custom_buildstep.py

@@ -15,6 +15,8 @@
 
 import mock
 
+from StringIO import StringIO
+
 from buildbot import config
 from buildbot.buildslave.base import BuildSlave
 from buildbot.process import builder
@@ -23,6 +25,7 @@
 from buildbot.process import factory
 from buildbot.process import slavebuilder
 from buildbot.status import results
+from buildbot.steps import shell
 from buildbot.test.fake import fakemaster
 from buildbot.test.fake import fakeprotocol
 from twisted.internet import defer
@@ -107,6 +110,44 @@ def start(self):
         raise self.exception()
 
 
+class OldBuildEPYDoc(shell.ShellCommand):
+
+    command = ['epydoc']
+
+    def runCommand(self, cmd):
+        # we don't have a real buildslave in this test harness, so fake it
+        l = cmd.logs['stdio']
+        l.addStdout('some\noutput\n')
+        return defer.succeed(None)
+
+    def createSummary(self, log):
+        for line in StringIO(log.getText()):
+            # what we do with the line isn't important to the test
+            assert line in ('some\n', 'output\n')
+
+
+class OldPerlModuleTest(shell.Test):
+
+    command = ['perl']
+
+    def runCommand(self, cmd):
+        # we don't have a real buildslave in this test harness, so fake it
+        l = cmd.logs['stdio']
+        l.addStdout('a\nb\nc\n')
+        return defer.succeed(None)
+
+    def evaluateCommand(self, cmd):
+        # Get stdio, stripping pesky newlines etc.
+        lines = map(
+            lambda line: line.replace('\r\n', '').replace('\r', '').replace('\n', ''),
+            self.getLog('stdio').readlines()
+        )
+        # .. the rest of this method isn't htat interesting, as long as the
+        # statement above worked
+        assert lines == ['a', 'b', 'c']
+        return results.SUCCESS
+
+
 class RunSteps(unittest.TestCase):
 
     @defer.inlineCallbacks
@@ -200,7 +241,6 @@ def test_OldStyleCustomBuildStep_failure(self):
     def test_step_raising_buildstepfailed_in_start(self):
         self.factory.addStep(FailingCustomStep())
         bs = yield self.do_test_step()
-        # , status_text=["generic"])
         self.assertEqual(bs.getResults(), results.FAILURE)
 
     @defer.inlineCallbacks
@@ -218,3 +258,17 @@ def test_Latin1ProducingCustomBuildStep(self):
         self.assertLogs({
             u'xx': u'o\N{CENT SIGN}\n',
         })
+
+    @defer.inlineCallbacks
+    def test_OldBuildEPYDoc(self):
+        # test old-style calls to log.getText, figuring readlines will be ok
+        self.factory.addStep(OldBuildEPYDoc())
+        bs = yield self.do_test_step()
+        self.assertEqual(bs.getResults(), results.FAILURE)
+
+    @defer.inlineCallbacks
+    def test_OldPerlModuleTest(self):
+        # test old-style calls to self.getLog
+        self.factory.addStep(OldPerlModuleTest())
+        bs = yield self.do_test_step()
+        self.assertEqual(bs.getResults(), results.SUCCESS)

master/buildbot/test/unit/test_process_buildstep.py

@@ -269,6 +269,24 @@ def test_describe_suffix(self):
         self.assertEqual(step2.describe(done=True),
                          [step2.name] + descriptionSuffix)
 
+    @defer.inlineCallbacks
+    def test_step_getLog(self):
+        testcase = self
+
+        class TestGetLogStep(buildstep.BuildStep):
+
+            @defer.inlineCallbacks
+            def run(self):
+                testcase.assertRaises(KeyError, lambda:
+                                      self.getLog('testy'))
+                log1 = yield self.addLog('testy')
+                log2 = self.getLog('testy')
+                testcase.assertIdentical(log1, log2)
+                defer.returnValue(SUCCESS)
+        self.setupStep(TestGetLogStep())
+        self.expectOutcome(result=SUCCESS, status_text=["generic"])
+        yield self.runStep()
+
     @defer.inlineCallbacks
     def test_step_renders_flunkOnFailure(self):
         self.setupStep(

master/buildbot/test/util/steps.py

@@ -141,10 +141,11 @@ def ss_setText2(strings):
         def addLog(name, type='s', logEncoding=None):
             assert type == 's', "type must be 's' until Data API backend is in place"
             l = logfile.FakeLogFile(name, step)
+            self.step.logs[name] = l
             ss.logs[name] = l
-            return l
-
+            return defer.succeed(l)
         step.addLog = addLog
+        step.addLog_newStyle = addLog
 
         def addHTMLLog(name, html):
             l = logfile.FakeLogFile(name, step)

master/docs/developer/cls-buildsteps.rst

@@ -349,6 +349,15 @@ BuildStep
 
         Add a new logfile with the given name to the step, and return the log file instance.
 
+    .. py:method:: getLog(name)
+
+        :param name: log name
+        :raises KeyError: if there is no such log
+        :returns: :class:`~buildbot.process.log.Log` instance
+
+        Return an existing logfile, previously added with :py:meth:`addLog`.
+        Note that this return value is synchronous, and only available after :py:meth:`addLog`'s deferred has fired.
+
     .. py:method:: addCompleteLog(name, text)
 
         :param name: log name