search

n0-computer / iroh

A toolkit for building distributed applications
https://iroh.computer
Apache License 2.0
2.27k stars 145 forks source link

test_run_rpc_lock_file is flaky #2438

Closed flub closed 2 months ago

flub commented 2 months ago

https://github.com/n0-computer/iroh/actions/runs/9743628245/job/26887495078?pr=2436

--- STDOUT:              iroh-cli::bin/iroh commands::start::tests::test_run_rpc_lock_file ---

running 1 test
test commands::start::tests::test_run_rpc_lock_file ... FAILED

failures:

failures:
    commands::start::tests::test_run_rpc_lock_file

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 5 filtered out; finished in 3.03s

--- STDERR:              iroh-cli::bin/iroh commands::start::tests::test_run_rpc_lock_file ---
2024-07-01T11:57:21.113555Z  INFO iroh_metrics::service: Starting metrics server on 127.0.0.1:9090
2024-07-01T11:57:21.685618Z  WARN iroh::node::builder: RPC port 4919 already in use, switching to random port
2024-07-01T11:57:21.686353Z DEBUG quic_rpc::transport::quinn: Waiting for incoming connection...
2024-07-01T11:57:21.762529Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service: iroh_net::portmapper: portmap starting
2024-07-01T11:57:21.763170Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}: iroh_net::magicsock::udp_conn: binding network=V4 port=11204
2024-07-01T11:57:21.763479Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}: iroh_net::magicsock::udp_conn: candidate ports ports=[11204, 0]
2024-07-01T11:57:21.764787Z  WARN magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}: iroh_net::magicsock::udp_conn: failed to bind: Error {
    context: "0.0.0.0:11204",
    source: Error {
        context: "binding",
        source: Os {
            code: 98,
            kind: AddrInUse,
            message: "Address already in use",
        },
    },
} network=V4 port=11204
2024-07-01T11:57:21.765321Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}: iroh_net::magicsock::udp_conn: successfully bound network=V4 local_addr=0.0.0.0:42386
2024-07-01T11:57:21.765588Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}: iroh_net::magicsock::udp_conn: binding network=V6 port=42387
2024-07-01T11:57:21.765817Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}: iroh_net::magicsock::udp_conn: candidate ports ports=[42387, 0]
2024-07-01T11:57:21.766174Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}: iroh_net::magicsock::udp_conn: successfully bound network=V6 local_addr=[::]:42387
2024-07-01T11:57:21.774389Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service: iroh_net::portmapper: getting a port mapping for 5.9.119.203:42386 -> None
2024-07-01T11:57:21.775044Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: netcheck actor starting
2024-07-01T11:57:21.775833Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service:upnp: igd_next::aio::tokio: sending broadcast request to: 239.255.255.250:1900 on interface: Ok(0.0.0.0:50065)    
2024-07-01T11:57:21.782675Z DEBUG netlink_proto::connection: reading incoming messages    
2024-07-01T11:57:21.782807Z DEBUG netlink_proto::codecs: NetlinkCodec: decoding next message    
2024-07-01T11:57:21.783012Z DEBUG netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2024-07-01T11:57:21.783138Z DEBUG netlink_proto::connection: forwarding responses to previous requests to the connection handle    
2024-07-01T11:57:21.783255Z DEBUG netlink_proto::connection: handling requests    
2024-07-01T11:57:21.783390Z DEBUG netlink_proto::connection: sending messages    
2024-07-01T11:57:21.783894Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: scheduling periodic_stun to run immediately and in 24s
2024-07-01T11:57:21.785851Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor:re_stun{me=l76fmx76dtkuy6yf}: iroh_net::magicsock: re_stun: periodic
2024-07-01T11:57:21.786409Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor:update_endpoints: iroh_net::magicsock: starting endpoint update (periodic)
2024-07-01T11:57:21.786842Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor:update_endpoints:update_net_info: iroh_net::magicsock: requesting netcheck report
2024-07-01T11:57:21.791087Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service: iroh_net::portmapper: getting a port mapping for 5.9.119.203:42386 -> None
2024-07-01T11:57:21.792243Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service:upnp: igd_next::aio::tokio: sending broadcast request to: 239.255.255.250:1900 on interface: Ok(0.0.0.0:53434)    
2024-07-01T11:57:21.793126Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: reportstate actor starting port_mapper=true
2024-07-01T11:57:21.798673Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Local interfaces if_state=1. lo Loopback ipv4=[127.0.0.1/8] ipv6=[::1/128]; 2. enp41s0 Ethernet ipv4=[5.9.119.203/32] ipv6=[2a01:4f8:162:64cd::2/64, fe80::aaa1:59ff:fec1:2018/64] (default); 3. docker0 Ethernet ipv4=[172.17.0.1/16] ipv6=[fe80::42:f9ff:feb5:3653/64]; 234789. ovs-system Ethernet ipv4=[] ipv6=[]; 234790. natswir0 Ethernet ipv4=[] ipv6=[]; 234791. s1 Ethernet ipv4=[] ipv6=[]; 
2024-07-01T11:57:21.803401Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:21.804006Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:21.804555Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:21.805096Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:21.810629Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service:portmapper.probe: igd_next::aio::tokio: sending broadcast request to: 239.255.255.250:1900 on interface: Ok(0.0.0.0:55831)    
2024-07-01T11:57:21.811294Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: Performing DNS A lookup for relay addr proto=StunIpv4 hostname=euw1-1.relay.iroh.network.
2024-07-01T11:57:21.811908Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: Performing DNS A lookup for relay addr proto=StunIpv4 hostname=use1-1.relay.iroh.network.
2024-07-01T11:57:21.812481Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: Performing DNS AAAA lookup for relay addr proto=StunIpv6 hostname=euw1-1.relay.iroh.network.
2024-07-01T11:57:21.813088Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: Performing DNS AAAA lookup for relay addr proto=StunIpv6 hostname=use1-1.relay.iroh.network.
2024-07-01T11:57:21.814895Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::xfer::dns_handle: querying: euw1-1.relay.iroh.network. A
2024-07-01T11:57:21.815418Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server_pool: sending request: [Query { name: Name("euw1-1.relay.iroh.network."), query_type: A, query_class: IN }]
2024-07-01T11:57:21.815950Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server: reconnecting: NameServerConfig { socket_addr: 127.0.0.53:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, tls_config: None, bind_addr: None }
2024-07-01T11:57:21.816520Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::xfer: enqueueing message:QUERY:[Query { name: Name("euw1-1.relay.iroh.network."), query_type: A, query_class: IN }]
2024-07-01T11:57:21.817456Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::xfer::dns_handle: querying: use1-1.relay.iroh.network. A
2024-07-01T11:57:21.817907Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server_pool: sending request: [Query { name: Name("use1-1.relay.iroh.network."), query_type: A, query_class: IN }]
2024-07-01T11:57:21.818399Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server: existing connection: NameServerConfig { socket_addr: 127.0.0.53:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, tls_config: None, bind_addr: None }
2024-07-01T11:57:21.818760Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::xfer: enqueueing message:QUERY:[Query { name: Name("use1-1.relay.iroh.network."), query_type: A, query_class: IN }]
2024-07-01T11:57:21.819743Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::xfer::dns_handle: querying: euw1-1.relay.iroh.network. AAAA
2024-07-01T11:57:21.820195Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server_pool: sending request: [Query { name: Name("euw1-1.relay.iroh.network."), query_type: AAAA, query_class: IN }]
2024-07-01T11:57:21.820645Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server: existing connection: NameServerConfig { socket_addr: 127.0.0.53:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, tls_config: None, bind_addr: None }
2024-07-01T11:57:21.821000Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::xfer: enqueueing message:QUERY:[Query { name: Name("euw1-1.relay.iroh.network."), query_type: AAAA, query_class: IN }]
2024-07-01T11:57:21.821732Z DEBUG hickory_proto::udp::udp_client_stream: final message: ; header 7708:QUERY:RD:NoError:QUERY:0/0/0
; query
;; euw1-1.relay.iroh.network. IN A

