Re: wireguard-go: data race introduced in recent commit 9e2f386

[lsc <lsc@lv6.tw>]

Sure, here's the trace:

--
DEBUG: (wg1) 2023/03/22 23:46:39 peer(Suxf…6dEI) - Routine: sequential sender - stopped
panic: As4 called on IP zero value

goroutine 70 [running]:
net/netip.Addr.As4({{0xc0048b1200?, 0xc00058bb28?}, 0x0?})
        /opt/go1.20.2.linux-arm64/src/net/netip/netip.go:690 +0x174
golang.zx2c4.com/wireguard/conn.setSrcControl(0xc00931b018, 0xc006301640)
        /home/lsc36/wireguard-go/conn/sticky_linux.go:95 +0x280
golang.zx2c4.com/wireguard/conn.(*StdNetBind).send4(0xc0003b6000, 0xffffa9d04200?, 0xc0000b8230, {0x24e6e8?, 0xc006301640?}, {0xc000533800, 0x1, 0xba250?})
        /home/lsc36/wireguard-go/conn/bind_std.go:346 +0x178
golang.zx2c4.com/wireguard/conn.(*StdNetBind).Send(0xc0003b6000, {0xc000533800, 0x1, 0x80}, {0x24e6e8, 0xc006301640})
        /home/lsc36/wireguard-go/conn/bind_std.go:332 +0x1d8
golang.zx2c4.com/wireguard/device.(*Peer).SendBuffers(0xc0000be380, {0xc000533800?, 0x1, 0x80})
        /home/lsc36/wireguard-go/device/peer.go:126 +0x190
golang.zx2c4.com/wireguard/device.(*Peer).RoutineSequentialSender(0xc0000be380, 0x80)
        /home/lsc36/wireguard-go/device/send.go:519 +0x45c
created by golang.zx2c4.com/wireguard/device.(*Peer).Start
        /home/lsc36/wireguard-go/device/peer.go:198 +0x304
--

The offending call `ep.SrcIP().As4()` (sticky_linux.go:95) is only
reached when `ep.SrcIP().Is4() && ep.SrcIP().IsValid()` is true, yet it
panicked saying it was being called against a zero value. That's why I
suspected it's a data race in the first place.

On 3/24/23 01:00, Jordan Whited wrote:
> SC, thank you for reporting. Do you happen to have a stack trace from
> one of the panics?
> 
> On Thu, Mar 23, 2023 at 2:01 AM lsc <lsc@lv6.tw> wrote:
>>
>> Hi,
>>
>> Not sure if this is the correct place for bug reports, hope it's okay :)
>>
>> I found my wireguard-go server (built from current ToT 1417a47) always
>> panicking when I ran speedtest on a client via the server. I rebuilt the
>> server with data race detector (`go build -race`) and got the following
>> trace:
>>
>> ==================
>> WARNING: DATA RACE
>> Read at 0x00c00043b2f8 by goroutine 49:
>>    golang.zx2c4.com/wireguard/conn.setSrcControl()
>>        /home/lsc36/wireguard-go/conn/sticky_linux.go:76 +0x8c
>>    golang.zx2c4.com/wireguard/conn.(*StdNetBind).send4()
>>        /home/lsc36/wireguard-go/conn/bind_std.go:346 +0x174
>>    golang.zx2c4.com/wireguard/conn.(*StdNetBind).Send()
>>        /home/lsc36/wireguard-go/conn/bind_std.go:332 +0x1d4
>>    golang.zx2c4.com/wireguard/device.(*Peer).SendBuffers()
>>        /home/lsc36/wireguard-go/device/peer.go:126 +0x18c
>>    golang.zx2c4.com/wireguard/device.(*Peer).RoutineSequentialSender()
>>        /home/lsc36/wireguard-go/device/send.go:519 +0x458
>>    golang.zx2c4.com/wireguard/device.(*Peer).Start.func2()
>>        /home/lsc36/wireguard-go/device/peer.go:198 +0x40
>>
>> Previous write at 0x00c00043b2f8 by goroutine 47:
>>    golang.zx2c4.com/wireguard/conn.(*StdNetEndpoint).ClearSrc()
>>        /home/lsc36/wireguard-go/conn/bind_std.go:100 +0x48
>>    golang.zx2c4.com/wireguard/conn.getSrcFromControl()
>>        /home/lsc36/wireguard-go/conn/sticky_linux.go:18 +0x3c
>>    golang.zx2c4.com/wireguard/conn.(*StdNetBind).makeReceiveIPv4.func1()
>>        /home/lsc36/wireguard-go/conn/bind_std.go:232 +0x350
>>    golang.zx2c4.com/wireguard/device.(*Device).RoutineReceiveIncoming()
>>        /home/lsc36/wireguard-go/device/receive.go:107 +0x3ac
>>    golang.zx2c4.com/wireguard/device.(*Device).BindUpdate.func3()
>>        /home/lsc36/wireguard-go/device/device.go:530 +0x4c
>>
>> Goroutine 49 (running) created at:
>>    golang.zx2c4.com/wireguard/device.(*Peer).Start()
>>        /home/lsc36/wireguard-go/device/peer.go:198 +0x300
>>    golang.zx2c4.com/wireguard/device.(*ipcSetPeer).handlePostConfig()
>>        /home/lsc36/wireguard-go/device/uapi.go:268 +0x164
>>    golang.zx2c4.com/wireguard/device.(*Device).IpcSetOperation()
>>        /home/lsc36/wireguard-go/device/uapi.go:160 +0x35c
>>    golang.zx2c4.com/wireguard/device.(*Device).IpcHandle()
>>        /home/lsc36/wireguard-go/device/uapi.go:428 +0x248
>>    main.main.func4.1()
>>        /home/lsc36/wireguard-go/main.go:245 +0x4c
>>
>> Goroutine 47 (running) created at:
>>    golang.zx2c4.com/wireguard/device.(*Device).BindUpdate()
>>        /home/lsc36/wireguard-go/device/device.go:530 +0x4b8
>>    golang.zx2c4.com/wireguard/device.(*Device).handleDeviceLine()
>>        /home/lsc36/wireguard-go/device/uapi.go:223 +0x45c
>>    golang.zx2c4.com/wireguard/device.(*Device).IpcSetOperation()
>>        /home/lsc36/wireguard-go/device/uapi.go:183 +0x210
>>    golang.zx2c4.com/wireguard/device.(*Device).IpcHandle()
>>        /home/lsc36/wireguard-go/device/uapi.go:428 +0x248
>>    main.main.func4.1()
>>        /home/lsc36/wireguard-go/main.go:245 +0x4c
>> ==================
>>
>> The bug looks introduced by a recent commit 9e2f386 "conn, device, tun:
>> implement vectorized I/O on Linux". Without much knowledge to the
>> codebase, it seems to me that Endpoint is supposed to be guarded by the
>> RWMutex embedded in Peer, yet the change introduced a write without
>> locking the mutex (`ep.ClearSrc()` called from sticky_linux.go:18).
>>
>> In addition, I found it weird that Endpoint objects are reused via
>> `endpointPool`. The docstring suggests "Endpoints are immutable, so we
>> can re-use them" but that doesn't seem true.
>>
>> Added authors/reviewers of 9e2f386 to cc. Would you take a look?
>>
>> Regards,
>> SC
>>