Opened 5 years ago

Closed 5 years ago

#2951 closed defect (fixed)

AttributeError: 'NoneType' object has no attribute 'append'

Reported by: Ben Owned by: tardyp
Priority: critical Milestone: 0.9.0
Version: master Keywords:
Cc:

Description (last modified by dustin)

Using nine, my logs is full of it ... (multiple time for each per step). I can provide more information, just don;t know where to start ....

2014-10-20 13:29:55+0200 [-] Unhandled error in Deferred:
2014-10-20 13:29:55+0200 [-] Unhandled Error
        Traceback (most recent call last):
          File "/home/benoit/buildbot/buildbot/master/buildbot/process/buildstep.py", line 158, in next
            self._catchup()
          File "/home/benoit/buildbot/buildbot/master/buildbot/process/buildstep.py", line 156, in _catchup
            @d.addBoth
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 329, in addBoth
            callbackKeywords=kw, errbackKeywords=kw)
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/home/benoit/buildbot/buildbot/master/buildbot/process/buildstep.py", line 158, in next
            self._catchup()
          File "/home/benoit/buildbot/buildbot/master/buildbot/process/buildstep.py", line 160, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

2014-10-20 13:29:55+0200 [-] from an asynchronous method executed in an old-style step
        Traceback (most recent call last):
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1155, in gotResult
            _inlineCallbacks(r, g, deferred)
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1142, in _inlineCallbacks
            deferred.callback(e.value)
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
            self._startRunCallbacks(result)
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/home/benoit/buildbot/openvas/venv/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/home/benoit/buildbot/buildbot/master/buildbot/process/buildstep.py", line 136, in gotAsync
            self._catchup()
          File "/home/benoit/buildbot/buildbot/master/buildbot/process/buildstep.py", line 160, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

Change History (11)

comment:1 Changed 5 years ago by dustin

  • Description modified (diff)

comment:2 Changed 5 years ago by dustin

It looks like some newly-asynchronous method is being called *after* the run method finishes. run has:

    @defer.inlineCallbacks
    def run(self):
        self._start_deferred = defer.Deferred()
        unhandled = self._start_unhandled_deferreds = []
        try:
            ..
        finally:
            self._start_deferred = None
            unhandled = self._start_unhandled_deferreds
            self._start_unhandled_deferreds = None

The issue is that both addLog and log.addStdout are now asynchronous, so a call to log.addStdout needs to wait until addLog's deferred fires, and *then* queue up a call to its addStdout method. If addLog's deferred doesn't fire until after the "finally" block above runs, then _catchup has nowhere to put the deferred returned by addStdout.

So probably the better approach is to iteratively wait for Deferreds in _start_unhandled_deferreds until the list is empty.

comment:3 Changed 5 years ago by Ben

  • Owner set to dustin
  • Status changed from new to assigned

The point is, after that finally, in case unhandled is not empty, the result of the step switch to purple (EXCEPTION). All my steps that have no stdout (only stderr, still trying to configure my slave ...), have a purple status, and are probably the ones that spit out those errors. As soon as the step is generating some stdout, the status is red (ERROR), as expected.

All in all, the error is probably that addStdout is not being called once.

comment:4 Changed 5 years ago by Ben

  • Priority changed from major to critical
  • Version changed from 0.8.9 to master

Raising the priority as this is in the moment the issue preventing me from showcasing buildbot around there (unexplainable build status).

comment:5 Changed 5 years ago by tardyp

  • Owner changed from dustin to tardyp

I can look at it. Do you confirm that the simplest way of reproducing is just a step that does not output

ShellCommand?("sleep 1")

is currently finishing as exception, right?

comment:6 Changed 5 years ago by Ben

Not exactly ... I have to confess that I have hard time finding a minimal setup for it ...

I got it once with that:

c['builders'].append(util.BuilderConfig(name="bug2951", slavename="example-slave", factory=util.BuildFactory(
    [steps.ShellCommand(command='echo a; echo b 1>&2; exit 1') ] * 5 +
    [steps.ShellCommand(command=['echo', 'a'])] +
    [steps.ShellCommand(command='echo a; echo b 1>&2; exit 1') ] * 5
)))
c['schedulers'].append(schedulers.ForceScheduler(name="bug2951", builderNames=['bug2951']))

Once exactly ...

Here is the Traceback:

2014-10-26 17:08:39+0100 [-] closing log <buildbot.process.buildstep.SyncLogFileWrapper object at 0x102daa890>
2014-10-26 17:08:39+0100 [-] releaseLocks(<buildbot.steps.shell.ShellCommand object at 0x102db2e90>): []
2014-10-26 17:08:39+0100 [-]  step 'shell_3' complete: failure
2014-10-26 17:08:39+0100 [-] ShellCommand.startCommand(cmd=<RemoteShellCommand ''echo a; echo b 1>&2; exit 1''>)
2014-10-26 17:08:39+0100 [-]   cmd.args = {'workdir': 'build', 'env': None, 'want_stderr': 1, 'logEnviron': True, 'sigtermTime': None, 'logfiles': {}, 'timeout': 1200, 'want_stdout': 1, 'usePTY': 'slave-config', 'maxTime': None, 'initial_stdin': None}
2014-10-26 17:08:39+0100 [-] <RemoteShellCommand ''echo a; echo b 1>&2; exit 1''>: RemoteCommand.run [4]
2014-10-26 17:08:39+0100 [-] command 'echo a; echo b 1>&2; exit 1' in dir 'build'
2014-10-26 17:08:39+0100 [Broker,0,127.0.0.1] <RemoteShellCommand ''echo a; echo b 1>&2; exit 1''> rc=1
2014-10-26 17:08:39+0100 [-] closing log <buildbot.process.buildstep.SyncLogFileWrapper object at 0x102d9cbd0>
2014-10-26 17:08:39+0100 [-] Unhandled error in Deferred:
2014-10-26 17:08:39+0100 [-] Unhandled Error
        Traceback (most recent call last):
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 155, in _catchup
            @d.addBoth
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 329, in addBoth
            callbackKeywords=kw, errbackKeywords=kw)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

