robgjansen / onionperf Goto Github PK

View Code? Open in Web Editor NEW

19.0 19.0 25.0 169 KB

A utility to track the performance of Tor and Tor onion services

License: Other

Python 100.00%

onionperf's People

Contributors

Stargazers

Watchers

Forkers

kloesing mjuarezm parmegv irl mikeperry-tor banansb w3fs traumschule lnrsoft torproject liwenqiang1990 cyberflamego

onionperf's Issues

socket connection failed

Hi，
I encountered socket connection failed while testing the onion network. So why is this happening?

2018-07-16 21:39:19 1531748359.490587 [onionperf] [INFO] Using 'tor' binary at /root/shadow-plugin-tor/build/tor/src/or/tor
2018-07-16 21:39:19 1531748359.490765 [onionperf] [INFO] Using 'tgen' binary at /root/shadow/src/plugin/shadow-plugin-tgen/build/tgen
2018-07-16 21:39:19 1531748359.490812 [onionperf] [INFO] Using 'twistd' binary at /usr/bin/twistd
2018-07-16 21:39:30 1531748370.719282 [onionperf] [INFO] Bootstrapping started...
2018-07-16 21:39:30 1531748370.719409 [onionperf] [INFO] Log files for the client and server processes will be placed in /newdisk/onionperf/onionperf/onionperf-data
2018-07-16 21:39:30 1531748370.719454 [onionperf] [INFO] Starting TGen server process on port 8080...
2018-07-16 21:39:30 1531748370.720069 [onionperf] [INFO] TGen server running at 0.0.0.0:8080
2018-07-16 21:39:30 1531748370.720134 [onionperf] [INFO] Logging TGen server process output to /newdisk/onionperf/onionperf/onionperf-data/tgen-server/onionperf.tgen.log
2018-07-16 21:39:30 1531748370.720445 [onionperf] [INFO] Starting Tor server process with ControlPort=13505, SocksPort=20558...
2018-07-16 21:39:30 1531748370.720523 [onionperf] [INFO] Logging Tor server process output to /newdisk/onionperf/onionperf/onionperf-data/tor-server/onionperf.tor.log
2018-07-16 21:40:40 1531748440.430948 [onionperf] [INFO] Logging Tor server control port monitor output to /newdisk/onionperf/onionperf/onionperf-data/tor-server/onionperf.torctl.log
2018-07-16 21:40:43 1531748443.438111 [onionperf] [INFO] Creating ephemeral hidden service...
2018-07-16 21:41:25 1531748485.461941 [onionperf] [INFO] Cleaning up child processes now...
2018-07-16 21:41:25 1531748485.462292 [onionperf] [INFO] Joining tgen_server_watchdog thread...
Exception in thread torctl_server_helper:
Traceback (most recent call last):
File "/usr/lib64/python2.7/threading.py", line 812, in __bootstrap_inner
self.run()
File "/usr/lib64/python2.7/threading.py", line 765, in run
self.__target(*self.__args, **self.__kwargs)
File "/usr/lib/python2.7/site-packages/onionperf/monitor.py", line 84, in tor_monitor_run
torctl_monitor.run(newnym_interval_seconds=newnym_interval_seconds, done_ev=done_ev)
File "/usr/lib/python2.7/site-packages/onionperf/monitor.py", line 27, in run
torctl.authenticate()
File "/usr/lib/python2.7/site-packages/stem/control.py", line 991, in authenticate
stem.connection.authenticate(self, *args, **kwargs)
File "/usr/lib/python2.7/site-packages/stem/connection.py", line 520, in authenticate
raise AuthenticationFailure('socket connection failed (%s)' % exc)
AuthenticationFailure: socket connection failed (Received empty socket content.)
2018-07-16 21:41:25 1531748485.978180 [onionperf] [INFO] Joining tor_server_watchdog thread...
2018-07-16 21:41:26 1531748486.066931 [onionperf] [INFO] Joining torctl_server_helper thread...
2018-07-16 21:41:27 1531748487.070911 [onionperf] [INFO] Child processes terminated
2018-07-16 21:41:27 1531748487.071276 [onionperf] [INFO] Child process cleanup complete!
2018-07-16 21:41:27 1531748487.071451 [onionperf] [INFO] Exiting
Traceback (most recent call last):
File "./onionperf", line 504, in
if name == 'main': sys.exit(main())
File "./onionperf", line 330, in main
args.func(args)
File "./onionperf", line 383, in measure
server_tgen_listen_port=server_tgen_port, server_tor_ctl_port=server_tor_ctl_port, server_tor_socks_port=server_tor_socks_port, twistd_port=twistd_port)
File "/usr/lib/python2.7/site-packages/onionperf/measurement.py", line 214, in run
tor_writable, torctl_writable = self.__start_tor_server(server_tor_ctl_port, server_tor_socks_port, {client_tgen_connect_port:server_tgen_listen_port})
File "/usr/lib/python2.7/site-packages/onionperf/measurement.py", line 348, in __start_tor_server
return self.__start_tor("server", control_port, socks_port, hs_port_mapping)
File "/usr/lib/python2.7/site-packages/onionperf/measurement.py", line 395, in __start_tor
torctl.authenticate()
File "/usr/lib/python2.7/site-packages/stem/control.py", line 991, in authenticate
stem.connection.authenticate(self, *args, **kwargs)
File "/usr/lib/python2.7/site-packages/stem/connection.py", line 520, in authenticate
raise AuthenticationFailure('socket connection failed (%s)' % exc)
stem.connection.AuthenticationFailure: socket connection failed (Received empty socket content.)

Twisted v17.1.0 fails on port string

OnionPerf gives a warning when using twisted 17.1.0 that is not present on twisted 16.6.0:

[onionperf] [WARNING] command '/usr/local/bin/twistd -n -l - web --port
8090 --path /home/cloud/onionperf/onionperf-data/twistd/docroot
--mime-type=None' finished before expected

And the twisted log file onionperf-data/twistd/onionperf.twisted.log:

   app.run(runApp, ServerOptions)
 File
"/usr/local/lib/python2.7/dist-packages/twisted/application/app.py",
line 662, in run
   runApp(config)
 File
"/usr/local/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line
25, in runApp
   _SomeApplicationRunner(config).run()
 File
"/usr/local/lib/python2.7/dist-packages/twisted/application/app.py",
line 380, in run
   self.application = self.createOrGetApplication()
 File
"/usr/local/lib/python2.7/dist-packages/twisted/application/app.py",
line 440, in createOrGetApplication
   ser = plg.makeService(self.config.subOptions)
 File "/usr/local/lib/python2.7/dist-packages/twisted/web/tap.py", line
