HsCircPool::take_or_launch_stub_circuit disregards the target if vanguards are enabled.

Spotted by accident while testing full vanguards in shadow (but full vanguards have nothing to do with the bug described here).

After adding a couple of extra hosts for a new shadow test, one of the existing tests started failing because its tgen process didn't exit as expected:

618990:00:06:50.991981 [4717:shadow-worker] 00:30:00.000000000 [ERROR] [torclient-onion-artiserver:11.0.0.19] [process.rs:1525] [shadow_rs::host::process] process 'torclient-onion-artiserver.tgen.1001' exited with status StoppedByShadow; expected end state was exited: 0 but was running

Note: torclient-onion-artiserver is a tor client that connects to the fileserver-onion-arti hidden service.

Judging from the fileserver-onion-arti logs, it looks like the arti svc is unable to extend a circuit to the rendezvous point:

2000-01-01T00:15:03Z TRACE tor_proto::channel: Circ 1.7: Allocated CircId 3139191491
...
2000-01-01T00:17:13Z TRACE tor_proto::channel: Circ 1.30: Allocated CircId 2632283112
...
2000-01-01T00:25:02Z WARN tor_hsservice::helpers: Problem while accepting rendezvous request: error: Could not connect rendezvous circuit.: Could not establish circuit to rendezvous point: Tried to Establish a circuit to a rendezvous point 2 times, but all attempts failed
Attempt 1: Problem building circuit 1.7, while extending to chosen HS hop: Circuit closed
Attempt 2: Problem building circuit 1.30, while extending to chosen HS hop: Circuit closed

(The rest of this analysis only talks about circuit 2632283112, but the situation with 3139191491 is exactly the same)

The lifetime of circ 1.30 (2632283112) is:

tests/shadow/shadow.data/hosts/fileserver-onion-arti/arti-extra.1001.stdout
2000-01-01T00:17:13Z TRACE tor_proto::channel: Circ 1.30: Allocated CircId 2632283112
2000-01-01T00:17:13Z TRACE tor_proto::channel: Chan 1: Sending CREATE2 for 2632283112 [11.0.0.15:9111 ed25519:Y38BKwdfGaHWb5umhl3JmD1N8s9VAPFmkKHg5em7m9c $3fb0bd7827c760fe7f9dd810fcb10322d63ab4cf]
2000-01-01T00:17:13Z TRACE tor_proto::circuit::reactor: Circ 1.30: Running circuit reactor
2000-01-01T00:17:13Z TRACE tor_proto::circuit::reactor: Circ 1.30: Extending to hop 1 with CREATE2
2000-01-01T00:17:13Z TRACE tor_proto::channel: Chan 1: Sending CREATE2 for 2632283112
2000-01-01T00:17:14Z TRACE tor_proto::channel::reactor: UniqId(1): received CREATED2 for 2632283112
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Handshake complete; circuit created.
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Extending circuit to hop 2 with [EncodedLinkSpec { lstype: LinkSpecType(ORPORT_V4), body: [11, 0, 0, 17, 35, 151] }, EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [59, 174, 172, 142, 36, 200, 123, 78, 83, 100, 132, 131, 123, 103, 150, 100, 135, 169, 50, 20] }]
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Extending circuit to hop 2 $3baeac8e24c87b4e536484837b67966487a93214
2000-01-01T00:17:14Z TRACE tor_proto::channel: Chan 1: Sending RELAY_EARLY for 2632283112
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: waiting for EXTENDED2 cell
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: handling cell: Relay(Relay { body: .. })
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Received EXTENDED2 cell; completing handshake.
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Handshake complete; circuit extended.
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Extending circuit to hop 3 with [EncodedLinkSpec { lstype: LinkSpecType(ORPORT_V4), body: [100, 0, 0, 1, 35, 151] }, EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [165, 44, 165, 181, 108, 100, 216, 100, 246, 174, 67, 229, 111, 41, 172, 189, 87, 6, 221, 161] }]
1272:2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Extending circuit to hop 3 $a52ca5b56c64d864f6ae43e56f29acbd5706dda1
2000-01-01T00:17:14Z TRACE tor_proto::channel: Chan 1: Sending RELAY_EARLY for 2632283112
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: waiting for EXTENDED2 cell
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: handling cell: Relay(Relay { body: .. })
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Received EXTENDED2 cell; completing handshake.
2000-01-01T00:17:14Z TRACE tor_proto::circuit::reactor: Circ 1.30: Handshake complete; circuit extended.
2000-01-01T00:25:01Z TRACE tor_proto::circuit::reactor: Circ 1.30: Extending circuit to hop 4 with [EncodedLinkSpec { lstype: LinkSpecType(ORPORT_V4), body: [100, 0, 0, 1, 35, 151] }, EncodedLinkSpec { lstype: LinkSpecType(RSAID), body: [165, 44, 165, 181, 108, 100, 216, 100, 246, 174, 67, 229, 111, 41, 172, 189, 87, 6, 221, 161] }]
1625:2000-01-01T00:25:01Z TRACE tor_proto::circuit::reactor: Circ 1.30: Extending circuit to hop 4 $a52ca5b56c64d864f6ae43e56f29acbd5706dda1
2000-01-01T00:25:01Z TRACE tor_proto::channel: Chan 1: Sending RELAY_EARLY for 2632283112
2000-01-01T00:25:01Z TRACE tor_proto::circuit::reactor: Circ 1.30: waiting for EXTENDED2 cell
2000-01-01T00:25:02Z TRACE tor_proto::channel::reactor: UniqId(1): received DESTROY for 2632283112
2000-01-01T00:25:02Z TRACE tor_proto::channel::reactor: UniqId(1): Passing destroy to open circuit 2632283112
2000-01-01T00:25:02Z TRACE tor_proto::circuit::reactor: Circ 1.30: handling cell: Destroy(Destroy { reason: DestroyReason(DESTROYED) })
2000-01-01T00:25:02Z DEBUG tor_proto::circuit::reactor: Circ 1.30: Received DESTROY cell. Reason: Circuit was destroyed without client truncate [DESTROYED]
2000-01-01T00:25:02Z TRACE tor_proto::circuit::reactor: Circ 1.30: reactor shutdown due to handled cell
2000-01-01T00:25:02Z TRACE tor_proto::circuit::reactor: Circ 1.30: Circuit reactor stopped: Ok(())
2000-01-01T00:25:02Z TRACE tor_proto::channel::reactor: UniqId(1): reactor received CloseCircuit(CircId(2632283112))
2000-01-01T00:25:02Z TRACE tor_proto::channel::reactor: UniqId(1): Circuit 2632283112 is gone; sending DESTROY

