[2022-09-25T11:05:35.391Z INFO geph4_client] geph4-client v4.5.0-beta.1 starting... [2022-09-25T11:05:35.395Z INFO geph4_client::main_connect] exit = us-sfo-02.exits.geph.io, use_tcp = false, use_bridges = false [2022-09-25T11:05:35.395Z INFO geph4_client::main_connect] setting VPN file descriptor to 0 [2022-09-25T11:05:35.396Z INFO geph4_client::main_connect] connect mode started [2022-09-25T11:05:35.399Z DEBUG geph4_client::main_connect] starting dns... [2022-09-25T11:05:35.400Z DEBUG geph4_client] getting extra fronts... [2022-09-25T11:05:35.401Z WARN geph4_client::cache] ignore stale value for cache.exits created at 1664092595 [2022-09-25T11:05:35.401Z DEBUG geph4_client::cache] refreshing from binder for cache.exits [2022-09-25T11:05:35.401Z DEBUG geph4_client::dns] DNS loop started [2022-09-25T11:05:35.401Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:05:36.232Z DEBUG geph4_client] inserting extra 1 fronts [2022-09-25T11:05:37.334Z INFO geph4_client::main_connect] we are in CHINA :O [2022-09-25T11:05:37.335Z WARN geph4_client::cache] ignore stale value for cache.bridges.us-sfo-02.exits.geph.io created at 1664088223 [2022-09-25T11:05:37.335Z DEBUG geph4_client::cache] refreshing from binder for cache.bridges.us-sfo-02.exits.geph.io [2022-09-25T11:05:38.130Z WARN geph4_binder_transport] request_multi failed: Some(Err(Other("io error: unexpected end of file"))) [2022-09-25T11:05:38.238Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-09-25T11:05:38.605Z INFO geph4_client::tunman::getsess] connected to UDP for [redacted]:34056 [2022-09-25T11:05:38.605Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:34056 in 366 ms [2022-09-25T11:05:40.914Z DEBUG geph4_client::tunman] sending auth info... [2022-09-25T11:05:40.914Z DEBUG geph4_client::tunman] sent auth info! [2022-09-25T11:05:43.045Z INFO geph4_client::tunman] TUNNEL_MANAGER MAIN LOOP through [redacted]:34056 [2022-09-25T11:05:43.045Z INFO geph4_client::vpn] negotiating VPN with client id 129935754019823541872193408489452610026... [2022-09-25T11:05:43.967Z INFO geph4_client::vpn] negotiated IP address [redacted]! [2022-09-25T11:05:44.685Z DEBUG geph4_client::vpn] VPN received 1 pkts [2022-09-25T11:05:45.912Z DEBUG geph4_client::tunman] ** watchdog completed in 1.225951197s ** [2022-09-25T11:05:49.597Z DEBUG geph4_client::tunman] ** watchdog completed in 527.313489ms ** [2022-09-25T11:05:53.703Z DEBUG geph4_client::tunman] ** watchdog completed in 1.099136823s ** [2022-09-25T11:05:57.598Z DEBUG geph4_client::tunman] ** watchdog completed in 625.146302ms ** [2022-09-25T11:06:01.790Z DEBUG geph4_client::tunman] ** watchdog completed in 926.093176ms ** [2022-09-25T11:06:05.479Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:06:05.481Z DEBUG geph4_client::vpn] VPN received 1001 pkts [2022-09-25T11:06:05.545Z DEBUG geph4_client::tunman] ** watchdog completed in 703.594739ms ** [2022-09-25T11:06:09.311Z DEBUG geph4_client::tunman] ** watchdog completed in 646.38151ms ** [2022-09-25T11:06:13.353Z DEBUG geph4_client::tunman] ** watchdog completed in 714.514322ms ** [2022-09-25T11:06:17.162Z DEBUG geph4_client::vpn] VPN received 2001 pkts [2022-09-25T11:06:17.163Z DEBUG geph4_client::tunman] ** watchdog completed in 797.266823ms ** [2022-09-25T11:06:21.137Z DEBUG geph4_client::tunman] ** watchdog completed in 913.346458ms ** [2022-09-25T11:06:25.107Z DEBUG geph4_client::tunman] ** watchdog completed in 643.777812ms ** [2022-09-25T11:06:31.122Z DEBUG geph4_client::tunman] ** watchdog completed in 598.695417ms ** [2022-09-25T11:06:38.545Z DEBUG geph4_client::tunman] ** watchdog completed in 698.525937ms ** [2022-09-25T11:06:47.339Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:07:20.019Z DEBUG geph4_client::tunman] ** watchdog completed in 1.299184166s ** [2022-09-25T11:07:24.362Z DEBUG geph4_client::tunman] ** watchdog completed in 524.110417ms ** [2022-09-25T11:07:28.442Z DEBUG geph4_client::tunman] ** watchdog completed in 873.614271ms ** [2022-09-25T11:07:30.708Z DEBUG geph4_client::vpn] VPN received 3001 pkts [2022-09-25T11:07:32.541Z DEBUG geph4_client::tunman] ** watchdog completed in 898.512551ms ** [2022-09-25T11:07:36.659Z DEBUG geph4_client::tunman] ** watchdog completed in 1.024812552s ** [2022-09-25T11:07:36.659Z DEBUG geph4_client::tunman] ** sending telemetry: Telemetry { watchdog_ping_ms: 1024, version: "4-5-0-beta-1" } ** [2022-09-25T11:07:40.559Z DEBUG geph4_client::tunman] ** watchdog completed in 784.081249ms ** [2022-09-25T11:07:44.191Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:07:44.598Z DEBUG geph4_client::tunman] ** watchdog completed in 918.255573ms ** [2022-09-25T11:07:45.697Z DEBUG geph4_client::vpn] VPN received 4001 pkts [2022-09-25T11:07:48.750Z DEBUG geph4_client::tunman] ** watchdog completed in 984.130885ms ** [2022-09-25T11:07:53.299Z DEBUG geph4_client::tunman] ** watchdog completed in 661.303177ms ** [2022-09-25T11:07:57.122Z DEBUG geph4_client::tunman] ** watchdog completed in 547.575573ms ** [2022-09-25T11:08:02.102Z DEBUG geph4_client::tunman] ** watchdog completed in 1.069900781s ** [2022-09-25T11:08:05.944Z DEBUG geph4_client::tunman] ** watchdog completed in 839.503124ms ** [2022-09-25T11:08:09.548Z DEBUG geph4_client::tunman] ** watchdog completed in 572.715938ms ** [2022-09-25T11:08:09.549Z DEBUG geph4_client::tunman] ** sending telemetry: Telemetry { watchdog_ping_ms: 572, version: "4-5-0-beta-1" } ** [2022-09-25T11:08:13.378Z DEBUG geph4_client::tunman] ** watchdog completed in 819.702604ms ** [2022-09-25T11:08:14.205Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:08:15.221Z DEBUG geph4_client::vpn] VPN received 5001 pkts [2022-09-25T11:08:17.788Z DEBUG geph4_client::tunman] ** watchdog completed in 1.232894531s ** [2022-09-25T11:08:20.095Z DEBUG geph4_client::vpn] VPN received 6001 pkts [2022-09-25T11:08:21.921Z DEBUG geph4_client::tunman] ** watchdog completed in 841.66526ms ** [2022-09-25T11:08:24.066Z DEBUG geph4_client::vpn] VPN received 7001 pkts [2022-09-25T11:08:26.173Z DEBUG geph4_client::tunman] ** watchdog completed in 1.204472187s ** [2022-09-25T11:08:30.433Z DEBUG geph4_client::tunman] ** watchdog completed in 1.154445s ** [2022-09-25T11:08:34.772Z DEBUG geph4_client::tunman] ** watchdog completed in 921.576718ms ** [2022-09-25T11:08:39.586Z DEBUG geph4_client::tunman] ** watchdog completed in 709.250156ms ** [2022-09-25T11:08:44.299Z DEBUG geph4_client::tunman] ** watchdog completed in 716.515156ms ** [2022-09-25T11:08:44.610Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:08:49.728Z DEBUG geph4_client::tunman] ** watchdog completed in 767.629479ms ** [2022-09-25T11:08:49.728Z DEBUG geph4_client::tunman] ** sending telemetry: Telemetry { watchdog_ping_ms: 767, version: "4-5-0-beta-1" } ** [2022-09-25T11:08:54.537Z DEBUG geph4_client::tunman] ** watchdog completed in 945.462812ms ** [2022-09-25T11:08:58.840Z DEBUG geph4_client::tunman] ** watchdog completed in 709.489375ms ** [2022-09-25T11:09:02.933Z DEBUG geph4_client::tunman] ** watchdog completed in 1.023087604s ** [2022-09-25T11:09:08.052Z DEBUG geph4_client::tunman] ** watchdog completed in 818.678958ms ** [2022-09-25T11:09:12.660Z DEBUG geph4_client::tunman] ** watchdog completed in 828.743489ms ** [2022-09-25T11:09:14.999Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:09:31.638Z WARN geph4_client::tunman] watchdog conn failed! rerouting... [2022-09-25T11:09:31.639Z INFO geph4_client::main_connect] we are in CHINA :O [2022-09-25T11:09:31.639Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-09-25T11:09:33.041Z INFO geph4_client::tunman::getsess] connected to UDP for [redacted]:34056 [2022-09-25T11:09:33.041Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:34056 in 1402 ms [2022-09-25T11:09:33.042Z DEBUG geph4_client::tunman::getsess] starting hijack of other_id = 862f294c13... [2022-09-25T11:09:42.679Z DEBUG geph4_client::tunman::getsess] finished hijack of other_id = 862f294c13 with downstream data of 4! [2022-09-25T11:09:42.679Z WARN geph4_client::tunman] rerouting done. [2022-09-25T11:09:45.180Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:11:17.989Z WARN geph4_client::tunman] watchdog conn failed! rerouting... [2022-09-25T11:11:17.990Z INFO geph4_client::main_connect] we are in CHINA :O [2022-09-25T11:11:17.990Z WARN geph4_client::cache] ignore stale value for cache.bridges.us-sfo-02.exits.geph.io created at 1664103937 [2022-09-25T11:11:17.990Z DEBUG geph4_client::cache] refreshing from binder for cache.bridges.us-sfo-02.exits.geph.io [2022-09-25T11:11:19.664Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-09-25T11:11:21.895Z WARN geph4_client::tunman::getsess] switching to TCP for [redacted]:34056! [2022-09-25T11:11:22.597Z WARN geph4_client::tunman::getsess] switching to TCP for [redacted]:39209! [2022-09-25T11:11:22.609Z WARN geph4_client::tunman::getsess] switching to TCP for [redacted]:2777! [2022-09-25T11:11:23.752Z INFO geph4_client::tunman::getsess] connected to UDP for [redacted]:34056 [2022-09-25T11:11:23.753Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:34056 in 3858 ms [2022-09-25T11:11:23.754Z DEBUG geph4_client::tunman::getsess] starting hijack of other_id = 862f294c13... [2022-09-25T11:11:57.723Z WARN geph4_client::tunman] tunnel_actor restarting: rerouter timed out [2022-09-25T11:11:58.754Z INFO geph4_client::main_connect] we are in CHINA :O [2022-09-25T11:11:58.760Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-09-25T11:11:59.171Z INFO geph4_client::tunman::getsess] connected to UDP for [redacted]:34056 [2022-09-25T11:11:59.172Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:34056 in 411 ms [2022-09-25T11:12:04.101Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:14:04.005Z WARN geph4_client::tunman] tunnel_actor restarting: authentication timed out [2022-09-25T11:14:05.025Z INFO geph4_client::main_connect] we are in CHINA :O [2022-09-25T11:14:05.026Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-09-25T11:14:07.034Z WARN geph4_client::tunman::getsess] switching to TCP for [redacted]:39209! [2022-09-25T11:14:07.042Z WARN geph4_client::tunman::getsess] switching to TCP for [redacted]:2777! [2022-09-25T11:14:07.047Z WARN geph4_client::tunman::getsess] switching to TCP for [redacted]:34056! [2022-09-25T11:14:20.484Z INFO geph4_client::tunman::getsess] connected to UDP for [redacted]:34056 [2022-09-25T11:14:20.484Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:34056 in 15458 ms [2022-09-25T11:15:10.030Z WARN geph4_client::tunman] tunnel_actor restarting: authentication timed out [2022-09-25T11:15:34.728Z INFO geph4_client::main_connect] we are in CHINA :O [2022-09-25T11:15:34.728Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-09-25T11:15:34.733Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:15:35.416Z INFO geph4_client::tunman::getsess] connected to UDP for [redacted]:39209 [2022-09-25T11:15:35.416Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:39209 in 687 ms [2022-09-25T11:15:47.633Z DEBUG geph4_client::tunman] sending auth info... [2022-09-25T11:15:47.633Z DEBUG geph4_client::tunman] sent auth info! [2022-09-25T11:15:51.913Z INFO geph4_client::tunman] TUNNEL_MANAGER MAIN LOOP through [redacted]:39209 [2022-09-25T11:15:51.914Z INFO geph4_client::vpn] negotiating VPN with client id 163321879812060172104522493910714167259... [2022-09-25T11:15:52.728Z INFO geph4_client::vpn] negotiated IP address [redacted]! [2022-09-25T11:15:53.553Z DEBUG geph4_client::vpn] VPN received 1 pkts [2022-09-25T11:15:54.254Z DEBUG geph4_client::tunman] ** watchdog completed in 699.004271ms ** [2022-09-25T11:16:04.828Z DEBUG geph4_client::tunman] ** watchdog completed in 1.738795624s ** [2022-09-25T11:16:11.341Z DEBUG geph4_client::tunman] ** watchdog completed in 528.251823ms ** [2022-09-25T11:17:39.427Z DEBUG geph4_client::tunman] ** watchdog completed in 1.34111849s ** [2022-09-25T11:17:50.783Z DEBUG geph4_client::tunman] ** watchdog completed in 695.769687ms ** [2022-09-25T11:19:20.692Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-09-25T11:19:21.408Z DEBUG geph4_client::tunman] ** watchdog completed in 715.754219ms ** [2022-09-25T11:20:52.011Z DEBUG geph4_client::tunman] ** watchdog completed in 1.246524478s ** [2022-09-25T11:22:31.220Z DEBUG geph4_client::tunman] ** watchdog completed in 1.084387031s ** [2022-09-25T11:22:35.815Z DEBUG geph4_client::tunman] ** watchdog completed in 1.374078489s ** [2022-09-25T11:22:39.940Z INFO geph4_client::main_connect] ** recv_loss = 0.00% **