254, in makeService
   strports.service(config['port'], site).setServiceParent(s)
 File
"/usr/local/lib/python2.7/dist-packages/twisted/application/strports.py",
line 40, in service
   endpoints.serverFromString(reactor, description), factory)
 File
"/usr/local/lib/python2.7/dist-packages/twisted/internet/endpoints.py",
line 1569, in serverFromString
   nameOrPlugin, args, kw = _parseServer(description, None)
 File
"/usr/local/lib/python2.7/dist-packages/twisted/internet/endpoints.py",
line 1487, in _parseServer
   getPlugins(IStreamServerEndpointStringParser), endpointType
 File
"/usr/local/lib/python2.7/dist-packages/twisted/internet/endpoints.py",
line 1503, in _matchPluginToPrefix
   raise ValueError("Unknown endpoint type: '%s'" % (endpointType,))
ValueError: Unknown endpoint type: '8090'

Reported by @hiromipaw (thanks!)

tgen cannot bind to privileged port 80

The tgen server cannot bind to privileged port 80, which makes sense if the user doesn't give it the privileges to do so. But how would the user do that?

And would it be possible to be more verbose about this fact in the output? Here's what it says with default ports 80 and 50080:

ubuntu@ip-172-16-0-86:~/run$ onionperf measure --tor=/home/ubuntu/tor/src/or/tor --tgen=/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen --twistd=/usr/bin/twistd 
2016-02-10 15:10:44 1455117044.727352 [onionperf] [INFO] Using 'tor' binary at /home/ubuntu/tor/src/or/tor
2016-02-10 15:10:44 1455117044.727656 [onionperf] [INFO] Using 'tgen' binary at /home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen
2016-02-10 15:10:44 1455117044.727804 [onionperf] [INFO] Using 'twistd' binary at /usr/bin/twistd
2016-02-10 15:10:44 1455117044.754850 [onionperf] [INFO] Bootstrapping started...
2016-02-10 15:10:44 1455117044.755137 [onionperf] [INFO] Log files for the client and server processes will be placed in /home/ubuntu/run/onionperf-data
2016-02-10 15:10:44 1455117044.755283 [onionperf] [INFO] Starting TGen server process on port 80...
2016-02-10 15:10:44 1455117044.755948 [onionperf] [INFO] TGen server running at 0.0.0.0:80
2016-02-10 15:10:44 1455117044.756074 [onionperf] [INFO] Logging TGen client process output to /home/ubuntu/run/onionperf-data/tgen-server/onionperf.tgen.log
2016-02-10 15:10:44 1455117044.756326 [onionperf] [INFO] Starting Tor server process with ControlPort=59407, SocksPort=57797...
2016-02-10 15:10:44 1455117044.756452 [onionperf] [INFO] Logging Tor server process output to /home/ubuntu/run/onionperf-data/tor-server/onionperf.tor.log
2016-02-10 15:10:46 1455117046.844678 [onionperf] [INFO] Logging Tor server control port monitor output to /home/ubuntu/run/onionperf-data/tor-server/onionperf.torctl.log
2016-02-10 15:10:49 1455117049.848346 [onionperf] [INFO] Creating ephemeral hidden service...
2016-02-10 15:11:22 1455117082.793591 [onionperf] [INFO] Ephemeral hidden service is available at llx533trcg6ckpc7.onion
2016-02-10 15:11:22 1455117082.794289 [onionperf] [INFO] Starting Tor client process with ControlPort=45474, SocksPort=28006...
2016-02-10 15:11:22 1455117082.794485 [onionperf] [INFO] Logging Tor client process output to /home/ubuntu/run/onionperf-data/tor-client/onionperf.tor.log
2016-02-10 15:11:24 1455117084.762144 [onionperf] [INFO] Logging Tor client control port monitor output to /home/ubuntu/run/onionperf-data/tor-client/onionperf.torctl.log
2016-02-10 15:11:27 1455117087.765916 [onionperf] [INFO] Starting TGen client process on port 17852...
2016-02-10 15:11:27 1455117087.767585 [onionperf] [INFO] Logging TGen client process output to /home/ubuntu/run/onionperf-data/tgen-client/onionperf.tgen.log
2016-02-10 15:11:27 1455117087.768221 [onionperf] [INFO] Starting Twistd server process on port 50080...
2016-02-10 15:11:27 1455117087.768383 [onionperf] [INFO] Logging Twisted process output to /home/ubuntu/run/onionperf-data/twistd/onionperf.twisted.log
2016-02-10 15:11:27 1455117087.770162 [onionperf] [INFO] Twistd web server running at 0.0.0.0:50080
2016-02-10 15:11:27 1455117087.779889 [onionperf] [INFO] Bootstrapping finished, entering heartbeat loop
2016-02-10 15:11:28 1455117088.780653 [onionperf] [INFO] tgen_server_watchdog is alive
2016-02-10 15:11:28 1455117088.781053 [onionperf] [INFO] tor_server_watchdog is alive
2016-02-10 15:11:28 1455117088.781195 [onionperf] [INFO] torctl_server_helper is alive
2016-02-10 15:11:28 1455117088.781333 [onionperf] [INFO] tor_client_watchdog is alive
2016-02-10 15:11:28 1455117088.781468 [onionperf] [INFO] torctl_client_helper is alive
2016-02-10 15:11:28 1455117088.781605 [onionperf] [INFO] tgen_client_watchdog is alive
2016-02-10 15:11:28 1455117088.781712 [onionperf] [INFO] twistd_watchdog is alive
2016-02-10 15:11:28 1455117088.781812 [onionperf] [INFO] logrotate is alive
2016-02-10 15:11:28 1455117088.781908 [onionperf] [INFO] All helper processes seem to be alive :)
2016-02-10 15:11:28 1455117088.782003 [onionperf] [INFO] Main process will now sleep for 1 hour (helper processes run on their own schedule)
2016-02-10 15:11:28 1455117088.782126 [onionperf] [INFO] press CTRL-C for graceful shutdown...

In particular the tgen_server_watchdog is alive part is somewhat confusing.

Here's one of the error message from tgen-server/onionperf.tgen.log:

2016-02-10 14:47:37 1455115657.602374 [critical] [shd-tgen-server.c:75] [tgenserver_new] bind(): socket 12 returned -1 error 13: Permission denied
2016-02-10 14:47:37 1455115657.602401 [critical] [shd-tgen-main.c:138] [_tgenmain_run] Error initializing new TrafficGen instance

Add digests and sizes to index.xml

To allow CollecTor to know if it's downloaded the file successfully, add a filesize in bytes and a base64-encoded SHA-256 digest to index.xml. For some level of future proofing, we could also add a base64-encoded SHA3-256 digest.

