Closed as not planned
Closed as not planned
Description
Problem
I'm not sure if it's due to our fork or a problem originating from the original library, but there is a race between tun
receiving a packet on e.incomingPacket
and calling tun.Close()
.
The send seems like it was introduced in: coder/wireguard-go@d82b4ba#diff-313ba9fa7d53858743a9b3b5ea6b4f295a08b66208e29a05133537488d9bbeafR94
==================
WARNING: DATA RACE
Write at 0x00c000110fd0 by goroutine 7:
runtime.closechan()
/usr/local/go/src/runtime/chan.go:356 +0x0
golang.zx2c4.com/wireguard/tun/netstack.(*netTun).Close()
/home/maf/go/pkg/mod/github.com/coder/wireguard-go/tun/netstack@v0.0.0-20220614153727-d82b4ba8619f/tun.go:209 +0xb2
golang.zx2c4.com/wireguard/device.(*Device).Close()
/home/maf/go/pkg/mod/golang.zx2c4.com/wireguard@v0.0.0-20220703234212-c31a7b1ab478/device/device.go:365 +0x162
github.com/coder/coder/coderd/devtunnel_test.newFakeTunnelServer.func1()
/home/maf/src/coder/coderd/devtunnel/tunnel_test.go:142 +0x7e
testing.(*common).Cleanup.func1()
/usr/local/go/src/testing/testing.go:1034 +0x193
testing.(*common).runCleanup()
/usr/local/go/src/testing/testing.go:1203 +0x143
testing.tRunner.func2()
/usr/local/go/src/testing/testing.go:1433 +0x4f
runtime.deferreturn()
/usr/local/go/src/runtime/panic.go:436 +0x32
testing.(*T).Run.func1()
/usr/local/go/src/testing/testing.go:1486 +0x47
Previous read at 0x00c000110fd0 by goroutine 106:
runtime.chansend()
/usr/local/go/src/runtime/chan.go:159 +0x0
golang.zx2c4.com/wireguard/tun/netstack.(*endpoint).WritePackets()
/home/maf/go/pkg/mod/github.com/coder/wireguard-go/tun/netstack@v0.0.0-20220614153727-d82b4ba8619f/tun.go:94 +0xeb
gvisor.dev/gvisor/pkg/tcpip/stack.(*delegatingQueueingDiscipline).WritePacket()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/stack/nic.go:154 +0x83
gvisor.dev/gvisor/pkg/tcpip/stack.(*nic).writeRawPacket()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/stack/nic.go:398 +0x5c
gvisor.dev/gvisor/pkg/tcpip/stack.(*nic).writePacket()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/stack/nic.go:394 +0x59
gvisor.dev/gvisor/pkg/tcpip/stack.(*nic).WritePacket()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/stack/nic.go:355 +0x227
gvisor.dev/gvisor/pkg/tcpip/network/ipv6.(*endpoint).writePacket()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/network/ipv6/ipv6.go:855 +0x401
gvisor.dev/gvisor/pkg/tcpip/network/ipv6.(*endpoint).WritePacket()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/network/ipv6/ipv6.go:806 +0x2d7
gvisor.dev/gvisor/pkg/tcpip/stack.(*Route).WritePacket()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/stack/route.go:468 +0xe3
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.sendTCP()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/connect.go:892 +0x55b
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*endpoint).sendTCP()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/connect.go:790 +0x164
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*endpoint).sendRaw()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/connect.go:949 +0x3fd
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).sendSegmentFromView()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/snd.go:1677 +0x20f
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).sendSegment()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/snd.go:1643 +0x3c9
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).maybeSendSegment()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/snd.go:872 +0x4a9
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).sendData()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/snd.go:978 +0x599
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*endpoint).sendData()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/connect.go:975 +0xb8
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*endpoint).shutdownLocked()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/endpoint.go:2592 +0x444
gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*endpoint).Close()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/transport/tcp/endpoint.go:1138 +0x1d8
gvisor.dev/gvisor/pkg/tcpip/adapters/gonet.(*TCPConn).Close()
/home/maf/go/pkg/mod/gvisor.dev/gvisor@v0.0.0-20220407223209-21871174d445/pkg/tcpip/adapters/gonet/gonet.go:407 +0x47
net/http.(*persistConn).closeLocked()
/usr/local/go/src/net/http/transport.go:2714 +0x21b
net/http.(*persistConn).readLoopPeekFailLocked()
/usr/local/go/src/net/http/transport.go:2253 +0x324
net/http.(*persistConn).readLoop()
/usr/local/go/src/net/http/transport.go:2097 +0x1012
net/http.(*Transport).dialConn.func5()
/usr/local/go/src/net/http/transport.go:1750 +0x39
Goroutine 7 (running) created at:
testing.(*T).Run()
/usr/local/go/src/testing/testing.go:1486 +0x724
testing.runTests.func1()
/usr/local/go/src/testing/testing.go:1839 +0x99
testing.tRunner()
/usr/local/go/src/testing/testing.go:1439 +0x213
testing.runTests()
/usr/local/go/src/testing/testing.go:1837 +0x7e4
testing.(*M).Run()
/usr/local/go/src/testing/testing.go:1719 +0xa71
main.main()
_testmain.go:49 +0x2e4
runtime.main()
/usr/local/go/src/runtime/proc.go:250 +0x211
Goroutine 106 (finished) created at:
net/http.(*Transport).dialConn()
/usr/local/go/src/net/http/transport.go:1750 +0x24c4
net/http.(*Transport).dialConnFor()
/usr/local/go/src/net/http/transport.go:1449 +0x13a
net/http.(*Transport).queueForDial.func1()
/usr/local/go/src/net/http/transport.go:1418 +0x47
==================
--- FAIL: TestTunnel (1.09s)
t.go:81: 2022-07-26 08:20:50.308 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:373> (*Device).RoutineEncryption Routine: encryption worker 1 - started
t.go:81: 2022-07-26 08:20:50.308 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:373> (*Device).RoutineEncryption Routine: encryption worker 2 - started
t.go:81: 2022-07-26 08:20:50.309 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:209> (*Device).RoutineDecryption Routine: decryption worker 1 - started
t.go:81: 2022-07-26 08:20:50.311 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:241> (*Device).RoutineHandshake Routine: handshake worker 1 - started
t.go:81: 2022-07-26 08:20:50.311 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:241> (*Device).RoutineHandshake Routine: handshake worker 2 - started
t.go:81: 2022-07-26 08:20:50.312 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:373> (*Device).RoutineEncryption Routine: encryption worker 3 - started
t.go:81: 2022-07-26 08:20:50.312 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:209> (*Device).RoutineDecryption Routine: decryption worker 3 - started
t.go:81: 2022-07-26 08:20:50.312 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/tun.go:18> (*Device).RoutineTUNEventReader Routine: event worker - started
t.go:81: 2022-07-26 08:20:50.312 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/tun.go:43> (*Device).RoutineTUNEventReader Interface up requested
t.go:81: 2022-07-26 08:20:50.313 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:241> (*Device).RoutineHandshake Routine: handshake worker 6 - started
t.go:81: 2022-07-26 08:20:50.314 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:209> (*Device).RoutineDecryption Routine: decryption worker 4 - started
t.go:81: 2022-07-26 08:20:50.314 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:241> (*Device).RoutineHandshake Routine: handshake worker 3 - started
t.go:81: 2022-07-26 08:20:50.314 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:241> (*Device).RoutineHandshake Routine: handshake worker 4 - started
t.go:81: 2022-07-26 08:20:50.314 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/uapi.go:208> (*Device).handleDeviceLine UAPI: Updating private key
t.go:81: 2022-07-26 08:20:50.315 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:209> (*Device).RoutineDecryption Routine: decryption worker 2 - started
t.go:81: 2022-07-26 08:20:50.315 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:241> (*Device).RoutineHandshake Routine: handshake worker 5 - started
t.go:81: 2022-07-26 08:20:50.315 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:209> (*Device).RoutineDecryption Routine: decryption worker 5 - started
t.go:81: 2022-07-26 08:20:50.316 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:373> (*Device).RoutineEncryption Routine: encryption worker 5 - started
t.go:81: 2022-07-26 08:20:50.316 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:373> (*Device).RoutineEncryption Routine: encryption worker 6 - started
t.go:81: 2022-07-26 08:20:50.316 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:214> (*Device).RoutineReadFromTUN Routine: TUN reader - started
t.go:81: 2022-07-26 08:20:50.317 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:209> (*Device).RoutineDecryption Routine: decryption worker 6 - started
t.go:81: 2022-07-26 08:20:50.317 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:373> (*Device).RoutineEncryption Routine: encryption worker 4 - started
t.go:81: 2022-07-26 08:20:50.317 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/device.go:516> (*Device).BindUpdate UDP bind has been updated
t.go:81: 2022-07-26 08:20:50.317 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:79> (*Device).RoutineReceiveIncoming Routine: receive incoming v6 - started
t.go:81: 2022-07-26 08:20:50.317 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:79> (*Device).RoutineReceiveIncoming Routine: receive incoming v4 - started
t.go:81: 2022-07-26 08:20:50.318 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/uapi.go:218> (*Device).handleDeviceLine UAPI: Updating listen port
t.go:81: 2022-07-26 08:20:50.318 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:73> (*Device).RoutineReceiveIncoming.func1 Routine: receive incoming v4 - stopped
t.go:81: 2022-07-26 08:20:50.318 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:73> (*Device).RoutineReceiveIncoming.func1 Routine: receive incoming v6 - stopped
t.go:81: 2022-07-26 08:20:50.321 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/device.go:516> (*Device).BindUpdate UDP bind has been updated
t.go:81: 2022-07-26 08:20:50.321 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/device.go:165> (*Device).changeState Interface state was Down, requested Up, now Up
t.go:81: 2022-07-26 08:20:50.322 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:79> (*Device).RoutineReceiveIncoming Routine: receive incoming v4 - started
t.go:81: 2022-07-26 08:20:50.324 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:79> (*Device).RoutineReceiveIncoming Routine: receive incoming v6 - started
t.go:81: 2022-07-26 08:20:50.327 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/uapi.go:302> (*Device).handlePublicKeyLine peer(a8BT…DlE8) - UAPI: Created
t.go:81: 2022-07-26 08:20:50.328 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/uapi.go:377> (*Device).handlePeerLine peer(a8BT…DlE8) - UAPI: Adding allowedip
t.go:81: 2022-07-26 08:20:50.328 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/peer.go:182> (*Peer).Start peer(a8BT…DlE8) - Starting
t.go:81: 2022-07-26 08:20:50.328 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:415> (*Peer).RoutineSequentialSender peer(a8BT…DlE8) - Routine: sequential sender - started
t.go:81: 2022-07-26 08:20:50.329 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:403> (*Peer).RoutineSequentialReceiver peer(a8BT…DlE8) - Routine: sequential receiver - started
tunnel_test.go:70: https://[fcca::1]
t.go:81: 2022-07-26 08:20:50.367 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:343> (*Device).RoutineHandshake peer(a8BT…DlE8) - Received handshake initiation
t.go:81: 2022-07-26 08:20:50.367 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:143> (*Peer).SendHandshakeResponse peer(a8BT…DlE8) - Sending handshake response
t.go:81: 2022-07-26 08:20:50.373 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:432> (*Peer).RoutineSequentialReceiver peer(a8BT…DlE8) - Receiving keepalive packet
tunnel_test.go:221: Dial tcp [fcca::2]:8090
tunnel_test.go:55: got request for /
t.go:81: 2022-07-26 08:20:51.386 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/peer.go:258> (*Peer).Stop peer(a8BT…DlE8) - Stopping
t.go:81: 2022-07-26 08:20:51.386 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:414> (*Peer).RoutineSequentialSender.func1 peer(a8BT…DlE8) - Routine: sequential sender - stopped
t.go:81: 2022-07-26 08:20:51.386 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:400> (*Peer).RoutineSequentialReceiver.func1 peer(a8BT…DlE8) - Routine: sequential receiver - stopped
t.go:81: 2022-07-26 08:20:51.387 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/device.go:363> (*Device).Close Device closing
t.go:81: 2022-07-26 08:20:51.387 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/send.go:209> (*Device).RoutineReadFromTUN.func1 Routine: TUN reader - stopped
t.go:81: 2022-07-26 08:20:51.388 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/tun.go:53> (*Device).RoutineTUNEventReader Routine: event worker - stopped
t.go:81: 2022-07-26 08:20:51.388 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:73> (*Device).RoutineReceiveIncoming.func1 Routine: receive incoming v6 - stopped
t.go:81: 2022-07-26 08:20:51.388 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/receive.go:73> (*Device).RoutineReceiveIncoming.func1 Routine: receive incoming v4 - stopped
t.go:81: 2022-07-26 08:20:51.388 [DEBUG] (server.stdlib) <golang.zx2c4.com/wireguard/device/device.go:382> (*Device).Close Device closed
t.go:81: 2022-07-26 08:20:51.388 [DEBUG] (server) <github.com/coder/coder/coderd/devtunnel_test/tunnel_test.go:143> newFakeTunnelServer.func1 dev.Close()
testing.go:1312: race detected during execution of test
FAIL
FAIL github.com/coder/coder/coderd/devtunnel 1.132s
FAIL
(Logging in this test is based on #3194.)
// ping @coadler