View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0004897GNUnetcadet servicepublic2017-02-16 16:402018-06-07 00:24
Reporterlurchi Assigned ToChristian Grothoff  
PrioritynormalSeveritymajorReproducibilitysometimes
Status closedResolutionfixed 
OSDebian 
Product VersionGit master 
Target Version0.11.0pre66Fixed in Version0.11.0pre66 
Summary0004897: Received duplicate CADET_CONNECTION_CREATE message
Descriptiongnunet-cadet cannot create a connection sometimes. Either I get the logs described in 0004896, or I get this. Not sure, if 0004895 awoke from the dead or if this is something new.
Steps To Reproducestarting with a clear gnunet directory (./test in my case)
-GNUNET_FORCE_LOG="cadet;;;;DEBUG" gnunet-arm -s on both peers
-exchanging hellos using gnunet-peerinfo -g and gnunet-peerinfo -p
-gnunet-cadet -o 9999
-gnunet-cadet 7ER4YGE848FA4MN5EDNEFAKB8N4VWX1N9SR9AMZ0HZ03GBNKM8W0 9999
Additional Information[arm]
SYSTEM_ONLY = NO
USER_ONLY = NO

[hostlist]
AUTOSTART = NO
FORCESTART = NO

#[topology]
#FRIENDS-ONLY = YES

[peerinfo]
USE_INCLUDED_HELLOS = NO

[transport-udp]
BROADCAST = NO

[fs]
AUTOSTART = NO
FORCESTART = NO

[nse]
FORCESTART = NO

[set]
FORCESTART = NO

[statistics]
FORCESTART = NO

[vpn]
FORCESTART = NO

[PATHS]
GNUNET_HOME = ./test

