Skip to content

Data race on closed channel in library used by devtunnel (wireguard-go/tun/netstack) #3195

Closed as not planned
@mafredri

Description

@mafredri

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    apiArea: HTTP API

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions