Opened 4 months ago

Closed 8 weeks ago

#30942 closed defect (fixed)

[warn] Unexpected INTRODUCE_ACK on circuit 3944288021.

Reported by: arma Owned by:
Priority: Medium Milestone: Tor: 0.4.2.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-hs, tor-padding
Cc: mikeperry, asn, arma Actual Points:
Parent ID: Points: 0.2
Reviewer: dgoulet Sponsor:

Description

Running

Jun 19 01:26:41.987 [notice] Tor 0.4.2.0-alpha-dev (git-438b7eec856b0cac) running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1c, Zlib 1.2.11, Liblzma N/A, and Libzstd N/A.

Looking at my debug-level logs, here are some lines that look relevant:

Jun 20 14:42:15.423 [info] rend_client_introduction_acked(): Received ack. Telling rend circ...
Jun 20 14:42:15.423 [debug] circuit_change_purpose(): changing purpose of origin circ 87 from "Hidden service client: Pending rendezvous point" (10) to "Hidden service client: Pending rendezvous point (ack received)" (11)
Jun 20 14:42:15.423 [debug] circuit_change_purpose(): changing purpose of origin circ 88 from "Hidden service client: Waiting for ack from intro point" (7) to "Hidden service client: Received ack from intro point" (8)
Jun 20 14:42:15.423 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x562673bfdc90 for circ_id 2983373670, channel ID 29 (0x562674553c80)
Jun 20 14:42:15.423 [info] circuit_mark_for_close_(): Circuit 2983373670 (id: 88) marked for close at src/feature/rend/rendclient.c:418 (orig reason: 9, new reason: 0)
Jun 20 14:42:15.423 [info] rend_client_close_other_intros(): Closing introduction circuit 90 that we built in parallel (Purpose 7).
Jun 20 14:42:15.423 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x562673c1d930 for circ_id 3944288021, channel ID 29 (0x562674553c80)
Jun 20 14:42:15.423 [info] circpad_marked_circuit_for_padding(): Circuit 90 is not marked for close because of a  pending padding machine.
Jun 20 14:42:15.423 [debug] circuit_change_purpose(): changing purpose of origin circ 90 from "Hidden service client: Waiting for ack from intro point" (7) to "Circuit kept open for padding" (15)
[...]
Jun 20 14:42:15.470 [debug] connection_or_process_cells_from_inbuf(): 13: starting, inbuf_datalen 514 (0 pending in tls object).
Jun 20 14:42:15.470 [debug] channel_process_cell(): Processing incoming cell_t 0x7ffc169e5030 for channel 0x562674553c80 (global ID 29)
Jun 20 14:42:15.470 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x562673c1d930 for circ_id 3944288021, channel ID 29 (0x562674553c80)
Jun 20 14:42:15.470 [debug] circuit_receive_relay_cell(): Sending to origin.
Jun 20 14:42:15.470 [debug] connection_edge_process_relay_cell(): Now seen 205318 relay cells here (command 40, stream 0).
Jun 20 14:42:15.470 [warn] Unexpected INTRODUCE_ACK on circuit 3944288021.
Jun 20 14:42:15.470 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x562673c1d930 for circ_id 3944288021, channel ID 29 (0x562674553c80)
Jun 20 14:42:15.470 [info] pathbias_should_count(): Circuit 90 is not being counted by pathbias because it was ignored in the past. Purpose is Circuit kept open for padding, path state is new
Jun 20 14:42:15.471 [info] circuit_mark_for_close_(): Circuit 3944288021 (id: 90) marked for close at src/feature/hs/hs_client.c:1770 (orig reason: 1, new reason: 0)

I.e. it looks like we built two parallel intro circuits, one of them worked, so we closed the other, but we didn't actually close it, we put it into an "open for padding" state, and then the intro ack arrived on it after a while, which surprised us.

Child Tickets

Change History (21)

comment:1 Changed 4 months ago by dgoulet

Cc: mikeperry asn added
Keywords: tor-hs tor-padding added
Milestone: Tor: 0.4.2.x-final
Points: 0.2

Ahhh that re-purpose feature :) ... We'll have to build in a way to ignore any unrecognized cell on a "padding circuit" and not warn + close I believe...

comment:2 Changed 4 months ago by asn

Agreed. This seems to be what we need to do here.

comment:3 Changed 3 months ago by asn

Status: newneeds_review

Here is an attempt at this which I have not tested on the real network:
https://github.com/torproject/tor/pull/1187