2024-07-01T11:57:21.822067Z DEBUG hickory_proto::udp::udp_client_stream: final message: ; header 62372:QUERY:RD:NoError:QUERY:0/0/0
; query
;; use1-1.relay.iroh.network. IN A

2024-07-01T11:57:21.822421Z DEBUG hickory_proto::udp::udp_client_stream: final message: ; header 58429:QUERY:RD:NoError:QUERY:0/0/0
; query
;; euw1-1.relay.iroh.network. IN AAAA

2024-07-01T11:57:21.822988Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::udp::udp_stream: created socket successfully
2024-07-01T11:57:21.823677Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::udp::udp_stream: created socket successfully
2024-07-01T11:57:21.824335Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::udp::udp_stream: created socket successfully
2024-07-01T11:57:21.826123Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::xfer::dns_handle: querying: use1-1.relay.iroh.network. AAAA
2024-07-01T11:57:21.826578Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server_pool: sending request: [Query { name: Name("use1-1.relay.iroh.network."), query_type: AAAA, query_class: IN }]
2024-07-01T11:57:21.827098Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::name_server::name_server: existing connection: NameServerConfig { socket_addr: 127.0.0.53:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, tls_config: None, bind_addr: None }
2024-07-01T11:57:21.827463Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::xfer: enqueueing message:QUERY:[Query { name: Name("use1-1.relay.iroh.network."), query_type: AAAA, query_class: IN }]
2024-07-01T11:57:21.828245Z DEBUG hickory_proto::udp::udp_client_stream: final message: ; header 844:QUERY:RD:NoError:QUERY:0/0/0
; query
;; use1-1.relay.iroh.network. IN AAAA

