tahoe-lafs/trac

unit test failure: failed to download file with 2 shares on one server and one share on another #1191

New issue

Closed

opened 2010-09-03 04:57:24 +00:00 by zooko · 25 comments

zooko commented

2010-09-03 04:57:24 +00:00

For example in this run:

http://tahoe-lafs.org/buildbot/builders/hardy-amd64/builds/687/steps/test/logs/stdio

[ERROR]: allmydata.test.test_hung_server.HungServerDownloadTest.test_2_good_8_broken_copied_share

Traceback (most recent call last):
Failure: allmydata.interfaces.NotEnoughSharesError: ran out of shares: complete=sh0,sh2 pending= overdue= unused= need 3. Last failure: None

The download should have succeeded because server 0 should have shares 0 and 2 and server 1 should have share 1.

source:trunk/src/allmydata/test/test_hung_server.py@4661#L197

This test failure is nondeterministic. The first step is probably to understand why that is and make it fail every time.

For example in this run: <http://tahoe-lafs.org/buildbot/builders/hardy-amd64/builds/687/steps/test/logs/stdio> ``` [ERROR]: allmydata.test.test_hung_server.HungServerDownloadTest.test_2_good_8_broken_copied_share Traceback (most recent call last): Failure: allmydata.interfaces.NotEnoughSharesError: ran out of shares: complete=sh0,sh2 pending= overdue= unused= need 3. Last failure: None ``` The download should have succeeded because server 0 should have shares 0 and 2 and server 1 should have share 1. source:trunk/src/allmydata/test/test_hung_server.py@4661#L197 This test failure is nondeterministic. The first step is probably to understand why that is and make it fail every time.

zooko added the

labels 2010-09-03 04:57:24 +00:00

zooko added this to the 1.8.0 milestone 2010-09-03 04:57:24 +00:00

zooko commented

2010-09-03 05:45:57 +00:00

Author

This diff seems to have caused the test to be green every time. I'll leave it running overnight to be sure:

 Zooko-Ofsimplegeos-MacBook-Pro:~/playground/tahoe-lafs/trunk$ time darcs diff -u
diff -rN -u old-trunk/src/allmydata/test/no_network.py new-trunk/src/allmydata/test/no_network.py
--- old-trunk/src/allmydata/test/no_network.py  2010-09-02 23:24:54.000000000 -0600
+++ new-trunk/src/allmydata/test/no_network.py  2010-09-02 23:24:59.000000000 -0600
@@ -238,7 +238,8 @@
         self.rebuild_serverlist()

     def rebuild_serverlist(self):
-        self.all_servers = frozenset(self.servers_by_id.items())
+        # self.all_servers = list(reversed(sorted(frozenset(self.servers_by_id.items()))))
+        self.all_servers = sorted(frozenset(self.servers_by_id.items()))
         for c in self.clients:
             c._servers = self.all_servers

This diff seems to have caused the test to be green every time. I'll leave it running overnight to be sure: ``` Zooko-Ofsimplegeos-MacBook-Pro:~/playground/tahoe-lafs/trunk$ time darcs diff -u diff -rN -u old-trunk/src/allmydata/test/no_network.py new-trunk/src/allmydata/test/no_network.py --- old-trunk/src/allmydata/test/no_network.py 2010-09-02 23:24:54.000000000 -0600 +++ new-trunk/src/allmydata/test/no_network.py 2010-09-02 23:24:59.000000000 -0600 @@ -238,7 +238,8 @@ self.rebuild_serverlist() def rebuild_serverlist(self): - self.all_servers = frozenset(self.servers_by_id.items()) + # self.all_servers = list(reversed(sorted(frozenset(self.servers_by_id.items())))) + self.all_servers = sorted(frozenset(self.servers_by_id.items())) for c in self.clients: c._servers = self.all_servers ```

zooko commented

2010-09-03 06:03:50 +00:00

Author

No, that wasn't it. Even with that diff the test occasionally goes red.

zooko commented

2010-09-03 06:40:34 +00:00

Author

Okay, this patch makes it go red every time:

HACL Zooko-Ofsimplegeos-MacBook-Pro:~/playground/tahoe-lafs/trunk$ time darcs diff -u
diff -rN -u old-trunk/src/allmydata/test/test_hung_server.py new-trunk/src/allmydata/test/test_hung_server.py
--- old-trunk/src/allmydata/test/test_hung_server.py    2010-09-03 00:21:06.000000000 -0600
+++ new-trunk/src/allmydata/test/test_hung_server.py    2010-09-03 00:21:09.000000000 -0600
@@ -101,7 +101,8 @@
 
         self.c0 = self.g.clients[0]
         nm = self.c0.nodemaker
