Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

x/net/ipv4: TestPacketConnConcurrentReadWriteUnicastUDP timeout with goroutines blocked on net.rawConn.Read #54595

Open
bcmills opened this issue Aug 22, 2022 · 2 comments
Open

x/net/ipv4: TestPacketConnConcurrentReadWriteUnicastUDP timeout with goroutines blocked on net.rawConn.Read #54595

bcmills opened this issue Aug 22, 2022 · 2 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-FreeBSD
Milestone
Unreleased

Comments

@bcmills
Copy link
Contributor

bcmills commented Aug 22, 2022 •
edited 

#!watchflakes
post <- pkg == "golang.org/x/net/ipv4" && test == "TestPacketConnConcurrentReadWriteUnicastUDP" && `^net\.\(\*rawConn\).Read`

2022-08-18T05:32:36-3211cb9-a2c2f06/freebsd-amd64-13_0

panic: test timed out after 10m0s

goroutine 81 [running]:
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:176 +0x32

goroutine 1 [chan receive]:
testing.(*T).Run(0xc000083040, {0x5b8345?, 0xc000058bb0?}, 0x5bb2f0)
	/tmp/workdir/go/src/testing/testing.go:1494 +0x37a
testing.runTests.func1(0xc000083040?)
	/tmp/workdir/go/src/testing/testing.go:1846 +0x6e
testing.tRunner(0xc000083040, 0xc000058cd8)
	/tmp/workdir/go/src/testing/testing.go:1446 +0x10b
testing.runTests(0xc0000c2280?, {0x6e34e0, 0x19, 0x19}, {0x800b415b8?, 0x40?, 0x6e78e0?})
	/tmp/workdir/go/src/testing/testing.go:1844 +0x456
testing.(*M).Run(0xc0000c2280)
	/tmp/workdir/go/src/testing/testing.go:1726 +0x5d9
main.main()
	_testmain.go:101 +0x1aa

goroutine 40 [semacquire]:
sync.runtime_Semacquire(0xc0000e1b80?)
	/tmp/workdir/go/src/runtime/sema.go:62 +0x25
sync.(*WaitGroup).Wait(0x5ae420?)
	/tmp/workdir/go/src/sync/waitgroup.go:139 +0x52
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP(0xc0000f5a00)
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:322 +0x6aa
testing.tRunner(0xc0000f5a00, 0x5bb2f0)
	/tmp/workdir/go/src/testing/testing.go:1446 +0x10b
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:1493 +0x35f

