Opened 3 weeks ago

Closed 2 weeks ago

#30776 closed defect (invalid)

Circpad circuits do not expire as intended (invalid ticket)

Reported by: asn Owned by:
Priority: High Milestone: Tor: 0.4.1.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: 041-must wtf-pad
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description (last modified by asn)

Still investigating this issue. Might be caused by an outdated version of #28634 on the relay-side and might actually not be a bug.

I saw the following logs in my logs of Tor master (includes #28780, #28634 and #29034):

Jun 05 16:44:59.442 [notice] circpad_marked_circuit_for_padding(): Bug: Circuit 6 was not marked for close because of a  pending padding machine for over an hour. Circuit is a Circuit kept open for padding (on Tor 0.4.1.2-alpha 7f341d64828d48eb)
Jun 05 16:49:07.888 [notice] circpad_marked_circuit_for_padding(): Bug: Circuit 10 was not marked for close because of a  pending padding machine for over an hour. Circuit is a Circuit kept open for padding (on Tor 0.4.1.2-alpha 7f341d64828d48eb)
Jun 05 16:51:42.130 [notice] circpad_marked_circuit_for_padding(): Bug: Circuit 16 was not marked for close because of a  pending padding machine for over an hour. Circuit is a Circuit kept open for padding (on Tor 0.4.1.2-alpha 7f341d64828d48eb)

Seems like the logic that is supposed to expire circuits does not work. In particular I see the following pattern per-circuit:

Jun 05 15:37:03.318 [info] circpad_marked_circuit_for_padding(): Circuit 10 is not marked for close because of a  pending padding machine.
... 10 minutes pass...
Jun 05 15:47:07.862 [info] circpad_marked_circuit_for_padding(): Circuit 10 is not marked for close because of a  pending padding machine.
Jun 05 15:47:38.896 [info] circpad_marked_circuit_for_padding(): Circuit 10 is not marked for close because of a  pending padding machine.
Jun 05 15:48:09.921 [info] circpad_marked_circuit_for_padding(): Circuit 10 is not marked for close because of a  pending padding machine.
Jun 05 15:48:40.958 [info] circpad_marked_circuit_for_padding(): Circuit 10 is not marked for close because of a  pending padding machine.
Jun 05 15:49:11.998 [info] circpad_marked_circuit_for_padding(): Circuit 10 is not marked for close because of a  pending padding machine.
Jun 05 15:49:42.041 [info] circpad_marked_circuit_for_padding(): Circuit 10 is not marked for close because of a  pending padding machine.
... <etc>
Jun 05 16:49:07.888 [notice] circpad_marked_circuit_for_padding(): Bug: Circuit 10 was not marked for close because of a  pending padding machine for over an hour. Circu
it is a Circuit kept open for padding (on Tor 0.4.1.2-alpha 7f341d64828d48eb)

so it seems like the machine is still alive, or something thinks it still is.

The good thing is that the circuit does not stay up for ever and it does get closed after an hour, but our logic is still failing.

I think this is a definite 041-must but perhaps we don't need to stall the alpha for it.

Child Tickets

Change History (8)

comment:1 Changed 3 weeks ago by asn

Description: modified (diff)

comment:2 Changed 3 weeks ago by asn

Seems like we never receive a PADDING_NEGOTIATED STOP cell from the relay. This might be because I'm using Alex's relay who is running an outdated version of #28634. Will investigate more.

comment:3 Changed 3 weeks ago by asn

Description: modified (diff)

comment:4 Changed 3 weeks ago by nickm

Priority: MediumHigh

comment:5 Changed 3 weeks ago by asn

Note to self: This is not a serious bug, but the above log message can happen if you suspend your laptop for a few hours and open it up. Then it seems like the "1 hour protection" will trigger before the normal expiry function.

comment:6 Changed 2 weeks ago by asn

This seems to be a not bug. The relay-side was running an old version of the #28634 branch that was causing the circuits to not expire. Will update ticket as soon as I do some more testing.

comment:7 Changed 2 weeks ago by asn

Yes, verified this is not a bug. Here how it looks with both client and service running master:

Jun 07 11:39:51.343 [info] circpad_marked_circuit_for_padding(): Circuit 4 is not marked for close because of a  pending padding machine.
Jun 07 11:50:03.283 [info] circuit_mark_for_close_(): Circuit 2464891989 (id: 4) marked for close at src/core/or/circuituse.c:1507 (orig reason: 9, new reason: 0)
Jun 07 11:39:55.063 [info] circpad_marked_circuit_for_padding(): Circuit 17 is not marked for close because of a  pending padding machine.
Jun 07 11:50:03.283 [info] circuit_mark_for_close_(): Circuit 2582647544 (id: 17) marked for close at src/core/or/circuituse.c:1507 (orig reason: 9, new reason: 0)

Looks really good.

comment:8 Changed 2 weeks ago by asn

Resolution: invalid
Status: newclosed
Summary: Circpad circuits do not expire as intendedCircpad circuits do not expire as intended (invalid ticket)
Note: See TracTickets for help on using tickets.