View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0001829 | GNUnet | DHT service | public | 2011-10-18 23:23 | 2011-10-31 12:00 |
| Reporter | Christian Grothoff | Assigned To | Christian Grothoff | ||
| Priority | low | Severity | minor | Reproducibility | random |
| Status | closed | Resolution | fixed | ||
| Product Version | Git master | ||||
| Summary | 0001829: DHT multipeer test sometimes fails with an oddly round number of successes/failures | ||||
| Description | For example, just now on ARM: 50 gets succeeded, 50 gets failed! (60/40 splits are also common). I suspect the problem is not really the DHT but maybe some peer(s) not connecting or some datacaches failing completely (failure to store data). | ||||
| Tags | No tags attached. | ||||
|
|
What can be said from the logs is that for EACH of the 10 peers, the same number of queries (4 or 5) fails. So it would seem that 4 or 5 of the 10 peers simply fail *entirely* with their PUT operation (likely not even making the data available via loopback to themselves). |
|
|
Bart writes: I just tried to execute the test-dht-multipeer on my laptop and adding a 9 in front of the quota figures (x30) pushed the results from 67/33 to 100/0 (twice). I can send you the traces with the statistics once I get home, if you are interested. Cheers, Bart |
|
|
Problem happens because the DHT client disconnects just before the DHT service even has a chance to deliver the reply. Need to find out why the disconnect happens. |
|
|
Looks like our delivery to the API goes pretty far: # grep -E "MGKGCK9E|0x10d4b20" output_1 | head -n 100 | tail -n 25 Oct 24 23:48:03-296614 dht-28849 DEBUG Received request for MGKGCK9E from local client 0x10d4b20 Oct 24 23:48:03-296635 datacache-28849 DEBUG Processing request for key `MGKGCK9E' Oct 24 23:48:03-296656 datacache-sqlite-28849 DEBUG Processing `GET' for key `MGKGCK9E' Oct 24 23:48:03-296789 datacache-sqlite-28849 DEBUG Found 12-byte result when processing `GET' for key `MGKGCK9E' Oct 24 23:48:03-296810 dht-28849 DEBUG Found reply for query MGKGCK9E in datacache, evaluation result is 0 Oct 24 23:48:03-296842 dht-28849 DEBUG Evaluation result is 0 for key MGKGCK9E for local client's query Oct 24 23:48:03-296862 dht-28849 DEBUG Queueing reply to query MGKGCK9E for client 0x10d4b20 Oct 24 23:48:03-296879 dht-28849 DEBUG Asking for transmission of 104 bytes to client 0x10d4b20 Oct 24 23:48:03-309449 dht-28849 DEBUG Selected 1/7 peers at hop 0 for MGKGCK9E (target was 1) Oct 24 23:48:03-309469 dht-28849 DEBUG Adding myself (4Q99) to GET bloomfilter for MGKGCK9E Oct 24 23:48:03-309487 dht-28849 DEBUG Routing GET for MGKGCK9E after 0 hops to 2UVH Oct 24 23:48:03-310022 dht-28849 DEBUG Transmitting 104 bytes to client 0x10d4b20 Oct 24 23:48:03-310039 dht-28849 DEBUG Not asking for transmission to 0x10d4b20 now: no more messages Oct 24 23:48:03-310055 dht-28849 DEBUG Transmitted 104/104 bytes to client 0x10d4b20 Oct 24 23:48:03-317129 dht-28849 DEBUG Selected 1/7 peers at hop 0 for MGKGCK9E (target was 1) Oct 24 23:48:03-317148 dht-28849 DEBUG Adding myself (4Q99) to GET bloomfilter for MGKGCK9E Oct 24 23:48:03-317169 dht-28849 DEBUG Routing GET for MGKGCK9E after 0 hops to 2UVH Oct 24 23:48:03-327366 dht-28849 DEBUG Selected 1/7 peers at hop 0 for MGKGCK9E (target was 1) Oct 24 23:48:03-327386 dht-28849 DEBUG Adding myself (4Q99) to GET bloomfilter for MGKGCK9E Oct 24 23:48:03-327407 dht-28849 DEBUG Routing GET for MGKGCK9E after 0 hops to 2UVH Oct 24 23:48:03-352226 dht-28849 DEBUG Selected 1/7 peers at hop 0 for MGKGCK9E (target was 1) Oct 24 23:48:03-352245 dht-28849 DEBUG Adding myself (4Q99) to GET bloomfilter for MGKGCK9E Oct 24 23:48:03-352266 dht-28849 DEBUG Routing GET for MGKGCK9E after 0 hops to 2UVH Oct 24 23:48:03-369788 dht-28849 DEBUG Selected 1/7 peers at hop 0 for MGKGCK9E (target was 1) Oct 24 23:48:03-369812 dht-28849 DEBUG Adding myself (4Q99) to GET bloomfilter for MGKGCK9E buildslave:/home/buildslave/full/build/src/dht# grep -E "MGKGCK9E|0x10d4b20" output_1 | tail -n 3 Get from peer 4Q99 for key MGKGCK9E failed! Oct 24 23:53:03-195369 dht-28849 DEBUG Local client 0x10d4b20 disconnects Oct 24 23:53:03-195392 dht-28849 DEBUG Removing client 0x10ce3b0's record for key MGKGCK9E |
|
|
# grep 0x26a1f10 output_2 | grep dht-api Oct 25 14:13:21-017805 dht-api-13106 DEBUG Sending query for GBJV4A8D to DHT 0x26a1f10 Oct 25 14:13:21-089406 dht-api-13106 DEBUG Reconnedting with DHT 0x26a1f10 Oct 25 14:18:21-017444 dht-api-13106 DEBUG Sending STOP for GBJV4A8D to DHT via 0x26a1f10 So we query, reconnect (!) and then stop. So somehow the reconnect->redo GET part didn't work here, or? Also, why the reconnect? |
|
|
The reason given for the reconnect is: Oct 25 14:13:21-020103 dht-api-13106 DEBUG Error receiving data from DHT service, reconnecting |
|
|
Ok, second bug: we begin to 'receive' before we sent the first request (try_connect in dht_api.c). The main bug, though, is that we don't re-issue the GETs on reconnect. |
|
|
Actually, code does seem to re-issue GETs (was just not logged). Ugh. |
|
|
Ah, but *reconnect* did not re-initialize the receive loop! |
|
|
Should be fixed with SVN 17741. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2011-10-18 23:23 | Christian Grothoff | New Issue | |
| 2011-10-18 23:23 | Christian Grothoff | Status | new => assigned |
| 2011-10-18 23:23 | Christian Grothoff | Assigned To | => mrwiggles |
| 2011-10-18 23:24 | Christian Grothoff | Assigned To | mrwiggles => |
| 2011-10-18 23:24 | Christian Grothoff | Status | assigned => new |
| 2011-10-20 15:02 | Christian Grothoff | Note Added: 0004710 | |
| 2011-10-20 19:59 | Christian Grothoff | Assigned To | => Christian Grothoff |
| 2011-10-20 19:59 | Christian Grothoff | Status | new => assigned |
| 2011-10-21 09:39 | Christian Grothoff | Note Added: 0004718 | |
| 2011-10-21 11:48 | Christian Grothoff | Target Version | => 0.9.0 |
| 2011-10-24 23:12 | Christian Grothoff | Note Added: 0004759 | |
| 2011-10-25 14:04 | Christian Grothoff | Note Added: 0004764 | |
| 2011-10-25 14:21 | Christian Grothoff | Note Added: 0004765 | |
| 2011-10-25 14:23 | Christian Grothoff | Note Added: 0004766 | |
| 2011-10-25 14:24 | Christian Grothoff | Note Added: 0004767 | |
| 2011-10-25 14:33 | Christian Grothoff | Note Added: 0004768 | |
| 2011-10-25 14:36 | Christian Grothoff | Note Added: 0004769 | |
| 2011-10-25 14:37 | Christian Grothoff | Note Added: 0004770 | |
| 2011-10-25 14:37 | Christian Grothoff | Status | assigned => resolved |
| 2011-10-25 14:37 | Christian Grothoff | Fixed in Version | => 0.9.0pre4 |
| 2011-10-25 14:37 | Christian Grothoff | Resolution | open => fixed |
| 2011-10-25 17:03 | Christian Grothoff | Target Version | 0.9.0 => 0.9.0pre4 |
| 2011-10-31 12:00 | Christian Grothoff | Status | resolved => closed |
