Opened 3 months ago

Closed 2 months ago

#29122 closed defect (fixed)

Intermittent test failure in circuitpadding/circuitpadding_wronghop

Reported by: nickm Owned by:
Priority: Medium Milestone: Tor: 0.4.0.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords:
Cc: asn, mikeperry Actual Points:
Parent ID: Points:
Reviewer: mikeperry Sponsor:

Description

Try running circuitpadding_wronghop in a loop, like this:

while ./src/test/test circuitpadding/circuitpadding_wronghop ; do true; done

After a minute or two it will fail with an error like this:

  FAIL src/test/test_circuitpadding.c:1346: assert(n_client_cells OP_EQ 2): 3 vs 2

or sometimes like this

circuitpadding/circuitpadding_wronghop: [forking] 
  FAIL src/test/test_circuitpadding.c:1336: assert(n_client_cells OP_EQ 1): 2 vs 1

Child Tickets

Change History (17)

comment:1 Changed 3 months ago by nickm

Cc: asn mikeperry added

comment:2 Changed 3 months ago by asn

The issue here is that sometimes the test will schedule padding using timers that will trigger immediately during the test run and hence screw up our cell counting tests.

Here is a good run with stacktraces when n_client_cells gets incremented:

circuitpadding/circuitpadding_wronghop: [forking] Jan 21 12:28:44.174 [warn] Bug: . Stack trace: (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(log_backtrace_impl+0x46) [0x5601302e6486] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(+0xddd6c) [0x56012fea2d6c] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(relay_send_command_from_edge___real+0x139) [0x5601301af079] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(circpad_send_command_to_hop__real+0x66) [0x560130187216] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(circpad_negotiate_padding+0x15d) [0x560130189afd] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(+0x3c4ced) [0x560130189ced] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(+0xde288) [0x56012fea3288] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(test_circuitpadding_wronghop+0xff) [0x56012fea466f] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(+0x373f74) [0x560130138f74] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(testcase_run_one+0x2f1) [0x5601301392d1] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(tinytest_main+0x10c) [0x5601301398fc] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(main+0x2aa) [0x56012fe4510a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f8727f1309b] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(_start+0x2a) [0x56012fe4521a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug: . Stack trace: (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(log_backtrace_impl+0x46) [0x5601302e6486] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(+0xddd6c) [0x56012fea2d6c] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(relay_send_command_from_edge___real+0x139) [0x5601301af079] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(circpad_send_command_to_hop__real+0x66) [0x560130187216] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(circpad_negotiate_padding+0x15d) [0x560130189afd] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(test_circuitpadding_wronghop+0xcb3) [0x56012fea5223] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(+0x373f74) [0x560130138f74] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(testcase_run_one+0x2f1) [0x5601301392d1] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(tinytest_main+0x10c) [0x5601301398fc] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(main+0x2aa) [0x56012fe4510a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f8727f1309b] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
GOOD  [warn] Bug:     ./src/test/test(_start+0x2a) [0x56012fe4521a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
OK
1 tests ok.  (0 skipped)

and here is a bad run (see the last increment):

circuitpadding/circuitpadding_wronghop: [forking] Jan 21 12:28:44.234 [warn] Bug: . Stack trace: (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(log_backtrace_impl+0x46) [0x555e4b1bb486] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0xddd6c) [0x555e4ad77d6c] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(relay_send_command_from_edge___real+0x139) [0x555e4b084079] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_send_command_to_hop__real+0x66) [0x555e4b05c216] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_negotiate_padding+0x15d) [0x555e4b05eafd] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0x3c4ced) [0x555e4b05eced] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0xde288) [0x555e4ad78288] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(test_circuitpadding_wronghop+0xff) [0x555e4ad7966f] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0x373f74) [0x555e4b00df74] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(testcase_run_one+0x2f1) [0x555e4b00e2d1] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(tinytest_main+0x10c) [0x555e4b00e8fc] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(main+0x2aa) [0x555e4ad1a10a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f6dd5d4a09b] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(_start+0x2a) [0x555e4ad1a21a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug: . Stack trace: (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(log_backtrace_impl+0x46) [0x555e4b1bb486] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0xddd6c) [0x555e4ad77d6c] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(relay_send_command_from_edge___real+0x139) [0x555e4b084079] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_send_command_to_hop__real+0x66) [0x555e4b05c216] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_negotiate_padding+0x15d) [0x555e4b05eafd] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(test_circuitpadding_wronghop+0xcb3) [0x555e4ad7a223] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0x373f74) [0x555e4b00df74] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(testcase_run_one+0x2f1) [0x555e4b00e2d1] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(tinytest_main+0x10c) [0x555e4b00e8fc] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(main+0x2aa) [0x555e4ad1a10a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f6dd5d4a09b] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(_start+0x2a) [0x555e4ad1a21a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug: . Stack trace: (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(log_backtrace_impl+0x46) [0x555e4b1bb486] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0xddd6c) [0x555e4ad77d6c] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(relay_send_command_from_edge___real+0x139) [0x555e4b084079] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_send_command_to_hop__real+0x66) [0x555e4b05c216] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_send_padding_cell_for_callback+0x103) [0x555e4b05dc13] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(timers_run_pending+0x64) [0x555e4b15cb64] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0xddc5e) [0x555e4ad77c5e] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(relay_send_command_from_edge___real+0x139) [0x555e4b084079] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_send_command_to_hop__real+0x66) [0x555e4b05c216] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(circpad_negotiate_padding+0x15d) [0x555e4b05eafd] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(test_circuitpadding_wronghop+0xcb3) [0x555e4ad7a223] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(+0x373f74) [0x555e4b00df74] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(testcase_run_one+0x2f1) [0x555e4b00e2d1] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(tinytest_main+0x10c) [0x555e4b00e8fc] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(main+0x2aa) [0x555e4ad1a10a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f6dd5d4a09b] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)
BAD [warn] Bug:     ./src/test/test(_start+0x2a) [0x555e4ad1a21a] (on Tor 0.4.0.1-alpha-dev d1af4d65df8b5ef8)

  FAIL src/test/test_circuitpadding.c:1348: assert(n_client_cells OP_EQ 2): 3 vs 2
  [circuitpadding_wronghop FAILED]

