NetBSD Problem Report #58938

From christos@astron.com  Thu Dec 26 21:16:41 2024
Return-Path: <christos@astron.com>
Received: from mail.netbsd.org (mail.netbsd.org [199.233.217.200])
	(using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
	 key-exchange X25519 server-signature RSA-PSS (2048 bits)
	 client-signature RSA-PSS (2048 bits))
	(Client CN "mail.NetBSD.org", Issuer "mail.NetBSD.org CA" (not verified))
	by mollari.NetBSD.org (Postfix) with ESMTPS id BF5CC1A9238
	for <gnats-bugs@gnats.NetBSD.org>; Thu, 26 Dec 2024 21:16:41 +0000 (UTC)
Message-Id: <20241226200543.A8A6A6C28E@quasar.astron.com>
Date: Thu, 26 Dec 2024 20:05:43 +0000 (UTC)
From: christos@netbsd.org
Reply-To: christos@netbsd.org
To: gnats-bugs@NetBSD.org
Subject: wg tunnel dies after a few days
X-Send-Pr-Version: 3.95

>Number:         58938
>Category:       kern
>Synopsis:       wg tunnel dies after a few days
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Thu Dec 26 21:20:00 +0000 2024
>Last-Modified:  Wed Jan 15 16:53:21 +0000 2025
>Originator:     Christos Zoulas
>Release:        NetBSD 10.99.12
>Organization:
	clogged tunnels, llc
>Environment:
System: NetBSD quasar.astron.com 10.99.12 NetBSD 10.99.12 (QUASAR) #37: Mon Dec 16 12:41:24 EST 2024 christos@quasar.astron.com:/usr/src/sys/arch/amd64/compile/QUASAR amd64
Architecture: x86_64
Machine: amd64
>Description:
        After a few days my wg tunnel dies and the only way to fix it
        is destroy and create the interfaces again. Bringing them up
        and down does not work
>How-To-Repeat:
        Just bring a tunnel where one end point has an IP address that
        changes very frequently.
>Fix:
        Please:

Variable endpoint (initiator):
[ 1564986.114049] wg_task_send_init_message:3352: WGP_TASK_SEND_INIT_MESSAGE
[ 1564986.114049] wg_send_handshake_msg_init: session[L=e54c6cb9 R=(unknown)] ->
 WGS_STATE_INIT_ACTIVE
[ 1564986.114049] wg_fill_msg_init: wg_fill_msg_init: sender=e54c6cb9
[ 1564986.114049] wg_send_handshake_msg_init:1992: init msg sent
[ 1564991.114103] wg_handshake_timeout_timer:3846: enter
[ 1564991.114103] wg_schedule_peer_task: tasks=0, task=2
[ 1564991.114103] wg_task_retry_handshake:3386: WGP_TASK_RETRY_HANDSHAKE
[ 1564991.114103] wg_destroy_session: session[L=e54c6cb9 R=0] -> WGS_STATE_UNKNO
WN

Fixed endpoint:
[ 872259.780050] wg_overudp_cb:3692: enter
[ 872259.781102] wg_overudp_cb: type=1
[ 872259.781102] wg_handle_msg_init:1605: init msg received
[ 872259.781102] wg_handle_msg_init:1766: Session already initializing, destroyi
ng old states
[ 872259.781102] wg_destroy_session: session[L=195d8c06 R=3ad05aba] -> WGS_STATE
_UNKNOWN
[ 872259.781102] wg_update_endpoint_if_necessary: old=inet: 172.56.161.196:1234,
 new=inet: 172.56.161.196:1234
[ 872259.782050] wg_schedule_session_dtor_timer: session dtor already pending
[ 872259.782050] wg_fill_msg_resp: sender=fca71dad
[ 872259.782050] wg_fill_msg_resp: receiver=214c3c9a
[ 872259.782050] wg_send_handshake_msg_resp:2410: resp msg sent
[ 872259.782050] wg_handle_msg_init: session[L=fca71dad R=214c3c9a]: calculate k
eys as responder
[ 872259.783050] wg_handle_msg_init: session[L=fca71dad R=214c3c9a] -> WGS_STATE
_INIT_PASSIVE
[ 872259.783050] wg_handle_msg_init:1847: WGS_STATE_INIT_PASSIVE

>Release-Note:

>Audit-Trail:
From: "Taylor R Campbell" <riastradh@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/58938 CVS commit: src/sys/net
Date: Fri, 27 Dec 2024 15:55:19 +0000

 Module Name:	src
 Committed By:	riastradh
 Date:		Fri Dec 27 15:55:19 UTC 2024

 Modified Files:
 	src/sys/net: if_wg.c

 Log Message:
 wg(4): Add debug log for which address we send handshake msgs to.

 Maybe this will help to diagnose:

 PR kern/58938: wg tunnel dies after a few days


 To generate a diff of this commit:
 cvs rdiff -u -r1.133 -r1.134 src/sys/net/if_wg.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

From: "Taylor R Campbell" <riastradh@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/58938 CVS commit: src/sys/net
Date: Fri, 27 Dec 2024 16:42:28 +0000

 Module Name:	src
 Committed By:	riastradh
 Date:		Fri Dec 27 16:42:28 UTC 2024

 Modified Files:
 	src/sys/net: if_wg.c

 Log Message:
 wg(4): Fix thinko in previous.  Should unbreak the rump build.

 PR kern/58938: wg tunnel dies after a few days


 To generate a diff of this commit:
 cvs rdiff -u -r1.134 -r1.135 src/sys/net/if_wg.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