Many fields in Torperf output contain value 0.0

I found that quite a few fields in the Torperf output file have value 0.0. Example:

BUILDTIMES=0.47000002861,0.579999923706,0.840000152588 CIRC_ID=3343 CONNECT=0.0 DATACOMPLETE=1460635757.86 DATAPERC0=1460635757.24 DATAPERC10=1460635757.30 DATAPERC100=1460635757.86 DATAPERC20=1460635757.34 DATAPERC30=1460635757.36 DATAPERC40=1460635757.43 DATAPERC50=1460635757.48 DATAPERC60=1460635757.50 DATAPERC70=1460635757.62 DATAPERC80=1460635757.64 DATAPERC90=1460635757.76 DATAREQUEST=0.0 DATARESPONSE=0.0 DIDTIMEOUT=0 ENDPOINTLOCAL=localhost:127.0.0.1:58696 ENDPOINTPROXY=localhost:127.0.0.1:24910 ENDPOINTREMOTE=ec2-54-165-62-142.compute-1.amazonaws.com:54.165.62.142:80 FILESIZE=51200 HOSTNAMELOCAL=ip-172-16-0-86 HOSTNAMEREMOTE=ip-172-16-0-86 LAUNCH=1460635515.79 NEGOTIATE=0.0 PATH=$4DDA0BF725794C4703418514F3C46FAFA97EE931,$6E41F9BC3FE626D1897865CE9A9335D09A8DA5FE,$B74E1FB45443357979FE2A44CE0FEC1C2E20E431 QUANTILE=0.8 READBYTES=51278 REQUEST=0.0 RESPONSE=0.0 SOCKET=1460635756.62 SOURCE=ip-172-16-0-86 START=1460635756.62 TIMEOUT=1500 USED_AT=1460635757.86 USED_BY=6904 WRITEBYTES=63

See CONNECT, DATAREQUEST, DATARESPONSE, etc.

I noticed that previous runs produced lines with non-zero values there. The last such line is from 2016-03-24. Could it be that one of the last commits (shadow or onionperf) broke the code to fill in non-zero values there?

create new torperf tgen model

Create a new tgen model that mimics the current behavior of TorPerf. This includes downloading 50k, 1m, and 5m downloads, with absolute pause times so that timeouts don't change the number of downloads that happen every minute.

So this would go start -> pause -> transfer, where the pause loops back to itself.

Usage instructions suggest wrong placement of -h parameter

This is a very minor issue, but it might confuse new users.

The usage instructions say:

usage: onionperf [-h] {monitor,measure,analyze,visualize} ...

But the correct syntax would be:

usage: onionperf {monitor,measure,analyze,visualize} [-h] ...

Further down below the usage instructions (correctly) say:

Use 'onionperf <subcommand> --help' for more info

Maybe there's an easy fix?

process torctl/tgen logs and convert stats to torperf 1.0 format

Read stdout from the tor and tgen processes, log that info to file, and also pass it off to a worker that will produce a .tpf file in the current type torperf 1.0 format.

Attempt to search for tor binary and tgen binary if paths not given

Sensible test paths are probably /usr/local/bin and /usr/bin.

NoneType error when casting circuit_id to Int

I have noticed some of my measurements file are empty because of a NoneType to Int casting error. Details below:

 onionperf analyze -t --tgen=tgen-client/log_archive/onionperf_2017-03-15_23\:59\:59.tgen.log --torctl=tor-client/log_archive/onionperf_2017-03-15_23\:59\:59.torctl.log -p=twistd/docroot/
2017-03-20 09:50:02 1490003402.446086 [onionperf] [INFO] parsing log file at /home/cloud/onionperf/onionperf-data/tgen-client/log_archive/onionperf_2017-03-15_23:59:59.tgen.log
2017-03-20 09:50:03 1490003403.142353 [onionperf] [INFO] parsing log file at /home/cloud/onionperf/onionperf-data/tor-client/log_archive/onionperf_2017-03-15_23:59:59.torctl.log
545 795
2017-03-20 09:50:15 1490003415.877429 [onionperf] [INFO] saving analysis results to /home/cloud/onionperf/onionperf-data/twistd/docroot/onionperf.analysis.json.xz
2017-03-20 09:50:24 1490003424.114065 [onionperf] [INFO] done!
2017-03-20 09:50:24 1490003424.114919 [onionperf] [INFO] saving analysis results to /home/cloud/onionperf/onionperf-data/twistd/docroot/op-us-5242880-2017-03-20.tpf.xz
Traceback (most recent call last):
  File "/usr/local/bin/onionperf", line 472, in <module>
    if __name__ == '__main__': sys.exit(main())
  File "/usr/local/bin/onionperf", line 318, in main
    args.func(args)
  File "/usr/local/bin/onionperf", line 392, in analyze
    analysis.export_torperf_version_1_0(output_prefix=args.prefix, do_compress=True)
  File "/usr/local/lib/python2.7/dist-packages/onionperf/analysis.py", line 207, in export_torperf_version_1_0
    circid = int(stream_db['circuit_id'])
TypeError: int() argument must be a string or a number, not 'NoneType'

HOSTNAMEREMOTE contains HTTP

Pasting from issue 18:

"I noticed that some of the 'HOSTNAMEREMOTE' keys in your data contained 'HTTP'; that is not correct. I think this is because you are using an old version of TGen that does not do some basic authentication with itself, and so the server is being connected to by a non-tgen client that thinks it is a regular HTTP server."

Example (second line contains HTTP):

