Controller circuits don't pass the SOCKS request address in relay begin cells
If a stream is attached to a circuit with purpose
CIRCUIT_PURPOSE_CONTROLLER, a RELAY_BEGIN cell will be sent with an empty address. This is because of a bug in
tor_snprintf(payload,RELAY_PAYLOAD_SIZE, "%s:%d", (circ->base_.purpose == CIRCUIT_PURPOSE_C_GENERAL) ? ap_conn->socks_request->address : "", ap_conn->socks_request->port);
The function seems to assume that if it's not a general purpose circuit, then it is a rendezvous circuit. This was added in commit 5b6099e8.
There is a similar error in a logging statement in
link_apconn_to_circ() which logs that a controller circuit is to a "hidden service", even if the circuit is actually to an exit.
log_info(LD_APP, "Looks like completed circuit to %s %s allow " "optimistic data for connection to %s", circ->base_.purpose == CIRCUIT_PURPOSE_C_GENERAL ? /* node_describe() does the right thing if exitnode is NULL */ safe_str_client(node_describe(exitnode)) : "hidden service", apconn->may_use_optimistic_data ? "does" : "doesn't", safe_str_client(apconn->socks_request->address));
And another example is in
connection_ap_expire_beginning() which logs the warning:
[warn] connection_ap_expire_beginning(): Bug: circuit->purpose == CIRCUIT_PURPOSE_C_GENERAL failed. The purpose on the circuit was Circuit made by controller; it was in state open, path_state new. (on Tor 0.4.2.5 )
The relay which receives the RELAY_BEGIN cell will then make a dns request for the address "". Libevent will eventually give up after 3 tries (
global_timeout.tv_sec = 5 seconds per try).
Feb 01 01:11:41.369 [info] launch_resolve(): Launching eventdns request for "" Feb 01 01:11:41.369 [info] evdns_log_cb(): eventdns: Resolve requested. ... Feb 01 01:11:56.378 [info] eventdns: Giving up on request 0x5565c825ac80; tx_count==3
Back at the tor client, the streams detach (reason=timeout, remote_reason=none) after some time, then the controller circuits close a few seconds later (a total of 25 seconds after the streams were first attached) with:
[info] circuit_mark_for_close_(): Circuit 2262666673 (id: 15) marked for close at src/core/or/circuituse.c:1507 (orig reason: 9, new reason: 0)
Finally a SOCKS error code
0x5b is returned to the application after some long amount of time.
In summary, the main problems are:
(1) Tor has checks for only
CIRCUIT_PURPOSE_C_GENERAL when it should be checking for other circuit purposes like
(2) Tor attempts to resolve the address of an empty string.
(3) (Maybe?) It takes a long time before the application is notified that the SOCKS connection was unsuccessful.
Thanks to arma for help debugging this.