View Issue Details

IDProjectCategoryView StatusLast Update
0005818GNUnetcadet servicepublic2019-08-04 18:41
ReporterschanzenAssigned To 
PrioritynormalSeverityminorReproducibilityhave not tried
Status confirmedResolutionopen 
Product Version 
Target Version0.11.7Fixed in Version 
Summary0005818: test_cadet_2_keepalive always fails
DescriptionLooking at the test, it seems to run fine. But the success condition is odd:
/* Test is supposed to generate the following callbacks:
  * 1 incoming channel (@dest)
   * [wait]
    * 1 received channel destroy (@dest)
    */

This does not make sense as the test simply times out without incrementing the "ok" counter on channel destroy. Hence ok == 1 and never 2.
This should reliably fail though?
Steps To ReproduceJul 23 14:32:40-606276 test-92298 DEBUG DIRECT CONNECTIONs
Jul 23 14:32:40-609447 test_cadet_small-92298 DEBUG Starting HELPER process `/Users/schanzen/gnunet/build/lib//gnunet/libexec/gnunet-helper-testbed'
Jul 23 14:32:40-611112 test_cadet_small-92298 DEBUG Transmitted 4425 bytes to /Users/schanzen/gnunet/build/lib//gnunet/libexec/gnunet-helper-testbed
Jul 23 14:32:40-633349 test_cadet_small-92298 DEBUG Got 4522 bytes from helper `/Users/schanzen/gnunet/build/lib//gnunet/libexec/gnunet-helper-testbed'
Jul 23 14:32:40-872335 transport-92336 ERROR Assertion failed at nt.c:332.
Jul 23 14:32:40-873045 transport-udp-92336 WARNING Failed to join IPv6 multicast group: IPv6 broadcasting not running
Jul 23 14:32:40-873063 transport-92336 ERROR Assertion failed at nt.c:332.
Jul 23 14:32:40-873071 transport-udp-92336 WARNING Failed to join IPv6 multicast group: IPv6 broadcasting not running
Jul 23 14:32:40-879325 transport-92337 ERROR Assertion failed at nt.c:332.
Jul 23 14:32:40-879964 transport-udp-92337 WARNING Failed to join IPv6 multicast group: IPv6 broadcasting not running
Jul 23 14:32:40-880099 transport-92337 ERROR Assertion failed at nt.c:332.
Jul 23 14:32:40-880208 transport-udp-92337 WARNING Failed to join IPv6 multicast group: IPv6 broadcasting not running
Jul 23 14:32:40-885894 gnunet-rest-server-92326 ERROR `bind' failed at gnunet-rest-server.c:942 with error: Address already in use
Jul 23 14:32:40-890447 gnunet-rest-server-92327 ERROR `bind' failed at gnunet-rest-server.c:942 with error: Address already in use
Jul 23 14:32:40-901361 gnunet-rest-server-92327 ERROR `bind' failed at gnunet-rest-server.c:963 with error: Address already in use
Jul 23 14:32:40-901767 util-os-installation-92338 WARNING `access' failed on file `/Users/schanzen/gnunet/build/lib//gnunet/libexec/gnunet-helper-nat-server' at os_installation.c:938 with error: No such file or directory
Jul 23 14:32:40-902567 util-os-installation-92338 WARNING `access' failed on file `/Users/schanzen/gnunet/build/lib//gnunet/libexec/gnunet-helper-nat-server' at os_installation.c:938 with error: No such file or directory
Jul 23 14:32:40-907283 util-os-installation-92339 WARNING `access' failed on file `/Users/schanzen/gnunet/build/lib//gnunet/libexec/gnunet-helper-nat-server' at os_installation.c:938 with error: No such file or directory
Jul 23 14:32:40-907743 util-os-installation-92339 WARNING `access' failed on file `/Users/schanzen/gnunet/build/lib//gnunet/libexec/gnunet-helper-nat-server' at os_installation.c:938 with error: No such file or directory
Jul 23 14:32:40-927484 util-network-92337 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:40-927572 transport-udp-92337 WARNING UDP could not transmit message to `[fe80::1]:12035': `No route to host'
Jul 23 14:32:40-942732 transport-udp-92336 WARNING UDP could not transmit message to `[fe80::1c33:88ed:2960:3e2d]:12043': `No route to host'
Jul 23 14:32:40-942762 transport-udp-92336 WARNING UDP could not transmit message to `[fe80::aede:48ff:fe00:1122]:12043': `No route to host'
Jul 23 14:32:40-942774 transport-udp-92336 WARNING UDP could not transmit message to `[fe80::ed58:df6b:2fb6:8179]:12043': `No route to host'
Jul 23 14:32:40-942785 transport-udp-92336 WARNING UDP could not transmit message to `[fe80::74b5:23ff:fe6e:793d]:12043': `No route to host'
Jul 23 14:32:40-942795 transport-udp-92336 WARNING UDP could not transmit message to `[fe80::8d0:6427:a15d:80aa]:12043': `No route to host'
Jul 23 14:32:40-942806 transport-udp-92336 WARNING UDP could not transmit message to `[fe80::1]:12043': `No route to host'
Jul 23 14:32:40-942901 util-network-92336 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:40-969043 util-network-92336 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:40-970264 util-network-92337 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:40-970336 transport-udp-92337 WARNING UDP could not transmit message to `[fe80::1c33:88ed:2960:3e2d]:12035': `No route to host'
Jul 23 14:32:40-970358 transport-udp-92337 WARNING UDP could not transmit message to `[fe80::aede:48ff:fe00:1122]:12035': `No route to host'
Jul 23 14:32:40-970370 transport-udp-92337 WARNING UDP could not transmit message to `[fe80::ed58:df6b:2fb6:8179]:12035': `No route to host'
Jul 23 14:32:40-970381 transport-udp-92337 WARNING UDP could not transmit message to `[fe80::74b5:23ff:fe6e:793d]:12035': `No route to host'
Jul 23 14:32:40-970393 transport-udp-92337 WARNING UDP could not transmit message to `[fe80::8d0:6427:a15d:80aa]:12035': `No route to host'
Jul 23 14:32:40-975875 util-network-92336 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:40-991040 util-network-92336 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:40-998913 util-network-92337 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:41-008635 util-network-92337 WARNING `setsockopt' failed at network.c:355 with error: Invalid argument
Jul 23 14:32:41-031864 test_cadet_small-92298 DEBUG Testbed up, 2 peers and 1 links
Jul 23 14:32:41-031909 test_cadet_small-92298 INFO Connecting to cadet 0
Jul 23 14:32:41-031924 test_cadet_small-92298 INFO op handle 0x7fe6bdd00430
Jul 23 14:32:41-031928 test_cadet_small-92298 INFO Connecting to cadet 1
Jul 23 14:32:41-031934 test_cadet_small-92298 INFO op handle 0x7fe6bdd00620
Jul 23 14:32:41-038231 test_cadet_small-92298 DEBUG Listening to CADET port 38KQGBKV
Jul 23 14:32:41-038255 test_cadet_small-92298 INFO ...cadet 0 connected
Jul 23 14:32:41-038912 test_cadet_small-92298 DEBUG Listening to CADET port 38KQGBKV
Jul 23 14:32:41-038922 test_cadet_small-92298 INFO ...cadet 1 connected
Jul 23 14:32:41-038928 test_cadet_small-92298 DEBUG test main
Jul 23 14:32:41-038959 test_cadet_small-92298 DEBUG requested peer ids
Jul 23 14:32:41-039595 test_cadet_small-92298 DEBUG ID callback for 0
Jul 23 14:32:41-039613 test_cadet_small-92298 DEBUG id: 6DEV
Jul 23 14:32:41-040131 test_cadet_small-92298 DEBUG ID callback for 1
Jul 23 14:32:41-040154 test_cadet_small-92298 DEBUG id: 6YNB
Jul 23 14:32:41-040159 test_cadet_small-92298 DEBUG Got all IDs, starting test
Jul 23 14:32:41-040188 test_cadet_small-92298 DEBUG start_test: (null)
Jul 23 14:32:41-040196 test_cadet_small-92298 DEBUG Creating channel to peer 6YNB at port 38KQGBKV
Jul 23 14:32:42-090712 test_cadet_small-92298 INFO Incoming channel from 6DEV to 1: 0x7fe6bdc1f450
Jul 23 14:32:42-090777 test_cadet_small-92298 INFO ok: 1
Jul 23 14:33:02-096195 test_cadet_small-92298 INFO gathering statistics from line 952
Jul 23 14:33:02-096255 test_cadet_small-92298 INFO Destroying channel due to GNUNET_CADET_channel_destroy()
Jul 23 14:33:02-103272 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# keepalives received]: 19
Jul 23 14:33:02-103337 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# decrypted bytes]: 152
Jul 23 14:33:02-103374 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# keepalives received]: 19
Jul 23 14:33:02-103389 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# encrypted bytes]: 152
Jul 23 14:33:02-103414 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# decrypted bytes]: 152
Jul 23 14:33:02-103426 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# keepalives sent]: 19
Jul 23 14:33:02-103451 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# encrypted bytes]: 152
Jul 23 14:33:02-103480 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# keepalives sent]: 19
Jul 23 14:33:02-103509 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# DHT announce]: 5
Jul 23 14:33:02-103777 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# DHT announce]: 5
Jul 23 14:33:02-103858 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# channels]: 2
Jul 23 14:33:02-103885 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# KX_AUTH received]: 1
Jul 23 14:33:02-103897 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# KX_AUTH transmitted]: 1
Jul 23 14:33:02-103916 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# KX transmitted]: 1
Jul 23 14:33:02-103926 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# Fresh KX setup]: 1
Jul 23 14:33:02-103942 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# channels]: 1
Jul 23 14:33:02-103952 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# KX received]: 1
Jul 23 14:33:02-103970 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# DHT search]: 1
Jul 23 14:33:02-103981 test_cadet_small-92298 INFO STATS PEER 1 - cadet [# clients]: 1
Jul 23 14:33:02-104334 test_cadet_small-92298 DEBUG Cleaning all up
Jul 23 14:33:02-104644 test_cadet_small-92298 INFO STATS PEER 0 - cadet [# clients]: 1
Jul 23 14:33:02-104677 test_cadet_small-92298 INFO KA sent: 19, KA received: 19
Jul 23 14:33:02-105062 test_cadet_small-92298 DEBUG Cleaning all up
Jul 23 14:33:02-105275 test_cadet_small-92298 INFO disconnecting cadet service of peers, called from line 952
Jul 23 14:33:02-105293 test_cadet_small-92298 INFO Destroying channel due to GNUNET_CADET_channel_destroy()
Jul 23 14:33:02-106016 test_cadet_small-92298 DEBUG Ending test.
Jul 23 14:33:02-133134 test_cadet_small-92298 ERROR FAILED! (1/2)
TagsNo tags attached.

Activities

ch3

2019-07-23 15:41

developer   ~0014727

For me it looks like this:
Jul 23 15:31:40-907517 gnunet-rest-server-13886 ERROR `bind' failed at gnunet-rest-server.c:942 with error: Address already in use
Jul 23 15:31:40-907620 gnunet-rest-server-13886 ERROR `bind' failed at gnunet-rest-server.c:963 with error: Address already in use
Jul 23 15:31:40-934118 gnunet-rest-server-13882 ERROR `bind' failed at gnunet-rest-server.c:942 with error: Address already in use
Jul 23 15:31:40-946850 gnunet-rest-server-13882 ERROR `bind' failed at gnunet-rest-server.c:963 with error: Address already in use
Jul 23 15:32:02-479956 transport-api-core-13888 ERROR Error receiving from transport service (1), disconnecting temporarily.

Returning with a successful return value.

(I hat a gnunet peer running in parallel.)

ch3

2019-07-23 15:46

developer   ~0014728

Without running gnunet peer and debug messages enabled:

$ GNUNET_FORCE_LOG="test_cadet_small;;;;DEBUG" ./test_cadet_2_keepalive
Jul 23 15:42:10-346039 test-16447 DEBUG DIRECT CONNECTIONs
Jul 23 15:42:10-350543 test_cadet_small-16447 DEBUG Starting HELPER process `/home/gnunet/prefix_gn/lib//gnunet/libexec/gnunet-helper-testbed'
Jul 23 15:42:10-353270 test_cadet_small-16447 DEBUG Transmitted 5204 bytes to /home/gnunet/prefix_gn/lib//gnunet/libexec/gnunet-helper-testbed
Jul 23 15:42:10-371664 test_cadet_small-16447 DEBUG Got 5281 bytes from helper `/home/gnunet/prefix_gn/lib//gnunet/libexec/gnunet-helper-testbed'
Jul 23 15:42:10-493588 gnunet-rest-server-16482 ERROR `bind' failed at gnunet-rest-server.c:942 with error: Address already in use
Jul 23 15:42:10-493687 gnunet-rest-server-16482 ERROR `bind' failed at gnunet-rest-server.c:963 with error: Address already in use
Jul 23 15:42:10-521677 util-plugin-16475 ERROR `lt_dlopenext' failed for library `libgnunet_plugin_rest_identity_provider' with error: file not found
Jul 23 15:42:10-650032 test_cadet_small-16447 DEBUG Testbed up, 2 peers and 1 links
Jul 23 15:42:10-650094 test_cadet_small-16447 INFO Connecting to cadet 0
Jul 23 15:42:10-650131 test_cadet_small-16447 INFO op handle 0x55ecbc627f70
Jul 23 15:42:10-650151 test_cadet_small-16447 INFO Connecting to cadet 1
Jul 23 15:42:10-650173 test_cadet_small-16447 INFO op handle 0x55ecbc628390
Jul 23 15:42:10-657460 test_cadet_small-16447 DEBUG Listening to CADET port 38KQGBKV
Jul 23 15:42:10-657505 test_cadet_small-16447 INFO ...cadet 0 connected
Jul 23 15:42:10-659092 test_cadet_small-16447 DEBUG Listening to CADET port 38KQGBKV
Jul 23 15:42:10-659127 test_cadet_small-16447 INFO ...cadet 1 connected
Jul 23 15:42:10-659152 test_cadet_small-16447 DEBUG test main
Jul 23 15:42:10-659189 test_cadet_small-16447 DEBUG requested peer ids
Jul 23 15:42:10-661700 test_cadet_small-16447 DEBUG ID callback for 0
Jul 23 15:42:10-661739 test_cadet_small-16447 DEBUG id: 6DEV
Jul 23 15:42:10-661782 test_cadet_small-16447 DEBUG ID callback for 1
Jul 23 15:42:10-661803 test_cadet_small-16447 DEBUG id: 6YNB
Jul 23 15:42:10-661824 test_cadet_small-16447 DEBUG Got all IDs, starting test
Jul 23 15:42:10-661859 test_cadet_small-16447 DEBUG start_test: (null)
Jul 23 15:42:10-661887 test_cadet_small-16447 DEBUG Creating channel to peer 6YNB at port 38KQGBKV
Jul 23 15:42:11-736693 test_cadet_small-16447 INFO Incoming channel from 6DEV to 1: 0x55ecbc644900
Jul 23 15:42:11-736751 test_cadet_small-16447 INFO ok: 1
Jul 23 15:42:31-757008 test_cadet_small-16447 INFO gathering statistics from line 952
Jul 23 15:42:31-757164 test_cadet_small-16447 INFO Destroying channel due to GNUNET_CADET_channel_destroy()
Jul 23 15:42:31-772470 test_cadet_small-16447 INFO Channel disconnected at 1
Jul 23 15:42:31-772697 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# encrypted bytes]: 164
Jul 23 15:42:31-772873 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# decrypted bytes]: 164
Jul 23 15:42:31-772991 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# keepalives received]: 19
Jul 23 15:42:31-773126 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# decrypted bytes]: 152
Jul 23 15:42:31-773181 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# keepalives received]: 19
Jul 23 15:42:31-773220 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# keepalives sent]: 19
Jul 23 15:42:31-773270 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# encrypted bytes]: 152
Jul 23 15:42:31-773307 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# DHT announce]: 5
Jul 23 15:42:31-773356 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# keepalives sent]: 19
Jul 23 15:42:31-773394 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# KX_AUTH received]: 1
Jul 23 15:42:31-773442 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# DHT announce]: 5
Jul 23 15:42:31-773480 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# KX transmitted]: 1
Jul 23 15:42:31-773529 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# channels]: 2
Jul 23 15:42:31-773565 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# channels]: 1
Jul 23 15:42:31-773614 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# KX_AUTH transmitted]: 1
Jul 23 15:42:31-773650 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# DHT search]: 1
Jul 23 15:42:31-773698 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# Fresh KX setup]: 1
Jul 23 15:42:31-773735 test_cadet_small-16447 INFO STATS PEER 0 - cadet [# clients]: 1
Jul 23 15:42:31-774011 test_cadet_small-16447 DEBUG Cleaning all up
Jul 23 15:42:31-774076 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# KX received]: 1
Jul 23 15:42:31-774377 test_cadet_small-16447 INFO STATS PEER 1 - cadet [# clients]: 1
Jul 23 15:42:31-774439 test_cadet_small-16447 INFO KA sent: 19, KA received: 19
Jul 23 15:42:31-774700 test_cadet_small-16447 DEBUG Cleaning all up
Jul 23 15:42:31-774771 test_cadet_small-16447 INFO disconnecting cadet service of peers, called from line 952
Jul 23 15:42:31-775695 test_cadet_small-16447 DEBUG Ending test.
Jul 23 15:42:31-797608 test_cadet_small-16447 DEBUG success

schanzen

2019-07-23 16:44

developer   ~0014730

Last edited: 2019-07-23 17:15

View 2 revisions

test_cadet.c seems to think the CADET_channel_destroy() API still calls the disconnect callback. But it doesn't as of 7caba06019.
The whole test is thus build on a flawed assumption and probably must be rewritten.

schanzen

2019-07-23 16:59

developer   ~0014731

This happens on both Debian 9 and macOS for me.

schanzen

2019-07-23 17:23

developer   ~0014732

I shaved off the requirement of the disconnect ACKs in 91fa8e7cab1fdfcb4c52f79f459b899c7d9302f0 for now.
Still, this test needs be rewritten at some point...

xrs

2019-08-04 18:40

manager   ~0014771

test_cadet_2_keepalive only fails sometimes for me.

@schanzen: The success condition for this test is that keepalives have been seen by the receiving peer. This is done by asking gnunet-statistics. Thus, the two endpoints just have to establish a connection and do nothing and let cadet do the tunnel maintanance by processing keepalives.

Should we close this ticket?

test_cadet_2_keepalive.log (86,836 bytes)

schanzen

2019-08-04 18:41

developer   ~0014772

No, because this test needs to be rewritten to reflect the API change (see above). It currently has broken logic.

Issue History

Date Modified Username Field Change
2019-07-23 14:40 schanzen New Issue
2019-07-23 15:41 ch3 Note Added: 0014727
2019-07-23 15:46 ch3 Note Added: 0014728
2019-07-23 16:44 schanzen Note Added: 0014730
2019-07-23 16:59 schanzen Note Added: 0014731
2019-07-23 17:15 schanzen Note Edited: 0014730 View Revisions
2019-07-23 17:23 schanzen Note Added: 0014732
2019-07-23 17:23 schanzen Assigned To => schanzen
2019-07-23 17:23 schanzen Status new => confirmed
2019-08-01 10:36 schanzen Assigned To schanzen =>
2019-08-01 12:27 schanzen Target Version => 0.11.7
2019-08-04 18:40 xrs File Added: test_cadet_2_keepalive.log
2019-08-04 18:40 xrs Note Added: 0014771
2019-08-04 18:41 schanzen Note Added: 0014772