View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0003705 | GNUnet | set service | public | 2015-03-07 20:09 | 2018-06-07 00:39 |
| Reporter | Christian Grothoff | Assigned To | Florian Dold | ||
| Priority | high | Severity | major | Reproducibility | random |
| Status | closed | Resolution | fixed | ||
| Platform | i7 | OS | Debian GNU/Linux | OS Version | squeeze |
| Product Version | Git master | ||||
| Target Version | 0.11.0 | Fixed in Version | 0.11.0pre66 | ||
| Summary | 0003705: set union fails with "other peer disconnected prematurely" | ||||
| Description | I get this error when normal peers are running as part of their typical revocation set union calculation: Mar 07 19:58:58-516571 revocation-15465 DEBUG Peer `AZ7G' connected to us Mar 07 19:58:58-516647 revocation-15465 DEBUG Starting SET operation with peer `AZ7G' Mar 07 19:58:59-517691 revocation-15465 DEBUG Starting set exchange with peer `AZ7G' Mar 07 19:58:59-517820 set-15470 DEBUG Initiating union operation evaluation Mar 07 19:58:59-517851 set-15470 DEBUG sent op request without context message Mar 07 19:59:17-331942 revocation-15465 DEBUG Peer `CW42' connected to us Mar 07 19:59:17-331978 revocation-15465 DEBUG Starting SET operation with peer `CW42' Mar 07 19:59:17-700085 revocation-15465 DEBUG Peer `APHW' connected to us Mar 07 19:59:18-332643 revocation-15465 DEBUG Starting set exchange with peer `CW42' Mar 07 19:59:18-332771 set-15470 DEBUG Initiating union operation evaluation Mar 07 19:59:18-332798 set-15470 DEBUG sent op request without context message Mar 07 19:59:30-772084 set-15470 DEBUG channel_end_cb called Mar 07 19:59:30-772113 set-15470 DEBUG calling peer disconnect due to channel end Mar 07 19:59:30-772135 set-15470 WARNING other peer disconnected prematurely Mar 07 19:59:30-772145 set-15470 DEBUG destroying union op Mar 07 19:59:30-772195 set-15470 DEBUG destroying union op done Mar 07 19:59:30-772211 set-15470 DEBUG channel_end_cb finished Mar 07 19:59:30-772233 set-15470 DEBUG channel_end_cb called Mar 07 19:59:30-772241 set-15470 DEBUG calling peer disconnect due to channel end Mar 07 19:59:30-772248 set-15470 WARNING other peer disconnected prematurely Mar 07 19:59:30-772255 set-15470 DEBUG destroying union op Mar 07 19:59:30-772301 set-15470 DEBUG destroying union op done Mar 07 19:59:30-772309 set-15470 DEBUG channel_end_cb finished Mar 07 19:59:30-772438 set-api-15465 DEBUG Got result message with status 1 Mar 07 19:59:30-772486 revocation-15465 WARNING Error computing revocation set union with CW42 Mar 07 19:59:30-772517 set-api-15465 DEBUG Got result message with status 1 Mar 07 19:59:30-772529 revocation-15465 WARNING Error computing revocation set union with AZ7G | ||||
| Steps To Reproduce | Run a peer for a while. Note that it seems only the 'initiating' peer sees this error. OTOH, no set unions ever officially succeed as far as revocation's statistics are concerned. | ||||
| Additional Information | This involves two empty sets. | ||||
| Tags | No tags attached. | ||||
|
|
It's really difficult to see what's going on without the other peer's logs. It seems like the CADET channel is closed right after the initiating peer sends the first message (the request for a set operation). The REVOCATION service doesn't call reject on any set operation request, and the time between the request and channel end call is too short to be the timeout for unanswered incoming requests. Thus I'm unsure where the disconnect actually happens. There are a lot of places where we disconnect a peer because of protocol violations, but that only happens further along in the protocol. Is this a new bug / does it only happen sometimes? I'm not sure what you mean by "no set unions ever officially succeed as far as revocation's statistics are concerned". Shouldn't the corresponding test case for revocation fail then? |
|
|
That's the strange thing: the test has passed for a long time, but I don't have evidence this ever worked "in the real world". The bug is certainly not new, I just used to be able to blame it on other things... |
|
|
Any ideas what we can do to investigate this? From a look at the code and the logs there doesn't seem to be anything too obvious, I especially don't get why the test case passes. Did I understand you correctly that we *never* see a set reconciliation succeeding from revocation when running as a normal peer (and not in a testbed). |
|
|
Well, at least I have never seen the 'success' stat for revocation > 0. |
|
|
Alright, maybe this will get clearer after adding statistics to the set service (0003706). |
|
|
Oh, I was wrong, it does work sometimes: gnunet9@sam:~$ gnunet-statistics -s revocation revocation # peers connected: 15 revocation # revocation set unions completed: 36 revocation # revocation set unions failed: 9 |
|
|
Closing as recent fixes to CADET explain a _lot_ of these issues. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2015-03-07 20:09 | Christian Grothoff | New Issue | |
| 2015-03-07 20:09 | Christian Grothoff | Status | new => assigned |
| 2015-03-07 20:09 | Christian Grothoff | Assigned To | => Florian Dold |
| 2015-03-07 20:38 | Christian Grothoff | Target Version | => 0.11.0 |
| 2015-03-07 23:30 | Florian Dold | Note Added: 0008990 | |
| 2015-03-07 23:51 | Christian Grothoff | Note Added: 0008994 | |
| 2015-03-07 23:58 | Florian Dold | Note Added: 0008995 | |
| 2015-03-07 23:59 | Christian Grothoff | Note Added: 0008996 | |
| 2015-03-08 00:04 | Florian Dold | Note Added: 0008997 | |
| 2015-03-08 12:45 | Christian Grothoff | Note Added: 0008998 | |
| 2018-06-07 00:39 | Christian Grothoff | Status | assigned => closed |
| 2018-06-07 00:39 | Christian Grothoff | Resolution | open => fixed |
| 2018-06-07 00:39 | Christian Grothoff | Fixed in Version | => 0.11.0pre66 |
| 2018-06-07 00:39 | Christian Grothoff | Note Added: 0012989 |
