[2022-11-11T15:52:08.818Z INFO geph4_client] geph4-client v4.4.20 starting... [2022-11-11T15:52:08.819Z INFO geph4_client::main_connect] connect mode started [2022-11-11T15:52:08.821Z DEBUG geph4_client] getting extra fronts... [2022-11-11T15:52:08.824Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-11-11T15:52:08.824Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:52:08.972Z INFO geph4_client::fd_semaphore] ** set fd limit to 65535 ** [2022-11-11T15:52:12.470Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:38179 in 3646 ms [2022-11-11T15:52:14.523Z DEBUG geph4_client] inserting extra 1 fronts [2022-11-11T15:52:15.672Z DEBUG geph4_client::tunman] sending auth info... [2022-11-11T15:52:15.672Z DEBUG geph4_client::tunman] sent auth info! [2022-11-11T15:52:17.809Z INFO geph4_client::tunman] TUNNEL_MANAGER MAIN LOOP through [redacted]:38179 [2022-11-11T15:52:18.382Z DEBUG geph4_client::tunman] opened connection in 571 ms [2022-11-11T15:52:18.382Z DEBUG geph4_client::tunman] opened connection in 571 ms [2022-11-11T15:52:18.382Z DEBUG geph4_client::tunman] opened connection in 571 ms [2022-11-11T15:52:18.382Z DEBUG geph4_client::tunman] opened connection in 571 ms [2022-11-11T15:52:18.408Z DEBUG geph4_client::tunman] opened connection in 598 ms [2022-11-11T15:52:18.961Z DEBUG geph4_client::tunman] ** watchdog completed in 548.536231ms ** [2022-11-11T15:52:20.554Z DEBUG geph4_client::tunman] opened connection in 831 ms [2022-11-11T15:52:21.381Z DEBUG geph4_client::tunman] opened connection in 728 ms [2022-11-11T15:52:22.753Z DEBUG geph4_client::tunman] ** watchdog completed in 781.373824ms ** [2022-11-11T15:52:26.710Z DEBUG geph4_client::tunman] opened connection in 3408 ms [2022-11-11T15:52:27.503Z DEBUG geph4_client::tunman] opened connection in 3276 ms [2022-11-11T15:52:28.131Z DEBUG geph4_client::tunman] opened connection in 3736 ms [2022-11-11T15:52:28.419Z DEBUG geph4_client::tunman] opened connection in 3278 ms [2022-11-11T15:52:33.650Z DEBUG geph4_client::tunman] ** watchdog completed in 7.891196025s ** [2022-11-11T15:52:34.484Z DEBUG geph4_client::tunman] opened connection in 8502 ms [2022-11-11T15:52:38.880Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:52:38.888Z DEBUG geph4_client::tunman] opened connection in 3124 ms [2022-11-11T15:52:42.882Z DEBUG geph4_client::tunman] ** watchdog completed in 6.183114879s ** [2022-11-11T15:52:43.680Z DEBUG geph4_client::tunman] opened connection in 5702 ms [2022-11-11T15:52:44.869Z DEBUG geph4_client::tunman] opened connection in 5788 ms [2022-11-11T15:52:45.710Z DEBUG geph4_client::tunman] opened connection in 3972 ms [2022-11-11T15:52:45.979Z DEBUG geph4_client::tunman] opened connection in 4356 ms [2022-11-11T15:52:48.333Z DEBUG geph4_client::tunman] ** watchdog completed in 2.437939036s ** [2022-11-11T15:52:53.647Z DEBUG geph4_client::tunman] ** watchdog completed in 1.569878665s ** [2022-11-11T15:52:57.902Z DEBUG geph4_client::tunman] opened connection in 886 ms [2022-11-11T15:52:57.902Z DEBUG geph4_client::tunman] ** watchdog completed in 886.652174ms ** [2022-11-11T15:53:04.378Z DEBUG geph4_client::tunman] ** watchdog completed in 1.321921328s ** [2022-11-11T15:53:09.166Z DEBUG geph4_client::tunman] ** watchdog completed in 933.202997ms ** [2022-11-11T15:53:09.631Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:53:13.131Z DEBUG geph4_client::tunman] ** watchdog completed in 654.136744ms ** [2022-11-11T15:53:17.240Z DEBUG geph4_client::tunman] ** watchdog completed in 991.289467ms ** [2022-11-11T15:53:21.429Z DEBUG geph4_client::tunman] ** watchdog completed in 1.028480539s ** [2022-11-11T15:53:25.653Z DEBUG geph4_client::tunman] ** watchdog completed in 1.191995116s ** [2022-11-11T15:53:31.131Z DEBUG geph4_client::tunman] ** watchdog completed in 2.46814974s ** [2022-11-11T15:53:35.398Z DEBUG geph4_client::tunman] ** watchdog completed in 995.305479ms ** [2022-11-11T15:53:39.854Z DEBUG geph4_client::tunman] ** watchdog completed in 1.446664371s ** [2022-11-11T15:53:40.165Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:53:43.763Z DEBUG geph4_client::tunman] ** watchdog completed in 905.921325ms ** [2022-11-11T15:53:47.827Z DEBUG geph4_client::tunman] ** watchdog completed in 1.049648168s ** [2022-11-11T15:53:48.422Z DEBUG geph4_client::tunman] opened connection in 1083 ms [2022-11-11T15:53:51.952Z DEBUG geph4_client::tunman] ** watchdog completed in 949.948615ms ** [2022-11-11T15:53:55.712Z DEBUG geph4_client::tunman] ** watchdog completed in 736.27191ms ** [2022-11-11T15:54:00.955Z DEBUG geph4_client::tunman] ** watchdog completed in 1.131164969s ** [2022-11-11T15:54:05.761Z DEBUG geph4_client::tunman] ** watchdog completed in 1.73196342s ** [2022-11-11T15:54:09.997Z DEBUG geph4_client::tunman] ** watchdog completed in 1.208874665s ** [2022-11-11T15:54:10.421Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:54:14.881Z DEBUG geph4_client::tunman] ** watchdog completed in 1.758834043s ** [2022-11-11T15:54:19.048Z DEBUG geph4_client::tunman] ** watchdog completed in 1.05303296s ** [2022-11-11T15:54:23.459Z DEBUG geph4_client::tunman] ** watchdog completed in 1.218224699s ** [2022-11-11T15:54:28.572Z DEBUG geph4_client::tunman] ** watchdog completed in 1.493876433s ** [2022-11-11T15:54:33.388Z DEBUG geph4_client::tunman] ** watchdog completed in 1.748852323s ** [2022-11-11T15:54:38.433Z DEBUG geph4_client::tunman] ** watchdog completed in 1.997718662s ** [2022-11-11T15:54:40.427Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:54:43.990Z DEBUG geph4_client::tunman] ** watchdog completed in 2.232973167s ** [2022-11-11T15:54:48.086Z DEBUG geph4_client::tunman] ** watchdog completed in 1.037859121s ** [2022-11-11T15:54:52.941Z DEBUG geph4_client::tunman] ** watchdog completed in 1.789172688s ** [2022-11-11T15:54:57.703Z DEBUG geph4_client::tunman] ** watchdog completed in 1.738872861s ** [2022-11-11T15:55:03.119Z DEBUG geph4_client::tunman] ** watchdog completed in 1.241842938s ** [2022-11-11T15:55:07.642Z DEBUG geph4_client::tunman] ** watchdog completed in 1.312492778s ** [2022-11-11T15:55:10.429Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:55:11.919Z DEBUG geph4_client::tunman] ** watchdog completed in 440.810081ms ** [2022-11-11T15:55:15.553Z DEBUG geph4_client::tunman] ** watchdog completed in 565.633007ms ** [2022-11-11T15:55:19.203Z DEBUG geph4_client::tunman] ** watchdog completed in 375.12037ms ** [2022-11-11T15:55:22.728Z DEBUG geph4_client::tunman] ** watchdog completed in 391.892399ms ** [2022-11-11T15:55:26.103Z DEBUG geph4_client::tunman] ** watchdog completed in 370.554303ms ** [2022-11-11T15:55:27.852Z DEBUG geph4_client::tunman] opened connection in 284 ms [2022-11-11T15:55:29.747Z DEBUG geph4_client::tunman] ** watchdog completed in 634.032165ms ** [2022-11-11T15:55:33.143Z DEBUG geph4_client::tunman] ** watchdog completed in 373.483225ms ** [2022-11-11T15:55:36.624Z DEBUG geph4_client::tunman] ** watchdog completed in 472.094887ms ** [2022-11-11T15:55:39.996Z DEBUG geph4_client::tunman] ** watchdog completed in 332.986682ms ** [2022-11-11T15:55:40.430Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:55:43.591Z DEBUG geph4_client::tunman] ** watchdog completed in 307.70451ms ** [2022-11-11T15:55:47.284Z DEBUG geph4_client::tunman] ** watchdog completed in 349.249776ms ** [2022-11-11T15:55:50.708Z DEBUG geph4_client::tunman] ** watchdog completed in 277.781529ms ** [2022-11-11T15:55:54.222Z DEBUG geph4_client::tunman] ** watchdog completed in 294.376428ms ** [2022-11-11T15:55:57.882Z DEBUG geph4_client::tunman] ** watchdog completed in 318.107229ms ** [2022-11-11T15:56:01.623Z DEBUG geph4_client::tunman] ** watchdog completed in 720.003319ms ** [2022-11-11T15:56:03.355Z DEBUG geph4_client::tunman] opened connection in 865 ms [2022-11-11T15:56:04.687Z DEBUG geph4_client::tunman] opened connection in 412 ms [2022-11-11T15:56:05.193Z DEBUG geph4_client::tunman] ** watchdog completed in 555.621691ms ** [2022-11-11T15:56:10.431Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:56:11.753Z DEBUG geph4_client::tunman] ** watchdog completed in 3.495496121s ** [2022-11-11T15:56:15.641Z DEBUG geph4_client::tunman] ** watchdog completed in 753.89781ms ** [2022-11-11T15:56:19.469Z DEBUG geph4_client::tunman] ** watchdog completed in 808.653836ms ** [2022-11-11T15:56:23.651Z DEBUG geph4_client::tunman] ** watchdog completed in 913.307942ms ** [2022-11-11T15:56:27.751Z DEBUG geph4_client::tunman] ** watchdog completed in 693.09271ms ** [2022-11-11T15:56:27.751Z DEBUG geph4_client::tunman] opened connection in 693 ms [2022-11-11T15:56:37.764Z DEBUG geph4_client::tunman] ** watchdog completed in 6.759559164s ** [2022-11-11T15:56:40.434Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:56:43.813Z DEBUG geph4_client::tunman] ** watchdog completed in 3.017136819s ** [2022-11-11T15:56:48.524Z DEBUG geph4_client::tunman] ** watchdog completed in 1.688803191s ** [2022-11-11T15:56:52.689Z DEBUG geph4_client::tunman] ** watchdog completed in 1.155037989s ** [2022-11-11T15:56:58.778Z DEBUG geph4_client::tunman] ** watchdog completed in 3.058188186s ** [2022-11-11T15:57:02.557Z DEBUG geph4_client::tunman] ** watchdog completed in 582.754759ms ** [2022-11-11T15:57:06.404Z DEBUG geph4_client::tunman] ** watchdog completed in 829.420674ms ** [2022-11-11T15:57:10.436Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:57:10.553Z DEBUG geph4_client::tunman] ** watchdog completed in 1.076658173s ** [2022-11-11T15:57:14.083Z DEBUG geph4_client::tunman] ** watchdog completed in 522.739596ms ** [2022-11-11T15:57:17.981Z DEBUG geph4_client::tunman] ** watchdog completed in 861.541772ms ** [2022-11-11T15:57:21.574Z DEBUG geph4_client::tunman] ** watchdog completed in 550.886508ms ** [2022-11-11T15:57:26.950Z DEBUG geph4_client::tunman] ** watchdog completed in 2.373225736s ** [2022-11-11T15:57:32.404Z DEBUG geph4_client::tunman] ** watchdog completed in 2.430367004s ** [2022-11-11T15:57:37.366Z DEBUG geph4_client::tunman] ** watchdog completed in 1.929207698s ** [2022-11-11T15:57:40.438Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:57:45.798Z DEBUG geph4_client::tunman] ** watchdog completed in 5.36020685s ** [2022-11-11T15:57:49.865Z DEBUG geph4_client::tunman] ** watchdog completed in 1.040034625s ** [2022-11-11T15:57:53.796Z DEBUG geph4_client::tunman] ** watchdog completed in 828.695525ms ** [2022-11-11T15:57:58.274Z DEBUG geph4_client::tunman] ** watchdog completed in 971.339334ms ** [2022-11-11T15:58:02.172Z DEBUG geph4_client::tunman] ** watchdog completed in 792.832686ms ** [2022-11-11T15:58:05.863Z DEBUG geph4_client::tunman] ** watchdog completed in 521.78681ms ** [2022-11-11T15:58:10.439Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:58:10.539Z DEBUG geph4_client::tunman] ** watchdog completed in 586.653772ms ** [2022-11-11T15:58:14.879Z DEBUG geph4_client::tunman] ** watchdog completed in 481.791325ms ** [2022-11-11T15:58:20.329Z DEBUG geph4_client::tunman] ** watchdog completed in 693.481859ms ** [2022-11-11T15:58:25.595Z DEBUG geph4_client::tunman] ** watchdog completed in 532.946302ms ** [2022-11-11T15:58:29.160Z DEBUG geph4_client::tunman] ** watchdog completed in 495.020323ms ** [2022-11-11T15:58:32.720Z DEBUG geph4_client::tunman] ** watchdog completed in 534.847821ms ** [2022-11-11T15:58:37.802Z DEBUG geph4_client::tunman] ** watchdog completed in 526.095914ms ** [2022-11-11T15:58:40.441Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:58:41.724Z DEBUG geph4_client::tunman] ** watchdog completed in 786.579035ms ** [2022-11-11T15:58:46.091Z DEBUG geph4_client::tunman] ** watchdog completed in 861.683205ms ** [2022-11-11T15:58:48.298Z DEBUG geph4_client::tunman] opened connection in 953 ms [2022-11-11T15:58:49.984Z DEBUG geph4_client::tunman] ** watchdog completed in 739.831565ms ** [2022-11-11T15:58:54.198Z DEBUG geph4_client::tunman] ** watchdog completed in 872.207654ms ** [2022-11-11T15:58:58.794Z DEBUG geph4_client::tunman] ** watchdog completed in 859.410344ms ** [2022-11-11T15:59:03.190Z DEBUG geph4_client::tunman] ** watchdog completed in 1.205775496s ** [2022-11-11T15:59:07.460Z DEBUG geph4_client::tunman] ** watchdog completed in 950.424372ms ** [2022-11-11T15:59:10.442Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:59:12.471Z DEBUG geph4_client::tunman] ** watchdog completed in 615.762102ms ** [2022-11-11T15:59:12.471Z DEBUG geph4_client::tunman] opened connection in 615 ms [2022-11-11T15:59:16.993Z DEBUG geph4_client::tunman] ** watchdog completed in 630.534449ms ** [2022-11-11T15:59:21.157Z DEBUG geph4_client::tunman] ** watchdog completed in 714.863806ms ** [2022-11-11T15:59:25.447Z DEBUG geph4_client::tunman] ** watchdog completed in 847.117167ms ** [2022-11-11T15:59:29.257Z DEBUG geph4_client::tunman] ** watchdog completed in 621.79318ms ** [2022-11-11T15:59:32.976Z DEBUG geph4_client::tunman] ** watchdog completed in 646.105537ms ** [2022-11-11T15:59:38.808Z DEBUG geph4_client::tunman] ** watchdog completed in 546.795166ms ** [2022-11-11T15:59:40.444Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T15:59:40.988Z DEBUG geph4_client::tunman] opened connection in 1042 ms [2022-11-11T15:59:42.560Z DEBUG geph4_client::tunman] opened connection in 578 ms [2022-11-11T15:59:42.604Z DEBUG geph4_client::tunman] ** watchdog completed in 625.710044ms ** [2022-11-11T15:59:45.050Z DEBUG geph4_client::tunman] opened connection in 554 ms [2022-11-11T15:59:46.238Z DEBUG geph4_client::tunman] ** watchdog completed in 535.842705ms ** [2022-11-11T15:59:50.606Z DEBUG geph4_client::tunman] ** watchdog completed in 1.355438212s ** [2022-11-11T16:00:08.620Z WARN geph4_client::tunman] watchdog conn failed! rerouting... [2022-11-11T16:00:08.620Z WARN geph4_client::cache] ignore stale value for cache.bridges.3.mtl.ca.ngexits.geph.io created at 1668181757 [2022-11-11T16:00:08.620Z DEBUG geph4_client::cache] refreshing from binder for cache.bridges.3.mtl.ca.ngexits.geph.io [2022-11-11T16:00:08.993Z WARN geph4_binder_transport] request_multi failed: Some(Err(Other("io error: unexpected end of file"))) [2022-11-11T16:00:09.164Z WARN geph4_binder_transport] request_multi failed: Some(Err(Other("io error: unexpected end of file"))) [2022-11-11T16:00:09.431Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-11-11T16:00:10.445Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T16:00:10.565Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:38179 in 1133 ms [2022-11-11T16:00:10.565Z DEBUG geph4_client::tunman::getsess] starting hijack of other_id = b2fb14f946... [2022-11-11T16:00:11.463Z DEBUG geph4_client::tunman::getsess] finished hijack of other_id = b2fb14f946 with downstream data of 4! [2022-11-11T16:00:11.463Z WARN geph4_client::tunman] rerouting done. [2022-11-11T16:00:12.617Z DEBUG geph4_client::tunman] ** watchdog completed in 1.153576179s ** [2022-11-11T16:00:12.770Z DEBUG geph4_client::tunman] opened connection in 893 ms [2022-11-11T16:00:16.798Z DEBUG geph4_client::tunman] ** watchdog completed in 842.59343ms ** [2022-11-11T16:00:19.318Z DEBUG geph4_client::tunman] opened connection in 335 ms [2022-11-11T16:00:26.685Z DEBUG geph4_client::tunman] opened connection in 336 ms [2022-11-11T16:00:27.292Z DEBUG geph4_client::tunman] opened connection in 7924 ms [2022-11-11T16:00:27.770Z DEBUG geph4_client::tunman] opened connection in 417 ms [2022-11-11T16:00:27.823Z DEBUG geph4_client::tunman] ** watchdog completed in 7.905408702s ** [2022-11-11T16:00:27.865Z DEBUG geph4_client::tunman] opened connection in 7872 ms [2022-11-11T16:00:29.704Z DEBUG geph4_client::tunman] opened connection in 7798 ms [2022-11-11T16:00:36.101Z DEBUG geph4_client::tunman] ** watchdog completed in 277.202355ms ** [2022-11-11T16:00:38.732Z DEBUG geph4_client::tunman] opened connection in 312 ms [2022-11-11T16:00:39.769Z DEBUG geph4_client::tunman] opened connection in 363 ms [2022-11-11T16:00:39.769Z DEBUG geph4_client::tunman] ** watchdog completed in 364.283391ms ** [2022-11-11T16:00:39.878Z DEBUG geph4_client::tunman] opened connection in 291 ms [2022-11-11T16:00:39.901Z DEBUG geph4_client::tunman] opened connection in 298 ms [2022-11-11T16:00:39.903Z DEBUG geph4_client::tunman] opened connection in 285 ms [2022-11-11T16:00:40.614Z DEBUG geph4_client::tunman] opened connection in 285 ms [2022-11-11T16:00:40.617Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T16:00:45.755Z DEBUG geph4_client::tunman] ** watchdog completed in 340.102827ms ** [2022-11-11T16:00:48.810Z DEBUG geph4_client::tunman] opened connection in 289 ms [2022-11-11T16:00:49.143Z DEBUG geph4_client::tunman] ** watchdog completed in 329.314518ms ** [2022-11-11T16:01:11.192Z INFO geph4_client::main_connect] ** recv_loss = 0.00% ** [2022-11-11T16:01:12.144Z WARN geph4_client::tunman] watchdog conn failed! rerouting... [2022-11-11T16:01:12.144Z DEBUG geph4_client::tunman::getsess] got 3 bridges [2022-11-11T16:01:12.401Z DEBUG geph4_client::tunman] opened connection in 504 ms [2022-11-11T16:01:12.686Z DEBUG geph4_client::tunman] opened connection in 2138 ms [2022-11-11T16:01:12.751Z DEBUG geph4_client::tunman] opened connection in 2203 ms [2022-11-11T16:01:13.165Z DEBUG geph4_client::tunman] opened connection in 1972 ms [2022-11-11T16:01:13.207Z DEBUG geph4_client::tunman] opened connection in 2015 ms [2022-11-11T16:01:13.573Z INFO geph4_client::tunman::getsess] found fastest bridge [redacted]:53776 in 1428 ms [2022-11-11T16:01:13.573Z DEBUG geph4_client::tunman::getsess] starting hijack of other_id = b2fb14f946... [2022-11-11T16:01:13.666Z DEBUG geph4_client::tunman] opened connection in 8150 ms [2022-11-11T16:01:14.483Z DEBUG geph4_client::tunman::getsess] finished hijack of other_id = b2fb14f946 with downstream data of 4! [2022-11-11T16:01:14.483Z WARN geph4_client::tunman] rerouting done. [2022-11-11T16:01:15.332Z DEBUG geph4_client::tunman] opened connection in 809 ms [2022-11-11T16:01:15.475Z DEBUG geph4_client::tunman] opened connection in 15931 ms [2022-11-11T16:01:15.478Z DEBUG geph4_client::tunman] ** watchdog completed in 955.823441ms ** [2022-11-11T16:01:15.554Z DEBUG geph4_client::tunman] opened connection in 15815 ms [2022-11-11T16:01:15.647Z DEBUG geph4_client::tunman] opened connection in 8470 ms [2022-11-11T16:01:16.002Z DEBUG geph4_client::tunman] opened connection in 15813 ms [2022-11-11T16:01:16.357Z DEBUG geph4_client::tunman] opened connection in 15811 ms [2022-11-11T16:01:16.359Z DEBUG geph4_client::tunman] opened connection in 15814 ms [2022-11-11T16:01:18.009Z DEBUG geph4_client::tunman] opened connection in 7818 ms [2022-11-11T16:01:18.139Z DEBUG geph4_client::tunman] opened connection in 15804 ms [2022-11-11T16:01:20.928Z DEBUG geph4_client::tunman] opened connection in 320 ms [2022-11-11T16:01:20.937Z DEBUG geph4_client::tunman] ** watchdog completed in 329.679672ms ** [2022-11-11T16:01:21.943Z DEBUG geph4_client::tunman] opened connection in 334 ms [2022-11-11T16:01:27.761Z DEBUG geph4_client::tunman] opened connection in 393 ms [2022-11-11T16:01:27.761Z DEBUG geph4_client::tunman] ** watchdog completed in 393.555344ms **