@type torperf 1.0
BUILDTIMES=0.410000085831,0.5,0.649999856949 CIRC_ID=372 CONNECT=0.0 DATACOMPLETE=1458973033.40 DATAPERC0=1458972994.86 DATAPERC10=1458973001.62 DATAPERC100=1458973033.40 DATAPERC20=1458973005.54 DATAPERC30=1458973008.36 DATAPERC40=1458973011.13 DATAPERC50=1458973015.05 DATAPERC60=1458973019.12 DATAPERC70=1458973022.85 DATAPERC80=1458973026.48 DATAPERC90=1458973029.24 DATAREQUEST=0.0 DATARESPONSE=0.0 DIDTIMEOUT=0 ENDPOINTLOCAL=localhost:127.0.0.1:44766 ENDPOINTPROXY=localhost:127.0.0.1:12380 ENDPOINTREMOTE=ec2-54-165-62-142.compute-1.amazonaws.com:54.165.62.142:80 FILESIZE=5242880 HOSTNAMELOCAL=ip-172-16-0-86 HOSTNAMEREMOTE=ip-172-16-0-86 LAUNCH=1458972727.22 NEGOTIATE=0.0 PATH=$68A8F6716B75B777E6B180AF60ECE615BD91B93B,$21281A01279875A67C4FD2C6B125AC0587CBF9F9,$379FB450010D17078B3766C2273303C358C3A442 QUANTILE=0.8 READBYTES=5242936 REQUEST=0.0 RESPONSE=0.0 SOCKET=1458972993.23 SOURCE=ip-172-16-0-86 START=1458972993.23 TIMEOUT=1500 USED_AT=1458973033.4 USED_BY=708 WRITEBYTES=63
@type torperf 1.0
BUILDTIMES=0.569999933243,0.72000002861,1.21000003815 CIRC_ID=637 CONNECT=0.0 DATACOMPLETE=0.0 DATAPERC0=1459026393.69 DATAPERC10=0.0 DATAPERC20=0.0 DATAPERC30=0.0 DATAPERC40=0.0 DATAPERC50=0.0 DATAPERC60=0.0 DATAPERC70=0.0 DATAPERC80=0.0 DATAPERC90=0.0 DATAREQUEST=0.0 DATARESPONSE=0.0 DIDTIMEOUT=1 ENDPOINTLOCAL=localhost:127.0.0.1:45214 ENDPOINTPROXY=localhost:127.0.0.1:12380 ENDPOINTREMOTE=ec2-54-165-62-142.compute-1.amazonaws.com:54.165.62.142:80 FILESIZE=5242880 HOSTNAMELOCAL=ip-172-16-0-86 HOSTNAMEREMOTE=HTTP/1.1 LAUNCH=1459026155.22 NEGOTIATE=0.0 PATH=$7E44E0D39CE8666A98EA5DEBCBB8E12B3906410F,$6EFF230516717B09A5D0C79C8EF0A192DA769044,$C68988E3DD72549AD9C3D1A67FAD056241154775 QUANTILE=0.8 READBYTES=196 REQUEST=0.0 RESPONSE=0.0 SOCKET=1459026393.44 SOURCE=ip-172-16-0-86 START=1459026393.44 TIMEOUT=1500 USED_AT=1459026393.84 USED_BY=1253 WRITEBYTES=63

I think I'm using shadow commit f349fe5. Is there a way to display the tgen version on the console?

ubuntu@ip-172-16-0-86:~/shadow/src/plugin/shadow-plugin-tgen/build$ ./tgen --help
2016-03-27 09:34:28 1459071268.045555 [message] [shd-tgen-main.c:90] [_tgenmain_run] Initializing traffic generator on host ip-172-16-0-86 using log domain ip-172-16-0-86-tgen-30185
2016-03-27 09:34:28 1459071268.045747 [critical] [shd-tgen-graph.c:616] [tgengraph_new] path '--help' to tgen config graph is not valid or does not exist
2016-03-27 09:34:28 1459071268.045845 [critical] [shd-tgen-main.c:120] [_tgenmain_run] cannot continue: traffic generator config file '--help' failed validation
ubuntu@ip-172-16-0-86:~/shadow/src/plugin/shadow-plugin-tgen/build$ ./tgen --version
2016-03-27 09:34:39 1459071279.442808 [message] [shd-tgen-main.c:90] [_tgenmain_run] Initializing traffic generator on host ip-172-16-0-86 using log domain ip-172-16-0-86-tgen-30186
2016-03-27 09:34:39 1459071279.442936 [critical] [shd-tgen-graph.c:616] [tgengraph_new] path '--version' to tgen config graph is not valid or does not exist
2016-03-27 09:34:39 1459071279.442960 [critical] [shd-tgen-main.c:120] [_tgenmain_run] cannot continue: traffic generator config file '--version' failed validation

I uploaded the data directory here:

https://people.torproject.org/~karsten/volatile/onionperf-data-2016-03-27.tar.bz2

Traceback when producing .tpf file