-        self.servers = [(id, ss) for (id, ss) in nm.storage_broker.get_all_servers()]
+        self.servers = sorted([(id, ss) for (id, ss) in nm.storage_broker.get_all_servers()])
+        self.servers = self.servers[5:] + self.servers[:5]
 
         if mutable:
             d = nm.create_mutable_file(mutable_plaintext)

Okay, this patch makes it go red every time: ``` HACL Zooko-Ofsimplegeos-MacBook-Pro:~/playground/tahoe-lafs/trunk$ time darcs diff -u diff -rN -u old-trunk/src/allmydata/test/test_hung_server.py new-trunk/src/allmydata/test/test_hung_server.py --- old-trunk/src/allmydata/test/test_hung_server.py 2010-09-03 00:21:06.000000000 -0600 +++ new-trunk/src/allmydata/test/test_hung_server.py 2010-09-03 00:21:09.000000000 -0600 @@ -101,7 +101,8 @@ self.c0 = self.g.clients[0] nm = self.c0.nodemaker - self.servers = [(id, ss) for (id, ss) in nm.storage_broker.get_all_servers()] + self.servers = sorted([(id, ss) for (id, ss) in nm.storage_broker.get_all_servers()]) + self.servers = self.servers[5:] + self.servers[:5] if mutable: d = nm.create_mutable_file(mutable_plaintext) ```

zooko commented

2010-09-04 22:25:24 +00:00

Author

When I was looking at the behavior of the tests when it was non-deterministic, I noticed that there are two ways that this particular test could turn out: either the first server to respond claimed 2 shares and the second claimed 1 share, or the first server to respond claimed 1 share and the second claimed 2 shares. I observed that the download always failed in one case and always succeeded in the other. So I hypothesize that maybe the download logic which is trying to achieve diversity isn't realizing that it can use the newly arrived DYHB response for more than one share, or else it isn't realizing that it can use the previously arrived DYHB response for more than one share.

francois commented

2010-09-04 23:22:27 +00:00

Owner

Attachment test_2_good_8_broken_copied_share.txt (10638 bytes) added

**Attachment** test_2_good_8_broken_copied_share.txt (10638 bytes) added

test_2_good_8_broken_copied_share.txt

10 KiB

francois commented

2010-09-04 23:24:11 +00:00

Owner

As first step, the failing test was run with verbose logging, see attachment:test_2_good_8_broken_copied_share.txt.

francois commented

2010-09-05 00:51:43 +00:00

Owner

--- old-tahoe-upstream/src/allmydata/immutable/downloader/finder.py     2010-09-05 02:21:25.000000000 +0200
+++ new-tahoe-upstream/src/allmydata/immutable/downloader/finder.py     2010-09-05 02:21:25.000000000 +0200
@@ -220,7 +220,7 @@
         shares_s = ",".join([str(sh) for sh in shares])
         self.log(format="delivering shares: %s" % shares_s,
                  level=log.NOISY, umid="2n1qQw")
-        eventually(self.share_consumer.got_shares, shares)
+        self.share_consumer.got_shares(shares)
 
     def _got_error(self, f, peerid, req, d_ev, lp):
         d_ev.finished("error", now())

I don't really know why the following patch makes the test succeed (and breaks two others). But it might give some insight about the actual bug. Unfortunately, I'll probably won't find time to work on this during the next few days. ``` --- old-tahoe-upstream/src/allmydata/immutable/downloader/finder.py 2010-09-05 02:21:25.000000000 +0200 +++ new-tahoe-upstream/src/allmydata/immutable/downloader/finder.py 2010-09-05 02:21:25.000000000 +0200 @@ -220,7 +220,7 @@ shares_s = ",".join([str(sh) for sh in shares]) self.log(format="delivering shares: %s" % shares_s, level=log.NOISY, umid="2n1qQw") - eventually(self.share_consumer.got_shares, shares) + self.share_consumer.got_shares(shares) def _got_error(self, f, peerid, req, d_ev, lp): d_ev.finished("error", now()) ```

zooko commented

2010-09-06 04:41:54 +00:00

Author

Okay I think I understand the bug now. [ShareFinder._deliver_shares()]source:trunk/src/allmydata/immutable/downloader/finder.py@4707#L217 calls eventually(self.share_consumer.got_shares, shares) and then in the next tick—before got_shares() has been executed—[ShareFinder.loop()]source:trunk/src/allmydata/immutable/downloader/finder.py@4707#L89 runs and gives up and aborts the download because it isn't aware of the shares that were going to be delivered to it in a subsequent tick.