2024-07-01T11:57:21.828760Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::udp::udp_stream: created socket successfully
2024-07-01T11:57:21.829651Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::udp::udp_client_stream: received message id: 7708
2024-07-01T11:57:21.830200Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 7708:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; euw1-1.relay.iroh.network. IN A
; answers 1
euw1-1.relay.iroh.network. 218 IN A 116.203.71.221
; nameservers 0
; additionals 0

2024-07-01T11:57:21.830730Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 7708:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; euw1-1.relay.iroh.network. IN A
; answers 1
euw1-1.relay.iroh.network. 218 IN A 116.203.71.221
; nameservers 0
; additionals 0

2024-07-01T11:57:21.832296Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::udp::udp_client_stream: received message id: 62372
2024-07-01T11:57:21.832861Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 62372:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; use1-1.relay.iroh.network. IN A
; answers 1
use1-1.relay.iroh.network. 34 IN A 5.161.115.11
; nameservers 0
; additionals 0

2024-07-01T11:57:21.833381Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 62372:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; use1-1.relay.iroh.network. IN A
; answers 1
use1-1.relay.iroh.network. 34 IN A 5.161.115.11
; nameservers 0
; additionals 0

2024-07-01T11:57:21.834572Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_proto::udp::udp_client_stream: received message id: 58429
2024-07-01T11:57:21.835120Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 58429:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; euw1-1.relay.iroh.network. IN AAAA
; answers 1
euw1-1.relay.iroh.network. 219 IN AAAA 2a01:4f8:1c1b:58b6::1
; nameservers 0
; additionals 0

2024-07-01T11:57:21.835644Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 58429:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; euw1-1.relay.iroh.network. IN AAAA
; answers 1
euw1-1.relay.iroh.network. 219 IN AAAA 2a01:4f8:1c1b:58b6::1
; nameservers 0
; additionals 0

2024-07-01T11:57:21.837298Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: sending StunIpv4 probe relay_addr=116.203.71.221:3478 txid=transaction id (0xE8EC8CFEE646CE7001C87010)
2024-07-01T11:57:21.837879Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: sending StunIpv4 probe relay_addr=5.161.115.11:3478 txid=transaction id (0xAA982305347CD28D48D3AF87)
2024-07-01T11:57:21.838446Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: sending StunIpv6 probe relay_addr=[2a01:4f8:1c1b:58b6::1]:3478 txid=transaction id (0xFA42AC34E3D65033DF5C830B)
2024-07-01T11:57:21.839232Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_proto::udp::udp_client_stream: received message id: 844
2024-07-01T11:57:21.839739Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 844:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; use1-1.relay.iroh.network. IN AAAA
; answers 1
use1-1.relay.iroh.network. 56 IN AAAA 2a01:4ff:f0:81d7::1
; nameservers 0
; additionals 0

2024-07-01T11:57:21.840250Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: hickory_resolver::error: Response:; header 844:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; use1-1.relay.iroh.network. IN AAAA
; answers 1
use1-1.relay.iroh.network. 56 IN AAAA 2a01:4ff:f0:81d7::1
; nameservers 0
; additionals 0

