Downloads broken in tor-0.2.4.10-alpha

[robgjansen]

In the minimal experiment, the client is unable to complete any downloads starting with 0.2.4.10-alpha (including master), where this worked fine on 0.2.4.9-alpha and earlier.

cd resource/examples/scallion
tar xaf minimal.tar.xz
cd minimal
for f in authority.torrc exit.torrc relay.torrc client.torrc ; do echo "UseEntryGuardsAsDirGuards 0" >> ${f}; done
scallion -i hosts.xml
grep "fg-download-complete" data/scallion.log | wc -l

This should produce an output of 10 indicating the client successfully downloaded 10 files as instructed.

[robgjansen]

So, it looks like the fileclient has a socks connection error on the first download, which starts at virtual time 0:25:0:0. Before creating the circuit for the web server download, the router connects to a directory mirror, downloads and verifies the consensus, and then prints this:

0:0:4:163513 [thread-0] 0:25:1:263990148 [tor-message] [fileclient-56.1.0.0] [intercept_logv] [notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 5/5, and can only build 020274120f likely paths. (We have 05001111756f guards bw, 1005016602000f midpoint bw, and 013634243140f exit bw.)

Thats the last activity at the client until 120 seconds later, when this is printed:

0:0:4:305977 [thread-0] 0:27:0:000000000 [tor-message] [fileclient-56.1.0.0] [intercept_logv] [notice] void connection_ap_expire_beginning()() Tried for 120 seconds to get a connection to 52.1.0.0:80. Giving up. (waiting for circuit)
[...]
0:0:4:306342 [thread-0] 0:27:0:000000002 [torctl-message] [fileclient-56.1.0.0] [_torcontrollogger_handleEvents] [torcontrol-log] localhost:9051 STREAM 16 CLOSED 0 52.1.0.0:80 REASON=TIMEOUT
0:0:4:306374 [thread-0] 0:27:0:000000002 [file-message] [fileclient-56.1.0.0] [_filetransfer_logCallback] filegetter shutdown due to error 'FG_ERR_SOCKSCONN'... retrying in 60 seconds
0:0:4:306403 [thread-0] 0:27:0:000000002 [file-message] [fileclient-56.1.0.0] [_filetransfer_logCallback] [fg-pause] pausing for 60 seconds

@kloesing any ideas? Did a microdescriptor circuit policy change or something?

[kloesing]

I can reproduce the problem, but unfortunately I don't have any good ideas for fixing it. A few thoughts:

• About the first log message you mention about not having enough directory information:
  • That log message has a broken format, though I don't actually understand the bug there. I changed %d%% to %.4f and passed doubles instead of ints, which at least fixes the output. (If you happen to find out what the bug is, please file a ticket to fix that in master.)
  • I get a similar warning about not having enough directory information, though it never says 5/5. I added 5 more relays to my hosts.xml, and the highest number that gives me this warning is 8/10; that is, I never saw 10/10. And tor was right in saying it didn't have enough info in all those cases, because we want to be able to build at least 60% of likely paths.
  • There's a config option to lower that 60% to 25%, but it's broken in master. I opened #8599 which has a branch that fixes the issue.
  • Lowering the fraction to 25% using this branch doesn't solve the problem here. :(
• I saw an unusual number of warnings: "void make_socket_reuseable(int)() Error setting SO_REUSEADDR flag: Function not implemented". Could this cause the problem here?
• I also saw an unusual number of CIRC FAILED events. It seems that only ONEHOP circuits can be successfully built. Not even the directory mirrors or directory authority could build a circuit consisting of more than one hop. That indicates to me that the issue is unrelated to (micro)descriptor fetching. After all, the directory authority should have all descriptors it needs to build circuits.

[robgjansen]

FYI, I'm not getting CIRC FAILED or the make_socket_reuseable warnings on tor-0.2.4.10-alpha, which is where the problem first appeared.

[kloesing]

I narrowed down the problem to the changes between b415aba (works fine) and dfbd19d (first commit that doesn't work anymore): https://gitweb.torproject.org/gitweb.pl?p=tor.git;a=commitdiff;hp=b415aba;h=dfbd19d

The MaxOnionsPending torrc option has been replaced by the MaxOnionQueueDelay option. (Unfortunately, setting MaxOnionQueueDelay in all torrc's didn't do the trick. Would have been too easy.)

When I run dfbd19d, I get lots of CIRC FAILED events with REMOTE_REASON=RESOURCELIMIT or with REASON=NOPATH. I uploaded the scallion.log file here: https://people.torproject.org/~karsten/volatile/scallion-dfbd19d-2013-05-14.log.gz

Is there maybe anything in the diff that affects Shadow but does not affect normal execution outside of Shadow? I can apply any patch to dfbd19d that you think might fix the problem.

[robgjansen]

Thanks @kloesing !! Your last comment gave me the perfect information to develop a fix:-)

I verified that shadow at commit 8c1c194 works again with tor-0.2.4.12-alpha. (tor-0.2.4.10-alpha and tor-0.2.4.11-alpha both have the "UseEntryGuardsAsDirGuards 0" problem, so I was planning to ignore them.) I also verified that it was fixed with Tor at commit dfbd19d, but in that case you'll need to make the following changes:

diff --git a/src/plugins/scallion/CMakeLists.txt b/src/plugins/scallion/CMakeLists.txt
index 3b4f274..d5d94c1 100644
--- a/src/plugins/scallion/CMakeLists.txt
+++ b/src/plugins/scallion/CMakeLists.txt
@@ -39,9 +39,9 @@ endif()
 # version >= 0.2.4.10
 if((${TOR_VERSION_A} EQUAL 0 AND ${TOR_VERSION_B} EQUAL 2 AND ${TOR_VERSION_C} EQUAL 4 AND ${TOR_VERSION_D} GREATER 9) OR 
     (${TOR_VERSION_A} GREATER -1 AND ${TOR_VERSION_B} GREATER 1 AND ${TOR_VERSION_C} GREATER 4))
-    add_definitions(-DSCALLION_USEV2CPUWORKERTIMING)
-    message(STATUS "Added definition SCALLION_USEV2CPUWORKERTIMING")
 endif()
+add_definitions(-DSCALLION_USEV2CPUWORKERTIMING)
+message(STATUS "Added definition SCALLION_USEV2CPUWORKERTIMING")
 # version >= 0.2.4.11
 if((${TOR_VERSION_A} EQUAL 0 AND ${TOR_VERSION_B} EQUAL 2 AND ${TOR_VERSION_C} EQUAL 4 AND ${TOR_VERSION_D} GREATER 10) OR 
     (${TOR_VERSION_A} GREATER -1 AND ${TOR_VERSION_B} GREATER 1 AND ${TOR_VERSION_C} GREATER 4))

Can you double check my fix? Then we can close this issue.

[kloesing]

Hooray! Yes, I can confirm that the issue is fixed now. Feel free to close the issue! Thanks. :)