ERROR: AssertionError(), apparently on mutable publish during check/repair (current git)

[killyourtv]

Running a deep-check on one of my shares on the I2P grid yielded the following:

'debian/dists/squeeze/main/binary-i386/Release': healthy
'debian/dists/squeeze/main/binary-powerpc': healthy
'debian/dists/squeeze/main/binary-powerpc/Packages': healthy
'debian/dists/squeeze/main/binary-powerpc/Packages.bz2': not healthy
 repair successful
'debian/dists/squeeze/main/binary-powerpc/Packages.gz': healthy
'debian/dists/squeeze/main/binary-powerpc/Release': healthy
'debian/dists/squeeze/main/source': healthy
'debian/dists/squeeze/main/source/Release': healthy
'debian/dists/squeeze/main/source/Sources.gz': not healthy
 repair failed
'debian/pool': healthy
'debian/pool/dists': healthy
'debian/pool/dists/squeeze': healthy
'debian/pool/dists/squeeze/main': healthy
'debian/pool/dists/squeeze/main/binary-amd64': healthy
ERROR: AssertionError()
"[Failure instance: Traceback: <type 'exceptions.AssertionError'>: "
$INSTALL_DIR/src/allmydata/mutable/filenode.py:563:upload
$INSTALL_DIR/src/allmydata/mutable/filenode.py:661:_do_serialized
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:298:addCallback
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:287:addCallbacks
--- <exception caught here> ---
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:545:_runCallbacks
$INSTALL_DIR/src/allmydata/mutable/filenode.py:661:<lambda>
$INSTALL_DIR/src/allmydata/mutable/filenode.py:689:_upload
$INSTALL_DIR/src/allmydata/mutable/publish.py:404:publish

In twistd.log, (I don't know if it's related, I was AFK), I see

2012-02-14 08:53:30+0000 [-] Unhandled error in Deferred:
2012-02-14 08:53:30+0000 [-] Unhandled Error
	Traceback (most recent call last):
	  File "/usr/lib/python2.7/dist-packages/twisted/internet/base.py", line 800, in runUntilCurrent
	    call.func(*call.args, **call.kw)
	  File "/usr/lib/pymodules/python2.7/foolscap/eventual.py", line 26, in _turn
	    cb(*args, **kwargs)
	  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 362, in callback
	    self._startRunCallbacks(result)
	  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 458, in _startRunCallbacks
	    self._runCallbacks()
	--- <exception caught here> ---
	  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 545, in _runCallbacks
	    current.result = callback(current.result, *args, **kw)
	  File "/usr/lib/python2.7/dist-packages/nevow/appserver.py", line 181, in _cbFinishRender
	    self.finishRequest(  True )
	  File "/usr/lib/python2.7/dist-packages/nevow/appserver.py", line 176, in finishRequest
	    server.Request.finish(self)
	  File "/usr/lib/python2.7/dist-packages/twisted/web/http.py", line 866, in finish
	    "Request.finish called on a request after its connection was lost; "
	exceptions.RuntimeError: Request.finish called on a request after its connection was lost; use Request.notifyFinish to keep track of this.

[killyourtv]

active operations

[killyourtv]

As mentioned in previous tickets, tasks remain in the Active Operations section long after failures occur, such as

The top two jobs failed around 12 hours earlier. The bottom one is the AssertionError? that I've reported in this ticket.

[killyourtv]

Update: For what it's worth, with the current git revision the deep-check consistently fails at the same point.

$ tahoe deep-check -v --repair --add-lease tahoe:debian/pool/dists/squeeze
'<root>': healthy
'main': healthy
'main/binary-amd64': healthy
ERROR: AssertionError()
"[Failure instance: Traceback: <type 'exceptions.AssertionError'>: "
$INSTALL_DIR/src/allmydata/mutable/filenode.py:563:upload
$INSTALL_DIR/src/allmydata/mutable/filenode.py:661:_do_serialized
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:298:addCallback
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:287:addCallbacks
--- <exception caught here> ---
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:545:_runCallbacks
$INSTALL_DIR/src/allmydata/mutable/filenode.py:661:<lambda>
$INSTALL_DIR/src/allmydata/mutable/filenode.py:689:_upload
$INSTALL_DIR/src/allmydata/mutable/publish.py:404:publish

Reverting back to 1.8.3:

