Opened 10 months ago

Last modified 7 months ago

#9166 new defect

Write a UTP-based channel implementation

Reported by: nickm Owned by:
Priority: normal Milestone: Tor: unspecified
Component: Tor Version:
Keywords: tor-relay utp Cc: sjmurdoch, iang, robgjansen, jeroen@…
Actual Points: Parent ID: #9165
Points:

Description

Steven has a "utp" branch in https://gitweb.torproject.org/sjm217/tor.git that begins to implement a UTP-based transport. It requires a tweaked libutp with patches from https://github.com/sjmurdoch/libutp

It is probably close to good enough for initial performance testing. This ticket is about making it good enough to merge, if the initial simulations and testing are promising.

Child Tickets

Attachments (6)

sjm217-utp-combined.pdf (350.6 KB) - added by karsten 9 months ago.
sjm217-utp-combined.2.pdf (421.6 KB) - added by karsten 9 months ago.
sjm217-utp-64GB-seeds-combined.pdf (715.5 KB) - added by karsten 9 months ago.
sjm217-utp-64GB-traffic-combined.pdf (725.7 KB) - added by karsten 9 months ago.
sjm217-utp-4GB-socket.png (50.5 KB) - added by karsten 9 months ago.
utp-stats.pdf (68.3 KB) - added by karsten 8 months ago.
uTP stats from a client connecting to a private bridge over uTP

Change History (38)

comment:1 follow-up: Changed 10 months ago by hsn

QUIC would be most likely better choice. Its backed by Google and it will get well tuned.

http://blog.chromium.org/2013/06/experimenting-with-quic.html

comment:2 follow-up: Changed 10 months ago by nickm

As I understand it, the branch today works by adding a UTP connection "on the side" of every or_connection_t. Whenever an OR connection is launched, so is a corresponding UTP connection. The branch seems to want to use TLS for initial key setup, and does not appear to do encryption on the UTP connections yet.

I think that's going to be good enough for simulation, though: the setup characteristics are going to be significantly different than you'd see in a more polished implementation, but the throughput characteristics will be accurate (modulo the effects of no crypto).

For a polished, mergeable version here, I would want to see:

  • A proposal.
  • IPv6 support
  • An actual UTP-based channel, advertised in descriptors and microdescriptors, and implemented as its own channel_t implementation.
  • Integration with the bandwidth accounting and rate-limiting features in the rest of Tor.
  • Resolution for the issues noted below.
  • Encryption, obviously. This could be with TLS-over-UTP, or something different.

More fine-grained issues:

816abfac378f979d718782e17c5185c1dba43f24 Add a uTP connection in parallel to the channel:

  • Got to comment the new functions, if that doesn't happen.
  • It needs rate-limiting to work somehow.
  • need to avoid magic-numbers for inet_ntop buffer lengths.
  • remove magic-address 128.232.10.129
  • needs to bind something other than INADDR_ANY.
  • autoconf needs to check for utp, make it optional
  • Cast "userdata" to channel_tls_t in a local variable; don't say ((channel_tls_t*)userdata) more than once per function.

b1b18889cd4986a2d10e79137f99a9ad46006f08 -- Handle uTP reads using libevent

  • check all return values.

97aa42e4f235015ebd715ba673c475c978c48e67 -- Write payload data to uTP connection

  • utp_is_writable should get checked. Also, it looks like connection_or_write_cell_to_buf doesn't make sense when

tlschan->utp_write_buf is actually successful.

67589c6b4f036ca73b49135cf5f7ec5a708dce73 -- Tie up incoming uTP connections with the TLS counterpart

  • Aw geez. it's using the TLS master key as some kind of key material for the UTP session. That's pretty darned kludgy. I'd really want a key derivation function in there at least.
  • It doesn't appear anything uses the TLS master key though.

comment:3 Changed 10 months ago by nickm

Looking at the issues above, the issues likeliest to affect performance measurements (Assuming this actually works at all, which I haven't tested, but I believe Steven says it does) is the lack of rate-limiting, and the possibility of sending cells redundantly. (If I'm reading the code right, data is actually sent on both the TCP *and* the UTP connection. Was that fixed?)

Please let me know what I've gotten wrong there.

comment:4 in reply to: ↑ 1 Changed 10 months ago by nickm

Replying to hsn:

QUIC would be most likely better choice. Its backed by Google and it will get well tuned.

http://blog.chromium.org/2013/06/experimenting-with-quic.html

