8000 TestListenerCustomConnIDs sometimes times out or fails · Issue #712 · pion/dtls · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

TestListenerCustomConnIDs sometimes times out or fails #712

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.

Sign up for GitHub

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
Closed
Zacho2 opened this issue May 25, 2025 · 1 comment
8000
Closed

TestListenerCustomConnIDs sometimes times out or fails #712

Zacho2 opened this issue May 25, 2025 · 1 comment

Comments

@Zacho2
Copy link
Contributor
Zacho2 commented May 25, 2025

Your environment.

  • Version: 806ff2f
  • Other Information - go1.24.2, darwin/arm64

What did you do?

$ cd internal/net/udp
# Even a low count value reliably reproduces a failure pretty reliably on my machine
$ go test -run TestListenerCustomConnIDs -count=100

What did you expect?

The test to pass reliably

What happened?

I'm observing the test sometimes fail with two different failure modes. I originally encountered the the timeout failure mode when running all repository Go tests locally. When attempting to reproduce the timeout, I found a second failure mode.

The first failure mode is the test failing with a timeout. Here's example output from this failure:

$ go test -run TestListenerCustomConnIDs -count=10 -failfast
goroutine profile: total 6
1 @ 0x10025f20c 0x10029c484 0x100360994 0x1003607c0 0x10035deac 0x1003e4a40 0x1002a5184
#	0x100360993	runtime/pprof.writeRuntimeProfile+0xb3							/usr/local/go/src/runtime/pprof/pprof.go:796
#	0x1003607bf	runtime/pprof.writeGoroutine+0x4f							/usr/local/go/src/runtime/pprof/pprof.go:755
#	0x10035deab	runtime/pprof.(*Profile).WriteTo+0x14b							/usr/local/go/src/runtime/pprof/pprof.go:377
#	0x1003e4a3f	github.com/pion/dtls/v3/internal/net/udp.TestListenerCustomConnIDs.TimeOut.func6+0x3f	/Users/zach/go/pkg/mod/github.com/pion/transport/v3@v3.0.7/test/util.go:24

1 @ 0x10029d6f8 0x1002380fc 0x100237c94 0x10031c498 0x10031e420 0x10031b734 0x10031e33c 0x10031d098 0x1003e4df0 0x100269324 0x1002a5184
#	0x10031c497	testing.(*T).Run+0x387		/usr/local/go/src/testing/testing.go:1859
#	0x10031e41f	testing.runTests.func1+0x3f	/usr/local/go/src/testing/testing.go:2279
#	0x10031b733	testing.tRunner+0xe3		/usr/local/go/src/testing/testing.go:1792
#	0x10031e33b	testing.runTests+0x3eb		/usr/local/go/src/testing/testing.go:2277
#	0x10031d097	testing.(*M).Run+0x587		/usr/local/go/src/testing/testing.go:2142
#	0x1003e4def	main.main+0x8f			_testmain.go:57
#	0x100269323	runtime.main+0x283		/usr/local/go/src/runtime/proc.go:283

1 @ 0x10029d6f8 0x100262918 0x10029c8b0 0x1002ca2f8 0x1002cb428 0x1002cb419 0x10038d428 0x10039eb5c 0x10039dd1c 0x10039de9c 0x1003defc4 0x1002a5184
#	0x10029c8af	internal/poll.runtime_pollWait+0x9f					/usr/local/go/src/runtime/netpoll.go:351
#	0x1002ca2f7	internal/poll.(*pollDesc).wait+0x27					/usr/local/go/src/internal/poll/fd_poll_runtime.go:84
#	0x1002cb427	internal/poll.(*pollDesc).waitRead+0x1e7				/usr/local/go/src/internal/poll/fd_poll_runtime.go:89
#	0x1002cb418	internal/poll.(*FD).ReadFromInet4+0x1d8					/usr/local/go/src/internal/poll/fd_unix.go:248
#	0x10038d427	net.(*netFD).readFromInet4+0x27						/usr/local/go/src/net/fd_posix.go:66
#	0x10039eb5b	net.(*UDPConn).readFrom+0x13b						/usr/local/go/src/net/udpsock_posix.go:52
#	0x10039dd1b	net.(*UDPConn).readFromUDP+0x2b						/usr/local/go/src/net/udpsock.go:149
#	0x10039de9b	net.(*UDPConn).ReadFrom+0x4b						/usr/local/go/src/net/udpsock.go:158
#	0x1003defc3	github.com/pion/dtls/v3/internal/net/udp.(*listener).readLoop+0xb3	/Users/zach/Documents/src/dtls/internal/net/udp/packet_conn.go:214

1 @ 0x10029d6f8 0x10027ccc4 0x1003a5600 0x1003df7c4 0x1003e34b0 0x1002a5184
#	0x1003a55ff	github.com/pion/dtls/v3/internal/net.(*PacketBuffer).ReadFrom+0x1cf		/Users/zach/Documents/src/dtls/internal/net/buffer.go:205
#	0x1003df7c3	github.com/pion/dtls/v3/internal/net/udp.(*PacketConn).ReadFrom+0x23		/Users/zach/Documents/src/dtls/internal/net/udp/packet_conn.go:300
#	0x1003e34af	github.com/pion/dtls/v3/internal/net/udp.TestListenerCustomConnIDs.func3+0x2df	/Users/zach/Documents/src/dtls/internal/net/udp/packet_conn_test.go:503

