2023-04-26T05:13:00.2047740Z === Failed 2023-04-26T05:13:00.2048082Z === FAIL: agent TestAgent_EnvironmentVariables (15.80s) 2023-04-26T05:13:00.2048915Z t.go:81: 2023-04-26 05:05:19.269 [INFO] (agent) (*agent).runLoop connecting to coderd 2023-04-26T05:13:00.2051092Z t.go:81: 2023-04-26 05:05:19.269 [INFO] (agent) (*agent).run fetched manifest {"manifest": {"git_auth_configs": 0, "vscode_port_proxy_uri": "", "apps": null, "derpmap": {"Regions": {"1": {"EmbeddedRelay": false, "RegionID": 1, "RegionCode": "test", "RegionName": "Test", "Nodes": [{"Name": "t2", "RegionID": 1, "HostName": "", "IPv4": "127.0.0.1", "IPv6": "none", "STUNPort": 49192, "DERPPort": 36363, "InsecureForTests": true}]}}}, "environment_variables": {"EXAMPLE": "value"}, "startup_script": "", "startup_script_timeout": 0, "directory": "", "motd_file": "", "shutdown_script": "", "shutdown_script_timeout": 0, "metadata": null}} 2023-04-26T05:13:00.2052479Z t.go:81: 2023-04-26 05:05:19.270 [DEBUG] (agent) (*agent).setLifecycle set lifecycle state {"state": "starting", "last": ""} 2023-04-26T05:13:00.2053325Z t.go:81: 2023-04-26 05:05:19.272 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine [v1] using fake (no-op) tun device 2023-04-26T05:13:00.2054214Z t.go:81: 2023-04-26 05:05:19.272 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine [v1] using fake (no-op) OS network configurator 2023-04-26T05:13:00.2055088Z t.go:81: 2023-04-26 05:05:19.272 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine [v1] using fake (no-op) DNS configurator 2023-04-26T05:13:00.2055890Z t.go:81: 2023-04-26 05:05:19.273 [DEBUG] (agent.tailnet.wgengine) NewManager.func1 dns: using dns.noopManager 2023-04-26T05:13:00.2056935Z t.go:81: 2023-04-26 05:05:19.273 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine link state: interfaces.State{defaultRoute=eth0 ifs={docker0:[172.17.0.1/16] eth0:[10.0.0.18/22]} v4=true v6=false} 2023-04-26T05:13:00.2058066Z t.go:81: 2023-04-26 05:05:19.273 [DEBUG] (agent.tailnet.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2059192Z t.go:81: 2023-04-26 05:05:19.273 [DEBUG] (agent.tailnet.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2060311Z t.go:81: 2023-04-26 05:05:19.274 [DEBUG] (agent.tailnet.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2061445Z t.go:81: 2023-04-26 05:05:19.274 [DEBUG] (agent.tailnet.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2062602Z t.go:81: 2023-04-26 05:05:19.274 [DEBUG] (agent.tailnet.wgengine) NewConn [v1] couldn't create raw v4 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable 2023-04-26T05:13:00.2063738Z t.go:81: 2023-04-26 05:05:19.274 [DEBUG] (agent.tailnet.wgengine) NewConn [v1] couldn't create raw v6 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable 2023-04-26T05:13:00.2064688Z t.go:81: 2023-04-26 05:05:19.275 [DEBUG] (agent) (*agent).reportLifecycleLoop reporting lifecycle state {"state": "starting"} 2023-04-26T05:13:00.2065488Z t.go:81: 2023-04-26 05:05:19.275 [DEBUG] (agent) (*agent).runStartupScript running agent startup script 2023-04-26T05:13:00.2066414Z t.go:81: 2023-04-26 05:05:19.275 [DEBUG] (agent) (*agent).setLifecycle set lifecycle state {"state": "ready", "last": "starting"} 2023-04-26T05:13:00.2067247Z t.go:81: 2023-04-26 05:05:19.275 [DEBUG] (agent) (*agent).reportLifecycleLoop reporting lifecycle state {"state": "ready"} 2023-04-26T05:13:00.2068141Z t.go:81: 2023-04-26 05:05:19.276 [DEBUG] (agent.tailnet.wgengine) (*Conn).DiscoPublicKey magicsock: disco key = d:c326993d0d3b7fce 2023-04-26T05:13:00.2068970Z t.go:81: 2023-04-26 05:05:19.276 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine Creating WireGuard device... 2023-04-26T05:13:00.2069903Z t.go:81: 2023-04-26 05:05:19.277 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine Bringing WireGuard device up... 2023-04-26T05:13:00.2070780Z t.go:81: 2023-04-26 05:05:19.285 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v4 - started 2023-04-26T05:13:00.2071607Z t.go:81: 2023-04-26 05:05:19.292 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] UDP bind has been updated 2023-04-26T05:13:00.2072492Z t.go:81: 2023-04-26 05:05:19.292 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming receiveDERP - started 2023-04-26T05:13:00.2073400Z t.go:81: 2023-04-26 05:05:19.292 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v6 - started 2023-04-26T05:13:00.2074296Z t.go:81: 2023-04-26 05:05:19.302 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Interface state was Down, requested Up, now Up 2023-04-26T05:13:00.2075124Z t.go:81: 2023-04-26 05:05:19.302 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine Bringing router up... 2023-04-26T05:13:00.2075989Z t.go:81: 2023-04-26 05:05:19.303 [DEBUG] (agent.tailnet.wgengine) fakeRouter.Up [v1] warning: fakeRouter.Up: not implemented. 2023-04-26T05:13:00.2076992Z t.go:81: 2023-04-26 05:05:19.303 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine Clearing router settings... 2023-04-26T05:13:00.2077897Z t.go:81: 2023-04-26 05:05:19.303 [DEBUG] (agent.tailnet.wgengine) fakeRouter.Set [v1] warning: fakeRouter.Set: not implemented. 2023-04-26T05:13:00.2078734Z t.go:81: 2023-04-26 05:05:19.303 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine Starting link monitor... 2023-04-26T05:13:00.2079519Z t.go:81: 2023-04-26 05:05:19.320 [DEBUG] (agent.tailnet.wgengine) NewUserspaceEngine Engine created. 2023-04-26T05:13:00.2080383Z t.go:81: 2023-04-26 05:05:19.322 [DEBUG] (agent.tailnet.wgengine) (*Conn).SetPrivateKey magicsock: SetPrivateKey called (init) 2023-04-26T05:13:00.2081185Z t.go:81: 2023-04-26 05:05:19.330 [DEBUG] (agent.tailnet) NewConn updating network map 2023-04-26T05:13:00.2082079Z t.go:81: 2023-04-26 05:05:19.330 [DEBUG] (agent.tailnet.wgengine) (*Conn).SetNetworkMap [v1] magicsock: got updated network map; 0 peers 2023-04-26T05:13:00.2082906Z t.go:81: 2023-04-26 05:05:19.333 [DEBUG] (agent) (*agent).run running tailnet connection coordinator 2023-04-26T05:13:00.2083832Z t.go:81: 2023-04-26 05:05:19.333 [INFO] (agent) (*agent).runCoordinator connected to coordination endpoint 2023-04-26T05:13:00.2085833Z t.go:81: 2023-04-26 05:05:19.334 [DEBUG] (agent.tailnet) (*Conn).sendNode.func1 sending node {"node": {"id": 2509203776748616500, "as_of": "2023-04-26T05:05:19.334228Z", "key": "nodekey:ea9725798705e35d391898f5c4e6c1b87a3827d4e18faa22ffbbdf5d3b5ecf7f", "disco": "discokey:c326993d0d3b7fce16c56f9cab388997cf1743f306e84c89d49eccffb70f2f63", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": []}} 2023-04-26T05:13:00.2087255Z t.go:81: 2023-04-26 05:05:19.335 [DEBUG] (coord) (*coordinator).ServeAgent coordinating agent {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2088227Z t.go:81: 2023-04-26 05:05:19.335 [DEBUG] (coord) (*coordinator).ServeAgent added agent socket {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2089059Z t.go:81: 2023-04-26 05:05:19.336 [DEBUG] (client.wgengine) NewUserspaceEngine [v1] using fake (no-op) tun device 2023-04-26T05:13:00.2089920Z t.go:81: 2023-04-26 05:05:19.337 [DEBUG] (client.wgengine) NewUserspaceEngine [v1] using fake (no-op) OS network configurator 2023-04-26T05:13:00.2090748Z t.go:81: 2023-04-26 05:05:19.337 [DEBUG] (client.wgengine) NewUserspaceEngine [v1] using fake (no-op) DNS configurator 2023-04-26T05:13:00.2092998Z t.go:81: 2023-04-26 05:05:19.336 [DEBUG] (coord) (*coordinator).handleNextAgentMessage decoded agent node {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9", "node": {"id": 2509203776748616500, "as_of": "2023-04-26T05:05:19.334228Z", "key": "nodekey:ea9725798705e35d391898f5c4e6c1b87a3827d4e18faa22ffbbdf5d3b5ecf7f", "disco": "discokey:c326993d0d3b7fce16c56f9cab388997cf1743f306e84c89d49eccffb70f2f63", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": []}} 2023-04-26T05:13:00.2094238Z t.go:81: 2023-04-26 05:05:19.338 [DEBUG] (client.wgengine) NewManager.func1 dns: using dns.noopManager 2023-04-26T05:13:00.2095243Z t.go:81: 2023-04-26 05:05:19.338 [DEBUG] (client.wgengine) NewUserspaceEngine link state: interfaces.State{defaultRoute=eth0 ifs={docker0:[172.17.0.1/16] eth0:[10.0.0.18/22]} v4=true v6=false} 2023-04-26T05:13:00.2096274Z t.go:81: 2023-04-26 05:05:19.338 [DEBUG] (coord) (*coordinator).handleNextAgentMessage no client sockets {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2097373Z t.go:81: 2023-04-26 05:05:19.343 [DEBUG] (client.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2098481Z t.go:81: 2023-04-26 05:05:19.343 [DEBUG] (client.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2099574Z t.go:81: 2023-04-26 05:05:19.343 [DEBUG] (client.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2100681Z t.go:81: 2023-04-26 05:05:19.344 [DEBUG] (client.wgengine) trySetSocketBuffer.func1 magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted 2023-04-26T05:13:00.2101905Z t.go:81: 2023-04-26 05:05:19.344 [DEBUG] (client.wgengine) NewConn [v1] couldn't create raw v4 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable 2023-04-26T05:13:00.2103033Z t.go:81: 2023-04-26 05:05:19.344 [DEBUG] (client.wgengine) NewConn [v1] couldn't create raw v6 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable 2023-04-26T05:13:00.2103981Z t.go:81: 2023-04-26 05:05:19.345 [DEBUG] (client.wgengine) (*Conn).DiscoPublicKey magicsock: disco key = d:81b1030f1dcf8044 2023-04-26T05:13:00.2104879Z t.go:81: 2023-04-26 05:05:19.346 [DEBUG] (client.wgengine) NewUserspaceEngine Creating WireGuard device... 2023-04-26T05:13:00.2105690Z t.go:81: 2023-04-26 05:05:19.346 [DEBUG] (client.wgengine) NewUserspaceEngine Bringing WireGuard device up... 2023-04-26T05:13:00.2106532Z t.go:81: 2023-04-26 05:05:19.347 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v6 - started 2023-04-26T05:13:00.2107379Z t.go:81: 2023-04-26 05:05:19.347 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v4 - started 2023-04-26T05:13:00.2108167Z t.go:81: 2023-04-26 05:05:19.347 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] UDP bind has been updated 2023-04-26T05:13:00.2109013Z t.go:81: 2023-04-26 05:05:19.348 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming receiveDERP - started 2023-04-26T05:13:00.2109880Z t.go:81: 2023-04-26 05:05:19.348 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Interface state was Down, requested Up, now Up 2023-04-26T05:13:00.2110675Z t.go:81: 2023-04-26 05:05:19.360 [DEBUG] (client.wgengine) NewUserspaceEngine Bringing router up... 2023-04-26T05:13:00.2111507Z t.go:81: 2023-04-26 05:05:19.368 [DEBUG] (client.wgengine) fakeRouter.Up [v1] warning: fakeRouter.Up: not implemented. 2023-04-26T05:13:00.2112307Z t.go:81: 2023-04-26 05:05:19.368 [DEBUG] (client.wgengine) NewUserspaceEngine Clearing router settings... 2023-04-26T05:13:00.2113155Z t.go:81: 2023-04-26 05:05:19.369 [DEBUG] (client.wgengine) fakeRouter.Set [v1] warning: fakeRouter.Set: not implemented. 2023-04-26T05:13:00.2113979Z t.go:81: 2023-04-26 05:05:19.369 [DEBUG] (client.wgengine) NewUserspaceEngine Starting link monitor... 2023-04-26T05:13:00.2114730Z t.go:81: 2023-04-26 05:05:19.369 [DEBUG] (client.wgengine) NewUserspaceEngine Engine created. 2023-04-26T05:13:00.2115565Z t.go:81: 2023-04-26 05:05:19.370 [DEBUG] (client.wgengine) (*Conn).SetPrivateKey magicsock: SetPrivateKey called (init) 2023-04-26T05:13:00.2116844Z t.go:81: 2023-04-26 05:05:19.383 [DEBUG] (agent.tailnet.wgengine) NewConn.func6 netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest=false hair=true portmap= v4a=127.0.0.1:48318 derp=1 derpdist=1v4:0s 2023-04-26T05:13:00.2117692Z t.go:81: 2023-04-26 05:05:19.384 [DEBUG] (client) NewConn updating network map 2023-04-26T05:13:00.2118718Z t.go:81: 2023-04-26 05:05:19.388 [DEBUG] (client.wgengine) (*Conn).SetNetworkMap [v1] magicsock: got updated network map; 0 peers 2023-04-26T05:13:00.2119648Z t.go:81: 2023-04-26 05:05:19.390 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2120759Z t.go:81: 2023-04-26 05:05:19.391 [DEBUG] (coord) (*coordinator).ServeClient coordinating client {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2121727Z t.go:81: 2023-04-26 05:05:19.399 [DEBUG] (agent.tailnet.wgengine) (*Conn).setNearestDERP magicsock: home is now derp-1 (test) 2023-04-26T05:13:00.2123821Z t.go:81: 2023-04-26 05:05:19.399 [DEBUG] (client) (*Conn).sendNode.func1 sending node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.39055Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": []}} 2023-04-26T05:13:00.2125236Z t.go:81: 2023-04-26 05:05:19.400 [DEBUG] (agent.tailnet.wgengine) (*Conn).logEndpointChange magicsock: endpoints changed: 127.0.0.1:48318 (stun), 10.0.0.18:48318 (local), 172.17.0.1:48318 (local) 2023-04-26T05:13:00.2126209Z t.go:81: 2023-04-26 05:05:19.400 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2127197Z t.go:81: 2023-04-26 05:05:19.401 [DEBUG] (agent.tailnet.wgengine) (*Conn).derpWriteChanOfAddr magicsock: adding connection to derp-1 for home-keep-alive 2023-04-26T05:13:00.2128191Z t.go:81: 2023-04-26 05:05:19.402 [DEBUG] (agent.tailnet.wgengine) (*Conn).logActiveDerpLocked magicsock: 1 active derp conns: derp-1=cr0s,wr0s 2023-04-26T05:13:00.2129301Z t.go:81: 2023-04-26 05:05:19.402 [DEBUG] (agent.tailnet.wgengine) (*Client).connect derphttp.Client.Connect: connecting to derp-1 (test) 2023-04-26T05:13:00.2130916Z t.go:81: 2023-04-26 05:05:19.400 [DEBUG] (agent.tailnet) NewConn.func6 wireguard status {"status": "\u0026{AsOf:2023-04-26 05:05:19.40069149 +0000 UTC m=+11.835495277 Peers:[] LocalAddrs:[{Addr:127.0.0.1:48318 Type:stun} {Addr:10.0.0.18:48318 Type:local} {Addr:172.17.0.1:48318 Type:local}] DERPs:0}", "err": null} 2023-04-26T05:13:00.2132486Z t.go:81: 2023-04-26 05:05:19.403 [DEBUG] (agent.tailnet) NewConn.func6 wireguard status {"status": "\u0026{AsOf:2023-04-26 05:05:19.403053029 +0000 UTC m=+11.837856816 Peers:[] LocalAddrs:[{Addr:127.0.0.1:48318 Type:stun} {Addr:10.0.0.18:48318 Type:local} {Addr:172.17.0.1:48318 Type:local}] DERPs:1}", "err": null} 2023-04-26T05:13:00.2134141Z t.go:81: 2023-04-26 05:05:19.403 [DEBUG] (agent.tailnet) NewConn.func7 netinfo callback {"netinfo": {"MappingVariesByDestIP": false, "HairPinning": true, "WorkingIPv6": false, "OSHasIPv6": true, "WorkingUDP": true, "WorkingICMPv4": false, "UPnP": false, "PMP": false, "PCP": false, "PreferredDERP": 1, "DERPLatency": {"1-v4": 0.000164103}}} 2023-04-26T05:13:00.2136558Z t.go:81: 2023-04-26 05:05:19.403 [DEBUG] (agent.tailnet) (*Conn).sendNode.func1 sending node {"node": {"id": 2509203776748616500, "as_of": "2023-04-26T05:05:19.403011Z", "key": "nodekey:ea9725798705e35d391898f5c4e6c1b87a3827d4e18faa22ffbbdf5d3b5ecf7f", "disco": "discokey:c326993d0d3b7fce16c56f9cab388997cf1743f306e84c89d49eccffb70f2f63", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:48318", "10.0.0.18:48318", "172.17.0.1:48318"]}} 2023-04-26T05:13:00.2139574Z t.go:81: 2023-04-26 05:05:19.404 [DEBUG] (coord) (*coordinator).handleNextAgentMessage decoded agent node {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9", "node": {"id": 2509203776748616500, "as_of": "2023-04-26T05:05:19.403011Z", "key": "nodekey:ea9725798705e35d391898f5c4e6c1b87a3827d4e18faa22ffbbdf5d3b5ecf7f", "disco": "discokey:c326993d0d3b7fce16c56f9cab388997cf1743f306e84c89d49eccffb70f2f63", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:48318", "10.0.0.18:48318", "172.17.0.1:48318"]}} 2023-04-26T05:13:00.2141196Z t.go:81: 2023-04-26 05:05:19.419 [DEBUG] (coord) (*coordinator).handleNextAgentMessage no client sockets {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2143491Z t.go:81: 2023-04-26 05:05:19.411 [DEBUG] (agent.tailnet) (*Conn).sendNode.func1 sending node {"node": {"id": 2509203776748616500, "as_of": "2023-04-26T05:05:19.41192Z", "key": "nodekey:ea9725798705e35d391898f5c4e6c1b87a3827d4e18faa22ffbbdf5d3b5ecf7f", "disco": "discokey:c326993d0d3b7fce16c56f9cab388997cf1743f306e84c89d49eccffb70f2f63", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000164103}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:48318", "10.0.0.18:48318", "172.17.0.1:48318"]}} 2023-04-26T05:13:00.2146431Z t.go:81: 2023-04-26 05:05:19.420 [DEBUG] (coord) (*coordinator).handleNextAgentMessage decoded agent node {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9", "node": {"id": 2509203776748616500, "as_of": "2023-04-26T05:05:19.41192Z", "key": "nodekey:ea9725798705e35d391898f5c4e6c1b87a3827d4e18faa22ffbbdf5d3b5ecf7f", "disco": "discokey:c326993d0d3b7fce16c56f9cab388997cf1743f306e84c89d49eccffb70f2f63", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000164103}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:48318", "10.0.0.18:48318", "172.17.0.1:48318"]}} 2023-04-26T05:13:00.2147939Z t.go:81: 2023-04-26 05:05:19.421 [DEBUG] (coord) (*coordinator).handleNextAgentMessage no client sockets {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2149128Z t.go:81: 2023-04-26 05:05:19.423 [DEBUG] (coord) (*coordinator).ServeClient wrote initial node {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2150444Z t.go:81: 2023-04-26 05:05:19.423 [DEBUG] (coord) (*coordinator).ServeClient added tracked connection {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2152612Z t.go:81: 2023-04-26 05:05:19.423 [DEBUG] (client) (*Conn).UpdateNodes no preferred DERP, skipping node {"node": {"id": 2509203776748616500, "as_of": "2023-04-26T05:05:19.334228Z", "key": "nodekey:ea9725798705e35d391898f5c4e6c1b87a3827d4e18faa22ffbbdf5d3b5ecf7f", "disco": "discokey:c326993d0d3b7fce16c56f9cab388997cf1743f306e84c89d49eccffb70f2f63", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": []}} 2023-04-26T05:13:00.2153942Z t.go:81: 2023-04-26 05:05:19.424 [DEBUG] (client) (*Conn).UpdateNodes updating network map 2023-04-26T05:13:00.2154910Z t.go:81: 2023-04-26 05:05:19.424 [DEBUG] (client.netstack) (*Impl).updateIPs [v2] netstack: registered IP fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128 2023-04-26T05:13:00.2157657Z t.go:81: 2023-04-26 05:05:19.425 [DEBUG] (coord) (*coordinator).handleNextClientMessage got client node update {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9", "node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.39055Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": []}} 2023-04-26T05:13:00.2160319Z t.go:81: 2023-04-26 05:05:19.427 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes no preferred DERP, skipping node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.39055Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 0, "derp_latency": null, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": []}} 2023-04-26T05:13:00.2161563Z t.go:81: 2023-04-26 05:05:19.427 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes updating network map 2023-04-26T05:13:00.2162747Z t.go:81: 2023-04-26 05:05:19.427 [DEBUG] (coord) (*coordinator).handleNextClientMessage sent client node to agent {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2164025Z t.go:81: 2023-04-26 05:05:19.428 [DEBUG] (client.wgengine) (*userspaceEngine).maybeReconfigWireguardLocked wgengine: Reconfig: configuring userspace WireGuard config (with 0/0 peers) 2023-04-26T05:13:00.2165150Z t.go:81: 2023-04-26 05:05:19.429 [DEBUG] (agent.tailnet.netstack) (*Impl).updateIPs [v2] netstack: registered IP fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128 2023-04-26T05:13:00.2166294Z t.go:81: 2023-04-26 05:05:19.433 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).maybeReconfigWireguardLocked wgengine: Reconfig: configuring userspace WireGuard config (with 0/0 peers) 2023-04-26T05:13:00.2167296Z t.go:81: 2023-04-26 05:05:19.433 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] UAPI: Updating private key 2023-04-26T05:13:00.2168184Z t.go:81: 2023-04-26 05:05:19.435 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] UAPI: Updating private key 2023-04-26T05:13:00.2169115Z t.go:81: 2023-04-26 05:05:19.435 [DEBUG] (client.wgengine) (*userspaceEngine).Reconfig wgengine: Reconfig: configuring router 2023-04-26T05:13:00.2170060Z t.go:81: 2023-04-26 05:05:19.436 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).Reconfig wgengine: Reconfig: configuring router 2023-04-26T05:13:00.2171200Z t.go:81: 2023-04-26 05:05:19.437 [DEBUG] (agent.tailnet.wgengine) fakeRouter.Set [v1] warning: fakeRouter.Set: not implemented. 2023-04-26T05:13:00.2172160Z t.go:81: 2023-04-26 05:05:19.437 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).Reconfig wgengine: Reconfig: configuring DNS 2023-04-26T05:13:00.2173181Z t.go:81: 2023-04-26 05:05:19.438 [DEBUG] (agent.tailnet.wgengine) NewManager.func1 dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0} 2023-04-26T05:13:00.2174300Z t.go:81: 2023-04-26 05:05:19.438 [DEBUG] (agent.tailnet.wgengine) NewManager.func1 "dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[], cloud=\"azure\"}" 2023-04-26T05:13:00.2175343Z t.go:81: 2023-04-26 05:05:19.438 [DEBUG] (agent.tailnet.wgengine) NewManager.func1 dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]} 2023-04-26T05:13:00.2176280Z t.go:81: 2023-04-26 05:05:19.439 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).Reconfig [v1] wgengine: Reconfig done 2023-04-26T05:13:00.2177201Z t.go:81: 2023-04-26 05:05:19.437 [DEBUG] (client.wgengine) fakeRouter.Set [v1] warning: fakeRouter.Set: not implemented. 2023-04-26T05:13:00.2178322Z t.go:81: 2023-04-26 05:05:19.440 [DEBUG] (client.wgengine) (*userspaceEngine).Reconfig wgengine: Reconfig: configuring DNS 2023-04-26T05:13:00.2179492Z t.go:81: 2023-04-26 05:05:19.440 [DEBUG] (client.wgengine) NewManager.func1 dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0} 2023-04-26T05:13:00.2180474Z t.go:81: 2023-04-26 05:05:19.441 [DEBUG] (client.wgengine) NewManager.func1 "dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[], cloud=\"azure\"}" 2023-04-26T05:13:00.2181462Z t.go:81: 2023-04-26 05:05:19.441 [DEBUG] (client.wgengine) NewManager.func1 dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]} 2023-04-26T05:13:00.2182383Z t.go:81: 2023-04-26 05:05:19.441 [DEBUG] (client.wgengine) (*userspaceEngine).Reconfig [v1] wgengine: Reconfig done 2023-04-26T05:13:00.2183405Z t.go:81: 2023-04-26 05:05:19.441 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2184558Z t.go:81: 2023-04-26 05:05:19.442 [DEBUG] (client.wgengine) NewConn.func6 netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest=false hair= portmap= v4a=127.0.0.1:60879 derp=1 derpdist=1v4:12ms 2023-04-26T05:13:00.2185579Z t.go:81: 2023-04-26 05:05:19.443 [DEBUG] (client.wgengine) (*Conn).setNearestDERP magicsock: home is now derp-1 (test) 2023-04-26T05:13:00.2186655Z t.go:81: 2023-04-26 05:05:19.443 [DEBUG] (client.wgengine) (*Conn).derpWriteChanOfAddr magicsock: adding connection to derp-1 for home-keep-alive 2023-04-26T05:13:00.2188177Z t.go:81: 2023-04-26 05:05:19.443 [DEBUG] (client) NewConn.func7 netinfo callback {"netinfo": {"MappingVariesByDestIP": false, "HairPinning": null, "WorkingIPv6": false, "OSHasIPv6": true, "WorkingUDP": true, "WorkingICMPv4": false, "UPnP": false, "PMP": false, "PCP": false, "PreferredDERP": 1, "DERPLatency": {"1-v4": 0.0122452}}} 2023-04-26T05:13:00.2189359Z t.go:81: 2023-04-26 05:05:19.444 [DEBUG] (client.wgengine) (*Conn).logActiveDerpLocked magicsock: 1 active derp conns: derp-1=cr0s,wr0s 2023-04-26T05:13:00.2190503Z t.go:81: 2023-04-26 05:05:19.445 [DEBUG] (client.wgengine) (*Client).connect derphttp.Client.Connect: connecting to derp-1 (test) 2023-04-26T05:13:00.2191707Z t.go:81: 2023-04-26 05:05:19.445 [DEBUG] (client) NewConn.func6 wireguard status {"status": "\u0026{AsOf:2023-04-26 05:05:19.445531722 +0000 UTC m=+11.880335509 Peers:[] LocalAddrs:[] DERPs:1}", "err": null} 2023-04-26T05:13:00.2192854Z t.go:81: 2023-04-26 05:05:19.446 [DEBUG] (client.wgengine) (*Conn).logEndpointChange magicsock: endpoints changed: 127.0.0.1:60879 (stun), 10.0.0.18:60879 (local), 172.17.0.1:60879 (local) 2023-04-26T05:13:00.2195079Z t.go:81: 2023-04-26 05:05:19.445 [DEBUG] (client) (*Conn).sendNode.func1 sending node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.445061Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.0122452}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": []}} 2023-04-26T05:13:00.2197016Z t.go:81: 2023-04-26 05:05:19.447 [DEBUG] (client) NewConn.func6 wireguard status {"status": "\u0026{AsOf:2023-04-26 05:05:19.447142348 +0000 UTC m=+11.881946135 Peers:[] LocalAddrs:[{Addr:127.0.0.1:60879 Type:stun} {Addr:10.0.0.18:60879 Type:local} {Addr:172.17.0.1:60879 Type:local}] DERPs:1}", "err": null} 2023-04-26T05:13:00.2199745Z t.go:81: 2023-04-26 05:05:19.447 [DEBUG] (coord) (*coordinator).handleNextClientMessage got client node update {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9", "node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.445061Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.0122452}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": []}} 2023-04-26T05:13:00.2201212Z t.go:81: 2023-04-26 05:05:19.461 [DEBUG] (agent.tailnet.wgengine) (*Conn).runDerpReader magicsock: derp-1 connected; connGen=1 2023-04-26T05:13:00.2202444Z t.go:81: 2023-04-26 05:05:19.469 [DEBUG] (coord) (*coordinator).handleNextClientMessage sent client node to agent {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2204639Z t.go:81: 2023-04-26 05:05:19.469 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes adding node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.445061Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.0122452}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": []}} 2023-04-26T05:13:00.2286738Z t.go:81: 2023-04-26 05:05:19.470 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes updating network map 2023-04-26T05:13:00.2288550Z t.go:81: 2023-04-26 05:05:19.470 [DEBUG] (agent.tailnet.wgengine) (*Conn).SetNetworkMap [v1] magicsock: got updated network map; 1 peers 2023-04-26T05:13:00.2289710Z t.go:81: 2023-04-26 05:05:19.471 [DEBUG] (agent.tailnet.wgengine) (*Conn).SetNetworkMap magicsock: created endpoint key=[uIRZ3]: disco=d:81b1030f1dcf8044; derp=1(test) aip=fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf 2023-04-26T05:13:00.2290870Z t.go:81: 2023-04-26 05:05:19.471 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).maybeReconfigWireguardLocked wgengine: Reconfig: configuring userspace WireGuard config (with 0/1 peers) 2023-04-26T05:13:00.2291979Z t.go:81: 2023-04-26 05:05:19.475 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).Reconfig [v1] wgengine: Reconfig done 2023-04-26T05:13:00.2294119Z t.go:81: 2023-04-26 05:05:19.476 [DEBUG] (client) (*Conn).sendNode.func1 sending node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.476821Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.0122452}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": ["127.0.0.1:60879", "10.0.0.18:60879", "172.17.0.1:60879"]}} 2023-04-26T05:13:00.2297037Z t.go:81: 2023-04-26 05:05:19.478 [DEBUG] (coord) (*coordinator).handleNextClientMessage got client node update {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9", "node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.476821Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.0122452}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": ["127.0.0.1:60879", "10.0.0.18:60879", "172.17.0.1:60879"]}} 2023-04-26T05:13:00.2298688Z t.go:81: 2023-04-26 05:05:19.479 [DEBUG] (coord) (*coordinator).handleNextClientMessage sent client node to agent {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2300912Z t.go:81: 2023-04-26 05:05:19.480 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes adding node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.476821Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.0122452}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": ["127.0.0.1:60879", "10.0.0.18:60879", "172.17.0.1:60879"]}} 2023-04-26T05:13:00.2302066Z t.go:81: 2023-04-26 05:05:19.481 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes updating network map 2023-04-26T05:13:00.2302950Z t.go:81: 2023-04-26 05:05:19.482 [DEBUG] (agent.tailnet.wgengine) (*Conn).SetNetworkMap [v1] magicsock: got updated network map; 1 peers 2023-04-26T05:13:00.2303820Z t.go:81: 2023-04-26 05:05:19.482 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).Reconfig [v1] wgengine: Reconfig done 2023-04-26T05:13:00.2305018Z t.go:81: 2023-04-26 05:05:19.529 [DEBUG] (agent.tailnet.wgengine) NewConn.func6 netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest=false hair=true portmap= v4a=127.0.0.1:48318 derp=1 derpdist=1v4:6ms 2023-04-26T05:13:00.2306158Z t.go:81: 2023-04-26 05:05:19.530 [DEBUG] (client.wgengine) NewConn.func6 netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest= hair= portmap= v4a=127.0.0.1:60879 derp=1 derpdist=1v4:0s 2023-04-26T05:13:00.2307625Z t.go:81: 2023-04-26 05:05:19.531 [DEBUG] (client) NewConn.func7 netinfo callback {"netinfo": {"MappingVariesByDestIP": null, "HairPinning": null, "WorkingIPv6": false, "OSHasIPv6": true, "WorkingUDP": true, "WorkingICMPv4": false, "UPnP": false, "PMP": false, "PCP": false, "PreferredDERP": 1, "DERPLatency": {"1-v4": 0.000132302}}} 2023-04-26T05:13:00.2310047Z t.go:81: 2023-04-26 05:05:19.532 [DEBUG] (client) (*Conn).sendNode.func1 sending node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.532226Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000132302}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": ["127.0.0.1:60879", "10.0.0.18:60879", "172.17.0.1:60879"]}} 2023-04-26T05:13:00.2312961Z t.go:81: 2023-04-26 05:05:19.533 [DEBUG] (coord) (*coordinator).handleNextClientMessage got client node update {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9", "node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.532226Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000132302}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": ["127.0.0.1:60879", "10.0.0.18:60879", "172.17.0.1:60879"]}} 2023-04-26T05:13:00.2314394Z t.go:81: 2023-04-26 05:05:19.534 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2315550Z t.go:81: 2023-04-26 05:05:19.534 [DEBUG] (coord) (*coordinator).handleNextClientMessage sent client node to agent {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2318006Z t.go:81: 2023-04-26 05:05:19.537 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes adding node {"node": {"id": 4036598311977531526, "as_of": "2023-04-26T05:05:19.532226Z", "key": "nodekey:b88459df9134732ffe169e8c840ac260bacb97af85f8f355c26c117ffb17746f", "disco": "discokey:81b1030f1dcf8044e36d8f2d860042b92179723abc6e3fec4b48bf68e9131356", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000132302}, "derp_forced_websockets": {}, "addresses": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "allowed_ips": ["fd7a:115c:a1e0:4498:81d5:5ea4:71e7:5aaf/128"], "endpoints": ["127.0.0.1:60879", "10.0.0.18:60879", "172.17.0.1:60879"]}} 2023-04-26T05:13:00.2319179Z t.go:81: 2023-04-26 05:05:19.540 [DEBUG] (agent.tailnet) (*Conn).UpdateNodes updating network map 2023-04-26T05:13:00.2320071Z t.go:81: 2023-04-26 05:05:19.540 [DEBUG] (agent.tailnet.wgengine) (*Conn).SetNetworkMap [v1] magicsock: got updated network map; 1 peers 2023-04-26T05:13:00.2321092Z t.go:81: 2023-04-26 05:05:19.542 [DEBUG] (client.wgengine) (*Conn).runDerpReader magicsock: derp-1 connected; connGen=1 2023-04-26T05:13:00.2321962Z t.go:81: 2023-04-26 05:05:19.542 [DEBUG] (agent.tailnet.wgengine) (*userspaceEngine).Reconfig [v1] wgengine: Reconfig done 2023-04-26T05:13:00.2322870Z t.go:81: 2023-04-26 05:05:19.658 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2323786Z t.go:81: 2023-04-26 05:05:19.761 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2324801Z t.go:81: 2023-04-26 05:05:20.076 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2325712Z t.go:81: 2023-04-26 05:05:20.336 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2326661Z t.go:81: 2023-04-26 05:05:20.466 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2327554Z t.go:81: 2023-04-26 05:05:20.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2328472Z t.go:81: 2023-04-26 05:05:20.857 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2329370Z t.go:81: 2023-04-26 05:05:21.338 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2330273Z t.go:81: 2023-04-26 05:05:21.837 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2331195Z t.go:81: 2023-04-26 05:05:21.896 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2332080Z t.go:81: 2023-04-26 05:05:22.336 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2332984Z t.go:81: 2023-04-26 05:05:22.842 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2333892Z t.go:81: 2023-04-26 05:05:23.360 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2334816Z t.go:81: 2023-04-26 05:05:23.774 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2335711Z t.go:81: 2023-04-26 05:05:23.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2336609Z t.go:81: 2023-04-26 05:05:24.337 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2337504Z t.go:81: 2023-04-26 05:05:24.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2338524Z t.go:81: 2023-04-26 05:05:25.199 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2339428Z t.go:81: 2023-04-26 05:05:25.336 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2340312Z t.go:81: 2023-04-26 05:05:25.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2341205Z t.go:81: 2023-04-26 05:05:26.336 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2342178Z t.go:81: 2023-04-26 05:05:26.848 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2343073Z t.go:81: 2023-04-26 05:05:27.336 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2343971Z t.go:81: 2023-04-26 05:05:27.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2344883Z t.go:81: 2023-04-26 05:05:28.270 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2345788Z t.go:81: 2023-04-26 05:05:28.355 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2346701Z t.go:81: 2023-04-26 05:05:28.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2347604Z t.go:81: 2023-04-26 05:05:29.336 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2348503Z t.go:81: 2023-04-26 05:05:29.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2349392Z t.go:81: 2023-04-26 05:05:30.339 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2350278Z t.go:81: 2023-04-26 05:05:30.836 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2351170Z t.go:81: 2023-04-26 05:05:31.337 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2352077Z t.go:81: 2023-04-26 05:05:31.837 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2352990Z t.go:81: 2023-04-26 05:05:32.042 [DEBUG] (client.wgengine) (*userspaceEngine).Ping ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer 2023-04-26T05:13:00.2353887Z t.go:81: 2023-04-26 05:05:32.337 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2354787Z t.go:81: 2023-04-26 05:05:32.837 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2355687Z t.go:81: 2023-04-26 05:05:33.336 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2356915Z t.go:81: 2023-04-26 05:05:33.837 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2357835Z t.go:81: 2023-04-26 05:05:34.337 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2358298Z agent_test.go:1764: agent not reachable 2023-04-26T05:13:00.2359122Z t.go:81: 2023-04-26 05:05:34.391 [DEBUG] (client.wgengine) (*Conn).closeDerpLocked magicsock: closing connection to derp-1 (conn-close), age 15s 2023-04-26T05:13:00.2360163Z t.go:81: 2023-04-26 05:05:34.391 [DEBUG] (client.wgengine) (*Conn).logActiveDerpLocked magicsock: 0 active derp conns 2023-04-26T05:13:00.2361059Z t.go:81: 2023-04-26 05:05:34.392 [DEBUG] (client.wgengine) fakeRouter.Close [v1] warning: fakeRouter.Close: not implemented. 2023-04-26T05:13:00.2361850Z t.go:81: 2023-04-26 05:05:34.393 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Device closing 2023-04-26T05:13:00.2362663Z t.go:81: 2023-04-26 05:05:34.393 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v4 - stopped 2023-04-26T05:13:00.2363529Z t.go:81: 2023-04-26 05:05:34.394 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming receiveDERP - stopped 2023-04-26T05:13:00.2364375Z t.go:81: 2023-04-26 05:05:34.394 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v6 - stopped 2023-04-26T05:13:00.2365185Z t.go:81: 2023-04-26 05:05:34.395 [DEBUG] (client.wgengine) NewLogger.func1 wg: [v2] Device closed 2023-04-26T05:13:00.2366300Z t.go:81: 2023-04-26 05:05:34.395 [DEBUG] (coord) (*coordinator).ServeClient.func1 deleting tracked connection {"client_id": "3be242c6-397d-432f-a544-89766e117e81", "agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2367154Z t.go:81: 2023-04-26 05:05:34.396 [INFO] (agent) (*agent).runLoop disconnected from coderd 2023-04-26T05:13:00.2368069Z t.go:81: 2023-04-26 05:05:34.396 [DEBUG] (coord) (*coordinator).ServeAgent.func1 deleted agent socket {"agent_id": "7fe9b9f0-4f17-48b2-9595-25069a33cbb9"} 2023-04-26T05:13:00.2368840Z t.go:81: 2023-04-26 05:05:34.397 [INFO] (agent) (*agent).Close shutting down agent 2023-04-26T05:13:00.2369666Z t.go:81: 2023-04-26 05:05:34.397 [DEBUG] (agent) (*agent).setLifecycle set lifecycle state {"state": "shutting_down", "last": "ready"} 2023-04-26T05:13:00.2370520Z t.go:81: 2023-04-26 05:05:34.397 [DEBUG] (agent) (*agent).setLifecycle set lifecycle state {"state": "off", "last": "shutting_down"} 2023-04-26T05:13:00.2371352Z t.go:81: 2023-04-26 05:05:34.398 [DEBUG] (agent) (*agent).reportLifecycleLoop reporting lifecycle state {"state": "off"} 2023-04-26T05:13:00.2372305Z t.go:81: 2023-04-26 05:05:34.400 [DEBUG] (agent.tailnet.wgengine) (*Conn).closeDerpLocked magicsock: closing connection to derp-1 (conn-close), age 15s 2023-04-26T05:13:00.2373230Z t.go:81: 2023-04-26 05:05:34.400 [DEBUG] (agent.tailnet.wgengine) (*Conn).logActiveDerpLocked magicsock: 0 active derp conns 2023-04-26T05:13:00.2374274Z t.go:81: 2023-04-26 05:05:34.401 [DEBUG] (agent.tailnet.wgengine) fakeRouter.Close [v1] warning: fakeRouter.Close: not implemented. 2023-04-26T05:13:00.2375103Z t.go:81: 2023-04-26 05:05:34.401 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Device closing 2023-04-26T05:13:00.2375952Z t.go:81: 2023-04-26 05:05:34.402 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v4 - stopped 2023-04-26T05:13:00.2376848Z t.go:81: 2023-04-26 05:05:34.402 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming receiveDERP - stopped 2023-04-26T05:13:00.2377818Z t.go:81: 2023-04-26 05:05:34.403 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Routine: receive incoming v6 - stopped 2023-04-26T05:13:00.2378622Z t.go:81: 2023-04-26 05:05:34.403 [DEBUG] (agent.tailnet.wgengine) NewLogger.func1 wg: [v2] Device closed 2023-04-26T05:13:00.2379493Z t.go:81: 2023-04-26 05:05:34.404 [INFO] (agent) (*agent).startReportingConnectionStats.func1 skipping stat because nothing changed 2023-04-26T05:13:00.2379964Z stuntest.go:63: STUN server shutdown 2023-04-26T05:13:00.2380123Z