Skip to content

Intermittent failure in test_extend_ntor

Hi! I've started seeing this test failure recently:

Could it be due to any recent conflux-related changes? I don't know what else has been touching the relevant code.

cc @gabi-250

        FAIL [   0.039s] tor-proto tunnel::circuit::test::test_extend_ntor
  stdout ───

    running 1 test
    2025-05-20T13:10:14.018116Z TRACE tor_proto::channel::reactor: UniqId(0): Running reactor
    2025-05-20T13:10:14.018548Z TRACE tor_proto::tunnel::reactor: Circ 23.17: Running circuit reactor
    2025-05-20T13:10:14.019520Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received AddFakeHop { relay_cell_format: V0, fwd_lasthop: false, rev_lasthop: false, params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.019609Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received AddFakeHop { relay_cell_format: V0, fwd_lasthop: true, rev_lasthop: true, params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.019796Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received ExtendNtor { peer_id: OwnedChanTarget { addrs: [], method: Direct([]), ids: RelayIds { ed_identity: Some(Ed25519Identity { BgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgY }), rsa_identity: Some(RsaIdentity { $0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a }) } }, public_key: NtorPublicKey { id: RsaIdentity { $0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a }, pk: PublicKey(PublicKey(MontgomeryPoint([57, 92, 178, 107, 131, 179, 205, 75, 145, 219, 169, 145, 62, 86, 42, 232, 125, 33, 236, 221, 86, 132, 61, 167, 202, 147, 154, 106, 105, 0, 18, 83]))) }, linkspecs: [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }], params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.019971Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Extending circuit to hop 4 with [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }]
    2025-05-20T13:10:14.019982Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: waiting for EXTENDED2 cell
    2025-05-20T13:10:14.019989Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: sending relay cell: RelayMsgOuter { streamid: None, msg: Extend2(Extend2 { linkspec: [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }], handshake_type: HandshakeType(NTOR), handshake: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 57, 92, 178, 107, 131, 179, 205, 75, 145, 219, 169, 145, 62, 86, 42, 232, 125, 33, 236, 221, 86, 132, 61, 167, 202, 147, 154, 106, 105, 0, 18, 83, 245, 38, 196, 186, 29, 62, 14, 17, 225, 176, 135, 138, 252, 209, 237, 236, 43, 211, 105, 84, 141, 119, 13, 236, 134, 143, 108, 199, 93, 142, 248, 96] }) }
    2025-05-20T13:10:14.020040Z TRACE tor_proto::channel: Chan 0: Sending RELAY_EARLY for 128
      Using RNG seed ARTI_TEST_PRNG=003d422a944a2d1041a51a55f966774a4bfdb83ee784956cafe1ea7517bf2a32
      Using RNG seed ARTI_TEST_PRNG=f4e2f3a6906ca181c44baef4ebdd41ebd2fc3da4e105760e404d981596fbe2b4
    2025-05-20T13:10:14.021173Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: handling cell: Relay(Relay { body: .. })
    2025-05-20T13:10:14.021194Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: Received meta-cell UnparsedRelayMsg { internal: V0([15, 0, 0, 0, 0, 0, 0, 0, 0, 0, 66, 0, 64, 192, 94, 22, 58, 79, 176, 140, 126, 171, 56, 160, 236, 230, 54, 188, 244, 234, 162, 45, 173, 6, 82, 240, 37, 238, 60, 103, 127, 155, 57, 116, 63, 170, 35, 43, 70, 143, 228, 229, 21, 79, 25, 169, 191, 254, 40, 252, 125, 60, 123, 48, 227, 154, 64, 31, 91, 170, 115, 100, 254, 117, 51, 46, 111, 0, 0, 0, 0, 215, 176, 249, 9, 160, 43, 204, 19, 77, 3, 202, 62, 150, 128, 89, 160, 96, 215, 36, 237, 75, 64, 168, 66, 228, 228, 187, 127, 118, 1, 142, 169, 146, 217, 238, 47, 11, 211, 45, 238, 149, 127, 24, 41, 173, 106, 61, 243, 94, 238, 137, 145, 49, 52, 25, 145, 199, 2, 10, 199, 13, 100, 2, 234, 43, 120, 38, 107, 157, 2, 16, 130, 227, 137, 33, 10, 150, 55, 226, 103, 20, 235, 49, 210, 81, 162, 48, 125, 229, 199, 91, 36, 25, 76, 146, 159, 158, 74, 232, 176, 51, 242, 143, 172, 116, 94, 224, 147, 104, 75, 158, 9, 217, 166, 239, 121, 47, 56, 66, 148, 147, 160, 170, 219, 95, 162, 105, 44, 118, 156, 55, 135, 165, 166, 221, 175, 246, 83, 23, 193, 107, 218, 215, 34, 220, 182, 143, 218, 121, 203, 160, 105, 148, 145, 68, 36, 125, 223, 194, 175, 160, 143, 167, 126, 20, 214, 171, 120, 62, 205, 124, 190, 46, 132, 118, 97, 87, 173, 0, 75, 9, 89, 244, 196, 26, 227, 41, 37, 37, 125, 67, 20, 231, 116, 73, 56, 177, 222, 125, 177, 20, 179, 58, 36, 47, 51, 199, 150, 198, 246, 74, 102, 91, 205, 79, 165, 49, 135, 97, 142, 208, 141, 118, 201, 206, 59, 171, 50, 126, 42, 131, 223, 163, 231, 134, 58, 80, 118, 158, 106, 7, 139, 238, 95, 186, 88, 76, 9, 164, 77, 241, 180, 73, 103, 220, 64, 195, 71, 94, 124, 237, 65, 133, 112, 123, 186, 1, 160, 188, 131, 210, 23, 241, 151, 6, 114, 122, 11, 83, 62, 200, 87, 175, 38, 164, 145, 137, 42, 70, 84, 33, 153, 125, 123, 185, 8, 17, 202, 58, 115, 188, 251, 5, 175, 10, 100, 207, 214, 163, 236, 101, 112, 205, 166, 241, 214, 230, 106, 197, 83, 143, 229, 127, 51, 82, 175, 107, 240, 187, 78, 247, 169, 101, 79, 12, 143, 102, 8, 84, 62, 103, 122, 250, 75, 238, 10, 227, 124, 113, 101, 175, 49, 51, 134, 110, 80, 223, 171, 95, 188, 220, 192, 57, 1, 116, 95, 248, 213, 209, 57, 164, 93, 234, 153, 136, 243, 25, 147, 198, 48, 195, 144, 229, 90, 87, 56, 195, 191, 98, 179, 254, 240, 4, 124, 54, 79, 70, 51, 227, 169, 159, 232, 189, 8, 240, 215, 16, 84, 241, 219, 184, 134, 19, 201, 155, 49, 172, 249, 116, 36, 68, 249, 61, 171, 72, 168, 1, 131]) }
    2025-05-20T13:10:14.021222Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Received EXTENDED2 cell; completing handshake.
    2025-05-20T13:10:14.023065Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Handshake complete; circuit extended.
    2025-05-20T13:10:14.023104Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: meta handler completed with result: Ok(ConversationFinished)
    2025-05-20T13:10:14.023614Z TRACE tor_proto::tunnel::reactor: Circ 23.17: reactor shutdown due to command channel drop
    2025-05-20T13:10:14.023629Z TRACE tor_proto::tunnel::reactor: Circ 23.17: Circuit reactor stopped: Ok(())
    2025-05-20T13:10:14.023691Z DEBUG tor_proto::channel::reactor: UniqId(0): Reactor stopped: Ok(())
    2025-05-20T13:10:14.025234Z TRACE tor_proto::channel::reactor: UniqId(1): Running reactor
    2025-05-20T13:10:14.025282Z TRACE tor_proto::tunnel::reactor: Circ 23.17: Running circuit reactor
    2025-05-20T13:10:14.025751Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received AddFakeHop { relay_cell_format: V0, fwd_lasthop: false, rev_lasthop: false, params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.025927Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received AddFakeHop { relay_cell_format: V0, fwd_lasthop: true, rev_lasthop: true, params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.026642Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received ExtendNtor { peer_id: OwnedChanTarget { addrs: [], method: Direct([]), ids: RelayIds { ed_identity: Some(Ed25519Identity { BgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgY }), rsa_identity: Some(RsaIdentity { $0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a }) } }, public_key: NtorPublicKey { id: RsaIdentity { $0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a }, pk: PublicKey(PublicKey(MontgomeryPoint([57, 92, 178, 107, 131, 179, 205, 75, 145, 219, 169, 145, 62, 86, 42, 232, 125, 33, 236, 221, 86, 132, 61, 167, 202, 147, 154, 106, 105, 0, 18, 83]))) }, linkspecs: [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }], params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.026817Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Extending circuit to hop 4 with [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }]
    2025-05-20T13:10:14.026830Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: waiting for EXTENDED2 cell
    2025-05-20T13:10:14.026838Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: sending relay cell: RelayMsgOuter { streamid: None, msg: Extend2(Extend2 { linkspec: [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }], handshake_type: HandshakeType(NTOR), handshake: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 57, 92, 178, 107, 131, 179, 205, 75, 145, 219, 169, 145, 62, 86, 42, 232, 125, 33, 236, 221, 86, 132, 61, 167, 202, 147, 154, 106, 105, 0, 18, 83, 233, 115, 20, 215, 160, 232, 130, 95, 92, 159, 202, 240, 120, 3, 94, 161, 35, 33, 54, 172, 206, 156, 71, 249, 133, 186, 132, 109, 234, 165, 41, 54] }) }
    2025-05-20T13:10:14.026887Z TRACE tor_proto::channel: Chan 1: Sending RELAY_EARLY for 128
      Using RNG seed ARTI_TEST_PRNG=5349fa9c6ed79e47b0f4b5e96e2235448396b63de76bc69b803c7a43f9459567
      Using RNG seed ARTI_TEST_PRNG=7d12f6d395c0ca7a24ccae23638c9f4d20ce6013998ca88edff3e5ce0df6ed20
    2025-05-20T13:10:14.028020Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: handling cell: Relay(Relay { body: .. })
    2025-05-20T13:10:14.028040Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: Received meta-cell UnparsedRelayMsg { internal: V0([15, 0, 0, 0, 0, 0, 0, 0, 0, 0, 66, 0, 64, 183, 167, 45, 1, 206, 245, 47, 171, 161, 176, 140, 194, 102, 223, 82, 138, 14, 98, 162, 145, 88, 77, 36, 24, 83, 124, 222, 119, 156, 53, 168, 49, 146, 27, 214, 130, 235, 17, 196, 167, 212, 175, 159, 162, 146, 98, 242, 247, 194, 190, 87, 218, 255, 50, 28, 213, 38, 175, 145, 144, 131, 62, 151, 128, 0, 0, 0, 0, 135, 161, 196, 138, 195, 35, 23, 184, 50, 10, 130, 98, 200, 116, 192, 16, 226, 80, 94, 196, 135, 50, 160, 157, 224, 176, 9, 156, 163, 35, 130, 12, 16, 165, 96, 107, 193, 166, 219, 16, 25, 39, 234, 112, 17, 97, 219, 9, 219, 192, 110, 135, 118, 204, 131, 246, 86, 79, 30, 119, 154, 151, 104, 229, 93, 195, 5, 209, 142, 216, 38, 177, 197, 163, 131, 209, 77, 250, 48, 189, 229, 79, 182, 80, 210, 130, 251, 49, 148, 1, 130, 133, 6, 90, 95, 160, 241, 175, 192, 4, 144, 226, 0, 79, 62, 125, 1, 159, 207, 249, 60, 159, 88, 252, 31, 32, 65, 57, 116, 224, 172, 199, 64, 45, 234, 219, 75, 214, 166, 174, 34, 12, 148, 158, 211, 114, 182, 248, 189, 163, 26, 87, 233, 36, 232, 20, 237, 22, 89, 83, 167, 48, 133, 146, 253, 54, 251, 78, 23, 187, 249, 204, 190, 160, 193, 213, 30, 235, 236, 212, 166, 137, 41, 148, 248, 6, 184, 240, 250, 79, 100, 101, 125, 46, 226, 191, 198, 46, 74, 221, 144, 216, 252, 223, 35, 105, 219, 253, 144, 47, 26, 196, 126, 76, 135, 30, 227, 44, 236, 203, 76, 205, 85, 156, 165, 34, 248, 235, 106, 230, 248, 105, 177, 255, 67, 116, 100, 138, 55, 243, 240, 155, 52, 71, 20, 142, 173, 118, 234, 128, 242, 187, 61, 86, 237, 232, 1, 191, 193, 41, 64, 179, 62, 44, 197, 55, 36, 178, 148, 246, 20, 206, 137, 26, 60, 133, 170, 21, 78, 63, 145, 170, 142, 219, 74, 254, 166, 142, 122, 40, 1, 39, 97, 102, 217, 70, 109, 179, 4, 16, 154, 96, 38, 63, 177, 253, 114, 81, 79, 150, 43, 229, 99, 245, 98, 193, 51, 160, 234, 115, 164, 174, 5, 15, 119, 197, 105, 163, 38, 33, 214, 223, 35, 52, 131, 77, 113, 126, 67, 110, 25, 192, 75, 21, 123, 89, 36, 35, 151, 1, 160, 40, 106, 188, 235, 249, 149, 117, 79, 71, 62, 222, 110, 141, 251, 102, 76, 158, 154, 241, 125, 224, 123, 215, 1, 22, 54, 237, 207, 28, 230, 112, 151, 115, 126, 127, 183, 170, 108, 184, 78, 28, 194, 98, 29, 209, 187, 187, 128, 25, 63, 36, 110, 48, 54, 110, 13, 182, 103, 200, 36, 213, 178, 142, 156, 6, 78, 101, 69, 245, 151, 18, 205, 121, 219, 123, 42, 218, 2, 245, 203, 22, 147, 251, 83, 146, 162, 248]) }
    2025-05-20T13:10:14.028069Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Received EXTENDED2 cell; completing handshake.
    2025-05-20T13:10:14.028883Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Handshake complete; circuit extended.
    2025-05-20T13:10:14.028910Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: meta handler completed with result: Ok(ConversationFinished)
    2025-05-20T13:10:14.029161Z TRACE tor_proto::tunnel::reactor: Circ 23.17: Circuit reactor stopped: Ok(())
    2025-05-20T13:10:14.029194Z DEBUG tor_proto::channel::reactor: UniqId(1): Reactor stopped: Ok(())
    2025-05-20T13:10:14.030390Z TRACE tor_proto::channel::reactor: UniqId(2): Running reactor
    2025-05-20T13:10:14.030432Z TRACE tor_proto::tunnel::reactor: Circ 23.17: Running circuit reactor
    2025-05-20T13:10:14.031019Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received AddFakeHop { relay_cell_format: V0, fwd_lasthop: false, rev_lasthop: false, params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.031105Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received AddFakeHop { relay_cell_format: V0, fwd_lasthop: true, rev_lasthop: true, params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.032463Z TRACE tor_proto::tunnel::reactor::control: Circ 23.17: reactor received ExtendNtor { peer_id: OwnedChanTarget { addrs: [], method: Direct([]), ids: RelayIds { ed_identity: Some(Ed25519Identity { BgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgYGBgY }), rsa_identity: Some(RsaIdentity { $0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a }) } }, public_key: NtorPublicKey { id: RsaIdentity { $0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a0a }, pk: PublicKey(PublicKey(MontgomeryPoint([57, 92, 178, 107, 131, 179, 205, 75, 145, 219, 169, 145, 62, 86, 42, 232, 125, 33, 236, 221, 86, 132, 61, 167, 202, 147, 154, 106, 105, 0, 18, 83]))) }, linkspecs: [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }], params: CircParameters { extend_by_ed25519_id: true, ccontrol: CongestionControlParams { alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), fallback_alg: FixedWindow(FixedWindowParams { circ_window_start: 1000, circ_window_min: 100, circ_window_max: 1000 }), cwnd_params: CongestionWindowParams { cwnd_init: 124, cwnd_inc_pct_ss: Percentage { value: 100 }, cwnd_inc: 1, cwnd_inc_rate: 31, cwnd_min: 124, cwnd_max: 4294967295, sendme_inc: 31 }, rtt_params: RoundTripEstimatorParams { ewma_cwnd_pct: Percentage { value: 50 }, ewma_max: 10, ewma_ss_max: 2, rtt_reset_pct: Percentage { value: 100 } } } }, done: Sender { complete: false } }
    2025-05-20T13:10:14.032672Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Extending circuit to hop 4 with [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }]
    2025-05-20T13:10:14.032681Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: waiting for EXTENDED2 cell
    2025-05-20T13:10:14.032688Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: sending relay cell: RelayMsgOuter { streamid: None, msg: Extend2(Extend2 { linkspec: [EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10] }, EncodedLinkSpec { lstype: LinkSpecType(ED25519ID), body: [6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6] }], handshake_type: HandshakeType(NTOR), handshake: [10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 10, 57, 92, 178, 107, 131, 179, 205, 75, 145, 219, 169, 145, 62, 86, 42, 232, 125, 33, 236, 221, 86, 132, 61, 167, 202, 147, 154, 106, 105, 0, 18, 83, 105, 151, 202, 1, 40, 166, 87, 76, 221, 49, 93, 21, 111, 194, 74, 36, 7, 60, 22, 234, 51, 229, 88, 107, 148, 61, 244, 21, 138, 116, 82, 50] }) }
    2025-05-20T13:10:14.032735Z TRACE tor_proto::channel: Chan 2: Sending RELAY_EARLY for 128
      Using RNG seed ARTI_TEST_PRNG=a361a446420ec650ffb1b157d4c303ccf9b2f54efd17f5d81b37cd6e2b52ce84
      Using RNG seed ARTI_TEST_PRNG=d415087cf93386f3f1fa536c4aaf97208808d3efa7f6e4b8146f6c54b00c59dc
    2025-05-20T13:10:14.033983Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: handling cell: Relay(Relay { body: .. })
    2025-05-20T13:10:14.034005Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: Received meta-cell UnparsedRelayMsg { internal: V0([15, 0, 0, 0, 0, 0, 0, 0, 0, 0, 66, 0, 64, 147, 212, 140, 49, 224, 214, 95, 217, 145, 124, 59, 76, 184, 4, 48, 158, 138, 230, 180, 104, 61, 156, 195, 77, 180, 207, 13, 48, 165, 248, 166, 66, 188, 96, 208, 28, 86, 122, 32, 141, 72, 169, 54, 5, 199, 151, 85, 7, 149, 149, 248, 4, 208, 150, 88, 57, 220, 100, 239, 176, 19, 162, 180, 183, 0, 0, 0, 0, 204, 197, 80, 97, 41, 113, 11, 190, 105, 129, 213, 123, 207, 29, 215, 72, 141, 161, 134, 74, 46, 232, 245, 198, 254, 84, 161, 199, 93, 130, 90, 227, 79, 246, 33, 61, 29, 151, 157, 65, 4, 23, 129, 139, 133, 125, 45, 227, 183, 7, 55, 161, 7, 105, 109, 243, 194, 131, 66, 69, 24, 222, 209, 193, 94, 84, 22, 97, 53, 132, 38, 195, 139, 133, 12, 45, 0, 44, 96, 125, 170, 23, 211, 198, 144, 131, 79, 198, 191, 2, 32, 36, 13, 2, 106, 209, 142, 28, 141, 11, 160, 233, 73, 43, 218, 77, 78, 143, 65, 234, 238, 153, 218, 155, 103, 37, 60, 212, 103, 114, 141, 185, 81, 219, 97, 16, 6, 91, 22, 201, 11, 233, 17, 166, 94, 181, 15, 122, 2, 31, 12, 124, 210, 68, 206, 34, 68, 193, 70, 98, 115, 31, 30, 114, 109, 103, 105, 12, 203, 148, 234, 177, 245, 107, 214, 223, 38, 50, 197, 143, 191, 88, 131, 42, 4, 194, 214, 37, 211, 181, 115, 11, 170, 93, 66, 195, 71, 67, 198, 165, 78, 159, 167, 209, 246, 6, 197, 132, 174, 126, 73, 216, 238, 152, 230, 248, 17, 210, 15, 68, 187, 5, 53, 48, 17, 138, 150, 70, 238, 38, 118, 78, 139, 212, 194, 232, 99, 137, 195, 161, 156, 147, 46, 12, 24, 30, 145, 241, 198, 112, 104, 255, 121, 228, 118, 190, 174, 68, 13, 155, 154, 214, 47, 75, 120, 34, 79, 1, 240, 29, 33, 44, 74, 218, 182, 41, 119, 120, 9, 121, 194, 206, 206, 69, 188, 213, 201, 71, 59, 91, 178, 50, 155, 103, 36, 154, 208, 217, 246, 31, 190, 73, 223, 7, 106, 130, 245, 92, 139, 254, 157, 108, 22, 101, 101, 189, 127, 126, 165, 184, 245, 29, 95, 117, 184, 2, 161, 123, 119, 247, 195, 55, 87, 165, 46, 241, 43, 26, 250, 248, 151, 190, 38, 144, 146, 59, 232, 5, 237, 225, 118, 82, 181, 207, 247, 53, 71, 162, 33, 53, 82, 195, 195, 124, 144, 130, 69, 244, 216, 29, 37, 213, 30, 145, 38, 86, 223, 43, 193, 200, 125, 209, 24, 200, 220, 31, 67, 236, 27, 45, 115, 177, 64, 253, 171, 176, 3, 33, 191, 217, 181, 20, 58, 237, 83, 201, 64, 21, 255, 14, 18, 152, 100, 220, 77, 6, 124, 239, 196, 152, 61, 146, 102, 179, 95, 145, 92, 173, 29, 249, 44, 200, 139, 87, 248, 204, 98, 37]) }
    2025-05-20T13:10:14.034036Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Received EXTENDED2 cell; completing handshake.
    2025-05-20T13:10:14.034831Z TRACE tor_proto::tunnel::reactor::circuit::extender: Circ 23.17: Handshake complete; circuit extended.
    2025-05-20T13:10:14.034858Z TRACE tor_proto::tunnel::reactor::circuit: Circ 23.17: meta handler completed with result: Ok(ConversationFinished)
    2025-05-20T13:10:14.035929Z TRACE tor_proto::tunnel::reactor: Circ 23.17: Circuit reactor stopped: Ok(())
    2025-05-20T13:10:14.035973Z DEBUG tor_proto::channel::reactor: UniqId(2): Reactor stopped: Ok(())
    test tunnel::circuit::test::test_extend_ntor ... FAILED

    failures:

    failures:
        tunnel::circuit::test::test_extend_ntor

    test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 171 filtered out; finished in 0.03s
    
  stderr ───

    thread 'tokio-runtime-worker' panicked at /home/nickm/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/blocking/shutdown.rs:51:21:
    Cannot drop a runtime in a context where blocking is not allowed. This happens when a runtime is dropped from within an asynchronous context.
    note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

    thread 'tokio-runtime-worker' panicked at /home/nickm/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.44.2/src/runtime/blocking/shutdown.rs:51:21:
    Cannot drop a runtime in a context where blocking is not allowed. This happens when a runtime is dropped from within an asynchronous context.

    thread 'tunnel::circuit::test::test_extend_ntor' panicked at crates/tor-proto/src/tunnel/circuit.rs:1802:34:
    called `Result::unwrap()` on an `Err` value: CircuitClosed

  Cancelling due to test failure: 23 tests still running