handle MemoryError by failing quickly and loudly

[zooko]

When I tried to update my klog -- ​http://testgrid.allmydata.org:3567/uri/URI:DIR2-RO:j74uhg25nwdpjpacl6rkat2yhm:kav7ijeft5h7r7rxdp5bgtlt3viv32yabqajkrdykozia5544jqa/wiki.html # (testgrid) -- a couple of days ago I got an UncoordinatedWriteError. I also got an UncoordinatedWriteError when I tried to make a new unlinked directory on the test grid. The incident report from one of those is attached as 'incident-2009-02-27-215731-aj5o5ti.flog.bz2' . It contains the following lines:

# 21:57:32.317 [14105]: WEIRD our testv failed, so the write did not happen
# 21:57:32.317 [14106]: somebody modified the share on us: shnum=0: I thought they had #1:R=7ahx, but testv reported #1:R=7ahx

This reminds me of an issue that I thought we had fixed before the 1.3.0 release -- #546 (mutable-file surprise shares raise inappropriate UCWE).

At the time I did a check on my klog and saw that most of its shared were on a single storage server:

<zooko> check reports all good                                          [18:33] 
<zooko> 8 shares 
<zooko> 3 hosts with shares 
<zooko> 6 of those 8 are on bs3c1 
<zooko> recoverable versions 1 
<zooko> unrecoverable versions 0 
<zooko> Scary to realize that my klog is reliant upon the continued life of a 
        single node. 
