View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0002472 | GNUnet | transport service | public | 2012-06-30 13:54 | 2012-11-05 18:34 |
| Reporter | Christian Grothoff | Assigned To | Matthias Wachs | ||
| Priority | high | Severity | major | Reproducibility | random |
| Status | closed | Resolution | fixed | ||
| Product Version | Git master | ||||
| Target Version | 0.9.4 | ||||
| Summary | 0002472: WLAN testcases fail: peers got not connected | ||||
| Description | Jun 29 20:03:26-134717 test_transport_api_reliability_wlan-26506 ERROR Peers got NOT connected FAIL: test_transport_api_reliability_wlan | ||||
| Steps To Reproduce | https://gnunet.org/buildbot/builders/wachs-lenny-i386/builds/1462/steps/tests%20transport/logs/stdio | ||||
| Tags | No tags attached. | ||||
| related to | 0002480 | closed | Matthias Wachs | GNUNET_HELLO_address_cmp does not compare correctly |
| related to | 0002481 | closed | Matthias Wachs | transport validation messes up addresses |
|
|
Timeout in state ATS_INIT ... ATS does not suggest address Fails in 1 out of 4 runs More analysis is work in progress |
|
|
ATS cannot suggest, since it has no address Here an ATS log for a successfull ./test_transport_api_wlan run: Jul 03 11:30:59-809020 ats-10346 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/ats.conf~' Jul 03 11:30:59-809291 ats-10346 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/transport.conf~' Jul 03 11:30:59-811872 ats-10346 DEBUG MLP mode 0Jul 03 11:30:59-811890 ats-10346 DEBUG ATS started with SIMPLE mode Jul 03 11:30:59-811967 ats-10346 DEBUG Received `ATS_START' message Jul 03 11:30:59-812297 ats-10346 DEBUG Received `RESET_BACKOFF' message Jul 03 11:30:59-812351 ats-10346 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:30:59-812368 ats-10346 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:30:59-813748 ats-10350 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/ats.conf~' Jul 03 11:30:59-813993 ats-10350 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/transport.conf~' Jul 03 11:30:59-815936 ats-10350 DEBUG MLP mode 0Jul 03 11:30:59-815949 ats-10350 DEBUG ATS started with SIMPLE mode Jul 03 11:30:59-816004 ats-10350 DEBUG Received `ATS_START' message Jul 03 11:31:00-315310 ats-10346 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:00-813639 ats-10346 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:00-813680 ats-10346 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:00-813697 ats-10346 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:31:00-827959 ats-10346 DEBUG Received `ADDRESS_ADD' message -----> Jul 03 11:31:00-827993 ats-10346 DEBUG Added new address for peer `9P6V' session id 0, 0xc17890 Jul 03 11:31:00-828429 ats-10350 DEBUG Received `ADDRESS_ADD' message Jul 03 11:31:00-828493 ats-10346 DEBUG Received `ADDRESS_ADD' message -----> Jul 03 11:31:00-828510 ats-10350 DEBUG Added new address for peer `KJI3' session id 0, 0x21af780 Jul 03 11:31:00-828528 ats-10346 DEBUG Comparing peer 9P6V9SKT: address length 6 session 0 <-> address length 6 session 0 Jul 03 11:31:00-828545 ats-10346 DEBUG Updated existing address for peer `9P6V' 0xc17890 with new session 0 Jul 03 11:31:00-828885 ats-10350 DEBUG Received `ADDRESS_ADD' message Jul 03 11:31:00-828933 ats-10350 DEBUG Comparing peer KJI3AL00: address length 6 session 0 <-> address length 6 session 0 Jul 03 11:31:00-828945 ats-10350 DEBUG Updated existing address for peer `KJI3' 0x21af780 with new session 0 Jul 03 11:31:01-315195 ats-10346 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:01-814801 ats-10346 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:01-814835 ats-10346 DEBUG Resetting interval for peer `9P6V' address 0xc17890 from 0 to 0 Jul 03 11:31:01-814853 ats-10346 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:01-814871 ats-10346 DEBUG Address 0xc17890 ready for suggestion, block interval now 100 Jul 03 11:31:01-814885 ats-10346 DEBUG Suggesting address 0xc17890 for peer `9P6V' Jul 03 11:31:01-814896 ats-10346 DEBUG Recalculating bandwidth for all active connections Jul 03 11:31:01-814909 ats-10346 DEBUG New bandwidth for peer 9P6V is 1000000000/1000000000 Jul 03 11:31:01-814921 ats-10346 DEBUG ATS sends quota for peer `9P6V': (in/out) 1000000000/1000000000 Jul 03 11:31:01-815185 ats-scheduling-api-10344 DEBUG Get session ID for session 0x2383ec0 from peer KJI3 in 0x237eae0 Jul 03 11:31:01-815248 ats-scheduling-api-10344 DEBUG Get session ID for session 0x2383ec0 from peer KJI3 in 0x237eae0 Jul 03 11:31:01-815258 ats-scheduling-api-10344 DEBUG Assigning session ID 1 for session 0x2383ec0 of peer KJI3 in 0x237eae0 Jul 03 11:31:01-815345 ats-10350 DEBUG Received `ADDRESS_ADD' message Jul 03 11:31:01-815368 ats-10350 DEBUG Comparing peer KJI3AL00: address length 6 session 0 <-> address length 6 session 1 Jul 03 11:31:01-815382 ats-10350 DEBUG Updated existing address for peer `KJI3' 0x21af780 with new session 1 Jul 03 11:31:01-815406 ats-10350 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:01-815419 ats-10350 DEBUG Resetting interval for peer `KJI3' address 0x21af780 from 0 to 0 Jul 03 11:31:01-815430 ats-10350 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:01-815442 ats-10350 DEBUG Address 0x21af780 ready for suggestion, block interval now 100 Jul 03 11:31:01-815451 ats-10350 DEBUG Suggesting address 0x21af780 for peer `KJI3' Jul 03 11:31:01-815459 ats-10350 DEBUG Recalculating bandwidth for all active connections Jul 03 11:31:01-815470 ats-10350 DEBUG New bandwidth for peer KJI3 is 1000000000/1000000000 Jul 03 11:31:01-815481 ats-10350 DEBUG ATS sends quota for peer `KJI3': (in/out) 1000000000/1000000000 <snip> 0 |
|
|
Failed run: Jul 03 11:31:04-397145 ats-10380 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/ats.conf~' Jul 03 11:31:04-397335 ats-10380 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/transport.conf~' Jul 03 11:31:04-399288 ats-10380 DEBUG MLP mode 0Jul 03 11:31:04-399305 ats-10380 DEBUG ATS started with SIMPLE mode Jul 03 11:31:04-399387 ats-10380 DEBUG Received `ATS_START' message Jul 03 11:31:04-399713 ats-10380 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:04-399784 ats-10380 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:04-399807 ats-10380 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:31:04-401546 ats-10384 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/ats.conf~' Jul 03 11:31:04-401729 ats-10384 WARNING Skipping file `/home/mwachs/gnunet/gnb-debug/share/gnunet/config.d/transport.conf~' Jul 03 11:31:04-403678 ats-10384 DEBUG MLP mode 0Jul 03 11:31:04-403691 ats-10384 DEBUG ATS started with SIMPLE mode Jul 03 11:31:04-403746 ats-10384 DEBUG Received `ATS_START' message Jul 03 11:31:04-902122 ats-10380 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:05-400648 ats-10380 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:05-400721 ats-10380 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:05-400741 ats-10380 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:31:05-902526 ats-10380 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:06-406033 ats-10380 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:06-406070 ats-10380 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:06-406083 ats-10380 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:31:06-406555 ats-10384 DEBUG Received `ADDRESS_ADD' message -----> Jul 03 11:31:06-406632 ats-10384 DEBUG Added new address for peer `KJI3' session id 0, 0x1178780 Jul 03 11:31:06-406766 ats-10384 DEBUG Received `ADDRESS_ADD' message Jul 03 11:31:06-406810 ats-10384 DEBUG Comparing peer KJI3AL00: address length 6 session 0 <-> address length 6 session 0 Jul 03 11:31:06-406835 ats-10384 DEBUG Updated existing address for peer `KJI3' 0x1178780 with new session 0 Jul 03 11:31:06-908539 ats-10380 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:07-403376 ats-10380 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:07-403418 ats-10380 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:07-403433 ats-10380 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:31:07-906081 ats-10380 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:08-404591 ats-10380 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:08-404621 ats-10380 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:08-404637 ats-10380 DEBUG Cannot suggest address for peer `9P6V' <repeat repeat repeat> Jul 03 11:31:17-918383 ats-10380 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:18-416887 ats-10380 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:18-416909 ats-10380 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:18-416922 ats-10380 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:31:18-919569 ats-10380 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:19-418112 ats-10380 DEBUG Received `RESET_BACKOFF' message Jul 03 11:31:19-418136 ats-10380 DEBUG Received `REQUEST_ADDRESS' message Jul 03 11:31:19-418149 ats-10380 DEBUG Cannot suggest address for peer `9P6V' Jul 03 11:31:19-920810 ats-10380 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 11:31:20-255439 test_transport_api_wlan-10360 ERROR Fail! Could not connect peers |
|
|
In a successful run transport service gets 1 call for each peer: Jul 03 14:50:47-334896 transport-14384 ERROR plugin_env_address_change_notification: `13:22:33:44:73:D8' Jul 03 14:50:47-334890 transport-14385 ERROR plugin_env_address_change_notification: `13:22:33:44:93:A8' When test fails: Jul 03 14:50:51-918993 ats-14418 DEBUG Received `ATS_START' message Jul 03 14:50:51-919028 transport-14411 ERROR plugin_env_address_change_notification: `13:22:33:44:C1:11' Jul 03 14:50:51-919214 transport-14412 ERROR plugin_env_address_change_notification: `13:22:33:44:00:AA' Jul 03 14:50:52-420332 ats-14414 DEBUG Received `REQUEST_ADDRESS_CANCEL' message Jul 03 14:50:52-918685 transport-testing-14394 DEBUG Asking peer 1 (`KJI3') to connect peer 2 (`9P6V'), providing HELLO with 293 bytes Jul 03 14:50:52-919043 ats-14414 DEBUG Received `RESET_BACKOFF' message Jul 03 14:50:52-919065 ats-14414 DEBUG Received `REQUEST_ADDRESS' message Jul 03 14:50:52-919075 ats-14414 DEBUG Cannot suggest address for peer `9P6V' Jul 03 14:50:52-921685 transport-14411 ERROR plugin_env_address_change_notification: `13:22:33:44:C1:11' Jul 03 14:50:52-921728 transport-14411 ERROR plugin_env_address_change_notification: `13:22:33:44:5B:D7' Jul 03 14:50:52-921745 transport-14412 ERROR plugin_env_address_change_notification: `13:22:33:44:00:AA' Jul 03 14:50:52-921778 transport-14412 ERROR plugin_env_address_change_notification: `13:22:33:44:97:2D' |
|
|
for one of two peers: transport-neighbourd does not validate addresses included in HELLO message (Here some GNUNET_break debugging) Jul 03 17:26:23-340676 transport-2046 ERROR Refreshed my `HELLO', new size is 293 Jul 03 17:26:23-340709 transport-2047 ERROR Refreshed my `HELLO', new size is 293 Jul 03 17:26:23-340873 transport-testing-2029 ERROR Got new HELLO for peer `KJI3' with size 293 Jul 03 17:26:23-340957 transport-testing-2029 ERROR Got new HELLO for peer `9P6V' with size 293 Jul 03 17:26:23-840140 ats-2049 DEBUG Received `REQUEST_ADDRESS_CANCEL' message -> It should look like: Jul 03 17:26:24-331161 transport-2047 ERROR Adding `HELLO' without addresses for peer `KJI3' Jul 03 17:26:24-331191 transport-2047 ERROR Assertion failed at gnunet-service-transport_validation.c:1150. Jul 03 17:26:24-331220 transport-2047 ERROR Assertion failed at gnunet-service-transport_validation.c:979. Jul 03 17:26:24-331256 transport-2047 ERROR Assertion failed at gnunet-service-transport_validation.c:529. Jul 03 17:26:24-331268 transport-2047 ERROR Assertion failed at gnunet-service-transport_validation.c:535. Jul 03 17:26:24-331283 transport-2047 ERROR Assertion failed at gnunet-service-transport_validation.c:575. Jul 03 17:26:24-331294 transport-2047 ERROR Assertion failed at gnunet-service-transport_validation.c:458. Jul 03 17:26:24-331327 transport-2047 ERROR Assertion failed at gnunet-service-transport_validation.c:497. -> But it is: Jul 03 17:26:24-331628 transport-2046 ERROR Adding `HELLO' without addresses for peer `9P6V' Jul 03 17:26:24-331648 transport-2046 ERROR Assertion failed at gnunet-service-transport_validation.c:1150. Jul 03 17:26:24-331661 transport-2046 ERROR Assertion failed at gnunet-service-transport_validation.c:979. Jul 03 17:26:24-338293 transport-2046 ERROR Adding `HELLO' without addresses for peer `9P6V' |
|
|
Mystery solved: transport validation does not validate new HELLO message in validate_address_iterator because ve->revalidation_task is scheduled |
|
|
when new addresses should get validated, hello lib does not compare addresses correct, so an old and blocked! ve is returned and address is never validated! -> cannot be used for test -> tests fail! |
|
|
Caused by 0002480 and 0002481 Fixed with revision 22474 |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2012-06-30 13:54 | Christian Grothoff | New Issue | |
| 2012-06-30 13:54 | Christian Grothoff | Status | new => assigned |
| 2012-06-30 13:54 | Christian Grothoff | Assigned To | => Matthias Wachs |
| 2012-07-02 12:49 | Matthias Wachs | Note Added: 0006188 | |
| 2012-07-03 11:32 | Matthias Wachs | Note Added: 0006196 | |
| 2012-07-03 11:33 | Matthias Wachs | Note Edited: 0006196 | |
| 2012-07-03 11:34 | Matthias Wachs | Note Added: 0006197 | |
| 2012-07-03 14:53 | Matthias Wachs | Note Added: 0006200 | |
| 2012-07-03 17:33 | Matthias Wachs | Note Added: 0006202 | |
| 2012-07-03 17:44 | Matthias Wachs | Note Added: 0006203 | |
| 2012-07-03 17:44 | Matthias Wachs | Status | assigned => confirmed |
| 2012-07-04 09:31 | Christian Grothoff | Target Version | => 0.9.4 |
| 2012-07-04 09:31 | Christian Grothoff | Status | confirmed => assigned |
| 2012-07-04 09:31 | Christian Grothoff | Priority | normal => high |
| 2012-07-04 11:31 | Matthias Wachs | Relationship added | related to 0002480 |
| 2012-07-04 11:33 | Matthias Wachs | Note Added: 0006205 | |
| 2012-07-04 14:13 | Matthias Wachs | Relationship added | related to 0002481 |
| 2012-07-04 14:13 | Matthias Wachs | Note Added: 0006208 | |
| 2012-07-04 14:14 | Matthias Wachs | Status | assigned => resolved |
| 2012-07-04 14:14 | Matthias Wachs | Resolution | open => fixed |
| 2012-11-05 18:34 | Christian Grothoff | Status | resolved => closed |
