Opened 2 years ago

Last modified 4 days ago

#21084 assigned defect

sometimes we call circuit has_opened() more than 2 times on client side

Reported by: s7r Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.3.0.1-alpha
Severity: Normal Keywords: tor-hs needs-insight needs-analysis
Cc: dgoulet Actual Points:
Parent ID: Points: 0.5
Reviewer: Sponsor:

Description

We have a branch bug15618_030-testing at https://gitweb.torproject.org/user/dgoulet/tor.git that logs a warning when we call more than 2 times circuit has_opened() on a circuit. The patch was made to confirm the theory on #15618 related to a warning we see on relays. While until now I never saw the warning on relay side, I see it quite often on client side.

Based on the log messages, I think this is related to introduction point circuits and not rendezvous circuits as we thought. Basically it happens when we open a 4 hop circuit with last hop X, and immediately we extend that circuit to a 5 hop one with last hop Y, where Y is (I think) the introduction point. I got the warning 2 times in a row and the similarity between them is that they are 5 hop circuits with the last two hops 4 and 5 the same, but different hops 2 and 3.

Dec 25 13:15:15.000 [info] internal circ (length 5, last hop $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7): $A7C411B809D0AA98C4264917BB701ABF17B2181E(open) $B5212DB685A2A0FCFBAE425738E478D12361710D(open) $123F403DA94A74F959B7FE0E5B27FA57EFA12925(open) $1F4105C688E835A56AF3D66C787677B57240FFA2(open) $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7(open)
Dec 25 13:15:15.000 [info] entry_guards_note_guard_success(): Recorded success for primary confirmed guard sakujakira ($A7C411B809D0AA98C4264917BB701ABF17B2181E)
Dec 25 13:15:15.000 [info] circuit_send_next_onion_skin(): circuit built!
Dec 25 13:15:15.000 [warn] BLAM. Circuit has_opened() called 3 times.
Dec 25 13:15:15.000 [info] rend_client_introcirc_has_opened(): introcirc is open
Dec 25 13:15:15.000 [info] connection_ap_handshake_attach_circuit(): pending-join circ 3419634369 already here, with intro ack. Stalling. (stream 26 sec old)
Dec 25 13:15:15.000 [info] connection_ap_handshake_attach_circuit(): ready rend circ 2404371907 already here (no intro-ack yet on intro 2259155742). (stream 26 sec old)
Dec 25 13:15:15.000 [info] connection_ap_handshake_attach_circuit(): found open intro circ 2259155742 (rend 2404371907); sending introduction. (stream 26 sec old)
Dec 25 13:15:15.000 [info] rend_client_send_introduction(): Sending an INTRODUCE1 cell
Dec 25 13:15:15.000 [info] pathbias_count_use_attempt(): Used circuit 53293 is already in path state use succeeded. Circuit is a Hidden service client: Pending rendezvous point currently open.
Dec 25 13:15:16.000 [info] internal circ (length 5, last hop $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7): $A7C411B809D0AA98C4264917BB701ABF17B2181E(open) $5C01D5518D1F5A071C6F07D1F4630F577AB5B60A(open) $DA9DA02A7B0565DF5F3E961CA911E750072DCBBD(open) $1F4105C688E835A56AF3D66C787677B57240FFA2(open) $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7(open)
Dec 25 13:15:16.000 [info] entry_guards_note_guard_success(): Recorded success for primary confirmed guard sakujakira ($A7C411B809D0AA98C4264917BB701ABF17B2181E)
Dec 25 13:15:16.000 [info] circuit_send_next_onion_skin(): circuit built!
Dec 25 13:15:16.000 [warn] BLAM. Circuit has_opened() called 3 times.
Dec 25 13:15:16.000 [info] rend_client_introcirc_has_opened(): introcirc is open
Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): pending-join circ 3419634369 already here, with intro ack. Stalling. (stream 26 sec old)
Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): Intro circ 2259155742 present and awaiting ack (rend 2404371907). Stalling. (stream 26 sec old)
Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): Intro circ 3200472182 present and awaiting ack (rend 4286776399). Stalling. (stream 26 sec old)
Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): ready rend circ 2334828448 already here (no intro-ack yet on intro 4002828471). (stream 27 sec old)
Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): found open intro circ 4002828471 (rend 2334828448); sending introduction. (stream 27 sec old)
Dec 25 13:15:16.000 [info] rend_client_send_introduction(): Sending an INTRODUCE1 cell
Dec 25 13:15:16.000 [info] pathbias_count_use_attempt(): Used circuit 53301 is already in path state use succeeded. Circuit is a Hidden service client: Pending rendezvous point currently open.