<zooko> :-( 

This morning I tried again to update my klog, and this time I got a KeyError (full HTML output attached as "KeyError.html"). Doing a check now shows:

# Report:

Unrecoverable Versions: 2*seq20-qb3p
Unhealthy: some versions are unrecoverable
Unhealthy: no versions are recoverable

# Share Counts: need 3-of-10, have 2
# Hosts with good shares: 2
# Corrupt shares: none
# Wrong Shares: 0
# Good Shares (sorted in share order):
seq20-qb3p-sh2	2y7ldksggg447xnf4zwsjccx7ihs6wfm (amduser@tahoebs3:public/bs3c4)
seq20-qb3p-sh6	6fyx5u4zr7tvz3szynihc4x3uc6ct5gh (amduser@tahoebs1:public/client2)
# Recoverable Versions: 0
# Unrecoverable Versions: 1
# Share Balancing (servers in permuted order):
u5vgfpug7qhkxdtj76tcfh6bmzyo6w5s (amduser@tahoebs3:public/bs3c2)	
u5vgfpug7qhkxdtj76tcfh6bmzyo6w5s (amduser@tahoebs3:public/bs3c2)	
u5vgfpug7qhkxdtj76tcfh6bmzyo6w5s (amduser@tahoebs3:public/bs3c2)	
jfdpabh34vsrhll3lbdn3v23vem4hr2z (amduser@tahoebs4:public/bs4c2)	
jfdpabh34vsrhll3lbdn3v23vem4hr2z (amduser@tahoebs4:public/bs4c2)	
jfdpabh34vsrhll3lbdn3v23vem4hr2z (amduser@tahoebs4:public/bs4c2)	
2y7ldksggg447xnf4zwsjccx7ihs6wfm (amduser@tahoebs3:public/bs3c4)	seq20-qb3p-sh2
2y7ldksggg447xnf4zwsjccx7ihs6wfm (amduser@tahoebs3:public/bs3c4)	seq20-qb3p-sh2 

I just now verified that bs3c1 is connected to my client:

PeerID  	Nickname  	Connected?  	Since  	Announced  	Version  	Service Name
amduser@tahoebs3:public/bs3c1 	Yes: to 207.7.153.161:48663 	13:08:38 02-Mar-2009 	11:17:09 26-Feb-2009 	allmydata-tahoe/1.3.0 	storage

Then tried to load the write-cap to my klog again, got KeyError again, then did a check and got the same check results as above, then confirmed that bs3c1 is still connected.

So, what's going on? Is bs3c1 failing to respond to my client's requests, or has it somehow deleted the shares of my klog that it held a couple of days ago?

Oh! I see that I *can* access the read-only view of my klog through ​http://testgrid.allmydata.org:3567 even though I can't access the exact same URL with my local tahoe node. So either there is a networking problem, or there is a problem with the version of tahoe that I'm running here (allmydata-tahoe: 1.3.0-r3698, foolscap: 0.3.2, pycryptopp: 0.5.12, zfec: 1.4.4, Twisted: 8.2.0) but not the version running on testgrid (allmydata-tahoe: 1.3.0, foolscap: 0.3.2, pycryptopp: 0.5.2-1, zfec: 1.4.0-4, Twisted: 2.5.0).

Here's the result of a check (and verify) on the read-only view of the directory through testgrid.allmydata.org:

# Report:

Recoverable Versions: 8*seq1128-fgyi/3*seq1122-37fb/8*seq1129-6veq
Unhealthy: there are multiple recoverable versions
Best Recoverable Version: seq1129-6veq
Unhealthy: best version has only 8 shares (encoding is 3-of-10)

# Share Counts: need 3-of-10, have 8
# Hosts with good shares: 3
# Corrupt shares: none
# Wrong Shares: 11
# Good Shares (sorted in share order):
seq1122-37fb-sh3	xiktf6ok5f5ao5znxxttriv233hmvi4v (amduser@tahoebs4:public/bs4c3)
seq1122-37fb-sh8	lwkv6cjicbzqjwwwuifik3pogeupsicb (amduser@tahoebs4:public/bs4c4)
seq1122-37fb-sh9	6fyx5u4zr7tvz3szynihc4x3uc6ct5gh (amduser@tahoebs1:public/client2)
seq1128-fgyi-sh0	ckpjhpffmbmpv5rxc7uzrcdlu2ad6slj (amduser@tahoebs3:public/bs3c3)
	2y7ldksggg447xnf4zwsjccx7ihs6wfm (amduser@tahoebs3:public/bs3c4)
seq1128-fgyi-sh1	fcmlx6emlydpmgsksztuvtpxf5gdoamr (amduser@tahoebs4:public/bs4c1)
seq1128-fgyi-sh2	jfdpabh34vsrhll3lbdn3v23vem4hr2z (amduser@tahoebs4:public/bs4c2)
	trjdor3okozw4eld3l6zl4ap4z6h5tk6 (amduser@tahoebs5:public/bs5c4)
seq1128-fgyi-sh4	uf7kq2svc6ozcawfm63e2qrbik2oixvt (amduser@tahoebs5:public/bs5c1)
seq1128-fgyi-sh5	wfninubkrvhlyscum7rlschbhx5iarg3 (amduser@tahoebs1:public/client1)
seq1128-fgyi-sh7	iktgow2qpu6ikooaqowoskgv4hfrp444 (nej1)
seq1129-6veq-sh0	q5l37rle6pojjnllrwjyryulavpqdlq5 (amduser@tahoebs3:public/bs3c1)
seq1129-6veq-sh1	q5l37rle6pojjnllrwjyryulavpqdlq5 (amduser@tahoebs3:public/bs3c1)
seq1129-6veq-sh2	q5l37rle6pojjnllrwjyryulavpqdlq5 (amduser@tahoebs3:public/bs3c1)
seq1129-6veq-sh3	q5l37rle6pojjnllrwjyryulavpqdlq5 (amduser@tahoebs3:public/bs3c1)
seq1129-6veq-sh4	q5l37rle6pojjnllrwjyryulavpqdlq5 (amduser@tahoebs3:public/bs3c1)
seq1129-6veq-sh6	q5l37rle6pojjnllrwjyryulavpqdlq5 (amduser@tahoebs3:public/bs3c1)
seq1129-6veq-sh8	7tlov7egj7ultza3dy2dlgev6gijlgvk (amduser@tahoebs5:public/bs5c3)
seq1129-6veq-sh9	ivjakubrruewknqg7wgb5hbinasqupj6 (amduser@tahoebs5:public/bs5c2)
# Recoverable Versions: 3
# Unrecoverable Versions: 0

The most recent incident in my local incidents log says:

11:53:20.380 [43315]: WEIRD error during query: [Failure instance: Traceback: <class 'foolscap.ipb.DeadReferenceError'>: Calling Stale Broker /home/zooko/playground/allmydata/tahoe/trunk/trunk/src/allmydata/mutable/servermap.py:528:_do_query /home/zooko/playground/allmydata/tahoe/trunk/trunk/src/allmydata/mutable/servermap.py:540:_do_read /home/zooko/playground/allmydata/tahoe/trunk/trunk/src/allmydata/util/rrefutil.py:26:callRemote build/bdist.linux-x86_64/egg/foolscap/referenceable.py:395:callRemote --- <exception caught here> --- /usr/lib/python2.5/site-packages/Twisted-8.2.0-py2.5-linux-x86_64.egg/twisted/internet/defer.py:106:maybeDeferred build/bdist.linux-x86_64/egg/foolscap/referenceable.py:434:_callRemote build/bdist.linux-x86_64/egg/foolscap/broker.py:467:newRequestID ] FAILURE:

The full incident is attached as incident-2009-03-04-115318-ebt4x5a.flog.bz2

[warner]

We recently saw evidence of MemoryError exceptions on many of the testgrid nodes. These sorts of errors are always annoying, because they usually interfere with the error-handling code too (and it frequently causes some operations to fail but others to succeed). I also saw large VmSize values for many of these nodes. It appears that something caused the nodes to use a lot of memory (maybe quickly, maybe slowly), eventually causing memory problems for those nodes or for the other ones that share a host.

I think that this caused some number of storage server requests to fail. I think that this triggered #546-style problems.

I think that at some point, bs3c1 was the only functioning node that your client was connected to, which is why it ended up with so many shares. It might have been connected to the others but they were not accepting writes because of the memory problems, or it might not have been connected to them at all.

I still don't understand your second check results (the one that starts with "Unrecoverable Versions: 2*seq20-qb3p"). Is it possible that you checked the wrong object? That check shows seq20 on bs3c4, but then the third check you did (which shows 8*seq1128/3*seq1122/8*seq1129) shows seq1128 on that very same server.

The KeyError is a bug in mutable-retrieve: the self.remaining_sharemap table is updated (in get_data) while it is being iterated over. I've opened #667 for this. I suspect the bug is triggered by the mutable-retrieve process running out of shares during download, but it should be reported differently.

[zooko]

I think I might have reported check results from different objects. I was doing deep-checks on the directory which contains three different objects, and I might have cut and pasted check results from different objects.

[zooko]

What do we do about this ticket? I don't know how to reproduce the original problem -- ~MemoryErrors? due to unknown causes. Brian, did you fix the {{KeyError?}}} which was "a bug in mutable-retrieve?

I think we should either close this ticket as something horrible like "wontfix" or else leave it open in the hopes that someone will stumble upon a reproducible MemoryError in exactly the same way that caused this error.

Or, actually, I guess I would be satisfied if we could change the code so that future MemoryErrors would result in quick, clean, loud failures. Maybe change the name of this ticket to "handle MemoryError? quickly, cleanly, and loudly"?

[warner]

nope, #667 is still open. I haven't gotten to look at it yet.

I guess I'd recommend changing this ticket to be specifically about MemoryError, although I must admit I don't know how we can really fix it.

[zooko]

renaming this to "handle MemoryError by failing quickly and loudly" and putting it into Milestone "undecided"

[zooko]

People are reporting UncoordinatedWriteErrors on the test grid (#748), and so I checked some of the test grid storage servers and saw that one -- tahoebs5.allmydata.com bs5c1 -- has 1.5 GB of virt, 475 MB res. That is running some very old versions of foolscap and TahoeLAFS:

allmydata-tahoe: 1.3.0-r3747, foolscap: 0.3.2, pycryptopp: 0.5.2-1, zfec: 1.4.0-4, Twisted: 2.5.0, Nevow: 0.9.26, zope.interface: 3.3.1, python: 2.5.2, platform: Linux-Ubuntu_8.04-i686-32bit, simplejson: 1.7.3, argparse: 0.8.0, pyOpenSSL: 0.6, pyutil: 1.3.16-12, setuptools: 0.6c8

Hm... Yep, that one has MemoryError in its twisted.log. I wonder if we could monkeypatch Python's MemoryError class to do a sys.exit() or the like. I suppose this also suggests that we ought to be pushing this issue upstream to Python itself...

[zooko]

See also #529 (Implement Halt and Catch Fire)

[zooko]

nejucomo says setrlimit(2) to the rescue. We could setrlimit(2), at least on Unix, to ask the operating system to please kill us if we try to use up too much RAM.