HOSTNAMEREMOTE contains HTTP

[kloesing]

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

[robgjansen]

My OnionPerf instance is also using TGen from Shadow at https://github.com/shadow/shadow/commit/f349fe5a8d876385165573f8838608d40ce82a3f

This error is happening on the TGen client. For some reason it appears that your TGen client instance is connecting to a non-TGen server port. The non-TGen server is returning HTTP/1.1 as the first part of the response where normally TGen would return the server hostname.

(There's currently no way to check the version at run time, but that certainly would be helpful wouldn't it :-/)

[robgjansen]

I fixed #17 on the TGen server side by adding in a cookie to the initial client request so that the server could ignore requests from non-TGen clients. Perhaps I should also add a cookie to the initial server response so that the client can hangup if it detects a non-TGen server.

[robgjansen]

Forgot to link the commit, added a fix here https://github.com/shadow/shadow/commit/5c74ad7585f0113fa4fbb0c16d092e18a8c995ed

Errors where the cookie is not returned to the client on the initial response will now be logged as authentication errors.

I'm testing on my instance now; @kloesing could pull the tgen update from shadow and restart your onionperf instance, and let me know the result after a day or two? Thanks!

[kloesing]

I just pulled the update and restarted onionperf. I'll let you know tomorrow. Sorry for the delay!

[kloesing]

Huh, did I say tomorrow...

So, I think this issue is fixed now. I don't find any lines containing HTTP in their HOSTNAMEREMOTE in the recent run. Yay!

What I did find though is lines containing (null) in that field. Example:

BUILDTIMES=0.519999980927,0.640000104904,0.799999952316 CIRC_ID=2951 CONNECT=0.0 DATACOMPLETE=0.0 DATAPERC0=1460555058.10 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:58036 ENDPOINTPROXY=localhost:127.0.0.1:24910 ENDPOINTREMOTE=ec2-54-165-62-142.compute-1.amazonaws.com:54.165.62.142:80 FILESIZE=5242880 HOSTNAMELOCAL=ip-172-16-0-86 HOSTNAMEREMOTE=(null) LAUNCH=1460554815.79 NEGOTIATE=0.0 PATH=$63061EF1686E9A9F1ED7F31CB9156C5BC8E886BB,$789EA6C9AE9ADDD8760903171CFA9AC5741B0C70,$122DF4F0951DC0BAD9DC437D99A76C109BDF3BD0 QUANTILE=0.8 READBYTES=26 REQUEST=0.0 RESPONSE=0.0 SOCKET=1460555056.53 SOURCE=ip-172-16-0-86 START=1460555056.53 TIMEOUT=1500 USED_AT=1460555058.1 USED_BY=6094 WRITEBYTES=64

I think that happened whenever a request timed out (DIDTIMEOUT=1). If this is expect behavior, all is good.

[robgjansen]

This is expected behavior.

Two TGen instances communicate their hostnames to each other during the request/response phase. The requester sends its hostname in the request, and the responder sends its hostname back in the response. For the requester (i.e. client), the HOSTNAMEREMOTE field will be (null) if the client never received a response from the server, which should only happen if there was some kind of error.