goroutine 72 [IO wait]:
internal/poll.runtime_pollWait(0x8288bf9b8, 0x72)
	/tmp/workdir/go/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc00012e400?, 0x48?, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).RawRead(0xc00012e400, 0xc0001501e0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:766 +0x145
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6b40?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc0000adbc0, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9500, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f

goroutine 73 [semacquire]:
internal/poll.runtime_Semacquire(0x0?)
	/tmp/workdir/go/src/runtime/sema.go:67 +0x25
internal/poll.(*fdMutex).rwlock(0xc00012e400, 0x48?)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:154 +0xd2
internal/poll.(*FD).readLock(...)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:221
internal/poll.(*FD).RawRead(0xc00012e400, 0xc000150230)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:755 +0x45
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6b58?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc0000adc80, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9600, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f

goroutine 74 [semacquire]:
internal/poll.runtime_Semacquire(0x0?)
	/tmp/workdir/go/src/runtime/sema.go:67 +0x25
internal/poll.(*fdMutex).rwlock(0xc00012e400, 0x48?)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:154 +0xd2
internal/poll.(*FD).readLock(...)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:221
internal/poll.(*FD).RawRead(0xc00012e400, 0xc000150280)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:755 +0x45
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6b70?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc0000add40, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9700, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f

goroutine 75 [semacquire]:
internal/poll.runtime_Semacquire(0x0?)
	/tmp/workdir/go/src/runtime/sema.go:67 +0x25
internal/poll.(*fdMutex).rwlock(0xc00012e400, 0x48?)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:154 +0xd2
internal/poll.(*FD).readLock(...)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:221
internal/poll.(*FD).RawRead(0xc00012e400, 0xc0001502d0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:755 +0x45
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6b88?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc0000ade00, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9800, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f

goroutine 76 [semacquire]:
internal/poll.runtime_Semacquire(0x0?)
	/tmp/workdir/go/src/runtime/sema.go:67 +0x25
internal/poll.(*fdMutex).rwlock(0xc00012e400, 0x48?)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:154 +0xd2
internal/poll.(*FD).readLock(...)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:221
internal/poll.(*FD).RawRead(0xc00012e400, 0xc000150320)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:755 +0x45
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6ba0?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc0000adec0, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9900, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f

goroutine 77 [semacquire]:
internal/poll.runtime_Semacquire(0x0?)
	/tmp/workdir/go/src/runtime/sema.go:67 +0x25
internal/poll.(*fdMutex).rwlock(0xc00012e400, 0x48?)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:154 +0xd2
internal/poll.(*FD).readLock(...)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:221
internal/poll.(*FD).RawRead(0xc00012e400, 0xc000150370)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:755 +0x45
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6bb8?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc0000adf80, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9a00, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f

goroutine 78 [semacquire]:
internal/poll.runtime_Semacquire(0x0?)
	/tmp/workdir/go/src/runtime/sema.go:67 +0x25
internal/poll.(*fdMutex).rwlock(0xc00012e400, 0x48?)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:154 +0xd2
internal/poll.(*FD).readLock(...)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:221
internal/poll.(*FD).RawRead(0xc00012e400, 0xc0001503c0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:755 +0x45
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6bd0?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc000160060, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9b00, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f

goroutine 79 [semacquire]:
internal/poll.runtime_Semacquire(0x0?)
	/tmp/workdir/go/src/runtime/sema.go:67 +0x25
internal/poll.(*fdMutex).rwlock(0xc00012e400, 0x48?)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:154 +0xd2
internal/poll.(*FD).readLock(...)
	/tmp/workdir/go/src/internal/poll/fd_mutex.go:221
internal/poll.(*FD).RawRead(0xc00012e400, 0xc000150410)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:755 +0x45
net.(*rawConn).Read(0xc0000aa0e0, 0xc0000b6be8?)
	/tmp/workdir/go/src/net/rawconn.go:43 +0x45
golang.org/x/net/internal/socket.(*Conn).recvMsg(0xc0000ea640, 0xc000160120, 0x0)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/rawconn_msg.go:28 +0x179
golang.org/x/net/internal/socket.(*Conn).RecvMsg(...)
	/tmp/workdir/gopath/src/golang.org/x/net/internal/socket/socket.go:247
golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0xc000119b90, {0xc0000c9c00, 0x80, 0x80})
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/payload_cmsg.go:32 +0x528
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP.func2()
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:268 +0xeb
created by golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:320 +0x68f
FAIL	golang.org/x/net/ipv4	600.155s

It looks like there are many reader goroutines stuck with no writer goroutines remaining, which implies that either all of the writers succeeded, or one or more of writers failed but somehow didn't succeed in unblocking the readers by closing the PacketConn.

(I'm not able to find this failure using greplogs; it may have rolled off the end of what the dashboard is willing to serve.)

(attn @golang/freebsd, since this may be a symptom of a kernel bug)
@gopherbot gopherbot added this to the Unreleased milestone Aug 22, 2022
@bcmills bcmills added OS-FreeBSD NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Aug 22, 2022
@bcmills bcmills mentioned this issue Aug 22, 2022
Closed
@bcmills bcmills mentioned this issue Jul 21, 2023
Closed
@bcmills bcmills changed the title x/net/ipv4: TestPacketConnConcurrentReadWriteUnicastUDP timeout on freebsd-amd64-13_0 x/net/ipv4: TestPacketConnConcurrentReadWriteUnicastUDP timeout with goroutines blocked on net.rawConn.Read Jul 21, 2023
@bcmills
Copy link
Contributor Author

bcmills commented Jul 21, 2023

(CC @ianlancetaylor per https://dev.golang.org/owners)

@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "golang.org/x/net/ipv4" && test == "TestPacketConnConcurrentReadWriteUnicastUDP" && `^net\.\(\*rawConn\).Read`
2023-07-18 22:51 freebsd-amd64-13_0 net@d0912d40 go@8c8277b8 x/net/ipv4.TestPacketConnConcurrentReadWriteUnicastUDP (log) 
panic: test timed out after 10m0s

sync.runtime_Semacquire(0xc000159d00?)
	/tmp/workdir/go/src/runtime/sema.go:62 +0x25
sync.(*WaitGroup).Wait(0x5adfca?)
	/tmp/workdir/go/src/sync/waitgroup.go:139 +0x52
golang.org/x/net/ipv4_test.TestPacketConnConcurrentReadWriteUnicastUDP(0xc0001796c0)
	/tmp/workdir/gopath/src/golang.org/x/net/ipv4/readwrite_test.go:322 +0x60a
testing.tRunner(0xc0001796c0, 0x5bafa0)

— watchflakes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-FreeBSD
Projects
Test Flakes
Status: No status
Milestone
Unreleased
Development

No branches or pull requests
2 participants
@bcmills @gopherbot