2024-07-01T11:57:21.841629Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: sending StunIpv6 probe relay_addr=[2a01:4ff:f0:81d7::1]:3478 txid=transaction id (0xF997AB6F040CD2C7E2E40D43)
2024-07-01T11:57:21.842944Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: received known STUN packet src=116.203.71.221:3478 txn=transaction id (0xE8EC8CFEE646CE7001C87010)
2024-07-01T11:57:21.844091Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: received known STUN packet src=[2a01:4f8:1c1b:58b6::1]:3478 txn=transaction id (0xFA42AC34E3D65033DF5C830B)
2024-07-01T11:57:21.845742Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: finished probe probe_report=ProbeReport { ipv4_can_send: true, ipv6_can_send: false, icmpv4: None, icmpv6: None, latency: Some(11.339468ms), probe: StunIpv4 { delay: 0ns, node: RelayNode { url: RelayUrl("https://euw1-1.relay.iroh.network./"), stun_only: false, stun_port: 3478 } }, addr: Some(5.9.119.203:42386) }
2024-07-01T11:57:21.846877Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: finished probe probe_report=ProbeReport { ipv4_can_send: false, ipv6_can_send: true, icmpv4: None, icmpv6: None, latency: Some(7.905681ms), probe: StunIpv6 { delay: 0ns, node: RelayNode { url: RelayUrl("https://euw1-1.relay.iroh.network./"), stun_only: false, stun_port: 3478 } }, addr: Some([2a01:4f8:162:64cd::2]:42387) }
2024-07-01T11:57:21.848457Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: received our hairpin STUN request src=5.9.119.203:60180 txn=transaction id (0x9553EC1C9D161CFBBAE0BB85)
2024-07-01T11:57:21.849351Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:hairpin.actor: iroh_net::netcheck::reportgen::hairpin: hairpinning done in 1.660759ms, res: true
2024-07-01T11:57:21.905635Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 100ms to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:21.906361Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 100ms to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: Performing DNS A lookup for relay addr proto=StunIpv4 hostname=use1-1.relay.iroh.network.
2024-07-01T11:57:21.907090Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 100ms to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:21.907736Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 100ms to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: Performing DNS AAAA lookup for relay addr proto=StunIpv6 hostname=use1-1.relay.iroh.network.
2024-07-01T11:57:21.909687Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 100ms to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: sending StunIpv4 probe relay_addr=5.161.115.11:3478 txid=transaction id (0x54198D32E53F1BF74C1BE0C2)
2024-07-01T11:57:21.911405Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 100ms to https://use1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: sending StunIpv6 probe relay_addr=[2a01:4ff:f0:81d7::1]:3478 txid=transaction id (0x563CCCEC67A5A5FB2B885828)
2024-07-01T11:57:21.937353Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: received known STUN packet src=[2a01:4ff:f0:81d7::1]:3478 txn=transaction id (0xF997AB6F040CD2C7E2E40D43)
2024-07-01T11:57:21.939059Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: finished probe probe_report=ProbeReport { ipv4_can_send: false, ipv6_can_send: true, icmpv4: None, icmpv6: None, latency: Some(96.510426ms), probe: StunIpv6 { delay: 0ns, node: RelayNode { url: RelayUrl("https://use1-1.relay.iroh.network./"), stun_only: false, stun_port: 3478 } }, addr: Some([2a01:4f8:162:64cd::2]:42387) }
2024-07-01T11:57:21.939679Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Have enough probe reports, aborting further probes soon reports=2 delay=193.020852ms
2024-07-01T11:57:21.940976Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: received known STUN packet src=5.161.115.11:3478 txn=transaction id (0xAA982305347CD28D48D3AF87)
2024-07-01T11:57:21.942515Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: finished probe probe_report=ProbeReport { ipv4_can_send: true, ipv6_can_send: false, icmpv4: None, icmpv6: None, latency: Some(107.072566ms), probe: StunIpv4 { delay: 0ns, node: RelayNode { url: RelayUrl("https://use1-1.relay.iroh.network./"), stun_only: false, stun_port: 3478 } }, addr: Some(5.9.119.203:42386) }
2024-07-01T11:57:21.943106Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Have enough probe reports, aborting further probes soon reports=2 delay=193.020852ms
2024-07-01T11:57:22.005416Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Captive portal check started after 200ms
2024-07-01T11:57:22.007387Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:captive-portal: reqwest::connect: starting new connection: http://use1-1.relay.iroh.network./    
2024-07-01T11:57:22.007939Z DEBUG hyper_util::client::legacy::connect::dns: resolving host="use1-1.relay.iroh.network."
2024-07-01T11:57:22.010555Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: received known STUN packet src=[2a01:4ff:f0:81d7::1]:3478 txn=transaction id (0x563CCCEC67A5A5FB2B885828)
2024-07-01T11:57:22.012196Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:captive-portal: hyper_util::client::legacy::connect::http: connecting to [2a01:4ff:f0:81d7::1]:80
2024-07-01T11:57:22.013809Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: received known STUN packet src=5.161.115.11:3478 txn=transaction id (0x54198D32E53F1BF74C1BE0C2)
2024-07-01T11:57:22.106789Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=HTTPS after 300ms to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:22.107279Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=ICMPv4 after 300ms to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:22.108862Z DEBUG iroh_net::netcheck::reportgen: probe set aborted: ReportCheck says probe set no longer useful probe=Https { delay: 300ms, node: RelayNode { url: RelayUrl("https://euw1-1.relay.iroh.network./"), stun_only: false, stun_port: 3478 } }
2024-07-01T11:57:22.109203Z DEBUG iroh_net::netcheck::reportgen: probe set aborted: ReportCheck says probe set no longer useful probe=IcmpV4 { delay: 300ms, node: RelayNode { url: RelayUrl("https://euw1-1.relay.iroh.network./"), stun_only: false, stun_port: 3478 } }
2024-07-01T11:57:22.110412Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:captive-portal: hyper_util::client::legacy::connect::http: connected to [2a01:4ff:f0:81d7::1]:80
2024-07-01T11:57:22.111208Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor:run_probe{probe=ICMPv6 after 300ms to https://euw1-1.relay.iroh.network./}: iroh_net::netcheck::reportgen: starting probe
2024-07-01T11:57:22.112874Z DEBUG iroh_net::netcheck::reportgen: probe set aborted: ReportCheck says probe set no longer useful probe=IcmpV6 { delay: 300ms, node: RelayNode { url: RelayUrl("https://euw1-1.relay.iroh.network./"), stun_only: false, stun_port: 3478 } }
2024-07-01T11:57:22.135551Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: all tasks done
2024-07-01T11:57:22.135853Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: aborting 3 probe sets, already have enough reports
2024-07-01T11:57:22.136144Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Sending report to netcheck actor
2024-07-01T11:57:22.136863Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: reportgen actor finished
2024-07-01T11:57:22.137771Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:netcheck.actor: iroh_net::netcheck: Report { udp: true, ipv6: true, ipv4: true, ipv6_can_send: true, ipv4_can_send: true, os_has_ipv6: true, icmpv4: None, icmpv6: None, mapping_varies_by_dest_ip: Some(false), mapping_varies_by_dest_ipv6: Some(false), hair_pinning: Some(true), portmap_probe: None, preferred_relay: Some(RelayUrl("https://euw1-1.relay.iroh.network./")), relay_latency: RelayLatencies({RelayUrl("https://euw1-1.relay.iroh.network./"): 7.905681ms, RelayUrl("https://use1-1.relay.iroh.network./"): 96.510426ms}), relay_v4_latency: RelayLatencies({RelayUrl("https://euw1-1.relay.iroh.network./"): 11.339468ms, RelayUrl("https://use1-1.relay.iroh.network./"): 107.072566ms}), relay_v6_latency: RelayLatencies({RelayUrl("https://euw1-1.relay.iroh.network./"): 7.905681ms, RelayUrl("https://use1-1.relay.iroh.network./"): 96.510426ms}), global_v4: Some(5.9.119.203:42386), global_v6: Some([2a01:4f8:162:64cd::2]:42387), captive_portal: None }
2024-07-01T11:57:22.139817Z  INFO magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: home is now relay https://euw1-1.relay.iroh.network./, was None
2024-07-01T11:57:22.140561Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: scheduling periodic_stun to run in 24s
2024-07-01T11:57:22.140867Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: endpoint update done (periodic)
2024-07-01T11:57:22.141493Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: iroh_net::discovery::pkarr_publish: Publish node info to pkarr (info changed)
2024-07-01T11:57:22.141820Z  INFO pkarr_publish{me=l76fmx76dtkuy6yf}: iroh_net::discovery::pkarr_publish: Publish node info to pkarr relay_url=Some("https://euw1-1.relay.iroh.network./")
2024-07-01T11:57:22.146405Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: reqwest::connect: starting new connection: https://dns.iroh.link/    
2024-07-01T11:57:22.146927Z DEBUG hyper_util::client::legacy::connect::dns: resolving host="dns.iroh.link"
2024-07-01T11:57:22.148013Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://euw1-1.relay.iroh.network./ for peer None
2024-07-01T11:57:22.148365Z  INFO magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor: iroh_net::magicsock::relay_actor: adding connection to relay: https://euw1-1.relay.iroh.network./ for home-keep-alive
2024-07-01T11:57:22.150139Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor: iroh_net::magicsock::relay_actor: 1 active relay conns: relay-https://euw1-1.relay.iroh.network./
2024-07-01T11:57:22.150806Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client: iroh_net::relay::http::client: connect: initial connect, current client false
2024-07-01T11:57:22.151444Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: dial url self.url=https://euw1-1.relay.iroh.network./
2024-07-01T11:57:22.152922Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: connecting to [2a01:4f8:1c1b:58b6::1]:443
2024-07-01T11:57:22.153754Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:active-relay{url=https://euw1-1.relay.iroh.network./}: iroh_net::magicsock::relay_actor: initial dial https://euw1-1.relay.iroh.network./
2024-07-01T11:57:22.154371Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: hyper_util::client::legacy::connect::http: connecting to 49.13.207.244:443
2024-07-01T11:57:22.155168Z DEBUG iroh_net::magicsock: endpoints changed: 5.9.119.203:42386 (stun), [2a01:4f8:162:64cd::2]:42387 (stun), 172.17.0.1:42386 (local)
2024-07-01T11:57:22.833210Z DEBUG iroh_docs::store::fs::migrations: Start migration migration_001_populate_latest_table
2024-07-01T11:57:22.834021Z DEBUG iroh_docs::store::fs::migrations: Skip migration migration_001_populate_latest_table: Not needed
2024-07-01T11:57:22.834422Z DEBUG iroh_docs::store::fs::migrations: Start migration migration_002_namespaces_populate_v2
2024-07-01T11:57:22.835143Z DEBUG iroh_docs::store::fs::migrations: Skip migration migration_002_namespaces_populate_v2: Not needed
2024-07-01T11:57:22.835504Z DEBUG iroh_docs::store::fs::migrations: Start migration migration_003_namespaces_delete_v1
2024-07-01T11:57:22.836123Z DEBUG iroh_docs::store::fs::migrations: Skip migration migration_003_namespaces_delete_v1: Not needed
2024-07-01T11:57:22.836479Z DEBUG iroh_docs::store::fs::migrations: Start migration migration_004_populate_by_key_index
2024-07-01T11:57:22.837774Z  INFO iroh_docs::store::fs::migrations: Executed migration migration_004_populate_by_key_index (0 rows affected)
2024-07-01T11:57:22.842358Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: TCP stream connected server_addr=Ok([2a01:4f8:1c1b:58b6::1]:443) local_addr=[2a01:4f8:162:64cd::2]:41320
2024-07-01T11:57:22.843093Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: Starting TLS handshake
2024-07-01T11:57:22.843843Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: rustls::client::hs: No cached session for DnsName("euw1-1.relay.iroh.network.")    
2024-07-01T11:57:22.846713Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: rustls::client::hs: Not resuming any session    
2024-07-01T11:57:22.848381Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: hyper_util::client::legacy::connect::http: connected to 49.13.207.244:443
2024-07-01T11:57:22.848963Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: rustls::client::hs: No cached session for DnsName("dns.iroh.link")    
2024-07-01T11:57:22.851648Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: rustls::client::hs: Not resuming any session    
2024-07-01T11:57:22.853746Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service:portmapper.probe: iroh_net::portmapper::upnp: upnp probe failed: IO error: search timed out
2024-07-01T11:57:22.854769Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service:portmapper.probe: iroh_net::portmapper::nat_pmp: probe failed: deadline has elapsed
2024-07-01T11:57:22.855705Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service:portmapper.probe: iroh_net::portmapper::pcp: probe failed: deadline has elapsed
2024-07-01T11:57:22.857067Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:portmapper.service: iroh_net::portmapper: failed to get a port mapping IO error: search timed out
2024-07-01T11:57:22.858515Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
2024-07-01T11:57:22.859145Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: rustls::client::tls13: Not resuming    
2024-07-01T11:57:22.862772Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck]    
2024-07-01T11:57:22.863395Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: rustls::client::hs: ALPN protocol is None    
2024-07-01T11:57:22.884356Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: tls_connector connect success
2024-07-01T11:57:22.885149Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: Sending upgrade request
2024-07-01T11:57:22.886305Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
2024-07-01T11:57:22.886776Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: rustls::client::tls13: Not resuming    
2024-07-01T11:57:22.889922Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck]    
2024-07-01T11:57:22.890381Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: rustls::client::hs: ALPN protocol is None    
2024-07-01T11:57:22.911418Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect:http-driver: iroh_net::relay::http::client: HTTP upgrade driver started
Iroh is running
Node ID: l76fmx76dtkuy6yf3ctty3exo5fzajfpkm5wqt6edla4ernjbisa