1 @ 0x10029d6f8 0x10027db34 0x10027db15 0x10029ec0c 0x1002aaca0 0x1003dee4c 0x1002a5184
#	0x10029ec0b	sync.runtime_SemacquireWaitGroup+0x2b						/usr/local/go/src/runtime/sema.go:110
#	0x1002aac9f	sync.(*WaitGroup).Wait+0x6f							/usr/local/go/src/sync/waitgroup.go:118
#	0x1003dee4b	github.com/pion/dtls/v3/internal/net/udp.(*ListenConfig).Listen.func1+0x2b	/Users/zach/Documents/src/dtls/internal/net/udp/packet_conn.go:190

1 @ 0x10029d6f8 0x10027db34 0x10027db15 0x10029ec0c 0x1002aaca0 0x1003e29e8 0x10031b734 0x1002a5184
#	0x10029ec0b	sync.runtime_SemacquireWaitGroup+0x2b						/usr/local/go/src/runtime/sema.go:110
#	0x1002aac9f	sync.(*WaitGroup).Wait+0x6f							/usr/local/go/src/sync/waitgroup.go:118
#	0x1003e29e7	github.com/pion/dtls/v3/internal/net/udp.TestListenerCustomConnIDs+0x4b7	/Users/zach/Documents/src/dtls/internal/net/udp/packet_conn_test.go:593
#	0x10031b733	testing.tRunner+0xe3								/usr/local/go/src/testing/testing.go:1792

panic: timeout

goroutine 65 [running]:
github.com/pion/dtls/v3/internal/net/udp.TestListenerCustomConnIDs.TimeOut.func6()
	/Users/zach/go/pkg/mod/github.com/pion/transport/v3@v3.0.7/test/util.go:27 +0x88
created by time.goFunc
	/usr/local/go/src/time/sleep.go:215 +0x38
exit status 2
FAIL	github.com/pion/dtls/v3/internal/net/udp	20.159s

The second failure mode appears to be a test condition not being met.

$ go test -run TestListenerCustomConnIDs -count=10 -failfast
--- FAIL: TestListenerCustomConnIDs (0.41s)
    packet_conn_test.go:513:
        	Error Trace:	/Users/zach/Documents/src/dtls/internal/net/udp/packet_conn_test.go:513
        	            				/usr/local/go/src/runtime/asm_arm64.s:1223
        	Error:      	Should be false
        	Test:       	TestListenerCustomConnIDs
        	Messages:   	Multiple messages from single client 127.0.0.1:53506
FAIL
exit status 1
FAIL	github.com/pion/dtls/v3/internal/net/udp	0.562s
@Zacho2
Copy link
Contributor Author
Zacho2 commented May 26, 2025

From a little investigation, this seems to be related to PacketBuffer.ReadFrom() erroneously thinking it needs to wait for the next PacketBuffer.WriteTo() to notify the reader of new data when there is data in the buffer that could be read. It seems like this is related to when the buffer resize happens. When this happens, it seems like there is potential for some buffered packets to be lost.

Zacho2 added a commit to Zacho2/dtls that referenced this issue May 26, 2025
@Zacho2
Fix incorrect packet circular buffer read index after buffer resize
791c4be 
Fix a bug that caused the packet circular buffer to have an incorrect
read index after a buffer resize occurs when the write index is less
than the read index. When this occured, reading from a connection
would erroneously block (packet(s) are in the buffer) and some buffered
packets could be lost.

Fixes pion#712
Zacho2 added a commit to Zacho2/dtls that referenced this issue May 26, 2025
@Zacho2
Fix incorrect packet circular buffer read index after buffer resize
cf0e023 
Fix a bug that caused the packet circular buffer to have an incorrect
read index after a buffer resize occurs when the write index is less
than the read index. When this occured, reading from a connection
would erroneously block (packet(s) are in the buffer) and some buffered
packets could be lost.

Partially fixes pion#712. This specifically fixes the test failure mode
where the test times out due to blocking on reading a packet.
@Zacho2 Zacho2 mentioned this issue May 26, 2025
Merged
Zacho2 added a commit to Zacho2/dtls that referenced this issue May 26, 2025
@Zacho2
Fix packet buffer read index after buffer resize
2153330 
Fix a bug that caused the packet circular buffer to have an incorrect
read index after a buffer resize occurs when the write index is less
than the read index. When this occured, reading from a connection
would erroneously block (packet(s) are in the buffer) and some buffered
packets could be lost.

Partially fixes pion#712. This specifically fixes the test failure mode
where the test times out due to blocking on reading a packet even
though a buffered packet exists.
Zacho2 added a commit to Zacho2/dtls that referenced this issue May 26, 2025
@Zacho2
Fix packet buffer read index after buffer resize
3b5d316 
Fix a bug that caused the packet circular buffer to have an incorrect
read index after a buffer resize occurs when the read index is non-zero.
When this occured, reading from a connection would erroneously block
(packet(s) are in the buffer) and some buffered packets could be lost.

Partially fixes pion#712. This specifically fixes the test failure mode
where the test times out due to blocking on reading a packet even
though a buffered packet exists.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@Zacho2
0