Hi, I've managed to break p2p TLS again... not sure how I did this, but anyway.
This is "master + kp 1/4" running on FreeBSD, in a p2p --tls-server
instance. It passed the first few tests, but then got left alone for
an hour, trying to reestablish the connection to the "missing --tls-client".
Dec 13 22:18:41 fbsd14 tun-udp-p2p-tls-sha256[19966]: TLS Error: TLS key
negotiation failed to occur within 60 seconds (check your network connectivity)
Dec 13 22:18:41 fbsd14 tun-udp-p2p-tls-sha256[19966]: TLS Error: TLS handshake
failed
Dec 13 22:18:41 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:18:55 fbsd14 tun-udp-p2mp-topology-subnet[19846]: Failed to get peer
stats: Operation not supported (errno=45)
Dec 13 22:18:56 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:18:56 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 WRITE [14] to
[AF_INET6]::ffff:195.30.8.84:34745: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ]
pid=0 DATA len=0
Dec 13 22:18:56 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:18:58 fbsd14 syslogd: last message repeated 1 times
Dec 13 22:18:58 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 WRITE [14] to
[AF_INET6]::ffff:195.30.8.84:34745: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ]
pid=0 DATA len=0
Dec 13 22:18:58 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:19:02 fbsd14 syslogd: last message repeated 1 times
...
Dec 13 22:19:57 fbsd14 tun-udp-p2p-tls-sha256[19966]: TLS Error: TLS key
negotiation failed to occur within 60 seconds (check your network connectivity)
Dec 13 22:19:57 fbsd14 tun-udp-p2p-tls-sha256[19966]: TLS Error: TLS handshake
failed
Dec 13 22:19:57 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:20:12 fbsd14 syslogd: last message repeated 1 times
Dec 13 22:20:12 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 WRITE [14] to
[AF_INET6]::ffff:195.30.8.84:34745: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ]
pid=0 DATA len=0
Dec 13 22:20:12 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
...
Reconnecting *then*, the session did not work, and kernel/userland got
all confused about key state:
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [14] from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757:
P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: TLS: Initial packet from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757, sid=01cf646f 53158ed8
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 WRITE [26] to
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757:
P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [299] from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757: P_CONTROL_V1 kid=0 [ 0 ]
pid=1 DATA len=273
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
...
Dec 13 22:24:44 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:24:45 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [100] from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757: P_DATA_V2 kid=0 DATA len=99
Dec 13 22:24:45 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:24:47 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [116] from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757: P_DATA_V2 kid=0 DATA len=115
Dec 13 22:24:47 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:24:47 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [116] from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757: P_DATA_V2 kid=0 DATA len=115
(why do I see an UDPv6 READ with P_DATA_V2 here, when it should be
doing this in kernel?)
...
Dec 13 22:24:59 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [1512] from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757: P_DATA_V2 kid=0 DATA
len=1511
Dec 13 22:24:59 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=3710010
Dec 13 22:24:59 fbsd14 tun-udp-p2p-tls-sha256[19966]: Swapping primary and
secondary keys, now: id1=0 id2=0
Dec 13 22:24:59 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_swap_keys: peer-id
3710010
Dec 13 22:24:59 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [1512] from
[AF_INET6]2001:608:1:995a:250:56ff:febb:2084:35757: P_DATA_V2 kid=0 DATA
len=1511
...
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: TLS: tls_multi_process:
untrusted session promoted to trusted
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=9123839
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Swapping primary and
secondary keys, now: id1=0 id2=-1
"id2=-1"?
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_swap_keys: peer-id
9123839
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Failed to swap keys: Link
has been severed (errno=91)
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Cannot swap keys:
Operation not permitted (-1)
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 WRITE [364] to
[AF_INET6]::ffff:195.30.8.84:55171: P_CONTROL_V1 kid=0 [ 5 4 3 2 ] pid=4 DATA
len=326
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=9123839
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Swapping primary and
secondary keys, now: id1=0 id2=-1
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_swap_keys: peer-id
9123839
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Failed to swap keys: Link
has been severed (errno=91)
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Cannot swap keys:
Operation not permitted (-1)
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: UDPv6 READ [22] from
[AF_INET6]::ffff:195.30.8.84:55171: P_ACK_V1 kid=0 [ 4 ] DATA len=0
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Control Channel: TLSv1.2,
cipher TLS-ECDHE-RSA-WITH-CHACHA20-POLY1305-SHA256, 2048 bit key
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: [cron2-ubuntu-2004-amd64]
Peer Connection Initiated with [AF_INET6]::ffff:195.30.8.84:55171
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=9123839
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Swapping primary and
secondary keys, now: id1=0 id2=-1
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_swap_keys: peer-id
9123839
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Failed to swap keys: Link
has been severed (errno=91)
Dec 13 22:26:16 fbsd14 tun-udp-p2p-tls-sha256[19966]: Cannot swap keys:
Operation not permitted (-1)
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_del_peer: peer-id
9123839
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_new_peer: peer-id
15538802, fd 7
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: Data Channel: using
negotiated cipher 'AES-256-GCM'
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: Data Channel MTU parms [
mss_fix:1380 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768
tailroom:562 ET:0 ]
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_install_key:
peer_id=15538802 keyid=0
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_new_key: slot 1,
key-id 0, peer-id 15538802, cipher AES-256-GCM
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: Initialization Sequence
Completed
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_update_keys:
peer_id=15538802
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: Swapping primary and
secondary keys, now: id1=0 id2=0
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: dco_swap_keys: peer-id
15538802
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: Assertion failed at
dco.c:197 (secondary->dco_status == DCO_INSTALLED_PRIMARY)
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: Exiting due to fatal error
Dec 13 22:26:17 fbsd14 tun-udp-p2p-tls-sha256[19966]: Closing DCO interface
... this is very likely not related to the counter patch 1/4 but more
a generic "state machines getting confused" thing.
Not sure I can reproduce this, but I do have the full "verb 6" log
for this server instance if one of you wants to have a look.
We have this GH issue about DCO Linux getting out of sync with userland
if tortured with "reneg-sec 15". Seems we need to have a very close
look at renegotiations / key rotation, maybe combined with clients
disconnecting at inconvenient moments.
gert
--
"If was one thing all people took for granted, was conviction that if you
feed honest figures into a computer, honest figures come out. Never doubted
it myself till I met a computer with a sense of humor."
Robert A. Heinlein, The Moon is a Harsh Mistress
Gert Doering - Munich, Germany g...@greenie.muc.de
signature.asc
Description: PGP signature
_______________________________________________ Openvpn-devel mailing list Openvpn-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/openvpn-devel
