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:3472023-12-01T09:31:01.7877940Z                     /Users/runner/work/coder/coder/pty/ptytest/ptytest.go:1772023-12-01T09:31:01.7878680Z                     /Users/runner/work/coder/coder/cli/portforward_test.go:1692023-12-01T09:31:01.7879140Z         Error:      read error2023-12-01T09:31:01.7879480Z         Test:       TestPortForward/UDP_OnePort2023-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")