Skip to content

flake: test-go-macos: TestPortForward/UDP_OnePort: match deadline exceeded: context deadline exceeded #10979

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
johnstcn opened this issue Dec 1, 2023 · 4 comments · Fixed by #11119
Closed

flake: test-go-macos: TestPortForward/UDP_OnePort: match deadline exceeded: context deadline exceeded #10979

johnstcn opened this issue Dec 1, 2023 · 4 comments · Fixed by #11119
Assignees
@spikecurtis

Comments

@johnstcn
Copy link
Member

johnstcn commented Dec 1, 2023

Seen here: https://github.com/coder/coder/actions/runs/7058169983/job/19213216707?pr=10975

2023-12-01T09:31:01.7876690Z     portforward_test.go:169: 
2023-12-01T09:31:01.7877170Z         	Error Trace:	/Users/runner/work/coder/coder/pty/ptytest/ptytest.go:347
2023-12-01T09:31:01.7877940Z         	            				/Users/runner/work/coder/coder/pty/ptytest/ptytest.go:177
2023-12-01T09:31:01.7878680Z         	            				/Users/runner/work/coder/coder/cli/portforward_test.go:169
2023-12-01T09:31:01.7879140Z         	Error:      	read error
2023-12-01T09:31:01.7879480Z         	Test:       	TestPortForward/UDP_OnePort
2023-12-01T09:31:01.7942150Z         	Messages:   	match deadline exceeded: context deadline exceeded (wanted "Ready!"; got "2023-12-01 09:29:15.804 [debu]  cli.net.wgengine: [v1] using fake (no-op) tun device\r\n2023-12-01 09:29:15.804 [debu]  cli.net.wgengine: [v1] using fake (no-op) OS network configurator\r\n2023-12-01 09:29:15.804 [debu]  cli.net.wgengine: [v1] using fake (no-op) DNS configurator\r\n2023-12-01 09:29:15.804 [debu]  cli.net.wgengine: dns: using dns.noopManager\r\n2023-12-01 09:29:15.804 [debu]  cli.net.wgengine: link state: interfaces.State{defaultRoute=en0 ifs={en0:[192.168.64.24/24]} v4=true v6=false}\r\n2023-12-01 09:29:15.804 [debu]  cli.net.wgengine: [v1] couldn't create raw v4 disco listener, using regular listener instead: raw disco listening not supported on this OS\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: [v1] couldn't create raw v6 disco listener, using regular listener instead: raw disco listening not supported on this OS\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: magicsock: disco key = d:6a0fffa91fcce66a\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: Creating WireGuard device...\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: Bringing WireGuard device up...\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: wg: [v2] UDP bind has been updated\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: wg: [v2] Interface state was Down, requested Up, now Up\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: Bringing router up...\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: [v1] warning: fakeRouter.Up: not implemented.\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: Clearing router settings...\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: Starting network monitor...\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: Engine created.\r\n2023-12-01 09:29:15.805 [debu]  cli: magicsock debug logging disabled, use CODER_MAGICSOCK_DEBUG_LOGGING=true to enable\r\n2023-12-01 09:29:15.805 [debu]  cli.net.wgengine: magicsock: SetPrivateKey called (init)\r\n2023-12-01 09:29:15.806 [debu]  cli.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started\r\n2023-12-01 09:29:15.806 [debu]  cli.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - started\r\n2023-12-01 09:29:15.806 [debu]  cli.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started\r\n2023-12-01 09:29:15.807 [debu]  cli: updating network map\r\n2023-12-01 09:29:15.807 [debu]  cli.net.wgengine: [v1] magicsock: got updated network map; 0 peers\r\n2023-12-01 09:29:15.807 [debu]  cli: connecting to server for derp map updates\r\n2023-12-01 09:29:15.807 [debu]  cli: connecting\r\n2023-12-01 09:29:15.808 [debu]  cli.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:60568 (e7ea313cb4d5d5e6a4ef2ce3) in 78.208µs\r\n2023-12-01 09:29:15.808 [debu]  cli.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:60568 (afad975994c5288211ffe116) in 101.917µs\r\n2023-12-01 09:29:15.808 [debu]  cli.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:60568 (572c65b5713dfd989199bfe3) in 106.875µs\r\n2023-12-01 09:29:15.808 [debu]  cli.net.wgengine: ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer\r\n2023-12-01 09:29:15.808 [debu]  cli: skipped sending node; no PreferredDERP  node=\"&{ID:nodeid:68c043f940633a92 AsOf:2023-12-01 09:29:15.808836 +0000 UTC Key:nodekey:9d49246f15bb4cc0597124ab4d3b4d28bbf97d93cf9091bbfc665bb237388229 DiscoKey:discokey:6a0fffa91fcce66a1a55cb49f08bf33ae483a6d834bf31f1b15ec26b9dc2e86d PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] AllowedIPs:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] Endpoints:[]}\"\r\n2023-12-01 09:29:15.809 [debu]  cli: serving coordinator\r\n2023-12-01 09:29:15.808 [debu]  cli.net.wgengine: ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer\r\n2023-12-01 09:29:15.809 [debu]  cli: adding node  node=\"&{ID:nodeid:541f929d21f5d6e7 AsOf:2023-12-01 09:29:15.681441 +0000 UTC Key:nodekey:c9f4f56778e6346578a5ccd6ea17b7d01dd3cd4bc26ce0b8e64a48b3df3a9025 DiscoKey:discokey:82bc55c802d43ce94a957934802770c79549f65880aa2bb519866228fba37117 PreferredDERP:999 DERPLatency:map[999-v4:0.000197208] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4427:abe0:6d62:de0a:2919/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] AllowedIPs:[fd7a:115c:a1e0:4427:abe0:6d62:de0a:2919/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] Endpoints:[127.0.0.1:63347 192.168.64.24:63347]}\"\r\n2023-12-01 09:29:15.809 [debu]  cli: updating network map\r\n2023-12-01 09:29:15.809 [debu]  cli.net.wgengine: [v1] magicsock: got updated network map; 1 peers\r\n2023-12-01 09:29:15.809 [debu]  cli.net.wgengine: magicsock: created endpoint key=[yfT1Z]: disco=d:82bc55c802d43ce9; derp=999(coder) aip=fd7a:115c:a1e0:4427:abe0:6d62:de0a:2919 aip=fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4 ep=127.0.0.1:63347 ep=192.168.64.24:63347\r\n2023-12-01 09:29:15.809 [debu]  cli.net.netstack: [v2] netstack: registered IP fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128\r\n2023-12-01 09:29:15.809 [debu]  cli.net.wgengine: wgengine: Reconfig: configuring userspace WireGuard config (with 1/1 peers)\r\n2023-12-01 09:29:15.809 [debu]  cli.net.wgengine: wg: [v2] UAPI: Updating private key\r\n2023-12-01 09:29:15.809 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - UAPI: Created\r\n2023-12-01 09:29:15.809 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - UAPI: Updating endpoint\r\n2023-12-01 09:29:15.809 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - UAPI: Removing all allowedips\r\n2023-12-01 09:29:15.810 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - UAPI: Adding allowedip\r\n2023-12-01 09:29:15.810 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - UAPI: Adding allowedip\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - UAPI: Updating persistent keepalive interval\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - Starting\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: wgengine: Reconfig: configuring router\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: wgengine: Reconfig: configuring DNS\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[]}\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]}\r\n2023-12-01 09:29:15.812 [debu]  cli.net.wgengine: [v1] wgengine: Reconfig done\r\n2023-12-01 09:29:15.859 [debu]  cli.net.wgengine: netcheck: [v1] measuring ICMP latency of coder (999): no address for node 999b\r\n2023-12-01 09:29:15.860 [debu]  cli.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest=false hair= portmap= v4a=127.0.0.1:60568 derp=999 derpdist=999v4:0s\r\n2023-12-01 09:29:15.860 [debu]  cli.net.wgengine: magicsock: home is now derp-999 (coder)\r\n2023-12-01 09:29:15.860 [debu]  cli: netinfo callback  netinfo=\"NetInfo{varies=false hairpin= ipv6=false ipv6os=true udp=true icmpv4=false derp=#999 portmap= link=\\\"\\\"}\"\r\n2023-12-01 09:29:15.860 [debu]  cli.net.wgengine: magicsock: adding connection to derp-999 for home-keep-alive\r\n2023-12-01 09:29:15.860 [debu]  cli: sending node  node=\"&{ID:nodeid:68c043f940633a92 AsOf:2023-12-01 09:29:15.860402 +0000 UTC Key:nodekey:9d49246f15bb4cc0597124ab4d3b4d28bbf97d93cf9091bbfc665bb237388229 DiscoKey:discokey:6a0fffa91fcce66a1a55cb49f08bf33ae483a6d834bf31f1b15ec26b9dc2e86d PreferredDERP:999 DERPLatency:map[999-v4:0.000214292] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] AllowedIPs:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] Endpoints:[]}\"\r\n2023-12-01 09:29:15.860 [debu]  cli.net.wgengine: magicsock: 1 active derp conns: derp-999=cr0s,wr0s\r\n2023-12-01 09:29:15.861 [debu]  cli.net.wgengine: derphttp.Client.Connect: connecting to derp-999 (coder)\r\n2023-12-01 09:29:15.861 [debu]  cli: wireguard status  status=\"&{AsOf:2023-12-01 09:29:15.861416 +0000 UTC m=+0.992905751 Peers:[{TxBytes:0 RxBytes:0 LastHandshake:1970-01-01 00:00:00 +0000 UTC NodeKey:nodekey:c9f4f56778e6346578a5ccd6ea17b7d01dd3cd4bc26ce0b8e64a48b3df3a9025}] LocalAddrs:[] DERPs:1}\"  error=<nil>\r\n2023-12-01 09:29:15.861 [debu]  cli.net.wgengine: derphttp.Client.Connect: not using fast start\r\n2023-12-01 09:29:15.861 [debu]  cli.net.wgengine: magicsock: endpoints changed: 127.0.0.1:60568 (stun), 192.168.64.24:60568 (local)\r\n2023-12-01 09:29:15.862 [debu]  cli.net.wgengine: derphttp.Client.Connect: DERP server returned status 101\r\n2023-12-01 09:29:15.861 [debu]  cli: wireguard status  status=\"&{AsOf:2023-12-01 09:29:15.861982 +0000 UTC m=+0.993472126 Peers:[{TxBytes:0 RxBytes:0 LastHandshake:1970-01-01 00:00:00 +0000 UTC NodeKey:nodekey:c9f4f56778e6346578a5ccd6ea17b7d01dd3cd4bc26ce0b8e64a48b3df3a9025}] LocalAddrs:[{Addr:127.0.0.1:60568 Type:stun} {Addr:192.168.64.24:60568 Type:local}] DERPs:1}\"  error=<nil>\r\n2023-12-01 09:29:15.862 [debu]  cli: sending node  node=\"&{ID:nodeid:68c043f940633a92 AsOf:2023-12-01 09:29:15.862121 +0000 UTC Key:nodekey:9d49246f15bb4cc0597124ab4d3b4d28bbf97d93cf9091bbfc665bb237388229 DiscoKey:discokey:6a0fffa91fcce66a1a55cb49f08bf33ae483a6d834bf31f1b15ec26b9dc2e86d PreferredDERP:999 DERPLatency:map[999-v4:0.000214292] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] AllowedIPs:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] Endpoints:[127.0.0.1:60568 192.168.64.24:60568]}\"\r\n2023-12-01 09:29:15.862 [debu]  cli.net.wgengine: magicsock: derp-999 connected; connGen=1\r\n2023-12-01 09:29:15.863 [debu]  cli.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:60568 (a21f1b1f9208cd5f15b18135) in 148.25µs\r\n2023-12-01 09:29:15.864 [debu]  cli.net.wgengine: ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): sending disco ping to [yfT1Z]  ...\r\n2023-12-01 09:29:15.864 [debu]  cli.net.wgengine: [v1] magicsock: derp route for [yfT1Z] set to derp-999 (shared home)\r\n2023-12-01 09:29:15.865 [debu]  cli.net.wgengine: magicsock: disco: got disco-looking frame from d:82bc55c802d43ce9 via UDP socket\r\n2023-12-01 09:29:15.865 [debu]  cli.net.wgengine: magicsock: disco: disco.Parse = *disco.Pong, <nil>\r\n2023-12-01 09:29:15.865 [debu]  cli.net.wgengine: magicsock: disco: node [yfT1Z] d:82bc55c802d43ce9 now using 192.168.64.24:63347\r\n2023-12-01 09:29:15.865 [debu]  cli.net.wgengine: magicsock: disco: got disco-looking frame from d:82bc55c802d43ce9 via UDP socket\r\n2023-12-01 09:29:15.865 [debu]  cli.net.wgengine: magicsock: disco: disco.Parse = *disco.Pong, <nil>\r\n2023-12-01 09:29:15.865 [debu]  cli.net.wgengine: magicsock: disco: node [yfT1Z] d:82bc55c802d43ce9 now using 127.0.0.1:63347\r\nForwarding 'udp://127.0.0.1:59629' locally to 'udp://127.0.0.1:62592' in the workspace\r\n2023-12-01 09:29:15.866 [debu]  cli.net.wgengine: magicsock: disco: got disco-looking frame from d:82bc55c802d43ce9 via DERP\r\n2023-12-01 09:29:15.866 [debu]  cli.net.wgengine: magicsock: disco: disco.Parse = *disco.Pong, <nil>\r\n2023-12-01 09:29:15.866 [debu]  cli: closed netstack\r\n2023-12-01 09:29:15.866 [debu]  cli.net.wgengine: magicsock: disco: node [yfT1Z] d:82bc55c802d43ce9 now using DERP only (reset)\r\n2023-12-01 09:29:15.866 [debu]  cli.net.wgengine: magicsock: closing connection to derp-999 (conn-close), age 0s\r\n2023-12-01 09:29:15.867 [debu]  cli.net.wgengine: magicsock: 0 active derp conns\r\n2023-12-01 09:29:15.867 [debu]  cli.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped\r\n2023-12-01 09:29:15.867 [debu]  cli.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped\r\n2023-12-01 09:29:15.913 [debu]  cli.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest= hair= portmap= v4a=127.0.0.1:60568 derp=0\r\n2023-12-01 09:29:15.913 [debu]  cli.net.wgengine: [v1] warning: fakeRouter.Close: not implemented.\r\n2023-12-01 09:29:15.913 [debu]  cli.net.wgengine: wg: [v2] Device closing\r\n2023-12-01 09:29:15.913 [debu]  cli.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - stopped\r\n2023-12-01 09:29:15.913 [debu]  cli.net.wgengine: wg: [v2] [yfT1Z] - Stopping\r\n2023-12-01 09:29:15.913 [debu]  cli: netinfo callback  netinfo=\"NetInfo{varies= hairpin= ipv6=false ipv6os=true udp=true icmpv4=false derp=#999 portmap= link=\\\"\\\"}\"\r\n2023-12-01 09:29:15.913 [debu]  cli.net.wgengine: wg: [v2] Device closed\r\n2023-12-01 09:29:15.913 [debu]  cli: sending node  node=\"&{ID:nodeid:68c043f940633a92 AsOf:2023-12-01 09:29:15.913426 +0000 UTC Key:nodekey:9d49246f15bb4cc0597124ab4d3b4d28bbf97d93cf9091bbfc665bb237388229 DiscoKey:discokey:6a0fffa91fcce66a1a55cb49f08bf33ae483a6d834bf31f1b15ec26b9dc2e86d PreferredDERP:999 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] AllowedIPs:[fd7a:115c:a1e0:4039:bd98:8b2d:5b57:f51d/128] Endpoints:[127.0.0.1:60568 192.168.64.24:60568]}\"\r\n")