2014-10-26 17:08:39+0100 [-] Unhandled error in Deferred:
2014-10-26 17:08:39+0100 [-] Unhandled Error
        Traceback (most recent call last):
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 155, in _catchup
            @d.addBoth
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 329, in addBoth
            callbackKeywords=kw, errbackKeywords=kw)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

2014-10-26 17:08:39+0100 [-] Unhandled error in Deferred:
2014-10-26 17:08:39+0100 [-] Unhandled Error
        Traceback (most recent call last):
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 155, in _catchup
            @d.addBoth
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 329, in addBoth
            callbackKeywords=kw, errbackKeywords=kw)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

2014-10-26 17:08:39+0100 [-] Unhandled error in Deferred:
2014-10-26 17:08:39+0100 [-] Unhandled Error
        Traceback (most recent call last):
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 155, in _catchup
            @d.addBoth
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 329, in addBoth
            callbackKeywords=kw, errbackKeywords=kw)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

2014-10-26 17:08:39+0100 [-] from an asynchronous method executed in an old-style step
        Traceback (most recent call last):
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 1155, in gotResult
            _inlineCallbacks(r, g, deferred)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 1142, in _inlineCallbacks
            deferred.callback(e.value)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 382, in callback
            self._startRunCallbacks(result)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 490, in _startRunCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 135, in gotAsync
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

2014-10-26 17:08:39+0100 [-] releaseLocks(<buildbot.steps.shell.ShellCommand object at 0x102db2550>): []
2014-10-26 17:08:39+0100 [-]  step 'shell_4' complete: exception
2014-10-26 17:08:39+0100 [-]  <Build bug2951>: build finished
2014-10-26 17:08:39+0100 [-] Unhandled error in Deferred:
2014-10-26 17:08:39+0100 [-] Unhandled Error
        Traceback (most recent call last):
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 135, in gotAsync
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 155, in _catchup            @d.addBoth
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 329, in addBoth
            callbackKeywords=kw, errbackKeywords=kw)
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 295, in addCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "/Users/benoit/Python/buildbotEnv/lib/python2.7/site-packages/twisted/internet/defer.py", line 577, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 157, in next
            self._catchup()
          File "/Users/benoit/Python/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup
            self.step._start_unhandled_deferreds.append(d)
        exceptions.AttributeError: 'NoneType' object has no attribute 'append'

2014-10-26 17:08:39+0100 [-] releaseLocks(<BuildSlave u'example-slave'>): []
2014-10-26 17:08:39+0100 [-] tried to complete 1 buildreqests, but only completed 0

comment:7 Changed 5 years ago by tardyp

I wasn't able to reproduce, but given the tracebacks, I think this PR should be able to circumvent the problem.

https://github.com/buildbot/buildbot/pull/1296

The idea of dustin is probably also working, but I think it is a little bit more complicated

comment:8 Changed 5 years ago by Pierre Tardy <pierre.tardy@…>

In 4721f5468705e2f303215c12fd46adf8a4b54240:

integration test for trac #2951

add a test for the case which the db is too slow to complete the newLog before end of the step

if I revert previous commit, I get the error reported by benallard

===============================================================================
[ERROR]
Traceback (most recent call last):

File "/Users/ptardy/dev/bb/buildbot-heroku/buildbot/master/buildbot/process/buildstep.py", line 157, in next

self._catchup()

File "/Users/ptardy/dev/bb/buildbot-heroku/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup

self.step._start_unhandled_deferreds.append(d)

exceptions.AttributeError?: 'NoneType?' object has no attribute 'append'

buildbot.test.integration.test_custom_buildstep.RunSteps?.test_OldStyleCustomBuildStepSlowDB
buildbot.test.integration.test_custom_buildstep.RunSteps?.test_OldStyleCustomBuildStepSlowDB
===============================================================================
[ERROR]
Traceback (most recent call last):

File "/Users/ptardy/dev/bb/buildbot-heroku/buildbot/master/buildbot/process/buildstep.py", line 135, in gotAsync

self._catchup()

File "/Users/ptardy/dev/bb/buildbot-heroku/buildbot/master/buildbot/process/buildstep.py", line 159, in _catchup

self.step._start_unhandled_deferreds.append(d)

exceptions.AttributeError?: 'NoneType?' object has no attribute 'append'

buildbot.test.integration.test_custom_buildstep.RunSteps?.test_OldStyleCustomBuildStepSlowDB

Signed-off-by: Pierre Tardy <pierre.tardy@…>

comment:9 Changed 5 years ago by Mikhail Sobolev <mss@…>

In dae7c83eace772aa9d04b0fd6dd52b7879caecb6:

Merge pull request #1296 from tardyp/t2951

fix for ticket:2951: wait for the logs are created before finishing the step

comment:10 Changed 5 years ago by sa2ajj

(I wish GitHub had a better view on commit logs)

Closed by the above mentioned PR.

comment:11 Changed 5 years ago by Ben

  • Resolution set to fixed
  • Status changed from assigned to closed

I'm closing this one as it seems to have been fixed.

Note: See TracTickets for help on using tickets.