Okay I think I understand the bug now. [ShareFinder._deliver_shares()]source:trunk/src/allmydata/immutable/downloader/finder.py@4707#L217 calls `eventually(self.share_consumer.got_shares, shares)` and then in the next tick—*before* `got_shares()` has been executed—[ShareFinder.loop()]source:trunk/src/allmydata/immutable/downloader/finder.py@4707#L89 runs and gives up and aborts the download because it isn't aware of the shares that were going to be delivered to it in a subsequent tick.

warner commented

2010-09-06 18:16:09 +00:00

Oh, yeah, that's a bug. I think the proper behavior would be for the call to self.share_consumer.no_more_shares() to use the same eventual-send that the call to self.share_consumer.got_shares() uses (to make sure the no_more_shares cannot race ahead of the got_shares call).

This bug probably appeared during the diversity-seeking patch: part of that patch was to deliver all shares as quickly as possible, instead of trickling them out one share at a time.

I'll think about what the unit test for this should look like.. something that fails consistently without the patch, of course. Maybe just a way to consistentify test_2_good_8_broken_copied_share.

Oh, yeah, that's a bug. I think the proper behavior would be for the call to `self.share_consumer.no_more_shares()` to use the same eventual-send that the call to `self.share_consumer.got_shares()` uses (to make sure the `no_more_shares` cannot race ahead of the `got_shares` call). This bug probably appeared during the diversity-seeking patch: part of that patch was to deliver all shares as quickly as possible, instead of trickling them out one share at a time. I'll think about what the unit test for this should look like.. something that fails consistently without the patch, of course. Maybe just a way to consistentify `test_2_good_8_broken_copied_share`.

warner commented

2010-09-06 18:34:10 +00:00

Attachment 1191-fix.diff (644 bytes) added

fix for the bug, but lacks a specific unit test

**Attachment** 1191-fix.diff (644 bytes) added fix for the bug, but lacks a specific unit test

1191-fix.diff

644 B

warner commented

2010-09-06 18:35:16 +00:00

that patch definitely fixes the problem (consistently, thanks to the recent patch to test_hung_server.py which makes the share order consistent). But I'd like to have a test case which specifically exercises this code path to go along with the fix.

zooko commented

2010-09-06 19:53:10 +00:00

Author

To believe that attachment:1191-fix.diff fixes this issue, I think I would have to believe that eventually(A);eventually(B) where A does eventually(C) will always execute in order A;B;C and never A;C;B. Is it true that this fix requires that property?

It would be nice if the fix to this bug were more "local" and one could see by inspecting the source that the state was kept consistent. That is: isn't the problem here that a tick updates the ShareFinder's state to remove the last request from pending_requests but does not update the state to add the newly discovered share? And then loop runs between that tick and the later tick which is going to add the resulting share with got_shares? Wouldn't it be better if there was never a time in between ticks where one of those bits of state had been updated and the other had not?

If I understand correctly this patch leaves it the case that one tick updates pending_requests and a subsequent tick calls got_shares, but prevents the problem by ensuring that loop doesn't get run between those two ticks. This seems a bit fragile, but I guess as long as we have a robust test case for it then we'll know if it regresses. Maybe we could add some sort of internal consistency check assertion to the effect that, um, loop never gets called after _request_retired but before _got_shares ?

To believe that [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c) fixes this issue, I think I would have to believe that `eventually(A);eventually(B)` where `A` does `eventually(C)` will always execute in order `A;B;C` and never `A;C;B`. Is it true that this fix requires that property? It would be nice if the fix to this bug were more "local" and one could see by inspecting the source that the state was kept consistent. That is: isn't the problem here that a tick updates the `ShareFinder`'s state to remove the last request from `pending_requests` but does not update the state to add the newly discovered share? And then `loop` runs between that tick and the later tick which is going to add the resulting share with `got_shares`? Wouldn't it be better if there was never a time in between ticks where one of those bits of state had been updated and the other had not? If I understand correctly this patch leaves it the case that one tick updates `pending_requests` and a subsequent tick calls `got_shares`, but prevents the problem by ensuring that `loop` doesn't get run between those two ticks. This seems a bit fragile, but I guess as long as we have a robust test case for it then we'll know if it regresses. Maybe we could add some sort of internal consistency check assertion to the effect that, um, `loop` never gets called after `_request_retired` but before `_got_shares` ?