comment:3 Changed 3 months ago by asn

The fix is to disable the scheduling of padding timers for this test since it relies on preicse cell counting. See branch bug29122 in my repo: https://github.com/torproject/tor/pull/661

(Been running the while loop for 10 minutes and it hasnt triggered.)

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

comment:4 Changed 3 months ago by asn

Status: newneeds_review

comment:5 Changed 3 months ago by dgoulet

Reviewer: nickm

comment:6 Changed 3 months ago by nickm

LGTM, and fixes the issue too, but needs a changes file.

comment:7 Changed 3 months ago by nickm

Status: needs_reviewneeds_revision

comment:8 Changed 3 months ago by asn

Status: needs_revisionmerge_ready

Oops, missed that. Pushed squash commit with changes file.

comment:9 Changed 3 months ago by nickm

Thanks! Merged to master.

comment:10 Changed 3 months ago by nickm

Resolution: fixed
Status: merge_readyclosed

comment:11 Changed 3 months ago by nickm

I just pushed this -- looks like I forgot to push it yesterday :/

comment:12 Changed 3 months ago by teor

Resolution: fixed
Status: closedreopened

I don't think this issue is fixed: I got the 3 vs 2 error on a pull request against master yesterday:

circuitpadding/circuitpadding_circuitsetup_machine: [forking] 
  FAIL src/test/test_circuitpadding.c:1880: assert(n_client_cells OP_EQ 2): 3 vs 2
  [circuitpadding_circuitsetup_machine FAILED]

https://trac.torproject.org/projects/tor/ticket/23576#comment:24

comment:13 Changed 2 months ago by asn

OK, while this is not the same bug as the original bug of this ticket, let's use the same ticket for it (the original bug was in circuitpadding_wronghop, the teor one is in circuitsetup_machine).

So, I discussed this with mikeperry in brussels and we figured out what's the issue. The issue is that circuitpadding_circuitsetup_machine uses a 2-bin histogram, and the fact that it only has 2-bins causes undefined behavior since the spec has conflicting rules about how 2-bin histograms work. In particular, the current spec causes UB for 1-bin 2-bin and 3-bin histograms, because of the way the bin edges are calculated automatically.

The long-term fix here is to do #29298 which allows the histogram designer to specify the bin edges themselves, but we will do this in 041 since it's a non-trivial fix. The short-term fix here is probably to disable this unittest until the 041 fix comes in. Mike, do you agree?

comment:14 Changed 2 months ago by asn

Reviewer: nickmmikeperry
Status: reopenedneeds_review

Hello, pushed a branch that disables the offending unittest until we do #29298:
https://github.com/torproject/tor/pull/701

Mike, wanna take a look and see if you like the approach or you would prefer something else?

comment:15 Changed 2 months ago by mikeperry

Status: needs_reviewmerge_ready

I think it makes sense to just disable this test until #29298 is done. If we want to replace this functionality with something simpler no need to devote brain to making this old test work.

comment:16 Changed 2 months ago by nickm

Merged to 0.4.0 and forward. Please change the status on this branch, or make a new ticket as appropriate?

comment:17 Changed 2 months ago by asn

Resolution: fixed
Status: merge_readyclosed

Thanks. The test will be reenabled with #29298, but that's gonna be in 041.
Closing this ticket.

Note: See TracTickets for help on using tickets.