[warn] Unexpected INTRODUCE_ACK on circuit 3944288021.
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.