zooko commented

2010-09-07 05:56:59 +00:00

Author

Okay here is a log created by instrumenting ShareFinder to log each method call and DownloadNode to log got_shares and no_more_shares. This is without attachment:1191-fix.diff.

local#231 23:01:59.969: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._request_retired(<allmydata.immutable.downloader.finder.RequestToken instance at 0x104ef9c68>)
local#232 23:01:59.969: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._got_response({9: <allmydata.test.no_network.LocalWrapper instance at 0x1049dc3f8>}, {'http://allmydata.org/tahoe/protocols/storage/v1': {'maximum-immutable-share-size': 128704925696, 'tolerates-immutable-read-overrun': True, 'delete-mutable-shares-with-zero-length-writev': True}, 'application-version': 'allmydata-tahoe/1.8.0c3-r4715'}, <B9><A3>N<80>u<9C>_<F7><97>FSS<A7><BD>^B<F9>f$:      , <allmydata.immutable.downloader.finder.RequestToken instance at 0x104ef9c68>, <allmydata.immutable.downloader.status.DYHBEvent instance at 0x104ef9cb0>, 1283835719.96, 210)
local#233 23:01:59.969: got shnums [9] from [xgru5adv]
local#234 23:01:59.969: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._create_share(9, <allmydata.test.no_network.LocalWrapper instance at 0x1049dc3f8>, {'http://allmydata.org/tahoe/protocols/storage/v1': {'maximum-immutable-share-size': 128704925696, 'tolerates-immutable-read-overrun': True, 'delete-mutable-shares-with-zero-length-writev': True}, 'application-version': 'allmydata-tahoe/1.8.0c3-r4715'}, <B9><A3>N<80>u<9C>_<F7><97>FSS<A7><BD>^B<F9>f$:        , 0.0133891105652)
local#235 23:01:59.970: Share(sh9-on-xgru5) created
local#236 23:01:59.970: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._deliver_shares([Share(sh9-on-xgru5)])
local#237 23:01:59.970: delivering shares: Share(sh9-on-xgru5)
local#238 23:01:59.970: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop()
local#239 23:01:59.970: ShareFinder loop: running=True hungry=False, pending=
local#240 23:01:59.971: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop()
local#241 23:01:59.971: ShareFinder loop: running=True hungry=False, pending=
local#242 23:01:59.972: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.hungry()
local#243 23:01:59.972: ShareFinder[si=dglevpj4ueb7] hungry
local#244 23:01:59.972: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.start_finding_servers()
local#245 23:01:59.973: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop()
local#246 23:01:59.973: ShareFinder loop: running=True hungry=True, pending=
local#247 23:01:59.973: ShareFinder.loop: no_more_shares, ever
local#248 23:01:59.973: xxx ImmutableDownloadNode(dglevpj4ueb7).no_more_shares() ; _active_segment: <allmydata.immutable.downloader.fetcher.SegmentFetcher instance at 0x1049f6638>
local#249 23:01:59.975: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop()
local#250 23:01:59.975: ShareFinder loop: running=True hungry=True, pending=
local#251 23:01:59.975: ShareFinder.loop: no_more_shares, ever
local#252 23:01:59.975: xxx ImmutableDownloadNode(dglevpj4ueb7).no_more_shares() ; _active_segment: <allmydata.immutable.downloader.fetcher.SegmentFetcher instance at 0x1049f6638>
local#253 23:01:59.976: ran out of shares: complete=sh1,sh8 pending= overdue= unused= need 3. Last failure: None
local#254 23:01:59.976: SegmentFetcher(dglevpj4ueb7).stop
local#255 23:01:59.977: xxx ImmutableDownloadNode(dglevpj4ueb7).got_shares([Share(sh9-on-xgru5)])

(Sorry about the wide lines there.)

So at local#231 23:01:59.969 the request is retired but the resulting eventual got_shares won't happen until local#255 23:01:59.977 which is shortly after the loop at local#247 23:01:59.973 which said no_more_shares, ever, which set a flag named _no_more_shares in the SegmentFetcher so that the next time SegmentFetcher._do_loop runs then it gives up and says ran out of shares at local#253 23:01:59.976.