Quite possibly! UTP is more mature and more widely deployed for now, though. Another experimental thing to look at is MinimaLT (http://cr.yp.to/tcpip/minimalt-20130522.pdf).

In any case, this ticket isn't about picking the best possible channel backend protocol -- it's about (first) getting Steven's initial branch that he wrote last year good enough to test, and keeping track of what more would need to be done to merge it.

comment:5 in reply to: ↑ 2 Changed 10 months ago by sjmurdoch

Replying to nickm:

As I understand it, the branch today works by adding a UTP connection "on the side" of every or_connection_t. Whenever an OR connection is launched, so is a corresponding UTP connection. The branch seems to want to use TLS for initial key setup, and does not appear to do encryption on the UTP connections yet.

That's correct. Cells that are sent via channels go via uTP (and not TLS) but versions, netinfo, certs and auth* get sent directly on a OR connection rather than channel. I tried sending these via channels but this failed (my reverted attempt was in 4b674b6ba1a665703c2fbc4244eff40ae5e3e673)

  • Aw geez. it's using the TLS master key as some kind of key material for the UTP session. That's pretty darned kludgy. I'd really want a key derivation function in there at least.
  • It doesn't appear anything uses the TLS master key though.

Indeed this is horrid, but only necessary because uTP and TCP connections need to be linked to the same OR connection. Once all necessary cells are sent over uTP there will be no need for any such mechanism.

Replying to nickm:

Looking at the issues above, the issues likeliest to affect performance measurements (Assuming this actually works at all, which I haven't tested, but I believe Steven says it does) is the lack of rate-limiting, and the possibility of sending cells redundantly. (If I'm reading the code right, data is actually sent on both the TCP *and* the UTP connection. Was that fixed?)

I intended that cells except handshake cells should be sent over uTP and handshake cells sent over TCP. The (badly described) commit of fc63eca9ff26384b66707f3dfc15a4555c259a5d stops cells being sent on the OR connection if a uTP connection is available.

comment:6 Changed 10 months ago by iang

  • Cc iang added

Changed 9 months ago by karsten

comment:7 Changed 9 months ago by karsten

I finally got Shadow simulations of Steven's utp branch running (with help by Steven and Rob). See attached simulation results of a variant that uses uTP for all links and one that uses it for none of the links. This was in a "tiny" Shadow network with 20 relays, which took almost 2.5 hours per simulation.

Here's the code change I made to enable (if (1 ||) or disable uTP (if (0 &&):

diff --git a/src/or/channeltls.c b/src/or/channeltls.c
index 0551b73..b7b36e1 100644
--- a/src/or/channeltls.c
+++ b/src/or/channeltls.c
@@ -418,7 +418,7 @@ channel_tls_connect(const tor_addr_t *addr, uint16_t
port,
   /* Create a uTP connection */
   tor_addr_to_sockaddr(addr, port, (struct sockaddr*)&sin, sizeof(sin));
   tor_addr_to_str(addr_str, addr, sizeof(addr_str), 0);
-  if (!strncmp(addr_str, "128.232.10.129", sizeof(addr_str))) {
+  if (1 || !strncmp(addr_str, "128.232.10.129", sizeof(addr_str))) {
     log_info(LD_CHANNEL,
              "Trying uTP connection to %s", addr_str);
     tlschan->utp = UTP_Create(tor_UTPSendToProc, tlschan, (const struct
sockaddr*)&sin,

Am I doing the simulation right? Should I apply different code changes to turn uTP on/off? Should I run this in a larger Shadow network?

comment:8 Changed 9 months ago by sjmurdoch

That looks fine to me Karsten (assuming you are using the LLVM hoist globals version of Shadow; prior ones probably won't work due to the issue described at https://github.com/bittorrent/libutp/issues/51).

Is 2.5 hours larger than it would be for a network of the same size without libutp? If so it would be worth investigating this as it probably would indicate a deeper problem.

Changed 9 months ago by karsten

comment:9 Changed 9 months ago by karsten

Replying to sjmurdoch:

That looks fine to me Karsten (assuming you are using the LLVM hoist globals version of Shadow; prior ones probably won't work due to the issue described at https://github.com/bittorrent/libutp/issues/51).

I'm using Shadow master (91fc269). How do I know it worked correctly? Are there log messages indicating UDP vs. TCP traffic?

Is 2.5 hours larger than it would be for a network of the same size without libutp? If so it would be worth investigating this as it probably would indicate a deeper problem.

2.5 hours is normal. I ran another simulation using vanilla 0.2.4.4-alpha, and that took as long as the other two simulations. See results attached.

So, I wonder, shouldn't the black and blue line overlap more? Is there anything else I should change in your branch to turn off uTP?

Changed 9 months ago by karsten

Changed 9 months ago by karsten

comment:10 follow-up: Changed 9 months ago by karsten

  • Cc robgjansen added

I just finished new Shadow simulations using the large 64 GB network configuration. See attached two PDFs:

  • sjm217-utp-64GB-seeds-combined.pdf compares two runs with uTP for none of the links to two runs with uTP for all links. The two runs using the same configuration use different random seeds (using scallion vs. scallion -s 2). The motivation for this experiment was to see if the large 64 GB network configuration shows more significant performance differences than the small 16 GB network configuration, and to see if differences are real or random. Unfortunately, it looks like differences are mostly random.
  • sjm217-utp-64GB-traffic-combined.pdf compares the runs with seed 1 to similar runs that put additional non-Tor TCP traffic on the Shadow network. Additional TCP traffic is produced by adding a second instance of Shadow's filetransfer plugin called traffic, making all clients perform requests to fileservers directly, and removing all ".*[traffic-.*" lines from scallion.log before making graphs. The motivation for this experiment was to see if additional network load has any effect on Tor performance. Looks like this is not the case.

I'd like to do one more experiment: can Shadow somehow output what amount of traffic uses TCP vs. UDP? I'd like to re-run the simulation in a small or tiny network with uTP enabled and disabled, to confirm that enabling/disabling uTP actually worked. Rob, any idea how Shadow could provide this information?

comment:11 in reply to: ↑ 10 Changed 9 months ago by robgjansen

Replying to karsten:

I just finished new Shadow simulations using the large 64 GB network configuration. See attached two PDFs:

  • sjm217-utp-64GB-seeds-combined.pdf compares two runs with uTP for none of the links to two runs with uTP for all links. The two runs using the same configuration use different random seeds (using scallion vs. scallion -s 2). The motivation for this experiment was to see if the large 64 GB network configuration shows more significant performance differences than the small 16 GB network configuration, and to see if differences are real or random. Unfortunately, it looks like differences are mostly random.

Yeah, it definitely doesn't *look* like the experiments actually used a different transport.

  • sjm217-utp-64GB-traffic-combined.pdf compares the runs with seed 1 to similar runs that put additional non-Tor TCP traffic on the Shadow network. Additional TCP traffic is produced by adding a second instance of Shadow's filetransfer plugin called traffic, making all clients perform requests to fileservers directly, and removing all ".*[traffic-.*" lines from scallion.log before making graphs. The motivation for this experiment was to see if additional network load has any effect on Tor performance. Looks like this is not the case.

I wouldn't expect it to produce the results you want, unless you produce the extra TCP load on relays, clients, or fileservers that are bottlenecks -- you need to 'steal' bandwidth from the client's Tor application, or from a relay's Tor application. You could do this by adding the extra client applications on existing Tor client nodes, and then reduce their bandwidth to ensure the extra load means less bandwidth for Tor.

I'd like to do one more experiment: can Shadow somehow output what amount of traffic uses TCP vs. UDP? I'd like to re-run the simulation in a small or tiny network with uTP enabled and disabled, to confirm that enabling/disabling uTP actually worked. Rob, any idea how Shadow could provide this information?

Its your lucky day ;) It wasn't directly possible, but I just implemented and pushed it to shadow master. You need to include 'socket' in the attribute value of the 'heartbeatloginfo' attribute to the 'node' element. So, something like this:

<node heartbeatloginfo="node,ram,socket" ... >

Careful though, as this prints out information for every active socket for every node on which you enable this feature. grep the logs for '\[shadow-heartbeat\] \[socket'.

If you are feeling particularly adventurous, you can enable for every node in the simulation at the same time with the shadow command line switch:

scallion --heartbeat-log-info=node,ram,socket ...

Changed 9 months ago by karsten

comment:12 follow-up: Changed 9 months ago by karsten

Thanks for adding the heartbeatloginfo socket thing! I just ran two simulations in the tiny network with the new feature enabled for all nodes. Unfortunately, I didn't find a single UDP entry in the logs. I summed up read and written bytes for all nodes and made a graph out of them, and it looks like both simulations used TCP for everything.

So, does Shadow not detect UDP traffic correctly, or did I not enable/disable uTP correctly?

comment:13 in reply to: ↑ 12 Changed 9 months ago by robgjansen

Replying to karsten:

So, does Shadow not detect UDP traffic correctly, or did I not enable/disable uTP correctly?

Sorry about that, its Shadow's fault. I fixed it in Shadow master.

Test it with:

shadow -i socket --echo | grep _tracker_logSocket

You should now see logs for UDP sockets, some with non-zero transfer statistics.

comment:14 follow-up: Changed 9 months ago by karsten

I re-ran the 4 GB simulation with Shadow master, and I do see logs for UDP sockets, but transfer statistics are all zero. (I'm supposed to look at rx-bytes and tx-bytes, right?) Here's an example:

0:0:3:165168 [thread-0] 0:0:0:010000000 [shadow-message] [4uthority1-73.1.0.0] [_tracker_logSocket] [shadow-heartbeat] [socket-header] descriptor-number,protocol-string,hostname:port-peer,inbuflen-bytes,inbufsize-bytes,outbuflen-bytes,outbufsize-bytes,rx-bytes,tx-bytes;...
0:0:7:569507 [thread-0] 0:1:0:010000000 [shadow-message] [4uthority1-73.1.0.0] [_tracker_logSocket] [shadow-heartbeat] [socket] 1000007,UDP,UNSPEC:0,0,174760,0,131072,0,0;1000010,TCP,4uthority1:9112,0,16777216,0,16777216,574,2106;
2:29:45:053655 [thread-0] 0:59:0:080521716 [shadow-message] [4uthority1-73.1.0.0] [_tracker_logSocket] [shadow-heartbeat] [socket] 1000007,UDP,UNSPEC:0,0,174760,0,131072,0,0;1000033,TCP,exit4:9111,0,87380,31595,31595,249294,3432501;1000041,TCP,exit5:9111,0,87380,42775,42775,771244,10249000;1000049,TCP,exit6:9111,0,87380,88987,88987,777624,12352633;1000057,TCP,exit7:9111,0,521900,521687,521687,1583954,27365551;1000065,TCP,exit8:9111,0,268260,0,268260,52603126,3147344;1000238,TCP,nonexit11:9111,0,87380,0,54187,2154,2154;1000824,TCP,exit2:9111,0,87380,0,16384,0,0;1000908,TCP,nonexit8:9111,0,87380,0,24277,66,652;1000938,TCP,nonexit10:9111,0,87380,0,38340,66,652;1001007,TCP,nonexit3:9111,0,87380,0,117347,0,0;1001026,TCP,nonexit10:9111,0,87380,0,35145,0,0;

comment:15 in reply to: ↑ 14 Changed 9 months ago by robgjansen

Replying to karsten:

I re-ran the 4 GB simulation with Shadow master, and I do see logs for UDP sockets, but transfer statistics are all zero. (I'm supposed to look at rx-bytes and tx-bytes, right?)

Yes thats right. Statistics are correctly printed in my test case, so I'm not sure whats wrong. You can also try turning the loglevel to debug for some nodes

<node loglevel="debug" ...>

and then grepping for 'udp_sendUserData' and 'udp_receiveUserData'. You should get log messages of these formats:

buffered %lu outbound UDP bytes from user
user read %lu inbound UDP bytes

comment:16 Changed 9 months ago by yawning

I've also linked this on #tor-dev, but eventually libutp will need to be changed.

Security analysis of the micro transport protocol with a misbehaving receiver
http://openaccess.city.ac.uk/1967/1/cyberc12%2Dflorian%2Dpaper%20pdf.pdf

Of particular note is:

Therefore a good countermeasure against the delay attack yields to a
complete redesign of the LEDBAT congestion control.  That is why we 
don not[sic] propose a countermeasure against this attack and point
here to further research.

LEDBAT by design will yield to competing traffic anyway, so it's not the right congestion control algorithm for Tor. Implementing Reno+SACK shouldn't be too difficult as a starting point (a more modern algorithm like CUBIC could also be used).

comment:17 Changed 9 months ago by karsten

I found the problem why results of enabling or disabling uTP were so similar: my local changes to Steven's tor branch that enabled or disabled uTP have been ignored by Shadow when preparing the simulation (see Shadow issue 161 for details). All simulations ran Steven's unchanged uTP branch that only uses uTP when connecting to the public IP of Steven's test machine, which was of course not part of the Shadow networks. So, all results above that were meant to use uTP on all links are invalid. Bummer.

After fixing the Shadow setup on a 4 GB machine, I ran into a new issue: all tor nodes say they're attempting to use uTP for their connections (so, my local changes are accepted this time), but none of the file downloads succeeds. I uploaded the gzip'ed scallion.log here (8.8M): https://people.torproject.org/~karsten/volatile/utp-scallion.log.gz

comment:18 follow-up: Changed 9 months ago by karsten

After reading Tor/libutp code and staring at Tor/Shadow logs for about two days I need to pause a bit. Quick update of the current roadblocks:

  • There's probably a problem in Shadow that prevents nodes from sending or receiving UDP packets. As a result, libutp's callbacks on_read and on_write are never called, so there's no way how nodes can communicate using uTP. I'll look more into this once the next roadblock is out of the way.
  • Steven suggested setting up a client and private bridge in a non-simulated environment and use uTP for the first hop from client to bridge. This works only if the client has cached-* files in its data directory before starting, and it takes about a minute for the first circuit to be built. I assume there's something wrong with buffers, but I don't know yet what it is. I identified a few places in Steven's code which might be wrong and asked Steven for feedback, though fixing them didn't fix the described problem. I guess I should simply mention them below:
  1. https://gitweb.torproject.org/sjm217/tor.git/blob/refs/heads/utp:/src/or/channeltls.c#l203

Are you really sure you're supposed to return the number of bytes *left* in your virtual 8K buffer, not the number of bytes *in* your buffer? The documentation in utp.h says "The uTP socket layer calls this to retrieve number of bytes currently in read buffer", and the code in utp.cpp, AFAIU, expects the number of bytes in the buffer, too:

// Calculates the current receive window
size_t get_rcv_window() const
{
  ...
  // Trim window down according to what's already in buffer.
  const size_t numbuf = func.get_rb_size(userdata);
  assert((int)numbuf >= 0);
  return opt_rcvbuf > numbuf ? opt_rcvbuf - numbuf : 0;
}
  1. https://gitweb.torproject.org/sjm217/tor.git/blob/refs/heads/utp:/src/or/channeltls.c#l278

Could it be a problem that you're using malloc here, not tor_malloc_zero?

  1. https://gitweb.torproject.org/sjm217/tor.git/blob/refs/heads/utp:/src/or/channeltls.c#l900

Why do you think UTP_Write wants the total number of bytes in the buffer, not just the ones you just added?

  1. https://gitweb.torproject.org/sjm217/tor.git/blob/refs/heads/utp:/src/or/main.c#l1116

Why did you change this line from connection_or_write_cell_to_buf? Is this really related to the libutp stuff?

comment:19 in reply to: ↑ 18 Changed 9 months ago by robgjansen

Replying to karsten:

  • There's probably a problem in Shadow that prevents nodes from sending or receiving UDP packets. As a result, libutp's callbacks on_read and on_write are never called, so there's no way how nodes can communicate using uTP. I'll look more into this once the next roadblock is out of the way.

Can you describe the problem regarding Shadow and UDP any further (besides that libutp's callbacks on_read and on_write are never called) at this point? Are they using libevent to poll the kernel sockets?

comment:20 follow-up: Changed 8 months ago by karsten

I'm afraid I can only speculate about the problem. I only saw one part in the code that uses libevent, and that's in retry_utp_listener in src/or/connection.c where we listen for new incoming connections. I also think I found the place where we send out bytes to the network using sendto in tor_UTPSendToProc in src/or/channeltls.c. But I didn't find where we're informed about new incoming bytes from existing connections. Maybe this happens in a place that is not intercepted by Shadow?

Here's the full diff (which isn't that big), in case you want to have a look yourself: https://gitweb.torproject.org/gitweb?p=sjm217/tor.git;a=commitdiff;h=9628f86;hp=20912fb

comment:21 in reply to: ↑ 20 ; follow-up: Changed 8 months ago by karsten

Replying to karsten:

I'm afraid I can only speculate about the problem. I only saw one part in the code that uses libevent, and that's in retry_utp_listener in src/or/connection.c where we listen for new incoming connections. I also think I found the place where we send out bytes to the network using sendto in tor_UTPSendToProc in src/or/channeltls.c. But I didn't find where we're informed about new incoming bytes from existing connections. Maybe this happens in a place that is not intercepted by Shadow?

Correction: utp_read_callback isn't only called for new incoming connections, but also for new incoming bytes on existing connections. AFAIK.

comment:22 in reply to: ↑ 21 Changed 8 months ago by robgjansen

Replying to karsten:

Replying to karsten:

[...] But I didn't find where we're informed about new incoming bytes from existing connections. Maybe this happens in a place that is not intercepted by Shadow?

Correction: utp_read_callback isn't only called for new incoming connections, but also for new incoming bytes on existing connections. AFAIK.

This is the code that adds the libevent listener:

  ev = tor_event_new(tor_libevent_get_base(), utp_listener, EV_READ|EV_PERSIST, &utp_read_callback, NULL);
  retval = event_add(ev, NULL);
  log_notice(LD_NET, "Added uTP read event: %d, %d", ev!=NULL, retval);

This is telling libevent to call utp_read_callback whenever there is data ready to read (EV_READ) from the socket, and to pass utp_read_callback a NULL user argument. AFAIK, waiting for data on this utp_listener socket should be identical to any other socket, from Shadow's perspective.

Changed 8 months ago by karsten

uTP stats from a client connecting to a private bridge over uTP

comment:23 Changed 8 months ago by karsten

Some more progress from experimenting with a client and private bridge connected over uTP:

I wrote an updated utp branch with three code changes that fix issues with the libutp integration in tor. One of the changes was already stated above, the three remaining ones from above turned out to be non-issues. I didn't find any other potential bugs in the utp branch.

However, using my branch, bootstrapping a client using a private bridge over uTP takes about 2 minutes. See the attached graph that visualizes libutp's logs. Let me explain the six events marked with dashed lines:

  1. The experiment starts at 00:00:00 with the client opening its log file. The bridge has been running for a few minutes at this point to bootstrap.
  1. The first directory connection between client and private bridge is established at 00:00:27, and the client reports in connection_edge_process_relay_cell_not_open that it received 'connected' after 26 seconds. In fact, this is only possible, because I added CircuitStreamTimeout 30 to the torrc, because the default for giving up on a connection is 10 or 15 seconds. Otherwise, the client would have given up on the connection before and would have started creating a new connection. So, what happens? In the logs I can see cells sitting in uTP outbufs which are not sent for many seconds, including, for example, the RELAY_CONNECTED cell. I even tried forcing to send bytes from the outbufs by calling UTP_Write once per second, but libutp refuses. No luck, it just thinks the connection is not writable. Until it suddenly becomes writable and the bytes go through.
  1. It takes until 00:01:02 until the client launches a microdesc networkstatus consensus download (this delay probably has to do with tor's directory fetch retry intervals). The client uses the existing connection for this request. I can see the bridge's outbuf filling quickly to over 250K, containing the compresses microdesc consensus. However, the download rate in the next 30+ seconds is ridiculously low. Here's why: the bridge sends just a single packet containing 1382 bytes to the client, the client processes the full cells from it, and then they both sit there waiting. Only when the client runs UTP_CheckTimeouts as part of its run_scheduled_events, the client sends a 20 byte uTP control message to the bridge which immediately sends another 1382 bytes before going silent again. See the interesting pattern in wnduser from 00:01:02 to about 00:01:36. Then there's a short burst at about 00:01:07 when the bridge transfers a lot of bytes to the client. Shortly after this, there's again the 1-packet-per-second pattern for 15 seconds and then another, longer burst.
  1. The client receives its microdesc consensus at around 00:01:57 and then launches 48 requests for microdescs. These downloads are really, really fast, using the burst phase from before.
  1. The client says at 00:02:02 that it has enough directory information to build circuits.
  1. The client reports that it has successfully opened a circuit, so bootstrapped to 100%, at 00:02:03.

My current understanding is that we can fix the described delays by optimizing libutp's (and maybe tor's) configuration. It shouldn't take 26 seconds to flush 512 bytes from uTP's outbufs to finally get the RELAY_CONNECTED cell out, and the bridge shouldn't have to wait for the client's call to UTP_CheckTimeouts before sending the next data packet. I hope there are configuration parameters in uTP to improve this. For reference, I tried out the "utp_file" example to transfer 100 MiB of data from the client host to the private bridge host in just a few seconds.

In the next step, we might have to tweak tor's configuration to adapt to uTP's characteristics. For example, setting CircuitStreamTimeout 30 is kinda sad, but maybe we have to make similar configurations to make tor work more reliably with uTP. Tweaking uTP would be my preference though.

Oh, and once we did that, we'll want to throw the new branch into Shadow, see if there are remaining issues in Shadow preventing us from simulating it, and simulate it in large Shadow networks.

Feedback much appreciated.

comment:24 Changed 8 months ago by karsten

Solved both timing issues:

  • Turns out the reason for the client waiting until 00:01:02 is unrelated to uTP, but is a general problem of clients bootstrapping via bridges (#9229).

Will look into simulating this updated branch in Shadow next.

comment:25 follow-up: Changed 8 months ago by karsten

Progress!

  • Fixed a nasty and well-hidden segfault that I observed on directory authorities when running this branch in Chutney. This problem never showed up in the client/private bridge setting, nor was it a problem in Shadow. But it was an actual bug which is now fixed.
  • Got a tiny network of 3 directory authorities, 5 relays, and 2 clients bootstrapped in Chutney. tcpdump confirms that there's quite some UDP traffic going on.
  • Still works in my client/private bridge setting and bootstraps within about 6 seconds from an empty data directory.

So far, so good.

(Adding a brief pause here for applause...)

However, I didn't make any progress on Shadow simulations using the new branch. Shadow simply doesn't want to call libutp's on_read and on_write. For comparison, here's how often the various tor_UTP* functions are called in the Chutney network:

ubuntu@ip-10-8-18-21:~/src/chutney$ grep tor_UTP net/nodes/????/debug.log | cut -d" " -f5 | sort | uniq -c
 193561 tor_UTPGetRBSize():
     86 tor_UTPGotIncomingConnection():
      1 tor_UTPOnErrorProc():
 368788 tor_UTPOnOverheadProc():
 109627 tor_UTPOnReadProc():
   3286 tor_UTPOnStateChangeProc():
 118472 tor_UTPOnWriteProc():
 184412 tor_UTPSendToProc():

And here are the same calls in the Shadow network:

ubuntu@ip-10-8-18-21:~/src/shadow/resource/examples/scallion/minimal/data$ grep tor_UTP scallion.log | cut -d" " -f8 | sort | uniq -c
     92 tor_UTPGetRBSize(void
     88 tor_UTPGotIncomingConnection(void
     75 tor_UTPOnErrorProc(void
    343 tor_UTPOnOverheadProc(void
    262 tor_UTPSendToProc(void

AFAICS, the Shadow tor nodes attempt to write cells, but only stuff them in their outbufs without ever sending them. Here's an example:

0:0:39:272981 [thread-0] 0:7:8:369751244 [tor-debug] [relay2-59.1.0.0] [scalliontor_logmsg_cb] int channel_tls_write_packed_cell_method(channel_t *, packed_cell_t *)(): Asked to write packed cell uTP 512 bytes (560), got is_writable: 0
0:0:39:273114 [thread-0] 0:7:8:369751244 [tor-debug] [relay2-59.1.0.0] [scalliontor_logmsg_cb] int channel_tls_write_packed_cell_method(channel_t *, packed_cell_t *)(): Asked to write packed cell uTP 512 bytes (1072), got is_writable: 0
0:0:39:289406 [thread-0] 0:7:8:463049592 [tor-debug] [relay2-59.1.0.0] [scalliontor_logmsg_cb] int channel_tls_write_packed_cell_method(channel_t *, packed_cell_t *)(): Asked to write packed cell uTP 512 bytes (1584), got is_writable: 0
0:0:39:335289 [thread-0] 0:7:9:346200001 [tor-debug] [relay2-59.1.0.0] [scalliontor_logmsg_cb] int channel_tls_write_packed_cell_method(channel_t *, packed_cell_t *)(): Asked to write packed cell uTP 512 bytes (2096), got is_writable: 0

The first line says that 512 bytes are to be sent, in addition to the 48 bytes long connection ID. The number in parentheses is the number of bytes in the outbuf after attempting to send. So, all 560 bytes remain in the buffer.

In the second line, another 512 bytes shall be sent, but they're again only added to the buffer. Same applies to the third and fourth line. And then tor gives up on this connection and tries another one; without success.

I uploaded the full scallion.log here (7.5M).

Any idea what else I could try to make the utp branch work in Shadow?

comment:26 Changed 8 months ago by massar

  • Cc jeroen@… added

comment:27 in reply to: ↑ 25 ; follow-up: Changed 8 months ago by robgjansen

Replying to karsten:

Any idea what else I could try to make the utp branch work in Shadow?

Looking at your log file ('grep udp_ scallion-utp-minimal-2013-08-23.log') I'm only seeing udp_sendUserData and udp_receiveUserData getting called on 20 and 30 bytes of data at a time. I believe Steven mentioned this is internal utp protocol traffic. Indeed, Tor application data is not being sent to the Shadow network layer. The question is: why?

I'd like to trace this, but when building your new utp branch like this:

LDFLAGS="-L/home/rob/test/karsten_utp/libutp" CFLAGS="-I/home/rob/test/karsten_utp/libutp" LIBS="-lutp" ./configure --disable-asciidoc

I get this error:

src/or/libtor.a(channeltls.o): In function `tor_UTPOnReadProc':
channeltls.c:(.text+0x53e): undefined reference to `UTP_SetUserdata'

What am I missing?

Last edited 8 months ago by robgjansen (previous) (diff)

comment:28 in reply to: ↑ 27 ; follow-up: Changed 8 months ago by sjmurdoch

Replying to robgjansen:

I get this error:

src/or/libtor.a(channeltls.o): In function `tor_UTPOnReadProc':
channeltls.c:(.text+0x53e): undefined reference to `UTP_SetUserdata'

What am I missing?

You will need to use my fork of libutp: https://github.com/sjmurdoch/libutp (master branch, currently 569c044e8bd7b2a01476d4885c205f77be363d1f).

comment:29 follow-up: Changed 8 months ago by robgjansen

I spent some time looking into this problem. Here are some observations.

libutp does not have on_write and on_read functions that the OS (or shadow) calls. In fact, it does not handle OS events in any way - Tor is responsible for that (and it uses libevent to make this less painfull). Tor does this in connection.c line 2025.

It appears that only the one utp_listener socket is used for each chaneltls.

Tor creates a *READ* event for the utp listener, hands the event off to libevent, and then never looks at it again. This seems very fragile: all writes can only be triggered during a read event. Even worse, the return value for sendto is never checked and handled: I'm not sure the implications of sendto failing here. (Failing could in fact mean EAGAIN, ie EWOULDBLOCK, and isn't necessarily a bad thing.)

utp_read_callback seems to be getting called by Shadow just fine. The problem is that the call to UTP_IsIncomingUTP triggers the sending of a reset here, meaning that libutp never thinks the socket is writable and so UTP_Write never writes.

I suggest the next step here is turing on libutp debug logs and trying to figure out why its sending resets in UTP_IsIncomingUTP.

comment:30 in reply to: ↑ 29 Changed 7 months ago by karsten

Replying to robgjansen:

I spent some time looking into this problem.

Thanks! Much appreciated.

Here are some observations.

libutp does not have on_write and on_read functions that the OS (or shadow) calls. In fact, it does not handle OS events in any way - Tor is responsible for that (and it uses libevent to make this less painfull). Tor does this in connection.c line 2025.

It appears that only the one utp_listener socket is used for each chaneltls.

Tor creates a *READ* event for the utp listener, hands the event off to libevent, and then never looks at it again.

Yes, so far this all matches my understanding.

This seems very fragile: all writes can only be triggered during a read event.

Aha! This would support why 346d38c makes the utp branch much faster. Of course, reverting that commit and fixing the actual issue would be much better. How would we fix this and make it less fragile?

Even worse, the return value for sendto is never checked and handled: I'm not sure the implications of sendto failing here. (Failing could in fact mean EAGAIN, ie EWOULDBLOCK, and isn't necessarily a bad thing.)

Agreed that return values should be checked. I think I did that while debugging and didn't get a non-zero return value, but that was before making the other fixes. Worth adding this back in. What would we do if we can't send, other than logging this fact? Want to write a patch that I add to my utp branch, or shall I write that patch?

utp_read_callback seems to be getting called by Shadow just fine. The problem is that the call to UTP_IsIncomingUTP triggers the sending of a reset here, meaning that libutp never thinks the socket is writable and so UTP_Write never writes.

I suggest the next step here is turing on libutp debug logs and trying to figure out why its sending resets in UTP_IsIncomingUTP.

I'm not entirely sure how to turn on libutp debug logs. I think it should be possible to log libutp messages to tor's logs. Do you know how to do that? If so, do you mind writing a patch? And would it be useful if I created some libutp debug logs in my Chutney network for you to compare to?

comment:31 in reply to: ↑ 28 ; follow-up: Changed 7 months ago by karsten

Replying to sjmurdoch:

Replying to robgjansen:

I get this error:

src/or/libtor.a(channeltls.o): In function `tor_UTPOnReadProc':
channeltls.c:(.text+0x53e): undefined reference to `UTP_SetUserdata'

What am I missing?

You will need to use my fork of libutp: https://github.com/sjmurdoch/libutp (master branch, currently 569c044e8bd7b2a01476d4885c205f77be363d1f).

Speaking of, we might get rid of our custom libutp branch if we do the following two things:

  • Call the existing UTP_SetCallbacks instead of the newly added UTP_SetUserdata, passing the same UTPFunctionTable as we pass to the other call of UTP_SetCallbacks. This one is easy, I think.
  • Fix the other problem that Steven found ("Needed -fPIC for compiling with Tor") without forking libutp. I don't know enough about this compiler flag to suggest a fix.

If somebody can suggest a fix to the second problem, I'll update the utp tor branch to use the official libutp branch.

comment:32 in reply to: ↑ 31 Changed 7 months ago by robgjansen

Replying to karsten:

If somebody can suggest a fix to the second problem, I'll update the utp tor branch to use the official libutp branch.

One way to handle the '-fPIC' issue without forking libutp is using ENV. That also requires a patch, but one that is more generic and will hopefully be accepted by the libutp devs.

I opened a pull request:
https://github.com/bittorrent/libutp/pull/55

Note: See TracTickets for help on using tickets.