2024-07-01T11:57:22.919081Z DEBUG node{me=l76fmx76dtkuy6yf}: iroh::node: listening at: 0.0.0.0:42386 and [::]:42387
2024-07-01T11:57:22.919510Z DEBUG node{me=l76fmx76dtkuy6yf}: iroh::node: rpc listening at: [Socket(127.0.0.1:35870)]
2024-07-01T11:57:22.920185Z DEBUG node{me=l76fmx76dtkuy6yf}: iroh::node: gossip initial update: [DirectAddr { addr: 5.9.119.203:42386, typ: Stun }, DirectAddr { addr: [2a01:4f8:162:64cd::2]:42387, typ: Stun }, DirectAddr { addr: 172.17.0.1:42386, typ: Local }] me=PublicKey(l76fmx76dtkuy6yf)
2024-07-01T11:57:22.921407Z DEBUG gossip{me=l76fmx76dtkuy6yf}: iroh_gossip::net: handle in_event  UpdatePeerData(PeerData(74b))
2024-07-01T11:57:22.922417Z DEBUG gossip{me=l76fmx76dtkuy6yf}: iroh_gossip::net: handle in_event  UpdatePeerData(PeerData(74b))
2024-07-01T11:57:22.961158Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect:http-driver: iroh_net::relay::http::client: HTTP upgrade driver finished
2024-07-01T11:57:22.963693Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: starting upgrade
2024-07-01T11:57:22.964068Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::http::client: connection upgraded
2024-07-01T11:57:22.964421Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::client: server_handshake: started
2024-07-01T11:57:22.964708Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::client: server_handshake: sending client_key: ClientInfo { version: 3 }
2024-07-01T11:57:22.967524Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client:connect: iroh_net::relay::client: server_handshake: done
2024-07-01T11:57:22.968480Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor:client: iroh_net::relay::http::client: connect: actor msg, current client true
2024-07-01T11:57:22.969420Z DEBUG pkarr_publish{me=l76fmx76dtkuy6yf}: hyper_util::client::legacy::pool: pooling idle connection for ("https", dns.iroh.link)
2024-07-01T11:57:23.742403Z  WARN pkarr_publish{me=l76fmx76dtkuy6yf}: iroh_net::discovery::pkarr_publish: Failed to publish to pkarr err=Publish request failed with status 429 Too Many Requests

