[tor-dev] Chutney tests fail for tor/maint-0.3.5 (bug #33677)

Sat Mar 28 11:41:49 UTC 2020

Hi,

For the Outreachy.org internship project I decided to take on bug
#33677 [1].

I followed steps to run `make test-network-all` both on tor master and
maint-0.3.5 branches, using Chutney master branch. I tested before and
after tweaking value of HS_WAIT_FOR_UNCHECKED_DIR_INFO just to ensure
my testing environment was sane; all tests passed (except for two that
were skipped on master: mixed+hs-v23 and mixed+hs-v23-ipv6, and one
on 0.3.5: mixed+hs-v2, I assume this is expected though) on the first
go, on both branches of Tor.

Tests pass on Tor master after setting HS_WAIT_FOR_UNCHECKED_DIR_INFO
to 0, but on maint-0.3.5 I've run tests a few times (both with and
without CHUTNEY_DEBUG set) each time with a different outcome. Some of
the tests which fail: basic-min [2], single-onion-v23 [3],
bridges+ipv6-min [4], and ipv6-exit-min [5]. I have excerpted logs at
the bottom of this message, narrowed down to test failures; let me know
if I need to provide full logs or additional information.

I'll keep digging on this issue; I just wanted to show my current
progress and share what I hope to be useful information.

Caitlin

[1]: <https://trac.torproject.org/projects/tor/ticket/33677>
     "Stop waiting a set time for onion service descriptors"

[2]: basic-min.log
[...]
Connecting:
  Exit to 127.0.0.1:4747 via client localhost:9005
DEBUG: socket 5 connecting to ('localhost', 9005)...
DEBUG: Registering send-data-11
DEBUG: Registering check-12
Transmitting Data:
DEBUG: Socks 4a request to 127.0.0.1:4747
DEBUG: Test status: {'send-data-11': 'not done', 'check-12': 'not done'}: 2/0/0
DEBUG: Test status: {'send-data-11': 'not done', 'check-12': 'not done'}: 2/0/0
DEBUG: Done with run(); all_done == False and failure_count == 0
Transmission: Failure
[...]
chutney verify round 1/1 failed
Chutney failed 1 bootstraps; we may have a problem here.
FAIL basic-min (exit status: 1)

[3]: single-onion-v23.log
[...]
Connecting:
  HS to bkjqakom5elyh45a.onion:5858 (127.0.0.1:4747) via client localhost:9005
DEBUG: socket 7 connecting to ('localhost', 9005)...
DEBUG: Registering send-data-21
DEBUG: Registering check-22
  HS to moymkdharroenjd6zarfurdwmrr55j2zune6k7wafyfakwy2cis327id.onion:5858 (127.0.0.1:4747) via client localhost:9005
DEBUG: socket 8 connecting to ('localhost', 9005)...
DEBUG: Registering send-data-23
DEBUG: Registering check-24
Transmitting Data:
DEBUG: Socks 4a request to bkjqakom5elyh45a.onion:5858
DEBUG: Socks 4a request to moymkdharroenjd6zarfurdwmrr55j2zune6k7wafyfakwy2cis327id.onion:5858
DEBUG: new client from 127.0.0.1:54314 (fd=9)
DEBUG: successfully connected (fd=8)
DEBUG: Succeeded send-data-23
DEBUG: successful verification
DEBUG: Succeeded check-24
DEBUG: Test status: {'send-data-21': 'not done', 'check-22': 'not done', 'send-data-23': 'success', 'check-24': 'success'}: 2/2/0
DEBUG: Test status: {'send-data-21': 'not done', 'check-22': 'not done', 'send-data-23': 'success', 'check-24': 'success'}: 2/2/0
DEBUG: Done with run(); all_done == False and failure_count == 0
Transmission: Failure
[...]
chutney verify round 1/1 failed
Chutney failed 1 bootstraps; we may have a problem here.
FAIL single-onion-v23 (exit status: 1)

[4]: bridges+ipv6-min.log
[...]
Couldn't launch test005bc    command '/home/c/git/tor/src/app/tor -f /home/c/git/chutney/net/nodes/005bc/torrc': exit 1, output 'Mar 28 10:47:36.717 [notice] Tor 0.3.5.10-dev (git-38e07b88fac51f2a) running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1d, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.7.
Mar 28 10:47:36.717 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Mar 28 10:47:36.717 [notice] Read configuration file "/home/c/git/chutney/net/nodes/005bc/torrc".
Mar 28 10:47:36.721 [warn] You have used DirAuthority or AlternateDirAuthority to specify alternate directory authorities in your configuration. This is potentially dangerous: it can make you look different from all other Tor users, and hurt your anonymity. Even if you've specified the same authorities as Tor uses by default, the defaults could change in the future. Be sure you know what you're doing.
Mar 28 10:47:36.721 [warn] TestingTorNetwork is set. This will make your node almost unusable in the public Tor network, and is therefore only advised if you are building a testing Tor network!
Mar 28 10:47:36.722 [notice] Opening Socks listener on 127.0.0.1:9005
Mar 28 10:47:36.722 [warn] Could not bind to 127.0.0.1:9005: Address already in use. Is Tor already running?
Mar 28 10:47:36.722 [notice] Opening Control listener on 127.0.0.1:8005
Mar 28 10:47:36.722 [warn] Could not bind to 127.0.0.1:8005: Address already in use. Is Tor already running?
Mar 28 10:47:36.722 [notice] Opening Control listener on /home/c/git/chutney/net/nodes/005bc/control
Mar 28 10:47:36.722 [notice] Opened Control listener on /home/c/git/chutney/net/nodes/005bc/control
Mar 28 10:47:36.722 [notice] Closing partially-constructed Control listener on /home/c/git/chutney/net/nodes/005bc/control:0
Mar 28 10:47:36.722 [warn] Failed to parse/validate config: Failed to bind one of the listener ports.
Mar 28 10:47:36.722 [err] Reading config failed--see warnings above.
'
[...]
Launching chutney using Python 3.7.6
DEBUG: Tor version 0.3.5.10-dev (git-38e07b88fac51f2a).

test000a     is running with PID  2870: Tor 0.3.5.10-dev (git-38e07b88fac51f2a)
test001a     is running with PID  2873: Tor 0.3.5.10-dev (git-38e07b88fac51f2a)
test002ba    is running with PID  2911: Tor 0.3.5.10-dev (git-38e07b88fac51f2a)
test003r     is running with PID  2879: Tor 0.3.5.10-dev (git-38e07b88fac51f2a)
test004br    is running with PID  2882: Tor 0.3.5.10-dev (git-38e07b88fac51f2a)
test005bc    is stopped: Tor 0.3.5.10-dev (git-38e07b88fac51f2a)
5/6 nodes are running
[...]
bootstrap-network.sh failed
Chutney failed 1 bootstraps; we may have a problem here.
FAIL bridges+ipv6-min (exit status: 1)

[5]: ipv6-exit-min.log
[...]
Connecting:
  Exit to 127.0.0.1:4747 via client localhost:9005
DEBUG: socket 5 connecting to ('localhost', 9005)...
DEBUG: Registering send-data-11
DEBUG: Registering check-12
Transmitting Data:
DEBUG: Socks 4a request to 127.0.0.1:4747
DEBUG: Test status: {'send-data-11': 'not done', 'check-12': 'not done'}: 2/0/0
DEBUG: Test status: {'send-data-11': 'not done', 'check-12': 'not done'}: 2/0/0
DEBUG: Done with run(); all_done == False and failure_count == 0
Transmission: Failure
[...]
chutney verify round 1/1 failed
Chutney failed 1 bootstraps; we may have a problem here.
FAIL ipv6-exit-min (exit status: 1)