$ tahoe deep-check -v --repair --add-lease tahoe:debian/dists/squeeze
'<root>': healthy
'Contents-amd64': healthy
'Contents-amd64.bz2': healthy
'Contents-amd64.gz': healthy
'Contents-armel': healthy
'Contents-armel.bz2': healthy
'Contents-armel.gz': healthy
'Contents-i386': healthy
'Contents-i386.bz2': healthy
'Contents-i386.gz': healthy
'Contents-powerpc': healthy
'Contents-powerpc.bz2': healthy
'Contents-powerpc.gz': healthy
'InRelease': healthy
'Release': healthy
'Release.gpg': healthy
'main': healthy
'main/binary-amd64': healthy
'main/binary-amd64/Packages': healthy
'main/binary-amd64/Packages.bz2': healthy
'main/binary-amd64/Packages.gz': healthy
'main/binary-amd64/Release': healthy
'main/binary-armel': healthy
'main/binary-armel/Packages': healthy
'main/binary-armel/Packages.bz2': healthy
'main/binary-armel/Packages.gz': healthy
'main/binary-armel/Release': healthy
'main/binary-i386': healthy
'main/binary-i386/Packages': healthy
'main/binary-i386/Packages.bz2': healthy
'main/binary-i386/Packages.gz': healthy
'main/binary-i386/Release': healthy
'main/binary-powerpc': healthy
'main/binary-powerpc/Packages': not healthy
 repair successful
'main/binary-powerpc/Packages.bz2': healthy
'main/binary-powerpc/Packages.gz': healthy
'main/binary-powerpc/Release': healthy
'main/source': healthy
'main/source/Release': healthy
'main/source/Sources.gz': healthy
done: 40 objects checked
 pre-repair: 39 healthy, 1 unhealthy
 1 repairs attempted, 1 successful, 0 failed
 post-repair: 40 healthy, 0 unhealthy

[kevan]

If it's convenient, could you attach an incident report corresponding to this bug? I think I know what's causing this -- the Retrieve object doesn't keep track of whether it has successfully fetched, validated, and stored the private key when asked to do so -- but having logs would help to confirm that.

[zooko]

This is a regression in 1.8→1.9, isn't it? I propose we put it into the "1.9.2" Milestone.

[warner]

hey, is this maybe a dupe of #1689?

[davidsarah]

Replying to warner:

hey, is this maybe a dupe of #1689?

The traceback is the same, so probably.

killyourtv, can you reproduce this with trunk?

[killyourtv]

Sorry for the delayed response.

Trying with trunk and the patchset from #68 applied (assuming I refactored it properly) yielded the following

'debian/dists/lenny/main/binary-i386/Packages.gz': healthy
'debian/dists/lenny/main/binary-i386/Release': healthy
'debian/dists/lenny/main/source': not healthy
 repair successful
'debian/dists/lenny/main/source/Release': healthy
'debian/dists/lenny/main/source/Sources.gz': healthy
"ERROR: AttributeError('NoneType' object has no attribute 'callRemote')"
"[Failure instance: Traceback: <type 'exceptions.AttributeError'>: 'NoneType' object has no attribute 'callRemote'"
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:545:_runCallbacks
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:796:_cbDeferred
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:362:callback
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:458:_startRunCallbacks
--- <exception caught here> ---
/usr/lib/python2.7/dist-packages/twisted/internet/defer.py:545:_runCallbacks
$SRC/src/allmydata/mutable/servermap.py:1178:_check_for_done
$SRC/src/allmydata/mutable/servermap.py:1206:_send_more_queries
$SRC/src/allmydata/mutable/servermap.py:580:_do_query
$SRC/src/allmydata/mutable/servermap.py:601:_do_read

I'm currently trying again with just #1007 and #1010 applied.

[killyourtv]

I re-refactored the patch from #68 (I think I made a mistake when I did it the first time earlier tonight).

The repair process on my rather large share has been going for a bit over an hour now. It's certainly going farther than it has at any other point with 1.9.x.

I'll post another update once it completes but so far it's looking very good!

[killyourtv]

Several hours later

done: 664 objects checked
 pre-repair: 587 healthy, 77 unhealthy
 77 repairs attempted, 77 successful, 0 failed
 post-repair: 664 healthy, 0 unhealthy

So far, so good. I'll stay on trunk to test a bit more.

[killyourtv]

I think this problem has been resolved. I'll close this ticket. Thanks, all!