Stack backtrace:
   0: anyhow::kind::Adhoc::new
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.86/src/backtrace.rs:27:14
   1: iroh_net::discovery::pkarr_publish::PkarrRelayClient::publish::{{closure}}
             at /root/actions-runner/_work/iroh/iroh/iroh-net/src/discovery/pkarr_publish.rs:208:13
   2: iroh_net::discovery::pkarr_publish::PublisherService::publish_current::{{closure}}
             at /root/actions-runner/_work/iroh/iroh/iroh-net/src/discovery/pkarr_publish.rs:172:51
   3: iroh_net::discovery::pkarr_publish::PublisherService::run::{{closure}}
             at /root/actions-runner/_work/iroh/iroh/iroh-net/src/discovery/pkarr_publish.rs:137:62
   4: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9
   5: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/core.rs:328:17
   6: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/loom/std/unsafe_cell.rs:16:9
   7: tokio::runtime::task::core::Core<T,S>::poll
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/core.rs:317:13
   8: tokio::runtime::task::harness::poll_future::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:485:19
   9: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panic/unwind_safe.rs:272:9
  10: std::panicking::try::do_call
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  11: __rust_try
  12: std::panicking::try
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  13: std::panic::catch_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  14: tokio::runtime::task::harness::poll_future
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:473:18
  15: tokio::runtime::task::harness::Harness<T,S>::poll_inner
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:208:27
  16: tokio::runtime::task::harness::Harness<T,S>::poll
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:153:15
  17: tokio::runtime::task::raw::poll
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/raw.rs:271:5
  18: tokio::runtime::task::raw::RawTask::poll
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/raw.rs:201:18
  19: tokio::runtime::task::LocalNotified<S>::run
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/mod.rs:427:9
  20: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:700:25
  21: tokio::runtime::coop::with_budget
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:107:5
  22: tokio::runtime::coop::budget
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:73:5
  23: tokio::runtime::scheduler::current_thread::Context::run_task::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:343:43
  24: tokio::runtime::scheduler::current_thread::Context::enter
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:404:19
  25: tokio::runtime::scheduler::current_thread::Context::run_task
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:343:23
  26: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:699:35
  27: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:68
  28: tokio::runtime::context::scoped::Scoped<T>::set
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/scoped.rs:40:9
  29: tokio::runtime::context::set_scheduler::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context.rs:176:26
  30: std::thread::local::LocalKey<T>::try_with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:286:12
  31: std::thread::local::LocalKey<T>::with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:262:9
  32: tokio::runtime::context::set_scheduler
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context.rs:176:9
  33: tokio::runtime::scheduler::current_thread::CoreGuard::enter
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:27
  34: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:646:19
  35: tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:175:28
  36: tokio::runtime::context::runtime::enter_runtime
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/runtime.rs:65:16
  37: tokio::runtime::scheduler::current_thread::CurrentThread::block_on
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:167:9
  38: tokio::runtime::runtime::Runtime::block_on
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/runtime.rs:349:47
  39: iroh::commands::start::tests::test_run_rpc_lock_file
             at ./src/commands/start.rs:259:9
  40: iroh::commands::start::tests::test_run_rpc_lock_file::{{closure}}
             at ./src/commands/start.rs:192:42
  41: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  42: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  43: test::__rust_begin_short_backtrace
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:623:18
  44: test::run_test_in_process::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:646:60
  45: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panic/unwind_safe.rs:272:9
  46: std::panicking::try::do_call
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  47: std::panicking::try
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  48: std::panic::catch_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  49: test::run_test_in_process
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:646:27
  50: test::run_test::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:569:43
  51: test::run_test::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:597:41
  52: std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:155:18
  53: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/mod.rs:542:17
  54: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panic/unwind_safe.rs:272:9
  55: std::panicking::try::do_call
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  56: std::panicking::try
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  57: std::panic::catch_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  58: std::thread::Builder::spawn_unchecked_::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/mod.rs:541:30
  59: core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  60: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/alloc/src/boxed.rs:2022:9
  61: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/alloc/src/boxed.rs:2022:9
  62: std::sys::pal::unix::thread::Thread::new::thread_start
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys/pal/unix/thread.rs:108:17
  63: <unknown>
  64: <unknown> url=https://dns.iroh.link/pkarr