>Unformatted:


 It is stuck again:

 Initiator:

 [ 1542077.588886] wg_task_send_init_message:3358: WGP_TASK_SEND_INIT_MESSAGE
 [ 1542077.588886] wg_send_handshake_msg_init: session[L=e09b73e2 R=(unknown)] -> WGS_STATE_INIT_ACTIVE
 [ 1542077.588886] wg_fill_msg_init: wg_fill_msg_init: sender=e09b73e2
 [ 1542077.588886] wg_send_hs: send handshake msg to inet: 104.162.232.43:1234
 [ 1542077.588886] wg_send_handshake_msg_init:1998: init msg sent
 [ 1542082.588947] wg_handshake_timeout_timer:3875: enter
 [ 1542082.588947] wg_schedule_peer_task: tasks=0, task=2
 [ 1542082.588947] wg_task_retry_handshake:3392: WGP_TASK_RETRY_HANDSHAKE
 [ 1542082.588947] wg_destroy_session: session[L=e09b73e2 R=0] -> WGS_STATE_UNKNOWN

 Receiver:
 [ 1548461.674806] wg_destroy_session: session[L=39f339a0 R=b5fd9f65] -> WGS_STATE_UNKNOWN
 [ 1548461.675855] wg_update_endpoint_if_necessary: old=inet: 172.56.161.196:1234, new=inet: 172.56.161.196:1234
 [ 1548461.675855] wg_schedule_session_dtor_timer: session dtor already pending
 [ 1548461.675855] wg_fill_msg_resp: sender=2ed74962
 [ 1548461.675855] wg_fill_msg_resp: receiver=435a41c5
 [ 1548461.675855] wg_send_hs: send handshake msg to inet: 172.56.161.196:1234
 [ 1548461.675855] wg_send_handshake_msg_resp:2416: resp msg sent
 [ 1548461.675855] wg_handle_msg_init: session[L=2ed74962 R=435a41c5]: calculate keys as responder
 [ 1548461.675855] wg_handle_msg_init: session[L=2ed74962 R=435a41c5] -> WGS_STATE_INIT_PASSIVE
 [ 1548461.676913] wg_handle_msg_init:1848: WGS_STATE_INIT_PASSIVE
 [ 1548466.672837] wg_overudp_cb:3698: enter
 [ 1548466.672837] wg_overudp_cb: type=1
 [ 1548466.672837] wg_handle_msg_init:1606: init msg received
 [ 1548466.673835] wg_handle_msg_init:1767: Session already initializing, destroying old states

 Note that receiver still thinks that initiator is at 172.56.161.196, but
 it has moved to
 blazar:~ [DING!] 77#/usr/local/etc/myip
 172.56.167.108

 Why does it believe that the IP address has not changed?

 So on the Reveiver tcpdump shows that it receives from the old address:
 [11:12am] 33#tcpdump -n -i wm0 port 1234
 tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
 listening on wm0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
 11:13:08.781466 IP 172.56.161.196.1234 > 104.162.232.43.1234: UDP, length 148
 11:13:08.782960 IP 104.162.232.43.1234 > 172.56.161.196.1234: UDP, length 92
 11:13:13.755402 IP 172.56.161.196.1234 > 104.162.232.43.1234: UDP, length 148
 11:13:13.756886 IP 104.162.232.43.1234 > 172.56.161.196.1234: UDP, length 92
 11:13:18.781141 IP 172.56.161.196.1234 > 104.162.232.43.1234: UDP, length 148

 On the sender, I can't tell because it is behind NAT, but it sends:

 11:14:40.636291 IP 192.168.0.116.1234 > 104.162.232.43.1234: UDP, length 148
 11:14:45.636301 IP 192.168.0.116.1234 > 104.162.232.43.1234: UDP, length 148
 11:14:50.636414 IP 192.168.0.116.1234 > 104.162.232.43.1234: UDP, length 148
 11:14:55.636424 IP 192.168.0.116.1234 > 104.162.232.43.1234: UDP, length 148
 11:15:00.636534 IP 192.168.0.116.1234 > 104.162.232.43.1234: UDP, length 148

 It could be that the telco gateway somehow gets stuck sending from
 the old address? Why does deleting and recreating the interfaces
 makes it work again?

 Yet, icmp comes from the correct address:
 [11:51am] 16#tcpdump -i wm0  icmp
 tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
 listening on wm0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
 11:51:53.623974 IP 172.56.165.168 > syn-104-162-232-043.res.spectrum.com: ICMP echo request, id 11225, seq 0, length 64
 11:51:53.624024 IP syn-104-162-232-043.res.spectrum.com > 172.56.165.168: ICMP echo reply, id 11225, seq 0, length 64
 11:51:54.506375 IP 172.56.165.168 > syn-104-162-232-043.res.spectrum.com: ICMP echo request, id 11225, seq 1, length 64
 11:51:54.506422 IP syn-104-162-232-043.res.spectrum.com > 172.56.165.168: ICMP echo reply, id 11225, seq 1, length 64
 11:51:55.505721 IP 172.56.165.168 > syn-104-162-232-043.res.spectrum.com: ICMP echo request, id 11225, seq 2, length 64
 11:51:55.505763 IP syn-104-162-232-043.res.spectrum.com > 172.56.165.168: ICMP echo reply, id 11225, seq 2, length 64
 11:51:56.507965 IP 172.56.165.168 > syn-104-162-232-043.res.spectrum.com: ICMP echo request, id 11225, seq 3, length 64
 11:51:56.508004 IP syn-104-162-232-043.res.spectrum.com > 172.56.165.168: ICMP echo reply, id 11225, seq 3, length 64


 (the address changes constantly)

Home	PR Database Search