Full raw logs: see gist
@johnstcn johnstcn added the flake label Dec 1, 2023
@cdr-bot cdr-bot bot added the chore label Dec 1, 2023
@johnstcn johnstcn changed the title flake: TestPortForward/UDP_OnePort: match deadline exceeded: context deadline exceeded flake: test-macos: TestPortForward/UDP_OnePort: match deadline exceeded: context deadline exceeded Dec 1, 2023
@johnstcn johnstcn changed the title flake: test-macos: TestPortForward/UDP_OnePort: match deadline exceeded: context deadline exceeded flake: test-go-macos: TestPortForward/UDP_OnePort: match deadline exceeded: context deadline exceeded Dec 1, 2023
@spikecurtis spikecurtis self-assigned this Dec 1, 2023
@spikecurtis
Copy link
Contributor

related? TestPortForward/UDP_TwoPorts

@matifali matifali removed the chore label Dec 3, 2023
@spikecurtis
Copy link
Contributor

Pretty sure this is ye olde classic flake of the port you want to listen on not being free, but our logging is just bad.

@spikecurtis spikecurtis mentioned this issue Dec 11, 2023
Merged
spikecurtis added a commit that referenced this issue Dec 11, 2023
@spikecurtis
fix: use fake local network for port-forward tests (#11119)
50575e1 
Fixes #10979

Testing code that listens on a specific port has created a long battle with flakes.  Previous attempts to deal with this include opening a listener on a port chosen by the OS, then closing the listener, noting the port and starting the test with that port.
This still flakes, notably in macOS which has a proclivity to reuse ports quickly.

Instead of fighting with the chaos that is an OS networking stack, this PR fakes the host networking in tests.

I've taken a small step here, only faking out the Listen() calls that port-forward makes, but I think over time we should be transitioning all networking the CLI does to an abstract interface so we can fake it.  This allows us to run in parallel without flakes and
presents an opportunity to test error paths as well.
@matifali
Copy link
Member

matifali commented Dec 16, 2023 •
edited
Loading

Again seen in: https://github.com/coder/coder/actions/runs/7226765867/job/19693041460#step:5:320

@matifali matifali reopened this Dec 16, 2023
@spikecurtis
Copy link
Contributor

@matifali same test but different cause. I opened a new issue: #11294

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@spikecurtis spikecurtis

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix: use fake local network for port-forward tests coder/coder
3 participants
@johnstcn @spikecurtis @matifali