Some refactoring had to take place for this change to be more easily reviewable and to reduce technical debt.

comment:4 Changed 3 months ago by dgoulet

Reviewer: dgoulet
Status: needs_reviewneeds_revision

One comment. Let me know if doable? Else the code flow does work.

comment:5 Changed 3 months ago by asn

Status: needs_revisionneeds_review

Hello, thanks for review! I had to rebase the branch because of some conflicts with practracker on master.
New PR is https://github.com/torproject/tor/pull/1189 and includes a fix to your comment above.

Let me know how you like that! :)

comment:6 Changed 3 months ago by dgoulet

Status: needs_reviewneeds_revision

Nice!

One LAST tiny thing: handle_relay_command(), maybe reflect that it is actually handling a relay cell so like handle_relay_cell_command()? In terms of semantic would be good in the code to pin in the name that the function is handling a cell as in taking a cell.

Agree or not, feel free to put in merge_ready after :).

comment:7 in reply to:  6 Changed 2 months ago by asn

Status: needs_revisionmerge_ready

Replying to dgoulet:

Nice!

One LAST tiny thing: handle_relay_command(), maybe reflect that it is actually handling a relay cell so like handle_relay_cell_command()? In terms of semantic would be good in the code to pin in the name that the function is handling a cell as in taking a cell.

Agree or not, feel free to put in merge_ready after :).

Done and pushed a new PR because there were conflicts with master due to the recent practracker improvements:
https://github.com/torproject/tor/pull/1197

Moving to merge_ready as requested.

comment:8 Changed 2 months ago by nickm

Should this be an 041 backport, or is it okay to have it in 0.4.2 only?

Last edited 2 months ago by nickm (previous) (diff)

comment:9 Changed 2 months ago by asn

Keywords: 041-backport? added

Hm, the bug (and any other related bugs) exist also in 041, so I guess there is a strong point for backporting this to 041. Still, I think the refactoring is a bit too complicated to go in 041, so I made a slimmer patch for 041: https://github.com/torproject/tor/pull/1198

Feel free to merge either approach to 041, since I think both will merge cleanly at this point.

comment:10 Changed 2 months ago by dgoulet

ACK on the backport branch.

comment:11 Changed 2 months ago by nickm

I've merged PR 1198 to both branches. Could I have a squashed version of 1197? It doesn't squash cleanly for me.

comment:12 in reply to:  11 Changed 2 months ago by asn

Replying to nickm:

I've merged PR 1198 to both branches. Could I have a squashed version of 1197? It doesn't squash cleanly for me.

Please see https://github.com/torproject/tor/pull/1202 .

Last edited 2 months ago by asn (previous) (diff)

comment:13 Changed 2 months ago by nickm

Milestone: Tor: 0.4.2.x-finalTor: 0.4.1.x-final
Resolution: fixed
Status: merge_readyclosed

Merged!

comment:14 Changed 2 months ago by mikeperry

Cc: arma added
Resolution: fixed
Status: closedreopened

Nick and arma asked for a comment cleanup, so here's PRs for that:

I also think we should make this into a protocol warn, and use the vanguards addon + testing to find the most common ones, as a separate effort (which I do from time to time, but could also be part of our testing infra).

But: if making this into a protocol warn would spam our testing frameworks too much, feel free to drop/revert that second commit.

comment:15 Changed 2 months ago by mikeperry

Also I realize the master version is a little messy due to CI fixups.. but we hit another CI failure in #31343 so I sort of stopped (I think making that line llabs() is an ok fix but not sure). Lmk if you want me to make a different master version.

comment:16 Changed 2 months ago by nickm

Status: reopenedneeds_review

comment:17 Changed 2 months ago by mikeperry

Here is a single commit master branch patch: https://github.com/torproject/tor/pull/1231

I don't think we need to backport either the warn, or the comment, so I closed the earlier 0.4.1 PR. Much simpler this way.

comment:18 Changed 2 months ago by asn

Status: needs_reviewmerge_ready

LGTM.

comment:19 Changed 8 weeks ago by teor

Keywords: 041-backport? removed
Milestone: Tor: 0.4.1.x-finalTor: 0.4.2.x-final

Fix tags and release.

comment:20 Changed 8 weeks ago by nickm

merged to master.

comment:21 Changed 8 weeks ago by nickm

Resolution: fixed
Status: merge_readyclosed
Note: See TracTickets for help on using tickets.