GitLab

I noticed that my prop224 client had some reconnects and I did some log digging. The original disconnect was caused by a truncate cell (probably natural causes) but then a whole dance of introduction/rendezvous started which ended up marking 3 intro circs as timed out within seconds:

<FIRST TIMED-OUT INTRO CIRC>
Sep 28 03:55:26.000 [notice] Introduction circuit 2276964442 has opened. Attaching streams.
Sep 28 03:55:26.000 [info] connection_ap_handshake_attach_circuit(): Intro (2276964442) and rend (2943321454) circs are not both ready. Stalling conn. (2 sec old)
Sep 28 03:55:29.000 [info] circuit_expire_building(): Marking circ 2276964442 (state 4:open, purpose 6) as timed-out HS circ
<SECOND TIMED-OUT INTRO CIRC>
Sep 28 03:55:29.000 [info] circuit_get_best(): There is an intro circuit being created right now, but it has already taken quite a while. Starting one in parallel.
Sep 28 03:55:29.000 [notice] Introduction circuit 4126528467 has opened. Attaching streams.
Sep 28 03:55:29.000 [info] connection_ap_handshake_attach_circuit(): Intro (4126528467) and rend (2943321454) circs are not both ready. Stalling conn. (5 sec old)
Sep 28 03:55:34.000 [info] circuit_expire_building(): Marking circ 4126528467 (state 4:open, purpose 6) as timed-out HS circ
<THIRD TIMED-OUT INTRO CIRC>
Sep 28 03:55:29.000 [info] circuit_get_best(): There is an intro circuit being created right now, but it has already taken quite a while. Starting one in parallel.
Sep 28 03:55:34.000 [notice] Introduction circuit 4282777781 has opened. Attaching streams.
Sep 28 03:55:34.000 [info] connection_ap_handshake_attach_circuit(): Intro (4282777781) and rend (2943321454) circs are not both ready. Stalling conn. (10 sec old)
Sep 28 03:55:39.000 [info] circuit_expire_building(): Marking circ 4282777781 (state 4:open, purpose 6) as timed-out HS circ
<CIRCUITS CLOSE>
Sep 28 03:57:26.000 [info] circuit_expire_building(): Abandoning circ 232 137.205.124.35:1720:2276964442 (state 1,4:open, purpose 6, len 4)
Sep 28 03:57:26.000 [info] circuit_mark_for_close_(): Circuit 2276964442 (id: 232) marked for close at src/or/circuituse.c:820 (orig reason: 10, new reason: 0)
Sep 28 03:57:30.000 [info] circuit_expire_building(): Abandoning circ 231 137.205.124.35:1720:4126528467 (state 1,4:open, purpose 6, len 4)
Sep 28 03:57:30.000 [info] circuit_mark_for_close_(): Circuit 4126528467 (id: 231) marked for close at src/or/circuituse.c:820 (orig reason: 10, new reason: 0)
Sep 28 03:57:35.000 [info] circuit_expire_building(): Abandoning circ 233 137.205.124.35:1720:4282777781 (state 1,4:open, purpose 6, len 4)
Sep 28 03:57:35.000 [info] circuit_mark_for_close_(): Circuit 4282777781 (id: 233) marked for close at src/or/circuituse.c:820 (orig reason: 10, new reason: 0)

You can see that we went ahead and marked intro circs as timed-out within 3 seconds of launching them which makes no sense, and caused a whole lot of mess in the prop224 state machine.

We should try to figure out if there is a bug here.