2024-07-01T11:57:23.745486Z DEBUG node{me=l76fmx76dtkuy6yf}: iroh_net::endpoint: Closing connections
2024-07-01T11:57:23.745781Z DEBUG node{me=l76fmx76dtkuy6yf}: iroh_net::endpoint: Connections closed
2024-07-01T11:57:23.746679Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: shutting down
2024-07-01T11:57:23.747046Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: known nodes persisted count=0
2024-07-01T11:57:23.747363Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: stopping connections
2024-07-01T11:57:23.747580Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:actor: iroh_net::magicsock: shutdown complete
2024-07-01T11:57:23.748153Z  WARN iroh::node: failed to retrieve local endpoints
2024-07-01T11:57:23.748927Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor: iroh_net::magicsock::relay_actor: closing connection: conn-close url=https://euw1-1.relay.iroh.network./
2024-07-01T11:57:23.749259Z DEBUG sync{me=l76fmx76dtkuy6yf}: iroh_docs::actor: docs actor shutdown
2024-07-01T11:57:23.749282Z DEBUG magic_ep{me=l76fmx76dtkuy6yf}:magicsock{me=l76fmx76dtkuy6yf}:relay-actor: iroh_net::magicsock::relay_actor: 0 active relay conns
2024-07-01T11:57:23.981036Z DEBUG iroh_blobs::store::fs: redb actor done
2024-07-01T11:57:24.004952Z DEBUG node{me=l76fmx76dtkuy6yf}: quic_rpc::transport::quinn: Dropping server endpoint
2024-07-01T11:57:24.006281Z DEBUG downloader{me=l76fmx76dtkuy6yf}: iroh_blobs::downloader: shutting down
Error: First `run_with_command` never closed

