Closed TechSec-me closed 4 years ago
We should reduce the severity of this log line. The most likely issue you are seeing is a high latency link getting in the way between those two hosts.
As for the delay, handshake processing could likely use some performance tuning.
And just to be clear, the already seen log line stops happening after a small amount of time, correct?
Hi, thanks very much for the reply, just to follow up, no the error is consistent, if I set a constant ping running it appears every 4 or so pings. I set a nmap scan running and it flooded the log.
I'll add an additional node later tonight and see if it behaves the same, might just be something on the VM. Thank you.
Hmm, that is interesting then. Any chance you can share the full logs from each node?
Ahh it must be something to do with the particular VM. I setup an additional node and it can ping the lighthouse consistently without these errors but when I ping the original node with the new node or vice versa I'm getting these errors.
So it's a virtual box VM, when I'm running the NIC in bridge mode I get these errors but if I run it using NAT everything pings fine with no errors. I'll do some more tests and if I get the exact config that's causing it I'll post here before closing the issue.
This log is with the client in Bridge mode and experiencing the issue. I've changed the WAN IPs but nothing else.
DEBU[0000] Trusted CA fingerprints fingerprints="[2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b]"
DEBU[0000] Client nebula certificate cert="NebulaCertificate {\n\tDetails {\n\t\tName: srv1\n\t\tIps: [\n\t\t\t192.168.99.100/24\n\t\t]\n\t\tSubnets: []\n\t\tGroups: []\n\t\tNot before: 2020-03-02 15:58:04 +0000 UTC\n\t\tNot After: 2021-03-02 15:51:48 +0000 UTC\n\t\tIs CA: false\n\t\tIssuer: 2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b\n\t\tPublic key: 9367633af2f2103a3c81ff3ec907638a6f6126c5835c5e4529b24991326a3415\n\t}\n\tFingerprint: 74216618ed8c95cf945ba2f418c5a9ea21cc5f8bc1fb7e22aae841f54920b788\n\tSignature: 6deabfff1a6b455e12006148500f1d18026febfcd1936995dcb918a2aa0c1555dff4fbb34f1ec5a721a2073776f8c0b618fbcb2a703cf29745b8b9f5f1991c0e\n}"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:outgoing endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:incoming endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall started firewallHash=d3a0adbbdb4fad17a45d355d33be1ad9a43378dc8f061373949fd972cbfcc83d
INFO[0000] Main HostMap created network=192.168.99.100/24 preferredRanges="[]"
INFO[0000] UDP hole punching enabled
INFO[0000] Nebula interface is active build=1.1.0 interface=srv1 network=192.168.99.100/24
DEBU[0000] Generated index index=1406497351
DEBU[0000] Packet store length=1 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 36 0 1 254 128 0 0 0 0 0 0 84 115 62 59 242 242 59 253 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 22 58 0 5 2 0 0 1 0 143 0 174 104 0 0 0 1 4 0 0 0 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3]"
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 9 244 126 0 33 17 255 254 128 0 0 0 0 0 0 84 115 62 59 242 242 59 253 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3 20 235 20 235 0 33 233 202 216 105 0 0 0 1 0 0 0 0 0 0 7 99 101 110 116 111 115 56 0 0 255 0 1]"
DEBU[0000] Packet store length=2 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 9 244 126 0 33 17 255 254 128 0 0 0 0 0 0 84 115 62 59 242 242 59 253 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3 20 235 20 235 0 33 233 202 216 105 0 0 0 1 0 0 0 0 0 0 7 99 101 110 116 111 115 56 0 0 255 0 1]"
DEBU[0000] Packet store length=3 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 9 244 126 0 33 17 255 254 128 0 0 0 0 0 0 84 115 62 59 242 242 59 253 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3 20 235 20 235 0 33 233 202 216 105 0 0 0 1 0 0 0 0 0 0 7 99 101 110 116 111 115 56 0 0 255 0 1]"
DEBU[0000] Packet store length=4 stored=true vpnIp=0.0.0.0
DEBU[0000] Generated index index=3237092920
DEBU[0000] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:3237092920] indexNumber:3237092920 mapName:pending mapTotalSize:2]"
INFO[0000] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=2508272742 remoteIndex=0 responderIndex=0 udpAddr="5.5.5.5:56504" vpnIp=192.168.99.150
INFO[0000] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=2508272742 remoteIndex=0 responderIndex=3237092920 udpAddr="5.5.5.5:56504" vpnIp=192.168.99.150
DEBU[0000] deleting 192.168.99.150 from lighthouse.
DEBU[0000] Sending 0 stored packets vpnIp=192.168.99.150
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 36 0 1 254 128 0 0 0 0 0 0 84 115 62 59 242 242 59 253 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 22 58 0 5 2 0 0 1 0 143 0 174 104 0 0 0 1 4 0 0 0 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3]"
DEBU[0000] Packet store length=5 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 36 0 1 254 128 0 0 0 0 0 0 84 115 62 59 242 242 59 253 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 22 58 0 5 2 0 0 1 0 143 0 174 104 0 0 0 1 4 0 0 0 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3]"
DEBU[0003] Hostmap index deleted hostMap="map[indexNumber:3237092920 mapName:pending mapTotalSize:1]"
DEBU[0003] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:1 vpnIp:192.168.99.150]"
DEBU[0016] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.150
DEBU[0032] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:0.0.0.0]"
DEBU[0032] Hostmap index deleted hostMap="map[indexNumber:1406497351 mapName:pending mapTotalSize:0]"
DEBU[0038] Generated index index=4224596231
DEBU[0038] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:4224596231] indexNumber:4224596231 mapName:pending mapTotalSize:1]"
INFO[0038] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=988294845 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0038] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=988294845 remoteIndex=0 responderIndex=4224596231 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0038] deleting 192.168.99.101 from lighthouse.
DEBU[0038] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0040] Hostmap index deleted hostMap="map[indexNumber:4224596231 mapName:pending mapTotalSize:0]"
DEBU[0040] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0045] Recv error received index=988294845 udpAddr="2.2.2.2:42811"
DEBU[0052] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0061] Recv error received index=988294845 udpAddr="2.2.2.2:42811"
DEBU[0062] Recv error received index=988294845 udpAddr="2.2.2.2:42811"
DEBU[0063] Recv error received index=988294845 udpAddr="2.2.2.2:42811"
DEBU[0063] Hostmap index deleted hostMap="map[indexNumber:4224596231 mapName:main mapTotalSize:1]"
DEBU[0063] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0063] Hostmap index deleted hostMap="map[indexNumber:4224596231 mapName:pending mapTotalSize:0]"
DEBU[0063] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0064] Recv error sent index=4224596231 udpAddr="2.2.2.2:42811"
DEBU[0065] Recv error sent index=4224596231 udpAddr="2.2.2.2:42811"
DEBU[0066] Generated index index=1457583495
DEBU[0066] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:1457583495] indexNumber:1457583495 mapName:pending mapTotalSize:1]"
INFO[0066] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3818717161 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0066] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3818717161 remoteIndex=0 responderIndex=1457583495 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0066] deleting 192.168.99.101 from lighthouse.
DEBU[0066] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0066] Recv error received index=3818717161 udpAddr="2.2.2.2:42811"
DEBU[0067] Recv error received index=3818717161 udpAddr="2.2.2.2:42811"
DEBU[0068] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0068] Recv error received index=3818717161 udpAddr="2.2.2.2:42811"
DEBU[0069] Recv error received index=3818717161 udpAddr="2.2.2.2:42811"
DEBU[0069] Hostmap index deleted hostMap="map[indexNumber:1457583495 mapName:main mapTotalSize:1]"
DEBU[0069] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0069] Hostmap index deleted hostMap="map[indexNumber:1457583495 mapName:pending mapTotalSize:0]"
DEBU[0069] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0069] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.150
DEBU[0070] Recv error sent index=1457583495 udpAddr="2.2.2.2:42811"
DEBU[0071] Recv error sent index=1457583495 udpAddr="2.2.2.2:42811"
DEBU[0072] Generated index index=4075049806
DEBU[0072] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:4075049806] indexNumber:4075049806 mapName:pending mapTotalSize:1]"
INFO[0072] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=1324001275 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0072] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=1324001275 remoteIndex=0 responderIndex=4075049806 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0072] deleting 192.168.99.101 from lighthouse.
DEBU[0072] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0072] Recv error received index=1324001275 udpAddr="2.2.2.2:42811"
DEBU[0073] Recv error received index=1324001275 udpAddr="2.2.2.2:42811"
DEBU[0074] Recv error received index=1324001275 udpAddr="2.2.2.2:42811"
DEBU[0075] Recv error received index=1324001275 udpAddr="2.2.2.2:42811"
DEBU[0075] Hostmap index deleted hostMap="map[indexNumber:4075049806 mapName:main mapTotalSize:1]"
DEBU[0075] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0075] Hostmap index deleted hostMap="map[indexNumber:4075049806 mapName:pending mapTotalSize:0]"
DEBU[0075] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0075] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0076] Recv error sent index=4075049806 udpAddr="2.2.2.2:42811"
DEBU[0077] Recv error sent index=4075049806 udpAddr="2.2.2.2:42811"
DEBU[0078] Generated index index=4036445350
DEBU[0078] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:4036445350] indexNumber:4036445350 mapName:pending mapTotalSize:1]"
INFO[0078] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3368464642 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0078] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3368464642 remoteIndex=0 responderIndex=4036445350 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0078] deleting 192.168.99.101 from lighthouse.
DEBU[0078] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0078] Recv error received index=3368464642 udpAddr="2.2.2.2:42811"
DEBU[0079] Recv error received index=3368464642 udpAddr="2.2.2.2:42811"
DEBU[0080] Recv error received index=3368464642 udpAddr="2.2.2.2:42811"
DEBU[0081] Recv error received index=3368464642 udpAddr="2.2.2.2:42811"
DEBU[0081] Hostmap index deleted hostMap="map[indexNumber:4036445350 mapName:main mapTotalSize:1]"
DEBU[0081] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0081] Hostmap index deleted hostMap="map[indexNumber:4036445350 mapName:pending mapTotalSize:0]"
DEBU[0081] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0082] Recv error sent index=4036445350 udpAddr="2.2.2.2:42811"
DEBU[0083] Recv error sent index=4036445350 udpAddr="2.2.2.2:42811"
DEBU[0084] Generated index index=1436836407
DEBU[0084] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:1436836407] indexNumber:1436836407 mapName:pending mapTotalSize:1]"
INFO[0084] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=117520851 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0084] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=117520851 remoteIndex=0 responderIndex=1436836407 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0084] deleting 192.168.99.101 from lighthouse.
DEBU[0084] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0084] Recv error received index=117520851 udpAddr="2.2.2.2:42811"
DEBU[0085] Recv error received index=117520851 udpAddr="2.2.2.2:42811"
DEBU[0085] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0086] Recv error received index=117520851 udpAddr="2.2.2.2:42811"
DEBU[0087] Recv error received index=117520851 udpAddr="2.2.2.2:42811"
DEBU[0087] Hostmap index deleted hostMap="map[indexNumber:1436836407 mapName:main mapTotalSize:1]"
DEBU[0087] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0087] Hostmap index deleted hostMap="map[indexNumber:1436836407 mapName:pending mapTotalSize:0]"
DEBU[0087] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0088] Recv error sent index=1436836407 udpAddr="2.2.2.2:42811"
DEBU[0089] Recv error sent index=1436836407 udpAddr="2.2.2.2:42811"
DEBU[0090] Generated index index=3576512358
DEBU[0090] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:3576512358] indexNumber:3576512358 mapName:pending mapTotalSize:1]"
INFO[0090] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3376082883 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0090] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3376082883 remoteIndex=0 responderIndex=3576512358 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0090] deleting 192.168.99.101 from lighthouse.
DEBU[0090] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0090] Recv error received index=3376082883 udpAddr="2.2.2.2:42811"
DEBU[0091] Recv error received index=3376082883 udpAddr="2.2.2.2:42811"
DEBU[0092] Recv error received index=3376082883 udpAddr="2.2.2.2:42811"
DEBU[0093] Hostmap index deleted hostMap="map[indexNumber:3576512358 mapName:pending mapTotalSize:0]"
DEBU[0093] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0093] Recv error received index=3376082883 udpAddr="2.2.2.2:42811"
DEBU[0093] Hostmap index deleted hostMap="map[indexNumber:3576512358 mapName:main mapTotalSize:1]"
DEBU[0093] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0093] Hostmap index deleted hostMap="map[indexNumber:3576512358 mapName:pending mapTotalSize:0]"
DEBU[0093] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0094] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0094] Recv error sent index=3576512358 udpAddr="2.2.2.2:42811"
DEBU[0095] Recv error sent index=3576512358 udpAddr="2.2.2.2:42811"
DEBU[0096] Generated index index=4279644773
DEBU[0096] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:4279644773] indexNumber:4279644773 mapName:pending mapTotalSize:1]"
INFO[0096] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3906315298 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0096] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3906315298 remoteIndex=0 responderIndex=4279644773 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0096] deleting 192.168.99.101 from lighthouse.
DEBU[0096] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0096] Recv error received index=3906315298 udpAddr="2.2.2.2:42811"
DEBU[0097] Recv error received index=3906315298 udpAddr="2.2.2.2:42811"
DEBU[0098] Recv error received index=3906315298 udpAddr="2.2.2.2:42811"
DEBU[0099] Hostmap index deleted hostMap="map[indexNumber:4279644773 mapName:pending mapTotalSize:0]"
DEBU[0099] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0099] Recv error received index=3906315298 udpAddr="2.2.2.2:42811"
DEBU[0099] Hostmap index deleted hostMap="map[indexNumber:4279644773 mapName:main mapTotalSize:1]"
DEBU[0099] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0099] Hostmap index deleted hostMap="map[indexNumber:4279644773 mapName:pending mapTotalSize:0]"
DEBU[0099] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0100] Recv error sent index=4279644773 udpAddr="2.2.2.2:42811"
DEBU[0101] Recv error sent index=4279644773 udpAddr="2.2.2.2:42811"
DEBU[0102] Generated index index=2557061082
DEBU[0102] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:2557061082] indexNumber:2557061082 mapName:pending mapTotalSize:1]"
INFO[0102] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=783569836 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0102] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=783569836 remoteIndex=0 responderIndex=2557061082 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0102] deleting 192.168.99.101 from lighthouse.
DEBU[0102] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0102] Recv error received index=783569836 udpAddr="2.2.2.2:42811"
DEBU[0103] Recv error received index=783569836 udpAddr="2.2.2.2:42811"
DEBU[0104] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0104] Recv error received index=783569836 udpAddr="2.2.2.2:42811"
DEBU[0105] Hostmap index deleted hostMap="map[indexNumber:2557061082 mapName:pending mapTotalSize:0]"
DEBU[0105] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0105] Recv error received index=783569836 udpAddr="2.2.2.2:42811"
DEBU[0105] Hostmap index deleted hostMap="map[indexNumber:2557061082 mapName:main mapTotalSize:1]"
DEBU[0105] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0105] Hostmap index deleted hostMap="map[indexNumber:2557061082 mapName:pending mapTotalSize:0]"
DEBU[0105] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0106] Recv error sent index=2557061082 udpAddr="2.2.2.2:42811"
DEBU[0107] Recv error sent index=2557061082 udpAddr="2.2.2.2:42811"
DEBU[0108] Generated index index=4251346426
DEBU[0108] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:4251346426] indexNumber:4251346426 mapName:pending mapTotalSize:1]"
INFO[0108] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=1968393612 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
INFO[0108] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=1968393612 remoteIndex=0 responderIndex=4251346426 udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0108] deleting 192.168.99.101 from lighthouse.
DEBU[0108] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0108] Recv error received index=1968393612 udpAddr="2.2.2.2:42811"
DEBU[0109] Recv error received index=1968393612 udpAddr="2.2.2.2:42811"
DEBU[0110] Recv error received index=1968393612 udpAddr="2.2.2.2:42811"
DEBU[0111] Hostmap index deleted hostMap="map[indexNumber:4251346426 mapName:pending mapTotalSize:0]"
DEBU[0111] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.101]"
DEBU[0112] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
INFO[0124] Close tunnel received, tearing down. udpAddr="2.2.2.2:42811" vpnIp=192.168.99.101
DEBU[0124] deleting 192.168.99.101 from lighthouse.
DEBU[0124] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0124] Hostmap index deleted hostMap="map[indexNumber:4251346426 mapName:main mapTotalSize:1]"
DEBU[0129] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.150
^CINFO[0134] Caught signal, shutting down signal=interrupt
DEBU[0134] Sending close tunnel message udpAddr="5.5.5.5:56504" vpnIp=192.168.99.150
INFO[0134] Goodbye signal=interrupt
DEBU[0000] Trusted CA fingerprints fingerprints="[2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b]"
DEBU[0000] Client nebula certificate cert="NebulaCertificate {\n\tDetails {\n\t\tName: ka-01\n\t\tIps: [\n\t\t\t192.168.99.101/24\n\t\t]\n\t\tSubnets: []\n\t\tGroups: []\n\t\tNot before: 2020-03-02 15:58:13 +0000 GMT\n\t\tNot After: 2021-03-02 15:51:48 +0000 GMT\n\t\tIs CA: false\n\t\tIssuer: 2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b\n\t\tPublic key: 2f4ac7fb3f93590b0f09a6f56748ac4f6be2e74172d32d0d5820d8da4a873657\n\t}\n\tFingerprint: 29866f921a61a540a934bf336b14e90f9df0ba94fcd0685ebcabec10e2a48781\n\tSignature: 78a97873b3b225a554118e921913d3056676e8e9a9ed9a94053351308fad378403bce8d021c7400e78b8ba7e85ffa9cefec7864c6a2289929bd2f6e342046e08\n}"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:outgoing endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:incoming endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall started firewallHash=d3a0adbbdb4fad17a45d355d33be1ad9a43378dc8f061373949fd972cbfcc83d
INFO[0000] Main HostMap created network=192.168.99.101/24 preferredRanges="[]"
INFO[0000] UDP hole punching enabled
INFO[0000] Nebula interface is active build=1.1.0 interface=ka-01 network=192.168.99.101/24
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 244 139 150 10 68 144 91 43 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 82 229 0 0 0 0]"
DEBU[0000] Generated index index=988294845
DEBU[0000] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0000] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=988294845 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0000] Handshake message received durationNs=362941342 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=988294845 remoteIndex=988294845 responderIndex=4224596231 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0000] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0000] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0000] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=988294845 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0000] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0000] Hostmap index deleted hostMap="map[indexNumber:988294845 mapName:pending mapTotalSize:0]"
DEBU[0004] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 244 139 150 10 68 144 91 43 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 82 229 0 0 0 0]"
DEBU[0008] Tunnel status tunnelCheck="map[method:active state:testing]" vpnIp=192.168.99.100
DEBU[0008] Recv error sent index=988294845 udpAddr="1.1.1.1:4242"
DEBU[0012] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 244 139 150 10 68 144 91 43 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 82 229 0 0 0 0]"
DEBU[0021] Tunnel status tunnelCheck="map[method:active state:alive]" vpnIp=192.168.99.100
DEBU[0023] Recv error sent index=988294845 udpAddr="1.1.1.1:4242"
DEBU[0024] Recv error sent index=988294845 udpAddr="1.1.1.1:4242"
DEBU[0025] Recv error sent index=988294845 udpAddr="1.1.1.1:4242"
DEBU[0026] Recv error received index=4224596231 udpAddr="1.1.1.1:4242"
DEBU[0026] Recv error received index=4224596231 udpAddr="1.1.1.1:4242"
DEBU[0027] Recv error received index=4224596231 udpAddr="1.1.1.1:4242"
DEBU[0027] Recv error received index=4224596231 udpAddr="1.1.1.1:4242"
DEBU[0027] Hostmap index deleted hostMap="map[indexNumber:988294845 mapName:main mapTotalSize:0]"
DEBU[0027] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0027] Hostmap index deleted hostMap="map[indexNumber:988294845 mapName:pending mapTotalSize:0]"
DEBU[0027] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0028] Generated index index=3818717161
DEBU[0028] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0028] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3818717161 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0028] Handshake message received durationNs=341865978 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3818717161 remoteIndex=3818717161 responderIndex=1457583495 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0028] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0028] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0028] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=3818717161 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0028] Recv error sent index=3818717161 udpAddr="1.1.1.1:4242"
DEBU[0028] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0028] Hostmap index deleted hostMap="map[indexNumber:3818717161 mapName:pending mapTotalSize:0]"
DEBU[0029] Recv error sent index=3818717161 udpAddr="1.1.1.1:4242"
DEBU[0030] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0030] Recv error sent index=3818717161 udpAddr="1.1.1.1:4242"
DEBU[0031] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 244 139 150 10 68 144 91 43 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 82 229 0 0 0 0]"
DEBU[0031] Recv error sent index=3818717161 udpAddr="1.1.1.1:4242"
DEBU[0032] Recv error received index=1457583495 udpAddr="1.1.1.1:4242"
DEBU[0032] Recv error received index=1457583495 udpAddr="1.1.1.1:4242"
DEBU[0033] Recv error received index=1457583495 udpAddr="1.1.1.1:4242"
DEBU[0033] Recv error received index=1457583495 udpAddr="1.1.1.1:4242"
DEBU[0033] Hostmap index deleted hostMap="map[indexNumber:3818717161 mapName:main mapTotalSize:0]"
DEBU[0033] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0033] Hostmap index deleted hostMap="map[indexNumber:3818717161 mapName:pending mapTotalSize:0]"
DEBU[0033] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0034] Generated index index=1324001275
DEBU[0034] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0034] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=1324001275 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0034] Handshake message received durationNs=335790470 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=1324001275 remoteIndex=1324001275 responderIndex=4075049806 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0034] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0034] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0034] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=1324001275 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0034] Recv error sent index=1324001275 udpAddr="1.1.1.1:4242"
DEBU[0034] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0034] Hostmap index deleted hostMap="map[indexNumber:1324001275 mapName:pending mapTotalSize:0]"
DEBU[0035] Recv error sent index=1324001275 udpAddr="1.1.1.1:4242"
DEBU[0036] Recv error sent index=1324001275 udpAddr="1.1.1.1:4242"
DEBU[0037] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0037] Recv error sent index=1324001275 udpAddr="1.1.1.1:4242"
DEBU[0038] Recv error received index=4075049806 udpAddr="1.1.1.1:4242"
DEBU[0038] Recv error received index=4075049806 udpAddr="1.1.1.1:4242"
DEBU[0039] Recv error received index=4075049806 udpAddr="1.1.1.1:4242"
DEBU[0039] Recv error received index=4075049806 udpAddr="1.1.1.1:4242"
DEBU[0039] Hostmap index deleted hostMap="map[indexNumber:1324001275 mapName:main mapTotalSize:0]"
DEBU[0039] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0039] Hostmap index deleted hostMap="map[indexNumber:1324001275 mapName:pending mapTotalSize:0]"
DEBU[0039] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0040] Generated index index=3368464642
DEBU[0040] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0040] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3368464642 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0040] Handshake message received durationNs=295809263 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3368464642 remoteIndex=3368464642 responderIndex=4036445350 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0040] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0040] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0040] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=3368464642 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0040] Recv error sent index=3368464642 udpAddr="1.1.1.1:4242"
DEBU[0040] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0040] Hostmap index deleted hostMap="map[indexNumber:3368464642 mapName:pending mapTotalSize:0]"
DEBU[0041] Recv error sent index=3368464642 udpAddr="1.1.1.1:4242"
DEBU[0042] Recv error sent index=3368464642 udpAddr="1.1.1.1:4242"
DEBU[0043] Recv error sent index=3368464642 udpAddr="1.1.1.1:4242"
DEBU[0044] Recv error received index=4036445350 udpAddr="1.1.1.1:4242"
DEBU[0044] Recv error received index=4036445350 udpAddr="1.1.1.1:4242"
DEBU[0045] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0045] Recv error received index=4036445350 udpAddr="1.1.1.1:4242"
DEBU[0045] Recv error received index=4036445350 udpAddr="1.1.1.1:4242"
DEBU[0045] Hostmap index deleted hostMap="map[indexNumber:3368464642 mapName:main mapTotalSize:0]"
DEBU[0045] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0045] Hostmap index deleted hostMap="map[indexNumber:3368464642 mapName:pending mapTotalSize:0]"
DEBU[0045] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0046] Generated index index=117520851
DEBU[0046] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0046] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=117520851 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0046] Handshake message received durationNs=250870006 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=117520851 remoteIndex=117520851 responderIndex=1436836407 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0046] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0046] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0046] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=117520851 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0046] Recv error sent index=117520851 udpAddr="1.1.1.1:4242"
DEBU[0046] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0046] Hostmap index deleted hostMap="map[indexNumber:117520851 mapName:pending mapTotalSize:0]"
DEBU[0047] Recv error sent index=117520851 udpAddr="1.1.1.1:4242"
DEBU[0048] Recv error sent index=117520851 udpAddr="1.1.1.1:4242"
DEBU[0049] Recv error sent index=117520851 udpAddr="1.1.1.1:4242"
DEBU[0050] Recv error received index=1436836407 udpAddr="1.1.1.1:4242"
DEBU[0050] Recv error received index=1436836407 udpAddr="1.1.1.1:4242"
DEBU[0051] Recv error received index=1436836407 udpAddr="1.1.1.1:4242"
DEBU[0051] Recv error received index=1436836407 udpAddr="1.1.1.1:4242"
DEBU[0051] Hostmap index deleted hostMap="map[indexNumber:117520851 mapName:main mapTotalSize:0]"
DEBU[0051] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0051] Hostmap index deleted hostMap="map[indexNumber:117520851 mapName:pending mapTotalSize:0]"
DEBU[0051] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0052] Generated index index=3376082883
DEBU[0052] Packet store length=1 stored=true vpnIp=192.168.99.100
DEBU[0052] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
INFO[0052] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3376082883 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0052] Handshake message received durationNs=294126528 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3376082883 remoteIndex=3376082883 responderIndex=3576512358 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0052] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0052] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0052] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=3376082883 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0052] Recv error sent index=3376082883 udpAddr="1.1.1.1:4242"
DEBU[0053] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0053] Hostmap index deleted hostMap="map[indexNumber:3376082883 mapName:pending mapTotalSize:0]"
DEBU[0053] Recv error sent index=3376082883 udpAddr="1.1.1.1:4242"
DEBU[0054] Recv error sent index=3376082883 udpAddr="1.1.1.1:4242"
DEBU[0055] Recv error sent index=3376082883 udpAddr="1.1.1.1:4242"
DEBU[0056] Recv error received index=3576512358 udpAddr="1.1.1.1:4242"
DEBU[0056] Recv error received index=3576512358 udpAddr="1.1.1.1:4242"
DEBU[0057] Recv error received index=3576512358 udpAddr="1.1.1.1:4242"
DEBU[0057] Recv error received index=3576512358 udpAddr="1.1.1.1:4242"
DEBU[0057] Hostmap index deleted hostMap="map[indexNumber:3376082883 mapName:main mapTotalSize:0]"
DEBU[0057] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0057] Hostmap index deleted hostMap="map[indexNumber:3376082883 mapName:pending mapTotalSize:0]"
DEBU[0057] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0058] Generated index index=3906315298
DEBU[0058] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0058] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=3906315298 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0058] Handshake message received durationNs=254228331 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=3906315298 remoteIndex=3906315298 responderIndex=4279644773 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0058] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0058] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0058] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=3906315298 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0058] Recv error sent index=3906315298 udpAddr="1.1.1.1:4242"
DEBU[0059] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0059] Hostmap index deleted hostMap="map[indexNumber:3906315298 mapName:pending mapTotalSize:0]"
DEBU[0059] Recv error sent index=3906315298 udpAddr="1.1.1.1:4242"
DEBU[0060] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0060] Recv error sent index=3906315298 udpAddr="1.1.1.1:4242"
DEBU[0061] Recv error sent index=3906315298 udpAddr="1.1.1.1:4242"
DEBU[0062] Recv error received index=4279644773 udpAddr="1.1.1.1:4242"
DEBU[0062] Recv error received index=4279644773 udpAddr="1.1.1.1:4242"
DEBU[0063] Recv error received index=4279644773 udpAddr="1.1.1.1:4242"
DEBU[0063] Recv error received index=4279644773 udpAddr="1.1.1.1:4242"
DEBU[0063] Hostmap index deleted hostMap="map[indexNumber:3906315298 mapName:main mapTotalSize:0]"
DEBU[0063] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0063] Hostmap index deleted hostMap="map[indexNumber:3906315298 mapName:pending mapTotalSize:0]"
DEBU[0063] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0064] Generated index index=783569836
DEBU[0064] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0064] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=783569836 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0064] Handshake message received durationNs=353240947 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=783569836 remoteIndex=783569836 responderIndex=2557061082 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0064] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0064] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0064] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=783569836 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0065] Recv error sent index=783569836 udpAddr="1.1.1.1:4242"
DEBU[0065] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0065] Hostmap index deleted hostMap="map[indexNumber:783569836 mapName:pending mapTotalSize:0]"
DEBU[0065] Recv error sent index=783569836 udpAddr="1.1.1.1:4242"
DEBU[0066] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 244 139 150 10 68 144 91 43 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 82 229 0 0 0 0]"
DEBU[0066] Recv error sent index=783569836 udpAddr="1.1.1.1:4242"
DEBU[0067] Recv error sent index=783569836 udpAddr="1.1.1.1:4242"
DEBU[0068] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0068] Recv error received index=2557061082 udpAddr="1.1.1.1:4242"
DEBU[0068] Recv error received index=2557061082 udpAddr="1.1.1.1:4242"
DEBU[0069] Recv error received index=2557061082 udpAddr="1.1.1.1:4242"
DEBU[0069] Recv error received index=2557061082 udpAddr="1.1.1.1:4242"
DEBU[0069] Hostmap index deleted hostMap="map[indexNumber:783569836 mapName:main mapTotalSize:0]"
DEBU[0069] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0069] Hostmap index deleted hostMap="map[indexNumber:783569836 mapName:pending mapTotalSize:0]"
DEBU[0069] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0070] Generated index index=1968393612
DEBU[0070] Packet store length=1 stored=true vpnIp=192.168.99.100
INFO[0070] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=1968393612 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0070] Handshake message received durationNs=294510291 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=1968393612 remoteIndex=1968393612 responderIndex=4251346426 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0070] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0070] Sending 1 stored packets vpnIp=192.168.99.100
ERRO[0070] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=1968393612 messagecounter=2" udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0071] Recv error sent index=1968393612 udpAddr="1.1.1.1:4242"
DEBU[0071] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0071] Hostmap index deleted hostMap="map[indexNumber:1968393612 mapName:pending mapTotalSize:0]"
DEBU[0071] Recv error sent index=1968393612 udpAddr="1.1.1.1:4242"
DEBU[0072] Recv error sent index=1968393612 udpAddr="1.1.1.1:4242"
DEBU[0076] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
^CINFO[0086] Caught signal, shutting down signal=interrupt
DEBU[0086] Sending close tunnel message udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0086] Goodbye signal=interrupt
DEBU[0000] Trusted CA fingerprints fingerprints="[2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b]"
DEBU[0000] Client nebula certificate cert="NebulaCertificate {\n\tDetails {\n\t\tName: srv1\n\t\tIps: [\n\t\t\t192.168.99.100/24\n\t\t]\n\t\tSubnets: []\n\t\tGroups: []\n\t\tNot before: 2020-03-02 15:58:04 +0000 UTC\n\t\tNot After: 2021-03-02 15:51:48 +0000 UTC\n\t\tIs CA: false\n\t\tIssuer: 2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b\n\t\tPublic key: 9367633af2f2103a3c81ff3ec907638a6f6126c5835c5e4529b24991326a3415\n\t}\n\tFingerprint: 74216618ed8c95cf945ba2f418c5a9ea21cc5f8bc1fb7e22aae841f54920b788\n\tSignature: 6deabfff1a6b455e12006148500f1d18026febfcd1936995dcb918a2aa0c1555dff4fbb34f1ec5a721a2073776f8c0b618fbcb2a703cf29745b8b9f5f1991c0e\n}"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:outgoing endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:incoming endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall started firewallHash=d3a0adbbdb4fad17a45d355d33be1ad9a43378dc8f061373949fd972cbfcc83d
INFO[0000] Main HostMap created network=192.168.99.100/24 preferredRanges="[]"
INFO[0000] UDP hole punching enabled
INFO[0000] Nebula interface is active build=1.1.0 interface=srv1 network=192.168.99.100/24
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 36 0 1 254 128 0 0 0 0 0 0 18 30 225 217 172 75 232 123 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 22 58 0 5 2 0 0 1 0 143 0 231 71 0 0 0 1 4 0 0 0 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3]"
DEBU[0000] Generated index index=3480559591
DEBU[0000] Packet store length=1 stored=true vpnIp=0.0.0.0
DEBU[0000] Packet store length=2 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 8 122 248 0 33 17 255 254 128 0 0 0 0 0 0 18 30 225 217 172 75 232 123 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3 20 235 20 235 0 33 57 72 193 203 0 0 0 1 0 0 0 0 0 0 7 99 101 110 116 111 115 56 0 0 255 0 1]"
DEBU[0000] Packet store length=3 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 36 0 1 254 128 0 0 0 0 0 0 18 30 225 217 172 75 232 123 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 22 58 0 5 2 0 0 1 0 143 0 231 71 0 0 0 1 4 0 0 0 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3]"
DEBU[0000] Packet store length=4 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 8 122 248 0 33 17 255 254 128 0 0 0 0 0 0 18 30 225 217 172 75 232 123 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3 20 235 20 235 0 33 57 72 193 203 0 0 0 1 0 0 0 0 0 0 7 99 101 110 116 111 115 56 0 0 255 0 1]"
DEBU[0000] Packet store length=5 stored=true vpnIp=0.0.0.0
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 8 122 248 0 33 17 255 254 128 0 0 0 0 0 0 18 30 225 217 172 75 232 123 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3 20 235 20 235 0 33 57 72 193 203 0 0 0 1 0 0 0 0 0 0 7 99 101 110 116 111 115 56 0 0 255 0 1]"
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 36 0 1 254 128 0 0 0 0 0 0 18 30 225 217 172 75 232 123 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 22 58 0 5 2 0 0 1 0 143 0 231 71 0 0 0 1 4 0 0 0 255 2 0 0 0 0 0 0 0 0 0 0 0 1 0 3]"
DEBU[0001] Generated index index=1050306239
DEBU[0001] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:1050306239] indexNumber:1050306239 mapName:pending mapTotalSize:2]"
INFO[0001] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=791897956 remoteIndex=0 responderIndex=0 udpAddr="5.5.5.5:56504" vpnIp=192.168.99.150
INFO[0001] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=791897956 remoteIndex=0 responderIndex=1050306239 udpAddr="5.5.5.5:56504" vpnIp=192.168.99.150
DEBU[0001] deleting 192.168.99.150 from lighthouse.
DEBU[0001] Sending 0 stored packets vpnIp=192.168.99.150
DEBU[0003] Hostmap index deleted hostMap="map[indexNumber:1050306239 mapName:pending mapTotalSize:1]"
DEBU[0003] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:1 vpnIp:192.168.99.150]"
DEBU[0006] Generated index index=3556263894
DEBU[0006] Hostmap index added hostMap="map[hostinfo:map[existing:false hostId:0.0.0.0 localIndexId:3556263894] indexNumber:3556263894 mapName:pending mapTotalSize:2]"
INFO[0006] Handshake message received handshake="map[stage:1 style:ix_psk0]" initiatorIndex=2304361489 remoteIndex=0 responderIndex=0 udpAddr="2.2.2.2:40314" vpnIp=192.168.99.101
INFO[0006] Handshake message sent handshake="map[stage:2 style:ix_psk0]" initiatorIndex=2304361489 remoteIndex=0 responderIndex=3556263894 udpAddr="2.2.2.2:40314" vpnIp=192.168.99.101
DEBU[0006] deleting 192.168.99.101 from lighthouse.
DEBU[0006] Sending 0 stored packets vpnIp=192.168.99.101
DEBU[0009] Hostmap index deleted hostMap="map[indexNumber:3556263894 mapName:pending mapTotalSize:1]"
DEBU[0009] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0017] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.150
DEBU[0022] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0029] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0031] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:0.0.0.0]"
DEBU[0031] Hostmap index deleted hostMap="map[indexNumber:3480559591 mapName:pending mapTotalSize:0]"
DEBU[0038] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0046] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0054] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0060] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.150
DEBU[0061] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
DEBU[0069] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.101
INFO[0073] Close tunnel received, tearing down. udpAddr="2.2.2.2:40314" vpnIp=192.168.99.101
DEBU[0073] deleting 192.168.99.101 from lighthouse.
DEBU[0073] Hostmap vpnIp deleted hostMap="map[mapName:main mapTotalSize:1 vpnIp:192.168.99.101]"
DEBU[0073] Hostmap index deleted hostMap="map[indexNumber:3556263894 mapName:main mapTotalSize:1]"
^CINFO[0077] Caught signal, shutting down signal=interrupt
DEBU[0077] Sending close tunnel message udpAddr="5.5.5.5:56504" vpnIp=192.168.99.150
INFO[0077] Goodbye signal=interrupt
DEBU[0000] Trusted CA fingerprints fingerprints="[2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b]"
DEBU[0000] Client nebula certificate cert="NebulaCertificate {\n\tDetails {\n\t\tName: ka-01\n\t\tIps: [\n\t\t\t192.168.99.101/24\n\t\t]\n\t\tSubnets: []\n\t\tGroups: []\n\t\tNot before: 2020-03-02 15:58:13 +0000 GMT\n\t\tNot After: 2021-03-02 15:51:48 +0000 GMT\n\t\tIs CA: false\n\t\tIssuer: 2fce04dff9a64eab399abc432b52db8a849f00db6e535761d7cc1cb9b71f711b\n\t\tPublic key: 2f4ac7fb3f93590b0f09a6f56748ac4f6be2e74172d32d0d5820d8da4a873657\n\t}\n\tFingerprint: 29866f921a61a540a934bf336b14e90f9df0ba94fcd0685ebcabec10e2a48781\n\tSignature: 78a97873b3b225a554118e921913d3056676e8e9a9ed9a94053351308fad378403bce8d021c7400e78b8ba7e85ffa9cefec7864c6a2289929bd2f6e342046e08\n}"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:outgoing endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall rule added firewallRule="map[caName: caSha: direction:incoming endPort:0 groups:[] host: ip:192.168.99.0/24 proto:0 startPort:0]"
INFO[0000] Firewall started firewallHash=d3a0adbbdb4fad17a45d355d33be1ad9a43378dc8f061373949fd972cbfcc83d
INFO[0000] Main HostMap created network=192.168.99.101/24 preferredRanges="[]"
INFO[0000] UDP hole punching enabled
INFO[0000] Nebula interface is active build=1.1.0 interface=ka-01 network=192.168.99.101/24
DEBU[0000] Generated index index=2304361489
DEBU[0000] Packet store length=1 stored=true vpnIp=192.168.99.100
DEBU[0000] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 160 218 172 208 8 116 112 40 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 182 239 0 0 0 0]"
INFO[0000] Handshake message sent handshake="map[stage:1 style:ix_psk0]" initiatorIndex=2304361489 remoteIndex=0 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0000] Handshake message received durationNs=366122016 handshake="map[stage:2 style:ix_psk0]" initiatorIndex=2304361489 remoteIndex=2304361489 responderIndex=3556263894 udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
DEBU[0000] Hostmap remote ip added hostMap="map[mapName:main mapTotalSize:1 udpAddr:1.1.1.1:4242 vpnIp:192.168.99.100]"
DEBU[0000] Sending 1 stored packets vpnIp=192.168.99.100
DEBU[0000] Hostmap vpnIp deleted hostMap="map[mapName:pending mapTotalSize:0 vpnIp:192.168.99.100]"
DEBU[0000] Hostmap index deleted hostMap="map[indexNumber:2304361489 mapName:pending mapTotalSize:0]"
DEBU[0004] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 160 218 172 208 8 116 112 40 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 182 239 0 0 0 0]"
DEBU[0007] Tunnel status tunnelCheck="map[method:active state:testing]" vpnIp=192.168.99.100
DEBU[0012] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 160 218 172 208 8 116 112 40 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 182 239 0 0 0 0]"
DEBU[0020] Tunnel status tunnelCheck="map[method:active state:alive]" vpnIp=192.168.99.100
DEBU[0028] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0029] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 160 218 172 208 8 116 112 40 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 182 239 0 0 0 0]"
DEBU[0035] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0043] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0050] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0058] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
DEBU[0064] Error while validating outbound packet: packet is not ipv4, type: 6 packet="[96 0 0 0 0 8 58 255 254 128 0 0 0 0 0 0 160 218 172 208 8 116 112 40 255 2 0 0 0 0 0 0 0 0 0 0 0 0 0 2 133 0 182 239 0 0 0 0]"
DEBU[0066] Tunnel status tunnelCheck="map[method:passive state:alive]" vpnIp=192.168.99.100
^CINFO[0067] Caught signal, shutting down signal=interrupt
DEBU[0067] Sending close tunnel message udpAddr="1.1.1.1:4242" vpnIp=192.168.99.100
INFO[0067] Goodbye signal=interrupt
I'm curious, what version of Virtualbox are you running? This sounds like an issue in Virtualbox with not filtering the packets for each host correctly (bridge mode works by intercepting packets on your host system and redirecting them: https://www.virtualbox.org/manual/ch06.html#network_bridged )
If you google around for "virtualbox bridged duplicate packets" you can see that this is an issue that comes up often, thus why I'm wondering if you are on an older version that might be missing the fix. Regardless, this looks like an issue in Virtualbox or your network config with it and not Nebula itself.
Thanks for the reply wadey, you are correct. I was on VBox 6.0 on Ubuntu 19, I upgraded to 6.1.4 but still had the issue. Just installed Ubuntu 20.04 and VBox 6.1.4 and now I'm getting none of those errors on the same VM.
Thanks for the pointer, closing issue.
Hi and first off apologies if this is the wrong forum to report this, feel free to close if it is. Really like the idea behind Nebula and have setup a network to test it out but have come up with a strange issue.
I have a lighthouse with a public IP and one node on a VM on my laptop, I am seeing the error below consistently if I run a ping between the two devices. Every time the error is returned the ping time jumps considerably and as it happens every 5 or so responses it's affecting the performance. I can't see anything about the error in my searches online:
ERRO[0000] Already seen this handshake packet handshake="map[stage:2 style:ix_psk0]" header="ver=1 type=handshake subtype=ix_psk0 reserved=0x0 remoteindex=289222265 messagecounter=2" udpAddr="#.#.#.#:4242" vpnIp=192.168.99.100
Happy to troubleshoot if there any suggestions. Thank you.