[conversation]
LINE = 2
TagsNo tags attached.
Attached Files
20160216.2.txt (14,203 bytes)    
Feb 16 16:30:22-035068 cadet-20787 INFO CADET started for peer Z1HN
Feb 16 16:30:22-045143 cadet-api-20792 DEBUG GNUNET_CADET_connect() 0x1208570
Feb 16 16:30:22-045377 cadet-api-20792 DEBUG Connecting to CADET
Feb 16 16:30:22-045809 cadet-20787 DEBUG Client(0) connected
Feb 16 16:30:22-058512 cadet-20787 DEBUG Open port X4QX93K5 requested by Client(0)
Feb 16 16:30:22-091222 cadet-api-20795 DEBUG GNUNET_CADET_connect() 0x1846e90
Feb 16 16:30:22-091344 cadet-api-20795 DEBUG Connecting to CADET
Feb 16 16:30:22-092456 cadet-20787 DEBUG Client(1) connected
Feb 16 16:30:22-120124 cadet-hll-20787 DEBUG Hello for MYD5 (472 bytes), expires on Fri Feb 17 04:28:55 2017
Feb 16 16:30:22-121728 cadet-per-20787 DEBUG Creating peer P(MYD5)
Feb 16 16:30:22-121779 cadet-per-20787 DEBUG Got 472 byte HELLO for peer P(MYD5)
Feb 16 16:30:22-133782 cadet-cor-20787 DEBUG CORE connection to peer Z1HN was established.
Feb 16 16:30:22-133858 cadet-per-20787 DEBUG Creating peer P(Z1HN)
Feb 16 16:30:22-133959 cadet-per-20787 DEBUG Message queue for peer P(Z1HN) is now 0x22264b0
Feb 16 16:30:22-134008 cadet-per-20787 DEBUG Updating peer P(Z1HN) activation state (0 connections) with CORE link
Feb 16 16:30:22-177604 nat-20805 ERROR UPnP enabled in configuration, but UPnP client `upnpc` command not found, disabling UPnP
Feb 16 16:30:22-300810 cadet-dht-20787 DEBUG Announcing my HELLO (472 bytes) in the DHT
Feb 16 16:30:23-641730 transport-20799 WARNING External protocol violation detected at plugin_transport_udp.c:1275.
Feb 16 16:30:25-591011 cadet-20787 DEBUG Client(2) connected
Feb 16 16:30:25-591318 cadet-20787 DEBUG Open port PR96BHN5 requested by Client(2)
Feb 16 16:30:28-322305 cadet-cor-20787 DEBUG CORE connection to peer MYD5 was established.
Feb 16 16:30:28-322434 cadet-per-20787 DEBUG Message queue for peer P(MYD5) is now 0x2227070
Feb 16 16:30:28-322483 cadet-per-20787 DEBUG Updating peer P(MYD5) activation state (0 connections) with CORE link
Feb 16 16:30:29-324521 cadet-api-20792 DEBUG Creating new channel to MYD5:701077288 at 0x1222e70 number 80000000
Feb 16 16:30:29-324808 cadet-api-20792 DEBUG CADET NOTIFY TRANSMIT READY on channel 80000000 allow_send is 0 to origin with 76 bytes
Feb 16 16:30:29-325092 cadet-20787 DEBUG New channel to MYD5 at port X4QX93K5 requested by Client(0)
Feb 16 16:30:29-325138 cadet-tun-20787 DEBUG Creating new ephemeral ratchet key (DHRs)
Feb 16 16:30:29-333334 cadet-per-20787 DEBUG Updating peer P(MYD5) activation state (0 connections) with tunnel with CORE link
Feb 16 16:30:29-333404 cadet-tun-20787 DEBUG Adding Channel MYD5:X4QX93K5 ctn:0(80000000/0) to Tunnel MYD5
Feb 16 16:30:29-333441 cadet-chn-20787 DEBUG Created channel to port X4QX93K5 at peer P(MYD5) for Client(0) using Tunnel MYD5
Feb 16 16:30:29-334740 cadet-tun-20787 DEBUG Performing connection maintenance for Tunnel MYD5.
Feb 16 16:30:29-334775 cadet-per-20787 DEBUG Iterating over paths to peer P(MYD5) including direct link
Feb 16 16:30:29-334800 cadet-per-20787 DEBUG Asked to look for paths at distance 0, but maximum for me is < 0
Feb 16 16:30:29-334828 cadet-per-20787 DEBUG Discovered that peer P(MYD5) is on path MYD5(0x220fb90) at offset 0
Feb 16 16:30:29-334870 cadet-con-20787 DEBUG Creating Connection KXWN7W (Tunnel MYD5) using path MYD5(0x220fb90)
Feb 16 16:30:29-334898 cadet-pat-20787 DEBUG Adding connection Connection KXWN7W (Tunnel MYD5) to path MYD5(0x220fb90) at offset 0
Feb 16 16:30:29-334923 cadet-per-20787 DEBUG Creating MQM 0x2227ee0 for peer P(MYD5)
Feb 16 16:30:29-334949 cadet-con-20787 DEBUG Core MQ for Connection KXWN7W (Tunnel MYD5) became available in state 0
Feb 16 16:30:29-334979 cadet-tun-20787 DEBUG Found interesting path MYD5(0x220fb90) for Tunnel MYD5, created Connection KXWN7W (Tunnel MYD5)
Feb 16 16:30:29-335003 cadet-pat-20787 DEBUG Created new path MYD5(0x220fb90) to create inverse for incoming connection
Feb 16 16:30:29-335029 cadet-per-20787 DEBUG Attaching path MYD5(0x220fb90) to peer P(MYD5) (forced)
Feb 16 16:30:29-335055 cadet-tun-20787 DEBUG Ignoring duplicate path MYD5(0x220fb90).
Feb 16 16:30:29-335078 cadet-tun-20787 DEBUG Ignoring duplicate path MYD5(0x220fb90).
Feb 16 16:30:29-335141 cadet-con-20787 DEBUG Sending CADET_CONNECTION_CREATE message for Connection KXWN7W (Tunnel MYD5)
Feb 16 16:30:29-335166 cadet-per-20787 DEBUG Queueing message to peer P(MYD5) in MQM 0x2227ee0
Feb 16 16:30:29-335193 cadet-per-20787 DEBUG Sending to peer P(MYD5) from MQM 0x2227ee0
Feb 16 16:30:29-335229 cadet-con-20787 DEBUG Core MQ for Connection KXWN7W (Tunnel MYD5) became available in state 2
Feb 16 16:30:29-337359 cadet-con-20787 DEBUG Sending CADET_CONNECTION_CREATE message for Connection KXWN7W (Tunnel MYD5)
Feb 16 16:30:29-337394 cadet-per-20787 DEBUG Queueing message to peer P(MYD5) in MQM 0x2227ee0
Feb 16 16:30:31-435512 cadet-cor-20787 DEBUG Received CADET_CONNECTION_CREATE message from P(MYD5) for connection T02JVM, building inverse path
Feb 16 16:30:31-436291 cadet-pat-20787 DEBUG check_match found match with path MYD5(0x220fb90)
Feb 16 16:30:31-436338 cadet-pat-20787 DEBUG Returning existing path MYD5(0x220fb90) as inverse for incoming connection
Feb 16 16:30:31-436395 cadet-con-20787 DEBUG Got two connections on MYD5(0x220fb90), dropping my existing Connection KXWN7W (Tunnel MYD5)
Feb 16 16:30:31-436701 cadet-per-20787 DEBUG Destroying MQM 0x2227ee0 for peer P(MYD5) with last ditch transmission
Feb 16 16:30:31-436751 cadet-con-20787 DEBUG Destroying Connection KXWN7W
Feb 16 16:30:31-436795 cadet-pat-20787 DEBUG Removing connection Connection KXWN7W to path MYD5(0x220fb90) at offset 0
Feb 16 16:30:31-436845 cadet-con-20787 DEBUG Creating Connection T02JVM (Tunnel MYD5) using path MYD5(0x220fb90)
Feb 16 16:30:31-436888 cadet-pat-20787 DEBUG Adding connection Connection T02JVM (Tunnel MYD5) to path MYD5(0x220fb90) at offset 0
Feb 16 16:30:31-436927 cadet-per-20787 DEBUG Creating MQM 0x2227ee0 for peer P(MYD5)
Feb 16 16:30:31-436968 cadet-con-20787 DEBUG Core MQ for Connection T02JVM (Tunnel MYD5) became available in state 3
Feb 16 16:30:31-437022 cadet-tun-20787 DEBUG Tunnel MYD5 has new Connection T02JVM (Tunnel MYD5)
Feb 16 16:30:31-437093 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-437136 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5), scheduling another ACK (MQM ready)
Feb 16 16:30:31-437203 cadet-con-20787 DEBUG Sending CONNECTION_CREATE_ACK message for Connection T02JVM (Tunnel MYD5)
Feb 16 16:30:31-437242 cadet-per-20787 DEBUG Queueing message to peer P(MYD5) in MQM 0x2227ee0
Feb 16 16:30:31-442919 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-442994 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5). MQ is busy, not queueing another ACK
Feb 16 16:30:31-448517 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-448585 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5). MQ is busy, not queueing another ACK
Feb 16 16:30:31-464244 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-464312 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5). MQ is busy, not queueing another ACK
Feb 16 16:30:31-496174 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-496242 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5). MQ is busy, not queueing another ACK
Feb 16 16:30:31-560305 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-560373 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5). MQ is busy, not queueing another ACK
Feb 16 16:30:31-688043 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-688089 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5). MQ is busy, not queueing another ACK
Feb 16 16:30:31-825016 core-20791 WARNING Client waited 3501 ms for permission to transmit to `MYD5' (priority 1)
Feb 16 16:30:31-825441 cadet-per-20787 DEBUG Sending to peer P(MYD5) completed
Feb 16 16:30:31-825487 cadet-per-20787 DEBUG Sending to peer P(MYD5) from MQM 0x2227ee0
Feb 16 16:30:31-825528 cadet-tun-20787 DEBUG Connection T02JVM (Tunnel MYD5) now ready for Tunnel MYD5 in state CADET_TUNNEL_KEY_UNINITIALIZED
Feb 16 16:30:31-825566 cadet-tun-20787 DEBUG Sending KX on Tunnel MYD5 via Connection T02JVM (Tunnel MYD5) using CADET_TUNNEL_KEY_UNINITIALIZED in state Ё"
Feb 16 16:30:31-825679 core-20791 WARNING Client waited 3501 ms for transmission of 348 bytes to `MYD5' (uncorked)
Feb 16 16:30:31-832625 cadet-tun-20787 DEBUG Tunnel MYD5 estate changed from CADET_TUNNEL_KEY_UNINITIALIZED to CADET_TUNNEL_KEY_AX_SENT
Feb 16 16:30:31-832673 cadet-con-20787 DEBUG Scheduling message for transmission on Connection T02JVM (Tunnel MYD5)
Feb 16 16:30:31-832707 cadet-per-20787 DEBUG Queueing message to peer P(MYD5) in MQM 0x2227ee0
Feb 16 16:30:31-832738 cadet-con-20787 DEBUG Core MQ for Connection T02JVM (Tunnel MYD5) became available in state 4
Feb 16 16:30:31-835700 cadet-per-20787 DEBUG Sending to peer P(MYD5) completed
Feb 16 16:30:31-835741 cadet-per-20787 DEBUG Sending to peer P(MYD5) from MQM 0x2227ee0
Feb 16 16:30:31-835775 cadet-tun-20787 DEBUG Connection T02JVM (Tunnel MYD5) now ready for Tunnel MYD5 in state CADET_TUNNEL_KEY_AX_SENT
Feb 16 16:30:31-835808 cadet-con-20787 DEBUG Core MQ for Connection T02JVM (Tunnel MYD5) became available in state 4
Feb 16 16:30:31-835845 cadet-con-20787 DEBUG Scheduling keepalive for Connection T02JVM (Tunnel MYD5) in 5 m
Feb 16 16:30:31-837209 cadet-per-20787 DEBUG Sending to peer P(MYD5) completed
Feb 16 16:30:31-944847 cadet-cor-20787 DEBUG Received duplicate CADET_CONNECTION_CREATE message on connection T02JVM
Feb 16 16:30:31-944904 cadet-con-20787 DEBUG Got duplicate CREATE for Connection T02JVM (Tunnel MYD5), scheduling another ACK (MQM ready)
Feb 16 16:30:31-944942 cadet-tun-20787 DEBUG Connection T02JVM (Tunnel MYD5) no longer ready for Tunnel MYD5
Feb 16 16:30:31-944996 cadet-con-20787 DEBUG Sending CONNECTION_CREATE_ACK message for Connection T02JVM (Tunnel MYD5)
Feb 16 16:30:31-945029 cadet-per-20787 DEBUG Queueing message to peer P(MYD5) in MQM 0x2227ee0
Feb 16 16:30:31-945060 cadet-per-20787 DEBUG Sending to peer P(MYD5) from MQM 0x2227ee0
Feb 16 16:30:31-945097 cadet-tun-20787 DEBUG Connection T02JVM (Tunnel MYD5) now ready for Tunnel MYD5 in state CADET_TUNNEL_KEY_AX_SENT
Feb 16 16:30:31-945129 cadet-con-20787 DEBUG Core MQ for Connection T02JVM (Tunnel MYD5) became available in state 4
Feb 16 16:30:31-945164 cadet-con-20787 DEBUG Scheduling keepalive for Connection T02JVM (Tunnel MYD5) in 5 m
Feb 16 16:30:31-945367 cadet-per-20787 DEBUG Sending to peer P(MYD5) completed
Feb 16 16:30:32-038878 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-038925 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-060044 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-060088 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-243528 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-243564 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-264618 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-264654 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-332747 cadet-tun-20787 DEBUG Trying to make KX progress on Tunnel MYD5 in state CADET_TUNNEL_KEY_AX_SENT
Feb 16 16:30:32-332785 cadet-tun-20787 DEBUG Sending KX on Tunnel MYD5 via Connection T02JVM (Tunnel MYD5) using CADET_TUNNEL_KEY_AX_SENT in state P}"
Feb 16 16:30:32-339478 cadet-con-20787 DEBUG Scheduling message for transmission on Connection T02JVM (Tunnel MYD5)
Feb 16 16:30:32-339510 cadet-per-20787 DEBUG Queueing message to peer P(MYD5) in MQM 0x2227ee0
Feb 16 16:30:32-339551 cadet-per-20787 DEBUG Sending to peer P(MYD5) from MQM 0x2227ee0
Feb 16 16:30:32-339582 cadet-tun-20787 DEBUG Connection T02JVM (Tunnel MYD5) now ready for Tunnel MYD5 in state CADET_TUNNEL_KEY_AX_SENT
Feb 16 16:30:32-339609 cadet-con-20787 DEBUG Core MQ for Connection T02JVM (Tunnel MYD5) became available in state 4
Feb 16 16:30:32-339636 cadet-con-20787 DEBUG Scheduling keepalive for Connection T02JVM (Tunnel MYD5) in 5 m
Feb 16 16:30:32-339826 cadet-per-20787 DEBUG Sending to peer P(MYD5) completed
Feb 16 16:30:32-447355 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-447391 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-468534 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-468569 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-651356 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-651392 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-672206 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-672241 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-855554 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-855645 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
Feb 16 16:30:32-875850 cadet-cor-20787 DEBUG Failed to route message of type 1002 from P(MYD5) on connection KXWN7W: no route
Feb 16 16:30:32-875894 cadet-per-20787 DEBUG Sending message to P(MYD5) out of management
20160216.2.txt (14,203 bytes)   

Activities

Christian Grothoff

2017-02-16 21:13

manager   ~0011769

This seems to ultimately be the same problem as 0004896, with the same already applied fix. Naturally, I might be wrong, but the _exact_ behavior shown in the logs should now be impossible.

Issue History

Date Modified Username Field Change
2017-02-16 16:40 lurchi New Issue
2017-02-16 16:40 lurchi Status new => assigned
2017-02-16 16:40 lurchi Assigned To => Christian Grothoff
2017-02-16 16:40 lurchi File Added: 20160216.2.txt
2017-02-16 21:13 Christian Grothoff Note Added: 0011769
2017-02-16 21:13 Christian Grothoff Status assigned => feedback
2017-02-16 21:13 Christian Grothoff Target Version => 0.11.0pre66
2017-02-19 00:10 Christian Grothoff Status feedback => resolved
2017-02-19 00:10 Christian Grothoff Resolution open => fixed
2017-02-19 00:10 Christian Grothoff Fixed in Version => 0.11.0pre66
2018-06-07 00:24 Christian Grothoff Status resolved => closed