Now attachment:1191-fix.diff makes it so that when loop decides no_more_shares, ever then it sets an eventual task to set the _no_more_shares flag in SegmentFetcher instead of doing it immediately. Is this guaranteed to always prevent this bug? I guess it is because when the _request_retired (local#231 23:01:59.969) is done immediately then during that same tick the got_shares (local#255 23:01:59.977) is put on the eventual queue, so when the setting of _no_more_shares is put on the eventual queue it will always take effect after the got_shares does.

Okay.

But this still feels fragile to me, for example after we apply attachment:1191-fix.diff, then if someone were to change the code of ShareFinder._got_response so that it invoked _deliver_shares eventually instead of immediately, or if they were to change _deliver_shares so that it invoked DownloadNode.got_shares eventually instead of immediately, or if they were to change DownloadNode.got_shares so that it updated its _shares data structure eventually instead of immediately, then that would reintroduce this bug.

It would feel nicer to me if we could update both the ShareFinder.pending_requests data structure and the DownloadNode._shares data structure in the same immediate call so that there is no tick that begins when those two data structures are in a mutually inconsistent state (with the request removed from the former but the share not yet added to the latter).

Okay now I'll try to make a narrow test case of this issue.

Okay here is a log created by instrumenting `ShareFinder` to log each method call and `DownloadNode` to log `got_shares` and `no_more_shares`. This is without [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c). ``` local#231 23:01:59.969: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._request_retired(<allmydata.immutable.downloader.finder.RequestToken instance at 0x104ef9c68>) local#232 23:01:59.969: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._got_response({9: <allmydata.test.no_network.LocalWrapper instance at 0x1049dc3f8>}, {'http://allmydata.org/tahoe/protocols/storage/v1': {'maximum-immutable-share-size': 128704925696, 'tolerates-immutable-read-overrun': True, 'delete-mutable-shares-with-zero-length-writev': True}, 'application-version': 'allmydata-tahoe/1.8.0c3-r4715'}, <B9><A3>N<80>u<9C>_<F7><97>FSS<A7><BD>^B<F9>f$: , <allmydata.immutable.downloader.finder.RequestToken instance at 0x104ef9c68>, <allmydata.immutable.downloader.status.DYHBEvent instance at 0x104ef9cb0>, 1283835719.96, 210) local#233 23:01:59.969: got shnums [9] from [xgru5adv] local#234 23:01:59.969: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._create_share(9, <allmydata.test.no_network.LocalWrapper instance at 0x1049dc3f8>, {'http://allmydata.org/tahoe/protocols/storage/v1': {'maximum-immutable-share-size': 128704925696, 'tolerates-immutable-read-overrun': True, 'delete-mutable-shares-with-zero-length-writev': True}, 'application-version': 'allmydata-tahoe/1.8.0c3-r4715'}, <B9><A3>N<80>u<9C>_<F7><97>FSS<A7><BD>^B<F9>f$: , 0.0133891105652) local#235 23:01:59.970: Share(sh9-on-xgru5) created local#236 23:01:59.970: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>._deliver_shares([Share(sh9-on-xgru5)]) local#237 23:01:59.970: delivering shares: Share(sh9-on-xgru5) local#238 23:01:59.970: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop() local#239 23:01:59.970: ShareFinder loop: running=True hungry=False, pending= local#240 23:01:59.971: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop() local#241 23:01:59.971: ShareFinder loop: running=True hungry=False, pending= local#242 23:01:59.972: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.hungry() local#243 23:01:59.972: ShareFinder[si=dglevpj4ueb7] hungry local#244 23:01:59.972: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.start_finding_servers() local#245 23:01:59.973: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop() local#246 23:01:59.973: ShareFinder loop: running=True hungry=True, pending= local#247 23:01:59.973: ShareFinder.loop: no_more_shares, ever local#248 23:01:59.973: xxx ImmutableDownloadNode(dglevpj4ueb7).no_more_shares() ; _active_segment: <allmydata.immutable.downloader.fetcher.SegmentFetcher instance at 0x1049f6638> local#249 23:01:59.975: xxx <allmydata.immutable.downloader.finder.ShareFinder instance at 0x1049f6050>.loop() local#250 23:01:59.975: ShareFinder loop: running=True hungry=True, pending= local#251 23:01:59.975: ShareFinder.loop: no_more_shares, ever local#252 23:01:59.975: xxx ImmutableDownloadNode(dglevpj4ueb7).no_more_shares() ; _active_segment: <allmydata.immutable.downloader.fetcher.SegmentFetcher instance at 0x1049f6638> local#253 23:01:59.976: ran out of shares: complete=sh1,sh8 pending= overdue= unused= need 3. Last failure: None local#254 23:01:59.976: SegmentFetcher(dglevpj4ueb7).stop local#255 23:01:59.977: xxx ImmutableDownloadNode(dglevpj4ueb7).got_shares([Share(sh9-on-xgru5)]) ``` (Sorry about the wide lines there.) So at `local#231 23:01:59.969` the request is retired but the resulting eventual `got_shares` won't happen until `local#255 23:01:59.977` which is shortly after the `loop` at `local#247 23:01:59.973` which said `no_more_shares, ever`, which set a flag named `_no_more_shares` in the `SegmentFetcher` so that the next time `SegmentFetcher._do_loop` runs then it gives up and says `ran out of shares` at `local#253 23:01:59.976`. Now [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c) makes it so that when `loop` decides `no_more_shares, ever` then it sets an eventual task to set the `_no_more_shares` flag in `SegmentFetcher` instead of doing it immediately. Is this guaranteed to always prevent this bug? I guess it is because when the `_request_retired` (`local#231 23:01:59.969`) is done immediately then during that same tick the `got_shares` (`local#255 23:01:59.977`) is put on the eventual queue, so when the setting of `_no_more_shares` is put on the eventual queue it will always take effect after the `got_shares` does. Okay. But this still feels fragile to me, for example after we apply [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c), then if someone were to change the code of `ShareFinder._got_response` so that it invoked `_deliver_shares` eventually instead of immediately, or if they were to change `_deliver_shares` so that it invoked `DownloadNode.got_shares` eventually instead of immediately, or if they were to change `DownloadNode.got_shares` so that it updated its `_shares` data structure eventually instead of immediately, then that would reintroduce this bug. It would feel nicer to me if we could update both the `ShareFinder.pending_requests` data structure and the `DownloadNode._shares` data structure in the same immediate call so that there is no tick that begins when those two data structures are in a mutually inconsistent state (with the request removed from the former but the share not yet added to the latter). Okay now I'll try to make a narrow test case of this issue.

zooko commented

2010-09-07 07:19:30 +00:00

Author

Okay I've written a test of ShareFinder in which everything that is provided to the ShareFinder is a fake/mock thing. I think that's pretty cool and it helped me learn the code better. I have to go to sleep now and currently the test doesn't exercise the bug because it doesn't arrange for the ShareFinder to execute its own loop in between the final request being retired and the final share being added to the node's _share. However, I'll attach the patch in case someone wants to play with it.

Okay I've written a test of `ShareFinder` in which everything that is provided to the `ShareFinder` is a fake/mock thing. I think that's pretty cool and it helped me learn the code better. I have to go to sleep now and currently the test doesn't exercise the bug because it doesn't arrange for the `ShareFinder` to execute its own `loop` in between the final request being retired and the final share being added to the node's `_share`. However, I'll attach the patch in case someone wants to play with it.

zooko commented

2010-09-07 07:20:58 +00:00

Author

Attachment test.patch.txt (10209 bytes) added

a test of ShareFinder in which everything that is provided to the ShareFinder is a fake/mock thing. This doesn't quite succeed at exercising the bug because it doesn't arrange for ShareFinder to run its own .loop after the last request is retired and before the last share is added to the node's _shares.

**Attachment** test.patch.txt (10209 bytes) added a test of [ShareFinder](wiki/ShareFinder) in which everything that is provided to the [ShareFinder](wiki/ShareFinder) is a fake/mock thing. This doesn't quite succeed at exercising the bug because it doesn't arrange for [ShareFinder](wiki/ShareFinder) to run its own .loop after the last request is retired and before the last share is added to the node's _shares.

test.patch.txt

10 KiB

zooko commented

2010-09-08 05:05:01 +00:00

Author

<zooko> Okay I need to talk out loud.				        [22:25]
<zooko> finder tells node "no more shares"
<zooko> when finder knows that it will never find more shares during this
	download, *and* node has said "I'm hungry--feed me more shares."
<zooko> This is fine, except that recently we (Brian) extended it so that the
	node will be hungry for more shares even though it has enough shares,
	because it wants better-distributed shares.
<zooko> So now this is an alternate (better) 
<zooko> explanation for #1191.
<zooko> That finder then tells node "WAH! Give up in despair!" when finder
	runs out of new shares.					        [22:27]
<zooko> But actually node should be content with the unevenly distributed set
	that it already has.
<zooko> Okay, cool. So now can I write a unit test of *that*...
<zooko> Well, for one thing this shows that it isn't really finder's fault.
<zooko> Oh no wait these are really *both* bugs.		        [22:28]
<zooko> I've just written a unit test for the bug that finder says "No more
	shares, ever!" immediately followed by "here's another share". 
<zooko> That's not right. :-)
<zooko> But then we also need *another* test which is that node, when told "no
	more shares ever" goes ahead and makes do with what it has if it can.

``` <zooko> Okay I need to talk out loud. [22:25] <zooko> finder tells node "no more shares" <zooko> when finder knows that it will never find more shares during this download, *and* node has said "I'm hungry--feed me more shares." <zooko> This is fine, except that recently we (Brian) extended it so that the node will be hungry for more shares even though it has enough shares, because it wants better-distributed shares. <zooko> So now this is an alternate (better) <zooko> explanation for #1191. <zooko> That finder then tells node "WAH! Give up in despair!" when finder runs out of new shares. [22:27] <zooko> But actually node should be content with the unevenly distributed set that it already has. <zooko> Okay, cool. So now can I write a unit test of *that*... <zooko> Well, for one thing this shows that it isn't really finder's fault. <zooko> Oh no wait these are really *both* bugs. [22:28] <zooko> I've just written a unit test for the bug that finder says "No more shares, ever!" immediately followed by "here's another share". <zooko> That's not right. :-) <zooko> But then we also need *another* test which is that node, when told "no more shares ever" goes ahead and makes do with what it has if it can. ```

zooko commented

2010-09-08 14:03:07 +00:00

Author

Okay I wrote a test for the first part -- it goes red if finder says "no more shares ever" and then delivers another share. I started writing a test for the second part -- it should go red if fetcher, given two shares on one server and one share on another server, gives up in despair. By inspection, it looks like fetcher doesn't have that bug: source:trunk/src/allmydata/immutable/downloader/fetcher.py@4707#L128. Also maybe that test is redundant with bigger downloader tests that we already have... I'll attach the patch as it exists in my sandbox at this moment.

zooko commented

2010-09-08 14:03:35 +00:00

Author

Attachment mockingtests.dpatch.txt (14928 bytes) added

**Attachment** mockingtests.dpatch.txt (14928 bytes) added

mockingtests.dpatch.txt

15 KiB

zooko commented

2010-09-09 06:54:51 +00:00

Author

Okay here is a narrowly focussed unit test which gives the finder a red mark because the finder announced "no more shares, ever" and then subsequently announces a new share: changeset:56a3258ff7560af3. (Note: it may be appropriate to write a more lenient unit test which allows the finder to do that and get away with it. However, the documentation for "no more shares" should then be updated and also I haven't yet been able to think of a unit test which is looser than this one and which still narrowly focusses on this bug.)

zooko commented

2010-09-09 18:58:44 +00:00

Author

I thought that the following patch (that I will attach to this ticket after I post this comment) would surely fix the bug by making the retire-request and add-new-share events happen in the same tick. Alas, it causes some other tests to fail in ways that I don't understand, namely allmydata.test.test_cli.Errors.test_get.

zooko commented

2010-09-09 18:59:23 +00:00

Author

Attachment do-retire-and-got-share-in-same-tick.dpatch.txt (2056 bytes) added

**Attachment** do-retire-and-got-share-in-same-tick.dpatch.txt (2056 bytes) added

do-retire-and-got-share-in-same-tick.dpatch.txt

2 KiB

zooko commented

2010-09-09 19:02:15 +00:00

Author

Hm, how could attachment:do-retire-and-got-share-in-same-tick.dpatch.txt cause a failure of allmydata.test.test_cli.Errors.test_get? This means there is some other dependency between state-updating events related to _retired_request() and _got_response, right?

I'm giving up for now. Help!

Hm, how could [attachment:do-retire-and-got-share-in-same-tick.dpatch.txt](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-28fbad40c16d) cause a failure of `allmydata.test.test_cli.Errors.test_get`? This means there is some other dependency between state-updating events related to `_retired_request()` and `_got_response`, right? I'm giving up for now. Help!

zooko commented

2010-09-10 04:34:57 +00:00

Author

Okay I applied Brian's patch attachment:1191-fix.diff and it made [my new test]source:trunk/src/allmydata/test/test_immutable.py@4715#L63 go green, so I guess I'll commit and stop worrying about why attachment:do-retire-and-got-share-in-same-tick.dpatch.txt made allmydata.test.test_cli.Errors.test_get hang. I consider attachment:1191-fix.diff combined with [my new test]source:trunk/src/allmydata/test/test_immutable.py@4715#L63 to be a sufficient fix for this issue.

Okay I applied Brian's patch [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c) and it made [my new test]source:trunk/src/allmydata/test/test_immutable.py@4715#L63 go green, so I guess I'll commit and stop worrying about why [attachment:do-retire-and-got-share-in-same-tick.dpatch.txt](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-28fbad40c16d) made `allmydata.test.test_cli.Errors.test_get` hang. I consider [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c) combined with [my new test]source:trunk/src/allmydata/test/test_immutable.py@4715#L63 to be a sufficient fix for this issue.

Brian Warner <warner@lothar.com> commented

2010-09-10 05:00:43 +00:00

Owner

In changeset:0475bd8e27ae8307:

immutable download: have the finder inform its share consumer "no more shares" in a subsequent tick, thus avoiding accidentally telling it "no more shares" now and then telling it "here's another share" in a subsequent tick
fixes #1191
Patch by Brian. This patch description was actually written by Zooko, but I forged Brian's name on the "author" field so that he would get credit for this patch in revision control history.

In changeset:0475bd8e27ae8307: ``` immutable download: have the finder inform its share consumer "no more shares" in a subsequent tick, thus avoiding accidentally telling it "no more shares" now and then telling it "here's another share" in a subsequent tick fixes #1191 Patch by Brian. This patch description was actually written by Zooko, but I forged Brian's name on the "author" field so that he would get credit for this patch in revision control history. ```

tahoe-lafs added the

r/fixed

label 2010-09-10 05:00:43 +00:00

Brian Warner <warner@lothar.com> closed this issue

2010-09-10 05:00:43 +00:00

zooko commented

2010-09-10 19:54:29 +00:00

Author

By the way there is a generalization that I could make about attachment:do-retire-and-got-share-in-same-tick.dpatch.txt compared to attachment:1191-fix.diff. We use state machines to handle asynchronous events, so when we want to have some behavior which spans multiple network events or timeouts and which has state, we have to store the state somewhere and check it in the next step of the state machine. But, we should really avoid the state machine paradigm whenever possible, so if we have some behavior which spans multiple ticks within one Twisted reactor, then we should not store the state somewhere and check the state in the function that we eventually run—we should instead pass that state as an argument to the eventually run function. That's just my opinion, man.

This is not to criticize attachment:1191-fix.diff. It is the smallest patch that fixes all the known problems, and it is what we're actually deploying in 1.8.0, but I wanted to explain why I spent time attempting (unsuccessfully) to write attachment:do-retire-and-got-share-in-same-tick.dpatch.txt instead.

A related idea that I have is: suppose you have a loop() method (we have several) which contains the core of the state machine. Suppose you have some new information/some new event to communicate to the state machine. Then do not write down the new event and trigger the state machine, like self._no_more_shares = True; eventually(self.loop), but instead extend the interface of loop() to accept this event, like eventually(self.loop, no_more_shares=True). That way people will not have to think about what happens if the state changes in other ways before that eventually(self.loop) happens, such as if there is already a different call to loop on the eventual queue. If we hadn't needed to consider such potential complications, it would have been easier for us to diagnose the issue in this ticket.

By the way there is a generalization that I could make about [attachment:do-retire-and-got-share-in-same-tick.dpatch.txt](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-28fbad40c16d) compared to [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c). We use state machines to handle asynchronous events, so when we want to have some behavior which spans multiple network events or timeouts and which has state, we have to store the state somewhere and check it in the next step of the state machine. *But*, we should really avoid the state machine paradigm whenever possible, so if we have some behavior which spans multiple ticks within one Twisted reactor, then we should *not* store the state somewhere and check the state in the function that we eventually run—we should instead *pass* that state as an argument to the eventually run function. That's just my opinion, man. This is not to criticize [attachment:1191-fix.diff](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-4425befc409c). It is the smallest patch that fixes all the known problems, and it is what we're actually deploying in 1.8.0, but I wanted to explain why I spent time attempting (unsuccessfully) to write [attachment:do-retire-and-got-share-in-same-tick.dpatch.txt](/tahoe-lafs/trac/attachments/000078ac-9060-63f0-0d25-28fbad40c16d) instead. A related idea that I have is: suppose you have a `loop()` method (we have several) which contains the core of the state machine. Suppose you have some new information/some new event to communicate to the state machine. Then do *not* write down the new event and trigger the state machine, like `self._no_more_shares = True; eventually(self.loop)`, but instead extend the interface of `loop()` to accept this event, like `eventually(self.loop, no_more_shares=True)`. That way people will not have to think about what happens if the state changes in other ways before that `eventually(self.loop)` happens, such as if there is already a different call to `loop` on the eventual queue. If we hadn't needed to consider such potential complications, it would have been easier for us to diagnose the issue in this ticket.

Rows
Columns