Stack backtrace:
   0: anyhow::error::<impl anyhow::Error>::msg
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.86/src/backtrace.rs:27:14
   1: anyhow::__private::format_err
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.86/src/lib.rs:689:13
   2: iroh::commands::start::tests::test_run_rpc_lock_file::{{closure}}
             at ./src/commands/start.rs:263:13
   3: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/future/future.rs:123:9
   4: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/future/future.rs:123:9
   5: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:659:57
   6: tokio::runtime::coop::with_budget
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:107:5
   7: tokio::runtime::coop::budget
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:73:5
   8: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:659:25
   9: tokio::runtime::scheduler::current_thread::Context::enter
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:404:19
  10: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:658:36
  11: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:68
  12: tokio::runtime::context::scoped::Scoped<T>::set
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/scoped.rs:40:9
  13: tokio::runtime::context::set_scheduler::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context.rs:176:26
  14: std::thread::local::LocalKey<T>::try_with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:286:12
  15: std::thread::local::LocalKey<T>::with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:262:9
  16: tokio::runtime::context::set_scheduler
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context.rs:176:9
  17: tokio::runtime::scheduler::current_thread::CoreGuard::enter
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:27
  18: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:646:19
  19: tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}}
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:175:28
  20: tokio::runtime::context::runtime::enter_runtime
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/runtime.rs:65:16
  21: tokio::runtime::scheduler::current_thread::CurrentThread::block_on
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:167:9
  22: tokio::runtime::runtime::Runtime::block_on
             at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/runtime.rs:349:47
  23: iroh::commands::start::tests::test_run_rpc_lock_file
             at ./src/commands/start.rs:259:9
  24: iroh::commands::start::tests::test_run_rpc_lock_file::{{closure}}
             at ./src/commands/start.rs:192:42
  25: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  26: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  27: test::__rust_begin_short_backtrace
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:623:18
  28: test::run_test_in_process::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:646:60
  29: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panic/unwind_safe.rs:272:9
  30: std::panicking::try::do_call
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  31: std::panicking::try
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  32: std::panic::catch_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  33: test::run_test_in_process
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:646:27
  34: test::run_test::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:569:43
  35: test::run_test::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/test/src/lib.rs:597:41
  36: std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:155:18
  37: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/mod.rs:542:17
  38: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panic/unwind_safe.rs:272:9
  39: std::panicking::try::do_call
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  40: std::panicking::try
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  41: std::panic::catch_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  42: std::thread::Builder::spawn_unchecked_::{{closure}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/mod.rs:541:30
  43: core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  44: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/alloc/src/boxed.rs:2022:9
  45: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/alloc/src/boxed.rs:2022:9
  46: std::sys::pal::unix::thread::Thread::new::thread_start
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys/pal/unix/thread.rs:108:17
  47: <unknown>
  48: <unknown>
dignifiedquire commented 2 months ago

duplicate of #2437