Child Tickets

Change History (13)

comment:1 Changed 2 years ago by nickm

Milestone: Tor: 0.3.0.x-final

comment:2 Changed 2 years ago by dgoulet

Status: newneeds_information

So intro points have this interesting behavior which is if you get a NACK client side, the client will reuse the circuit (a 3 hops circuit) and re-extend it to another intro point making the circuit 4 hops. It will do that until the circuit reaches its hard limit of 7 hops. But if this happens, you should see that log statement in your logs:

    log_info(LD_REND, "Got nack for %s from %s...",
        safe_str_client(rend_data_get_address(circ->rend_data)),
        safe_str_client(extend_info_describe(circ->build_state->chosen_exit)));

Else, I can see that it opens 2 times on a cannibalize circuit which is 3 hops and then extended to 4 hops. However, a 5 hops circuit, apart from the behavior described above, I'm not sure it's normal for both a service or client...?

comment:3 Changed 2 years ago by dgoulet

Owner: set to dgoulet
Status: needs_informationaccepted

comment:4 Changed 2 years ago by dgoulet

Status: acceptedneeds_information

comment:5 Changed 2 years ago by s7r

In that case, it should reuse the same circuit (a 3 hops circuit) and just re-extend it to another intro point, so the circuit path has to be exactly the same with just one hop added.

Above we have two different 5 hops circuits with different middle hops (2 and 3) but the same endpoints, for which circuit has_opened() was called 3 times. Since that log line is totally missing, the client may not have received a NACK. I am thinking of some weird race conditions, because we are only able to catch this behavior when quite a large amount of isolated requests are sent to the same hidden service in a very short period of time.

comment:6 in reply to:  5 Changed 2 years ago by dgoulet

Replying to s7r:

Above we have two different 5 hops circuits with different middle hops (2 and 3) but the same endpoints, for which circuit has_opened() was called 3 times. Since that log line is totally missing, the client may not have received a NACK. I am thinking of some weird race conditions, because we are only able to catch this behavior when quite a large amount of isolated requests are sent to the same hidden service in a very short period of time.

Is there a way you are able to learn the introduction point of the HS you are trying to reach.

I would bet that those two are IPs or at the very least the last one! :) If you can, listing the HSDir fp, the IPs fp and the RP fp would be useful so we can learn if those fingerprints that are both in two circuits of 5 hops are related to any entity of the HS dance. (I can help you with a patch to log those if you want.)

$1F4105C688E835A56AF3D66C787677B57240FFA2(open)
$D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7(open)

I bet you are right with this race here! Some circuit state could be wrong or updated to late. Figuring out if those two last hops are related to IPs would be very useful to narrow down our search.

comment:7 Changed 2 years ago by s7r

A patch that would log these would be awesome. Can you make it that it will log everything we need at warn level, because I have to send a large number of isolated requests in order to make it happen and it's hard to process the log at info or debug level. I guess we need the entire HS dance with full circuit paths (HSDir fetch, IP, rend).

comment:8 Changed 2 years ago by dgoulet

Status: needs_informationneeds_revision

comment:9 Changed 2 years ago by dgoulet

Milestone: Tor: 0.3.0.x-finalTor: 0.3.1.x-final

I owe you a patch s7r, it will come! I'm going to defer this to 031 because I'm not sure we'll have time to make it into 030. It doesn't seem to be something that breaks things or is dangerous for now. If we ever find out that it causes problems, we can consider it for a backport at that point.

comment:10 Changed 2 years ago by dgoulet

Points: 0.5

comment:11 Changed 2 years ago by dgoulet

Milestone: Tor: 0.3.1.x-finalTor: unspecified
Status: needs_revisionaccepted

I'm running an experiment to try to gather logs for this one with a very small patch I made. We'll see what I get but in the meantime deferring this one until we learn more.

comment:12 Changed 2 years ago by nickm

Cc: dgoulet added
Keywords: needs-insight needs-analysis added

comment:13 Changed 4 days ago by gaba

Owner: dgoulet deleted
Status: acceptedassigned

Releasing some old tickets.

Note: See TracTickets for help on using tickets.