Grepping for the 2632283112 CircId shows relay1 is tearing down the circuit in response to the DESTROY received from the arti service.

tests/shadow/shadow.data/hosts/relay1/tor.1000.stdout
Jan 01 00:25:02.306 [info] command_process_destroy_cell(): unknown circuit 2632283112 on connection from 11.0.0.12:45084. Dropping.

(I added some extra log messages after the "Extending circuit to..." ones to print the RSA linkspecs as fingerprints)

Note: the circuit stub that ends up as a basis for the rend circuit consists of the following relays:

3fb0bd7827c760fe7f9dd810fcb10322d63ab4cf (relay1)
3baeac8e24c87b4e536484837b67966487a93214 (relay3)
a52ca5b56c64d864f6ae43e56f29acbd5706dda1 (4uthority)
a52ca5b56c64d864f6ae43e56f29acbd5706dda1 (4uthority)

This service uses lite vanguards, so the expected length of a service-side rendezvous stub circuit is 3 (G -> L2 -> M), where G = relay1, L2 = relay3, M = 4authority). The rendezvous point happens to be 4authority too.

In conclusion:

the final EXTEND sent by the arti service is trying to extend the circuit to a hop that is already part of the circuit (as the last hop), namely to the 4uthority relay. This is because 4authority is the rendezvous point. This EXTEND is expected to fail, because a relay won't extend the circuit to itself.
this behavior became apparent in an existing test, after I added a new test involving a hidden service that uses full vanguards

The fact that the stub circuit used by the service is incompatible with the 4uthority rendezvous point is a bug in the circuit selection logic from take_or_launch_stub_circuit. If vanguards are enabled, we disregard the circuit target (avoid_target) entirely, which is wrong: the correct thing to do here is to select a stub circuit where avoid_target doesn't occur as the last hop or the hop before the last, while disregarding the same-family/same-subnet restrictions that usually apply when building circuits.

Edited May 22, 2024 by gabi-250