# Lab notes: setting up a torperf to a hidden service (#1944)

These notes describe the process of setting up a torperf instance to measure performance of a Tor hidden service.  These notes may later lead to code changes to automate more of these steps and/or make this process more user friendly.  But the current focus is to get performance results quickly.

## Preparing the test system

The following steps will be run on a Debian Wheezy 64 bit system, created by Vagrant/VirtualBox using the following `Vagrantfile`:

```
VAGRANTFILE_API_VERSION = "2"
Vagrant.configure(VAGRANTFILE_API_VERSION) do |config|
  config.vm.box = "wheezy64"
  config.vm.box_url = "http://puppet-vagrant-boxes.puppetlabs.com/debian-73-x64-virtualbox-puppet.box"
  config.vm.boot_timeout = 60
end
```

Run the following commands to initialize the test system:

```
vagrant up
vagrant ssh
sudo apt-get update
sudo apt-get upgrade
```

## Building a custom tor binary

We need a tor binary that provides an easy way to clean its hidden service descriptor caches and forget about rendezvous connections.

```
mkdir ~/src
cd ~/src/
git clone https://git.torproject.org/tor.git
cd tor/
git checkout -b bug1944 4c8b809
```

The patch is loosely based on arma's bug1944 branch and rebased to current master (4c8b809).  It's pretty simple:

```
diff --git a/src/or/main.c b/src/or/main.c
index 094120f..ad7fa0b 100644
--- a/src/or/main.c
+++ b/src/or/main.c
@@ -2102,9 +2102,13 @@ process_signal(uintptr_t sig)
       control_event_signal(sig);
       break;
     case SIGUSR2:
-      switch_logs_debug();
-      log_debug(LD_GENERAL,"Caught USR2, going to loglevel debug. "
-                "Send HUP to change back.");
+      /* Replace the USR2 functionality with bug1944-specific plans.
+       * Ugly hack, but it'll do. */
+      log_info(LD_GENERAL, "Clearing all rendezvous caches and "
+                           "forgetting about rendezvous connections...");
+      rend_cache_purge();
+      rend_client_purge_last_hid_serv_requests();
+      circuit_mark_all_dirty_circs_as_unusable();
       control_event_signal(sig);
       break;
     case SIGHUP:
```

Once this patch is applied, build tor and run its unit tests:

```
sudo apt-get install libevent-dev libssl-dev automake
./autogen.sh
./configure --disable-asciidoc
make
make test
```

## Configuring the hidden service

Create a new tor data directory for the tor instance hosting the hidden service.

```
mkdir -p ~/run/torhs
cd ~/run/torhs/
```

Use the following `torrc` file for this tor process:

```
DataDirectory /home/vagrant/run/torhs/
SocksPort 9019
UseEntryGuards 0
RunAsDaemon 1
Log info file /home/vagrant/run/torhs/info.log
ControlPort 10019
CookieAuthentication 1
HiddenServiceDir /home/vagrant/run/torhs/hidserv/
HiddenServicePort 80
```

Start the tor process:

```
~/src/tor/src/or/tor -f ~/run/torhs/torrc &
```

Print out the hidden service hostname:

```
cat ~/run/torhs/hidserv/hostname
```

In this case it's `7rpph4wsx4eosqi3.onion`.

Install nginx to serve some files and auto-generate these files using random data:

```
sudo apt-get install nginx
sudo service nginx start
sudo dd if=/dev/urandom of=/usr/share/nginx/www/.50kbfile count=1 bs=50K
sudo dd if=/dev/urandom of=/usr/share/nginx/www/.1mbfile count=1 bs=1M
sudo dd if=/dev/urandom of=/usr/share/nginx/www/.5mbfile count=1 bs=5M
```

Test that files are available via the hidden service using tor2web by visiting `https://7rpph4wsx4eosqi3.tor2web.org/.50kbfile` in a browser.

## Configuring three tor clients

Create three tor data directories for tor clients:

```
cd ~/run/
mkdir torclient50kb torclient1mb torclient5mb
```

Create `torrc` files for all three tor instances:

```
cat <<EOF >> torclient50kb/torrc
DataDirectory /home/vagrant/run/torclient50kb/
SocksPort 9020
MaxCircuitDirtiness 1 minute
UseEntryGuards 0
RunAsDaemon 1
Log info file /home/vagrant/run/torclient50kb/info.log
ControlPort 10020
CookieAuthentication 1
PidFile /home/vagrant/run/torclient50kb/tor.pid
EOF

cat <<EOF >> torclient1mb/torrc
DataDirectory /home/vagrant/run/torclient1mb/
SocksPort 9021
UseEntryGuards 0
RunAsDaemon 1
Log info file /home/vagrant/run/torclient1mb/info.log
ControlPort 10021
CookieAuthentication 1
PidFile /home/vagrant/run/torclient1mb/tor.pid
EOF

cat <<EOF >> torclient5mb/torrc
DataDirectory /home/vagrant/run/torclient5mb/
SocksPort 9022
UseEntryGuards 0
RunAsDaemon 1
Log info file /home/vagrant/run/torclient5mb/info.log
ControlPort 10022
CookieAuthentication 1
PidFile /home/vagrant/run/torclient5mb/tor.pid
EOF
```

Start the tor processes by creating the following script to `~/run/start-tors` (which also contains the tor process hosting the hidden service; attempting to start it while it's already running does no harm), making it executable, and executing it:

```
#!/bin/bash
~/src/tor/src/or/tor -f ~/run/torhs/torrc &
~/src/tor/src/or/tor -f ~/run/torclient50kb/torrc &
~/src/tor/src/or/tor -f ~/run/torclient1mb/torrc &
~/src/tor/src/or/tor -f ~/run/torclient5mb/torrc &
```

Ideally, put it into crontab:

```
@reboot cd ~/run/ && ./start-tors
```

## Building and testing torperf

Clone and build the torperf tool:

```
cd ~/src/
git clone https://git.torproject.org/torperf.git
cd torperf/
make
```

Make a first test run to fetch the 50 KiB file over Tor:

```
~/src/torperf/trivsocks-client 7rpph4wsx4eosqi3.onion 127.0.0.1:9020 /.50kbfile 51200 2>/dev/null
```

This command produces output like the following:

```
1411379100 454458 1411379100 454467 1411379100 455031 1411379100 455143 1411379100 455738 1411379106 922 1411379106 945 1411379106 502107 1411379107 130422 75 51427 0 1411379106 700760 1411379106 710348 1411379106 824048 1411379106 827450 1411379106 830742 1411379106 909961 1411379107 4770 1411379107 12142 1411379107 49708 
```

In this case, the time between starting the request (columns 1 and 2) and completing it (colums 17 and 18) was 6.7 seconds.

Let's also try out tor's patched behavior to clean its hidden service descriptor caches and forget about rendezvous connections.  First, we need to find out the process ID of the tor client we just used.  Then we can send the process a USR2 signal:

```
ps x     # shows PID 27598 for torclient50kb
kill -USR2 27598
grep "process_signal.*Clearing" ~/run/torclient50kb/info.log
```

## Setting up torperf cronjobs

Put the following three lines into the crontab:

```
*/5 * * * * cd ~/run/torclient50kb/ && timeout -s2 295 ~/src/torperf/trivsocks-client 7rpph4wsx4eosqi3.onion 127.0.0.1:9020 /.50kbfile 51200 >> torperf.log 2>/dev/null; kill -USR2 `cat tor.pid`
2,32 * * * * cd ~/run/torclient1mb/ && timeout -s2 1795 ~/src/torperf/trivsocks-client 7rpph4wsx4eosqi3.onion 127.0.0.1:9021 /.1mbfile 1048576 >> torperf.log 2>/dev/null; kill -USR2 `cat tor.pid`
8 * * * * cd ~/run/torclient5mb/ && timeout -s2 3595 ~/src/torperf/trivsocks-client 7rpph4wsx4eosqi3.onion 127.0.0.1:9022 /.5mbfile 5242880 >> torperf.log 2>/dev/null; kill -USR2 `cat tor.pid`
```

## Plotting simple performance metrics

The torperf output contains some performance data as observed by the SOCKS client that we can plot.

Install `R` and the `ggplot2` library:

```
sudo apt-get install r-base r-cran-ggplot2
```

Create a script with the plotting code and write it to `~/src/plot-torperf.R`:

```
require(ggplot2)
data <- rbind(
  data.frame(read.table("/home/vagrant/run/torclient50kb/torperf.log",
                        header = FALSE), size = 51200),
  data.frame(read.table("/home/vagrant/run/torclient1mb/torperf.log",
                        header = FALSE), size = 1048576),
  data.frame(read.table("/home/vagrant/run/torclient5mb/torperf.log",
                        header = FALSE), size = 5242880))
ggplot(data, aes(x = as.POSIXct(V1, origin = "1970-01-01 00:00:00"),
                 y = V17 + V18 / 1e6 - V1 - V2 / 1e6,
                 colour = as.factor(size))) +
geom_point() +
geom_line() +
scale_x_datetime("") +
scale_y_continuous("") +
scale_colour_hue("Request size\nin bytes") +
opts(title = "Time in seconds to complete request to hidden service\n") +
ggsave("/vagrant/torperf-2014-09-22.png", width = 8, height = 5, dpi = 100)
```

## Attaching tor controllers to log events

Torperf's output is already a fine start for measuring hidden service performance, but we want to learn more details about the process and its substeps.  We do this by attaching controllers to tor's control ports.

Install stem using pip:

```
sudo apt-get install python-pip
sudo pip install stem
```

Create a new file `~/src/log-events.py` containing a minimalistic controller that connects to a local tor control port, registers for events of type `CIRC`, `STREAM`, `CIRC_MINOR`, and `HS_DESC`, and appends incoming events to a file until hitting Ctrl-C:

```
#!/usr/bin/env python
import sys
import time
import datetime
from stem.control import Controller, EventType

if len(sys.argv) < 3:
    print('Usage: python %s <port> <filename>' % sys.argv[0])
    exit(1)

with Controller.from_port(port = int(sys.argv[1])) as controller:
    with open(sys.argv[2], 'a', 0) as file:
        controller.authenticate()
        controller.add_event_listener(
                lambda event: file.write('%s ARRIVED_AT=%s\n' % (
                              str(event), datetime.datetime.fromtimestamp(
                              event.arrived_at).strftime(
                              '%Y-%m-%dT%H:%M:%S.%f'))),
                EventType.CIRC, EventType.STREAM, EventType.CIRC_MINOR,
                EventType.HS_DESC)
        try:
            while True:
                time.sleep(5)
        except KeyboardInterrupt:
            pass
```

Start four instances of this controller for each tor process:

```
cd ~/run/torhs/ && python ~/src/log-events.py 10019 events.log &
cd ~/run/torclient50kb/ && python ~/src/log-events.py 10020 events.log &
cd ~/run/torclient1mb/ && python ~/src/log-events.py 10021 events.log &
cd ~/run/torclient5mb/ && python ~/src/log-events.py 10022 events.log &
```

The following command prints out the most relevant events and reformats them a bit for better readability:

```
egrep "^STREAM .*\.onion|^CIRC.*PURPOSE=HS_CLIENT|^HS_DESC" events.log | \
  sed 's/$[0-9A-F]\{40\}~[0-9a-zA-Z]\+,\?/*/g' | \
  sed 's/\(^STREAM.*NEW\)/\n\1/g'
```

## Reconstructing performance data from event logs

We need to post-process event logs to extract performance data.  In particular, we need to reconstruct which streams were attached to which rendezvous and introduction circuits.

The following timestamps have turned out to be relatively easy to measure:

 1. *started request*: a `STREAM` event to a target ending in `.onion` with status `NEW` marks the beginning of an application request;
 2. *fetched descriptor*: a `CIRC` or `CIRC_MINOR` event with hidden service state `HSCR_CONNECTING` is emitted when the tor client starts establishing a rendezvous point, which indicates that a usable hidden service descriptor has been fetched;
 3. *established rendezvous point*: a `CIRC` or `CIRC_MINOR` event with hidden service state `HSCR_ESTABLISHED_IDLE` tells us that the rendezvous point has been established;
 4. *acknowledged introduction*: two `CIRC` or `CIRC_MINOR` events with hidden service states `HSCI_INTRO_SENT` and `HSCR_ESTABLISHED_WAITING` in quick succession indicate a confirmation from the introduction point that it has received the client's introduction;
 5. *connected to hidden service*: a `STREAM` event with status `SENTCONNECT` indicates a successful connection to the tor process that hosts the hidden service;
 6. *connected to webserver*: a `STREAM` event with status `SUCCEEDED` tells us that the application that opened this stream (torperf) has successfully connected to the remote webserver (nginx); and finally
 7. *completed request*: a `STREAM` event with status `CLOSED` is emitted when the application has completed its request and closed the connection.

In theory, we could also reconstruct which introduction circuit(s) and directory circuit(s) have been used in the connection process, and we could combine client-side logs with server-side logs.  We might also want to include torperf logs, though it seems easiest to parse just a single log file.

The following Python script was used to parse event logs and extract timings for the described substeps (this code really belongs under version control, but these lab notes are meant to be readable without following links):

```
#!/usr/bin/env python
import sys
import time
import datetime
import stem.response
import stem.response.events

class Stream(object):
    def __init__(self, id):
        self.id = id
        self.circ_id = None
        self.events = {}

    def add_event(self, event, circ_id, arrived_at):
        event_str = str(event)
        if event_str not in self.events:
            self.events[event_str] = arrived_at
        if circ_id:
            self.circ_id = circ_id

    def get_event(self, event):
        try:
            return self.events[event]
        except KeyError:
            return None

    def __str__(self):
        return('stream id=%d circ_id=%s %s' % (self.id, self.circ_id,
               ' '.join(['%s=%s' % (event, arrived_at)
               for (event, arrived_at) in self.events.items()])))

class Circuit(object):
    def __init__(self, id):
        self.id = id
        self.events = {}

    def add_event(self, event, arrived_at):
        event_str = str(event)
        if event_str not in self.events:
            self.events[event_str] = arrived_at

    def get_event(self, event):
        try:
            return self.events[event]
        except KeyError:
            return None

    def __str__(self):
        return('circuit id=%d %s' % (self.id, ' '.join(['%s=%s' %
               (event, arrived_at) for (event, arrived_at) in
               self.events.items()])))

class Parser(object):
    def __init__(self, events_log_filename, events_csv_filename):
        self.events_log_filename = events_log_filename
        self.events_csv_filename = events_csv_filename
        self.streams = {}
        self.circuits = {}

    def handle_stream_event(self, event, arrived_at):
        if '.onion' not in event.target:
            return
        id = int(event.id)
        self.streams.setdefault(id, Stream(id)).add_event(event.status,
                                event.circ_id, arrived_at)

    def handle_circ_or_circ_minor_event(self, event, arrived_at):
        if event.purpose in (stem.CircPurpose.HS_CLIENT_INTRO,
                             stem.CircPurpose.HS_CLIENT_REND,
                             stem.CircPurpose.HS_SERVICE_INTRO,
                             stem.CircPurpose.HS_SERVICE_REND):
            id = int(event.id)
            self.circuits.setdefault(id, Circuit(id)).add_event(
                                     event.hs_state, arrived_at)

    def parse_file(self):
        with open(self.events_log_filename, 'r') as file:
            for line in file:
                try:
                    event_str, _, arrived_at_str = line.strip().partition(
                                                   ' ARRIVED_AT=')
                    if arrived_at_str == '':
                        print('Skipping line without ARRIVED_AT '
                              'timestamp: %s' % line)
                        continue
                    event = stem.response.ControlMessage.from_str(
                            '650 %s\r\n' % event_str)
                    stem.response.convert('EVENT', event)
                    arrived_at = datetime.datetime.strptime(
                                 arrived_at_str, '%Y-%m-%dT%H:%M:%S.%f')
                except ValueError:
                    print('Skipping invalid line: %s' % line)
                    continue
                if isinstance(event, (stem.response.events.CircuitEvent,
                              stem.response.events.CircMinorEvent)):
                    self.handle_circ_or_circ_minor_event(event,
                                                         arrived_at)
                elif isinstance(event, stem.response.events.StreamEvent):
                    self.handle_stream_event(event, arrived_at)
                else:
                    pass

    def reconstruct_requests(self):
        with open(self.events_csv_filename, 'w') as file:
            for id in sorted(self.streams.keys()):
                stream = self.streams[id]
                if not stream.get_event('NEW'):
                    continue
                timestamps = [ stream.get_event('NEW') ]
                file.write('%s,' % str(timestamps[0]))
                if stream.get_event('CLOSED'):
                    timedelta = stream.get_event('CLOSED') - \
                                stream.get_event('NEW')
                    file.write(str(timedelta.total_seconds()))
                else:
                    file.write('NA')
                if stream.circ_id and int(stream.circ_id) in self.circuits:
                    rend_circuit = self.circuits[int(stream.circ_id)]
                    timestamps.append(rend_circuit.get_event(
                                      'HSCR_CONNECTING'))
                    # the following events could be added here:
                    # intro_circuit.get_event('HSCI_CONNECTING')
                    timestamps.append(rend_circuit.get_event(
                                      'HSCR_ESTABLISHED_IDLE'))
                    # intro_circuit.get_event('HSCI_INTRO_SENT')
                    timestamps.append(rend_circuit.get_event(
                                      'HSCR_ESTABLISHED_WAITING'))
                    # intro_circuit.get_event('HSCI_DONE')
                    # rend_circuit.get_event('HSCR_JOINED')
                    timestamps.append(stream.get_event('SENTCONNECT'))
                    timestamps.append(stream.get_event('SUCCEEDED'))
                    timestamps.append(stream.get_event('CLOSED'))
                substeps = []
                previous = timestamps[0]
                for current in timestamps[1:]:
                    if previous and current:
                        timedelta = current - previous
                        substeps.append(str((timedelta).total_seconds()))
                    else:
                        substeps.append('NA')
                    previous = current
                if len(substeps) > 0:
                    file.write(',%s' % (','.join(substeps)))
                file.write('\n')

def main():
    if len(sys.argv) < 2:
        print('Usage: python %s <events.log> <events.csv>' % sys.argv[0])
        exit(1)
    parser = Parser(events_log_filename = sys.argv[1],
                    events_csv_filename = sys.argv[2])
    parser.parse_file()
    parser.reconstruct_requests()

if __name__ == '__main__':
    main()
```

Run this script on the three event logs:

```
cd ~/run/torclient50kb/ && python ~/src/parse-events.py events.log events.csv
cd ~/run/torclient1mb/ && python ~/src/parse-events.py events.log events.csv
cd ~/run/torclient5mb/ && python ~/src/parse-events.py events.log events.csv
```

## Plotting post-processed events

The comma-separated files produced in the earlier steps can be plotted using the following script, which could be stored to `~/src/plot-events.R`:

```
require(ggplot2)
require(reshape)

data <- rbind(
  data.frame(read.csv("torclient50kb/events.csv", header = FALSE),
             size = 51200),
  data.frame(read.csv("torclient1mb/events.csv", header = FALSE),
             size = 1048576),
  data.frame(read.csv("torclient5mb/events.csv", header = FALSE),
             size = 5242880))

ggplot(data, aes(x = as.POSIXct(V1), y = V2, colour = as.factor(size))) +
geom_point() +
geom_line() +
scale_x_datetime("") +
scale_y_continuous("") +
scale_colour_hue("Request size\nin bytes") +
opts(title = "Time in seconds to complete request to hidden service\n")
ggsave("torperf.png", width = 8, height = 5, dpi = 100)

colnames(data) <- c("started", "total", "fetch\ndescriptor",
                    "establish\nrendezvous\npoint",
                    "acknowledge\nintroduction",
                    "connect to\nhidden service",
                    "connect to\nwebserver", "complete\nrequest",
                    "size")
ggplot(melt(data[, -2], id.vars = c("started", "size")),
       aes(y = value, x = factor(size), fill = factor(size))) +
coord_flip() +
geom_boxplot() +
facet_grid(variable ~ .) +
scale_y_continuous("") +
scale_x_discrete("Request size in bytes\n") +
opts(title = "Time in seconds to complete hidden service substeps\n",
     legend.position = "none") +
ggsave("substeps.png", width = 8, height = 7, dpi = 100)
```

Run this with the following command:

```
cd ~/run/ && R --slave -f ~/src/plot-events.R
```