$ onionperf analyze --tgen ~/run/onionperf-data/tgen-client/onionperf.tgen.log --torctl ~/run/onionperf-data/tor-client/onionperf.torctl.log -t
2016-03-16 10:41:06 1458124866.543423 [onionperf] [INFO] parsing log file at /home/ubuntu/run/onionperf-data/tgen-client/onionperf.tgen.log
2016-03-16 10:41:06 1458124866.743521 [onionperf] [INFO] parsing log file at /home/ubuntu/run/onionperf-data/tor-client/onionperf.torctl.log
160 176
2016-03-16 10:41:10 1458124870.677777 [onionperf] [INFO] saving analysis results to /home/ubuntu/test/onionperf.analysis.json.xz
2016-03-16 10:41:12 1458124872.602096 [onionperf] [INFO] done!
2016-03-16 10:41:12 1458124872.602630 [onionperf] [INFO] saving analysis results to /home/ubuntu/test/ip-172-16-0-86-51200-2016-03-16.tpf.xz
{'last_byte': 0.727828, 'proxy_request': 0.00078, 'checksum': 0.727953, 'proxy_response': 0.179567, 'socket_connect': 0.000161, 'first_byte': 0.430547, 'proxy_init': 0.000204, 'command': 0.179648, 'proxy_choice': 0.000687, 'payload_progress': {0.0: 0.43041086196899414, 0.5: 0.5566728115081787, 0.4: 0.554987907409668, 0.8: 0.7180359363555908, 1.0: 0.7279529571533203, 0.1: 0.43041086196899414, 0.3: 0.4822959899902344, 0.6: 0.6364848613739014, 0.2: 0.47347283363342285, 0.9: 0.7196469306945801, 0.7: 0.6382029056549072}, 'response': 0.391301, 'socket_create': 9e-06}
{'last_byte': 0.957269, 'proxy_request': 0.000792, 'checksum': 0.957411, 'proxy_response': 0.301671, 'socket_connect': 0.000155, 'first_byte': 0.6422, 'proxy_init': 0.000198, 'command': 0.301736, 'proxy_choice': 0.000699, 'payload_progress': {0.0: 0.6420190334320068, 0.5: 0.755763053894043, 0.4: 0.7552042007446289, 0.8: 0.9045040607452393, 1.0: 0.9574110507965088, 0.1: 0.6420190334320068, 0.3: 0.7545981407165527, 0.6: 0.7615780830383301, 0.2: 0.6827092170715332, 0.9: 0.9054610729217529, 0.7: 0.8771240711212158}, 'response': 0.602979, 'socket_create': 9e-06}
{'last_byte': 1.408053, 'proxy_request': 0.000837, 'checksum': 1.408189, 'proxy_response': 0.410534, 'socket_connect': 0.00017, 'first_byte': 0.91325, 'proxy_init': 0.000213, 'command': 0.410607, 'proxy_choice': 0.000731, 'payload_progress': {0.0: 0.9130940437316895, 0.5: 1.102247953414917, 0.4: 1.063920021057129, 0.8: 1.2117180824279785, 1.0: 1.408189058303833, 0.1: 0.922875165939331, 0.3: 1.0104780197143555, 0.6: 1.185028076171875, 0.2: 0.9245650768280029, 0.9: 1.310528039932251, 0.7: 1.1860589981079102}, 'response': 0.81761, 'socket_create': 9e-06}
{'last_byte': 1.008355, 'proxy_request': 0.000745, 'checksum': 1.008492, 'proxy_response': 0.26041, 'socket_connect': 0.000154, 'first_byte': 0.642004, 'proxy_init': 0.000196, 'command': 0.260484, 'proxy_choice': 0.000656, 'payload_progress': {0.0: 0.641855001449585, 0.5: 0.8088200092315674, 0.4: 0.7797598838806152, 0.8: 0.8774838447570801, 1.0: 1.0084919929504395, 0.1: 0.6485989093780518, 0.3: 0.776033878326416, 0.6: 0.8739898204803467, 0.2: 0.686694860458374, 0.9: 0.9392130374908447, 0.7: 0.8739898204803467}, 'response': 0.64196, 'socket_create': 9e-06}
{'last_byte': 1.598095, 'proxy_request': 0.000808, 'checksum': 1.598229, 'proxy_response': 0.398845, 'socket_connect': 0.00017, 'first_byte': 0.835746, 'proxy_init': 0.000215, 'command': 0.39891, 'proxy_choice': 0.000717, 'payload_progress': {0.0: 0.8355889320373535, 0.5: 1.1602349281311035, 0.4: 1.1273140907287598, 0.8: 1.2698230743408203, 1.0: 1.598228931427002, 0.1: 0.8355889320373535, 0.3: 0.980633020401001, 0.6: 1.1625261306762695, 0.2: 0.8413970470428467, 0.9: 1.3796019554138184, 0.7: 1.1625261306762695}, 'response': 0.799344, 'socket_create': 9e-06}
{'last_byte': 1.047385, 'proxy_request': 0.000733, 'checksum': 1.047534, 'proxy_response': 0.321719, 'socket_connect': 0.000164, 'first_byte': 0.683479, 'proxy_init': 0.000206, 'command': 0.32178, 'proxy_choice': 0.000648, 'payload_progress': {0.0: 0.6832559108734131, 0.5: 0.8047139644622803, 0.4: 0.7945969104766846, 0.8: 0.94610595703125, 1.0: 1.0475339889526367, 0.1: 0.7028329372406006, 0.3: 0.792855978012085, 0.6: 0.837803840637207, 0.2: 0.7512240409851074, 0.9: 0.9545559883117676, 0.7: 0.8492250442504883}, 'response': 0.64676, 'socket_create': 1e-05}
{'payload_progress': {0.0: 0.1113278865814209}, 'proxy_request': 0.000926, 'proxy_response': 0.111466, 'socket_connect': 0.000197, 'first_byte': 0.233029, 'proxy_init': 0.00025, 'command': 0.111528, 'proxy_choice': 0.000717, 'response': 0.232986, 'socket_create': 1e-05}
Traceback (most recent call last):
  File "/usr/local/bin/onionperf", line 459, in <module>
    if __name__ == '__main__': sys.exit(main())
  File "/usr/local/bin/onionperf", line 312, in main
    args.func(args)
  File "/usr/local/bin/onionperf", line 385, in analyze
    analysis.export_torperf_version_1_0(output_prefix=args.prefix, do_compress=True)
  File "/usr/local/lib/python2.7/dist-packages/onionperf/analysis.py", line 187, in export_torperf_version_1_0
    d['DATACOMPLETE'] = ts_to_str(xfer_db['unix_ts_start'] + xfer_db['elapsed_seconds']['last_byte'])
KeyError: 'last_byte'

This is ae3a739 with an additional debug line:

diff --git a/onionperf/analysis.py b/onionperf/analysis.py
index 830d52d..aeb590c 100644
--- a/onionperf/analysis.py
+++ b/onionperf/analysis.py
@@ -183,6 +183,7 @@ class Analysis(object):
                         if xfer_db['elapsed_seconds']['payload_progress'][decile] is not None:
                             d['DATAPERC{0}'.format(int(decile * 100))] = ts_to_str(xfer_db['unix_ts_start'] + xfer_db['elapsed_seconds']['payload_progress'][decile])

+                    print xfer_db['elapsed_seconds']
                     d['DATACOMPLETE'] = ts_to_str(xfer_db['unix_ts_start'] + xfer_db['elapsed_seconds']['last_byte'])
                     # could be ioerror or timeout or etc, but i dont think torperf distinguishes these
                     d['DIDTIMEOUT'] = 1 if xfer_db['is_error'] is True else 0

I'm unsure what the right fix is here, because I don't know the reason why the last_byte field would be missing there. Maybe we can just skip that line then, but I'm not sure.

Relay blacklist

Allow onionperf to blacklist certain relays that may be running on the same machine as itself.

README is not honest about download frequency

The README says: by default it will download files over Tor every 60 minutes, and log the results., but that doesn't seem to be correct:

vagrant@vagrant:/vagrant/.onionperf$ grep transfer-complete client/tgen/tgen.log
2015-06-25 02:14:18 1435223658.161358 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-51200-vagrant-1-state=SUCCESS-error=NONE) total-bytes-read=51247 total-bytes-write=20 payload-bytes-read=51200/51200 (100.00%) msecs-to-command=3268 msecs-to-response=3712 msecs-to-first-byte=3712 msecs-to-last-byte=4435 msecs-to-checksum=4435
2015-06-25 02:14:41 1435223681.728424 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-1048576-vagrant-2-state=SUCCESS-error=NONE) total-bytes-read=1048623 total-bytes-write=22 payload-bytes-read=1048576/1048576 (100.00%) msecs-to-command=1461 msecs-to-response=1872 msecs-to-first-byte=1872 msecs-to-last-byte=12992 msecs-to-checksum=12992
2015-06-25 02:15:49 1435223749.921022 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-5242880-vagrant-3-state=SUCCESS-error=NONE) total-bytes-read=5242927 total-bytes-write=22 payload-bytes-read=5242880/5242880 (100.00%) msecs-to-command=1509 msecs-to-response=1777 msecs-to-first-byte=1777 msecs-to-last-byte=56165 msecs-to-checksum=56165
2015-06-25 02:16:05 1435223765.227869 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-51200-vagrant-4-state=SUCCESS-error=NONE) total-bytes-read=51247 total-bytes-write=20 payload-bytes-read=51200/51200 (100.00%) msecs-to-command=716 msecs-to-response=865 msecs-to-first-byte=865 msecs-to-last-byte=1450 msecs-to-checksum=1450
2015-06-25 02:16:34 1435223794.344534 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-1048576-vagrant-5-state=SUCCESS-error=NONE) total-bytes-read=1048623 total-bytes-write=22 payload-bytes-read=1048576/1048576 (100.00%) msecs-to-command=1908 msecs-to-response=2327 msecs-to-first-byte=2327 msecs-to-last-byte=15550 msecs-to-checksum=15550
2015-06-25 02:17:43 1435223863.658843 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-5242880-vagrant-6-state=SUCCESS-error=NONE) total-bytes-read=5242927 total-bytes-write=22 payload-bytes-read=5242880/5242880 (100.00%) msecs-to-command=1049 msecs-to-response=1269 msecs-to-first-byte=1269 msecs-to-last-byte=54846 msecs-to-checksum=54846
2015-06-25 02:17:55 1435223875.900771 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-51200-vagrant-7-state=SUCCESS-error=NONE) total-bytes-read=51247 total-bytes-write=20 payload-bytes-read=51200/51200 (100.00%) msecs-to-command=1019 msecs-to-response=1367 msecs-to-first-byte=1367 msecs-to-last-byte=2068 msecs-to-checksum=2068
2015-06-25 02:18:20 1435223900.897727 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-1048576-vagrant-8-state=SUCCESS-error=NONE) total-bytes-read=1048623 total-bytes-write=22 payload-bytes-read=1048576/1048576 (100.00%) msecs-to-command=894 msecs-to-response=1107 msecs-to-first-byte=1107 msecs-to-last-byte=12049 msecs-to-checksum=12049
2015-06-25 02:19:30 1435223970.031802 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-5242880-vagrant-9-state=SUCCESS-error=NONE) total-bytes-read=5242927 total-bytes-write=22 payload-bytes-read=5242880/5242880 (100.00%) msecs-to-command=891 msecs-to-response=1165 msecs-to-first-byte=1165 msecs-to-last-byte=56166 msecs-to-checksum=56166
2015-06-25 02:19:46 1435223986.270630 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-51200-vagrant-10-state=SUCCESS-error=NONE) total-bytes-read=51248 total-bytes-write=20 payload-bytes-read=51200/51200 (100.00%) msecs-to-command=1270 msecs-to-response=1756 msecs-to-first-byte=1756 msecs-to-last-byte=2380 msecs-to-checksum=2380
2015-06-25 02:20:10 1435224010.962650 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-1048576-vagrant-11-state=SUCCESS-error=NONE) total-bytes-read=1048624 total-bytes-write=22 payload-bytes-read=1048576/1048576 (100.00%) msecs-to-command=984 msecs-to-response=1237 msecs-to-first-byte=1237 msecs-to-last-byte=12053 msecs-to-checksum=12053
2015-06-25 02:26:27 1435224387.761450 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-5242880-vagrant-12-state=SUCCESS-error=NONE) total-bytes-read=5242928 total-bytes-write=22 payload-bytes-read=5242880/5242880 (100.00%) msecs-to-command=29369 msecs-to-response=41862 msecs-to-first-byte=41862 msecs-to-last-byte=363834 msecs-to-checksum=363834
2015-06-25 02:26:41 1435224401.308383 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-51200-vagrant-13-state=SUCCESS-error=NONE) total-bytes-read=51248 total-bytes-write=20 payload-bytes-read=51200/51200 (100.00%) msecs-to-command=1199 msecs-to-response=1630 msecs-to-first-byte=1630 msecs-to-last-byte=2311 msecs-to-checksum=2311
2015-06-25 02:27:11 1435224431.722295 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-1048576-vagrant-14-state=SUCCESS-error=NONE) total-bytes-read=1048624 total-bytes-write=22 payload-bytes-read=1048576/1048576 (100.00%) msecs-to-command=1338 msecs-to-response=1543 msecs-to-first-byte=1543 msecs-to-last-byte=17710 msecs-to-checksum=17710
2015-06-25 02:28:34 1435224514.875506 [message] [_tgentransfer_log] [transfer-complete] transport (TCP-10-localhost:127.0.0.1:9001-fgbnngzbmpjwtqs2.onion:(null):80) transfer (1-vagrant-GET-5242880-vagrant-15-state=SUCCESS-error=NONE) total-bytes-read=5242928 total-bytes-write=22 payload-bytes-read=5242880/5242880 (100.00%) msecs-to-command=14055 msecs-to-response=14434 msecs-to-first-byte=14434 msecs-to-last-byte=70845 msecs-to-checksum=70845

TGen server dies after roughly 24 hours for no obvious reason

My OnionPerf instance ran for about 24 hours before outputting the following warnings and terminating:

2016-03-10 12:19:10 1457612350.177991 [onionperf] [INFO] press CTRL-C for graceful shutdown...
2016-03-10 13:14:18 1457615658.720360 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:19 1457615659.730137 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:19 1457615659.737811 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:19 1457615659.743993 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:19 1457615659.750354 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:19 1457615659.756135 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:19 1457615659.761863 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:20 1457615660.768629 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:21 1457615661.776609 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:21 1457615661.783704 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:14:21 1457615661.789633 [onionperf] [WARNING] command '/home/ubuntu/shadow/src/plugin/shadow-plugin-tgen/build/tgen /home/ubuntu/run/onionperf-data/tgen-server/tgen.graphml.xml' finished before expected
2016-03-10 13:19:10 1457615950.259332 [onionperf] [WARNING] tgen_server_watchdog is dead!
2016-03-10 13:19:10 1457615950.259518 [onionperf] [INFO] tor_client_watchdog is alive
2016-03-10 13:19:10 1457615950.259616 [onionperf] [INFO] torctl_client_helper is alive
2016-03-10 13:19:10 1457615950.259697 [onionperf] [INFO] tgen_client_watchdog is alive
2016-03-10 13:19:10 1457615950.259775 [onionperf] [INFO] twistd_watchdog is alive
2016-03-10 13:19:10 1457615950.259852 [onionperf] [INFO] logrotate is alive
2016-03-10 13:19:10 1457615950.259937 [onionperf] [WARNING] Some parallel components failed too many times or have died :(
2016-03-10 13:19:10 1457615950.260010 [onionperf] [INFO] We are in a broken state, giving up and exiting now
2016-03-10 13:19:10 1457615950.260098 [onionperf] [INFO] Cleaning up child processes now...
2016-03-10 13:19:10 1457615950.260201 [onionperf] [INFO] Joining tgen_server_watchdog thread...
2016-03-10 13:19:10 1457615950.260302 [onionperf] [INFO] Joining tor_client_watchdog thread...
2016-03-10 13:19:10 1457615950.455452 [onionperf] [INFO] Joining torctl_client_helper thread...
2016-03-10 13:19:11 1457615951.095762 [onionperf] [INFO] Joining tgen_client_watchdog thread...
2016-03-10 13:19:11 1457615951.095964 [onionperf] [INFO] Joining twistd_watchdog thread...
2016-03-10 13:19:11 1457615951.096088 [onionperf] [INFO] Joining logrotate thread...
2016-03-10 13:19:12 1457615952.097378 [onionperf] [INFO] Child processes terminated
2016-03-10 13:19:12 1457615952.097585 [onionperf] [INFO] Child process cleanup complete!
2016-03-10 13:19:12 1457615952.097669 [onionperf] [INFO] Exiting

I don't really know how to debug this, that's why I'm pasting more details about my setup here in the hope that you can figure out.

Command to start OnionPerf:

onionperf measure --tor ~/tor/src/or/tor --tgen ~/shadow/src/plugin/shadow-plugin-tgen/build/tgen --tgen-connect-port 80 --twistd-port 50080 --no-onion --tgen-connect-ip 54.165.62.142

Tor version 0.2.7.6-dev (git-b0474572de5b9556).

Shadow commit 05fff25690ed1ea7241e2214e689ffec525d2230.

OnionPerf commit 44fb7a4 with a manual patch of the --tgen-connect-ip code:

diff --git a/onionperf/onionperf b/onionperf/onionperf
index f876214..f062e8c 100755
--- a/onionperf/onionperf
+++ b/onionperf/onionperf
@@ -438,7 +438,7 @@ def type_str_ip_in(value):
     ip = re.match(r'[\d]{1,3}\.[\d]{1,3}\.[\d]{1,3}\.[\d]{1,3}', s)
     if ip is None:
         raise argparse.ArgumentTypeError("IP address '%s' is not a valid address" % s)
-    return ip
+    return ip.group(0)

 # a custom action for passing in experimental data directories when plotting
 class PathStringArgsAction(argparse.Action):

Tarball with OnionPerf data directory available at https://people.torproject.org/~karsten/volatile/onionperf-data.tar.xz

add single onion service mode

Currently, OnionPerf can download over regular 3-relay-hop Tor circuit and to an ephemeral hidden service over a 6-relay-hop circuit. Now that single onion services are merged into Tor, we can also test its performance.

Make ports configurable

Currently all ports are hardcoded without documented options to change them.

build/lib/onionperf/measurement.py:    def run(self, do_onion=True, do_inet=True, client_tgen_listen_port=58888, client_tgen_connect_ip='0.0.0.0', client_tgen_connect_port=8080, client_tor_ctl_port=59050, client_tor_socks_port=59000,
build/lib/onionperf/measurement.py:        client_tgen_listen_port=58888, client_tgen_connect_port=8080, client_tor_ctl_port=59050, client_tor_socks_port=59000,
venv/lib/python3.6/site-packages/stem/response/getinfo.py:    # ORPort 9050
venv/lib/python3.6/site-packages/stem/util/ports.cfg:port 9050 => Tor
venv/lib/python3.6/site-packages/stem/util/system.py:  #   _tor     tor        4397  7  tcp4   51.64.7.84:9050    *:*
venv/lib/python3.6/site-packages/stem/util/connection.py:  # 3561 tor                 4 s - rw---n--   2       0 TCP 10.0.0.2:9050 10.0.0.1:22370
venv/lib/python3.6/site-packages/stem/cached_fallbacks.cfg:12AD30E5D25AA67F519780E2111E611A455FDC89.orport6_port 9050
venv/lib/python3.6/site-packages/stem/cached_fallbacks.cfg:439D0447772CB107B886F7782DBC201FA26B92D1.orport6_port 9050
venv/lib/python3.6/site-packages/stem/cached_fallbacks.cfg:7A32C9519D80CA458FC8B034A28F5F6815649A98.orport6_port 9050
venv/lib/python3.6/site-packages/stem/socket.py:  def __init__(self, address = '127.0.0.1', port = 9050, connect = True):

update torperf type to 1.1

See here:
https://trac.torproject.org/projects/tor/ticket/22263

Persistent Onion service address

Currently it looks like the Onion service address changes with every restart. This makes monitoring more difficult.

All OnionPerf downloads randomly started failing

For some reason all attempted downloads on my OnionPerf instance started failing due to READ errors starting on April 1st.

cd onionperf-deata/twistd/docroot
for i in *xz; do echo ${i}; xzcat ${i} | grep "is_error" | sort | uniq -c; done

That shows that there are no successful downloads after the file corresponding to April 1st.

2016-03-31.onionperf.analysis.json.xz
     30             "is_error": false,
2016-04-01.onionperf.analysis.json.xz
    164             "is_error": false,
    124             "is_error": true,
2016-04-02.onionperf.analysis.json.xz
    287             "is_error": true,
2016-04-03.onionperf.analysis.json.xz
    288             "is_error": true,
...

First execution ends with traceback, subsequent executions run just fine

vagrant@vagrant:/vagrant$ ./onionperf --tgen=/vagrant/shadow/src/plugin/shadow-plugin-tgen/build/tgen 
2015-06-25 02:11:06 1435223466.818067 [onionperf] [INFO] Using 'tor' binary at /usr/bin/tor
2015-06-25 02:11:06 1435223466.819609 [onionperf] [INFO] Using 'tgen' binary at /vagrant/shadow/src/plugin/shadow-plugin-tgen/build/tgen
2015-06-25 02:11:06 1435223466.821230 [onionperf] [INFO] Starting tgen server...
2015-06-25 02:11:06 1435223466.822458 [onionperf] [INFO] Starting tor server...
2015-06-25 02:11:28 1435223488.737308 [onionperf] [INFO] Starting tor client...
2015-06-25 02:11:45 1435223505.617906 [onionperf] [INFO] Starting tor loggers...
2015-06-25 02:11:45 1435223505.620156 [onionperf] [INFO] Pausing for 30 seconds to publish hidden service descriptor...
2015-06-25 02:12:15 1435223535.650621 [onionperf] [INFO] Starting tgen client...
2015-06-25 02:12:15 1435223535.651478 [onionperf] [INFO] Log files for the client and server porcesses are located in /vagrant
2015-06-25 02:12:15 1435223535.652675 [onionperf] [INFO] Cleaning up child processes now...
2015-06-25 02:12:17 1435223537.660627 [onionperf] [INFO] Child processes terminated
2015-06-25 02:12:17 1435223537.665249 [onionperf] [INFO] Child process cleanup complete!
2015-06-25 02:12:17 1435223537.665699 [onionperf] [INFO] Exiting
Traceback (most recent call last):
  File "./onionperf", line 388, in <module>
    if __name__ == '__main__': sys.exit(main())
  File "./onionperf", line 110, in main
    op.run()
  File "./onionperf", line 155, in run
    logging.info("Heartbeat: {0} downloads have completed successfully".format(self.__get_download_count()))
  File "./onionperf", line 187, in __get_download_count
    with open(".onionperf/client/tgen/tgen.log", 'r') as fin:
IOError: [Errno 2] No such file or directory: '.onionperf/client/tgen/tgen.log'

My assumption is that that file is written shortly after onionperf expects it to exist.

Monitor custom Tor events

Is it possible to monitor custom Tor events through the "--event" option?

Right now,

onionperf/onionperf/onionperf

Line 123 in 3b2b9eb

choices=get_supported_torctl_events())

you can only monitor events listed by get_supported_torctl_events() (

onionperf/onionperf/monitor.py

Line 15 in 3b2b9eb

def get_supported_torctl_events():

onionperf/onionperf/monitor.py

Line 15 in 3b2b9eb

def get_supported_torctl_events():

basically lists stem.control.EventType.

fix message logging and filtering

When running in measurement mode, new analysis results are produced every night at midnight utc. However, in cases when OnionPerf was not running at midnight and restarts on a later day, log messages from both partial days appear in the same log file. When the analysis is run at the midnight following the day it was restarted, downloads from the day it was first stopped may appear in the analysis results (the .tpf files).

We should fix this.

allow onionperf analysis mode to filter out log messages that do not match a certain date; onionperf measurement mode should take advantage of that feature
When exporting Torperf .tpf files, and a date filter is applied, we need to ensure that we do not include downloads that started on a different day (to handle the case where it ended on the filtered date but started on the previous day)
onionperf should name the log files according to the date of the log message timestamps, and each log message should only be appended to the file corresponding to that date

Measure mode with arbitrary tgen traffic models

onionperf measure currently runs using a Torperf-like measurement model by default. We should allow any tgen model to be given on the command line, and then our tgen client should use that model instead.

tgen should flush its internal write buffer for log files after each line

It looks like tgen uses an internal write buffer of size 4k and only flushes that buffer when it's full. The effects are that log files don't contain recent lines and that the last line is almost always truncated. Would it be possible to flush the buffer after writing a line?

It remains unclear whether/how the hidden-service descriptor cache is cleared

In Torperf, I'm using a modified tor version that accepts a USR2 signal to clear the hidden-service descriptor cache between runs. But OnionPerf seems to work just fine with an unmodified tor version. Does it also clear the cache between runs, and if so, how? If not, doesn't that make results harder to compare, because some of them will include descriptor fetches and some not?

Add new config option to specify public IP address

I'm running OnionPerf on an EC2 instance with this ifconfig output:

eth0      Link encap:Ethernet  HWaddr 0e:72:3c:bd:26:a1  
          inet addr:172.16.0.86  Bcast:172.16.0.255  Mask:255.255.255.0
          inet6 addr: fe80::c72:3cff:febd:26a1/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:9001  Metric:1
          RX packets:661816 errors:0 dropped:0 overruns:0 frame:0
          TX packets:476454 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:363109016 (363.1 MB)  TX bytes:113909581 (113.9 MB)

lo        Link encap:Local Loopback  
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:65536  Metric:1
          RX packets:164714 errors:0 dropped:0 overruns:0 frame:0
          TX packets:164714 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0 
          RX bytes:31426744 (31.4 MB)  TX bytes:31426744 (31.4 MB)

But the public IP address is 54.165.x.x. Would it be possible to add a config option for the IP address that overrides whatever OnionPerf guesses as the server's IP address?

support downloads through tor to an external tgen server

Collect statistics to an external, location-aware server running outside of Tor.

log the public IP address of the measurement node

The IP address of where each of the OnionPerf downloads are being performed will be useful for network location purposes, and may shed some light on performance results.

document the onionperf 1.0 json format

Add a description of keys/values to the README or a separate document in the repo.

onionperf monitor creates a directory when file doesn't exist

Running

onionperf monitor -l /path/to/a/file

if /path/to/a/file does not point to an existing file will create the /path/to/a/file directory. I'm not sure this is the expected behavior. I think onionperf should create the file instead.

add config option for onion service connect port

In the case where the user has some sort of proxy set up to handle incoming Internet connections, it may be useful to allow them to specify a port on which to connect to the onion service that is distinct from the port where they request regular Internet downloads.

remove twistd web server

Stop serving tpf files with OnionPerf using the twistd web server. The user can choose to make them available by other means, e.g., nginx.

Port to python3

https://docs.python.org/3/howto/pyporting.html
https://docs.python.org/2/library/2to3.html#to3-reference

Make the default model more similar to actual Torperf behavior

I noticed that the default model in OnionPerf is slightly different than Torperf's. Torperf makes requests as follows:

*:00 50 KiB
*:02 1 MiB
*:05 50 KiB
*:08 5 MiB
*:10 50 KiB
*:15 50 KiB
*:20 50 KiB
*:25 50 KiB
*:30 50 KiB
*:32 1 MiB
*:35 50 KiB
*:40 50 KiB
*:45 50 KiB
*:50 50 KiB
*:55 50 KiB

But OnionPerf picks one of the three downloads at random every 5 minutes. That means it's downloading 5 MiB much more often than Torperf. In absolute numbers:

ip-172-16-0-86-1048576-2016-03-08.tpf:38
ip-172-16-0-86-51200-2016-03-08.tpf:31
ip-172-16-0-86-5242880-2016-03-08.tpf:26

As an easy fix, how about we change the weights in OnionPerf's model as follows?

        g.add_edge("pause", "transfer50k", weight="12.0")
        g.add_edge("pause", "transfer1m", weight="2.0")
        g.add_edge("pause", "transfer5m", weight="1.0")

That's not exactly Torperf's model but hopefully a good-enough approximation.

An alternative would be to make three disconnected graphs, each of which having its own start node, an initial pause node, a transfer node, and a pause-between-requests node. But I guess TGen doesn't support multiple tokens in a graph, right?

onionperf monitor: 9050 is not a good default ctrl port

9050 is a common default SocksPort. 9051 is a common default ControlPort.