HS intro padding machine reactivates after receiving INTRODUCE_ACK
While reseaching wtf-pad I noticed that the intro machines display a weird shutdown/reactivation pattern.
In particular, what happens is that after INTRODUCE1 is sent, the machine starts up and sends all its padding, and then shuts down. Then when INTRODUCE_ACK arrives, it reactivates (probably because INTRODUCE_ACK is part of the accepted purposes and the machine is shutdown/freed at that time) and sends again padding, then again shuts down...
This does not work as intended and causes extra cells to fly in with a pattern that probably does not help them blend in.
Here are some Tor logs (with padanalysis incoming/outgoing cells logs):
Oct 11 13:25:54.000 [warn] outgoing-cell: EXTEND2 0
Oct 11 13:25:54.000 [warn] incoming-cell: EXTENDED2 0 66
Oct 11 13:25:54.000 [warn] outgoing-cell: EXTEND2 0
Oct 11 13:25:54.000 [warn] incoming-cell: EXTENDED2 0 66
Oct 11 13:25:57.000 [warn] outgoing-cell: EXTEND 0
Oct 11 13:25:58.000 [warn] incoming-cell: EXTENDED 0 148
Oct 11 13:25:58.000 [warn] outgoing-cell: INTRODUCE1 4
Oct 11 13:25:58.000 [warn] outgoing-cell: PADDING_NEGOTIATE 4
Oct 11 13:25:58.000 [warn] incoming-cell: PADDING_NEGOTIATED 4 4
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: PADDING_NEGOTIATED 4 4
Oct 11 13:25:58.000 [info] circpad_handle_padding_negotiated(): Received STOP command on PADDING_NEGOTIATED for circuit 5
Oct 11 13:25:58.000 [info] circpad_circuit_machineinfo_free_idx(): Freeing padding info idx 0 on circuit 5 (7)
Oct 11 13:25:58.000 [warn] incoming-cell: INTRODUCE_ACK 4 0
Oct 11 13:25:58.000 [info] rend_client_introduction_acked(): Received ack. Telling rend circ...
Oct 11 13:25:58.000 [info] circpad_setup_machine_on_circ(): Registering machine client_ip_circ to origin circ 5 (8)
Oct 11 13:25:58.000 [info] circpad_node_supports_padding(): Checking padding: supported
Oct 11 13:25:58.000 [info] circpad_negotiate_padding(): Negotiating padding on circuit 5 (8), command 2
Oct 11 13:25:58.000 [warn] outgoing-cell: 8 PADDING_NEGOTIATE 4
Oct 11 13:25:58.000 [info] circpad_machine_spec_transition(): Circuit 5 circpad machine 0 transitioning from 0 to 1
Oct 11 13:25:58.000 [info] circpad_marked_circuit_for_padding(): Circuit 5 is not marked for close because of a pending padding machine in index 0.
Oct 11 13:25:58.000 [warn] incoming-cell: PADDING_NEGOTIATED 4 4
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: DROP 4 0
Oct 11 13:25:58.000 [warn] incoming-cell: PADDING_NEGOTIATED 4 4
Oct 11 13:25:58.000 [info] circpad_handle_padding_negotiated(): Received STOP command on PADDING_NEGOTIATED for circuit 5
Oct 11 13:25:58.000 [info] circpad_circuit_machineinfo_free_idx(): Freeing padding info idx 0 on circuit 5 (15)
...
Oct 11 13:36:11.000 [info] circuit_mark_for_close_(): Circuit 4130340667 (id: 5) marked for close at src/core/or/circuituse.c:1509 (orig reason: 9, new reason: 0)I'm not sure what the fix should be here. It might be that we need to remove INTRODUCE_ACK from the list of accepted purposes, but if we do that then if INTRODUCE_ACK arrives earlier we will stop padding after. Hmm.