relay-throughput-testing/src/experiment-errors

DEBUG:root:Starting client protocol (id: 55, desc: ('127.0.0.1', 9118) -> 16: ['test003r', 'test030target', 'test048e'])
DEBUG:root:Starting client protocol (id: 5, desc: ('127.0.0.1', 9068) -> 17: ['test006r', 'test030target', 'test047e'])
DEBUG:root:Starting client protocol (id: 7, desc: ('127.0.0.1', 9070) -> 18: ['test003r', 'test030target', 'test048e'])
DEBUG:root:Starting client protocol (id: 15, desc: ('127.0.0.1', 9078) -> 17: ['test024r', 'test030target', 'test059e'])


DEBUG:root:Circuit 17 (CONTROLLER, controller=('127.0.0.1', 8068)) CLOSED: FINISHED; None



ERROR:root:Client protocol id: 55 had an error (07:23:07.419891)
ERROR:root:Client protocol id: 5 had an error (07:24:56.158961)
ERROR:root:Client protocol id: 7 had an error (07:24:56.194669)
ERROR:root:Client protocol id: 15 had an error (07:24:57.395246)



DEBUG:root:Stream 74 (None, controller=('127.0.0.1', 8119)) FAILED: TIMEOUT; None
Starting client protocol
Socket 2565 connected


ERROR:root:Client protocol id: 55 had an error (07:23:07.419891)



Feb 12 07:23:07.184 [info] connection_edge_process_relay_cell_not_open(): 'connected' received for circid 2355205080 streamid 34331 after 8 seconds.
Feb 12 07:23:07.184 [info] exit circ (length 3): $5AFB76E7105B036D4A5297712ED84F2B4D1D7AF0(open) $C0DE6D7DDCDB12B59FF33E123BA7AB3CA58D7CEA(open) $3A73C6B8BDC470EFBC0BF55D56B59001006E1483(open)
Feb 12 07:23:07.416 [info] handle_relay_cell_command(): 34: end cell (connection reset) for stream 34331. Removing stream.


Feb 12 07:23:40.710 [info] connection_edge_process_relay_cell_not_open(): 'connected' received for circid 2818801185 streamid 24523 after 3 seconds.
Feb 12 07:23:40.710 [info] exit circ (length 3): $E4E39348FCB5CC9494CFA3FBD6386630B64662A6(open) $C0DE6D7DDCDB12B59FF33E123BA7AB3CA58D7CEA(open) $335338CD4C5E48852859E29D8371FACB4A2155DE(open)
Feb 12 07:25:27.298 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 16 to 172.19.156.16:5021 (9AB7F01CA3AA2749B2115C49B5CE4596B9169E1B) after 6060 ms. Delta 3ms
Feb 12 07:25:27.395 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 13 to 172.19.156.16:5009 (9B20E5578F75081B63326B7C8A762DBE081C8256) after 5716 ms. Delta 1ms
Feb 12 07:25:28.742 [info] handle_relay_cell_command(): 37: end cell (connection reset) for stream 24523. Removing stream.
Feb 12 07:25:29.558 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 8 to 172.19.156.16:5027 (03813EFF1620E9F45CAB94808011FA966C2A8869) after 6872 ms. Delta 1ms
Feb 12 07:25:29.940 [info] connection_handle_listener_read(): New SOCKS connection opened from 127.0.0.1



ERROR:root:Client protocol id: 514 had an error (07:25:28.743687)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 245, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/throughput_protocols.py", line 30, in _run_iteration
    if self.sub_protocol.run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 434, in _run_iteration
    if self.protocol_helper.recv(self.socket, response_size):
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 39, in recv
    raise ProtocolException('The socket was closed.')
basic_protocols.ProtocolException: The socket was closed.
WARNING:root:Client protocol with error successfully added self to global queue

ERROR:root:Client protocol id: 55 had an error (07:23:07.419891)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 245, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/throughput_protocols.py", line 30, in _run_iteration
    if self.sub_protocol.run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 434, in _run_iteration
    if self.protocol_helper.recv(self.socket, response_size):
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 39, in recv
    raise ProtocolException('The socket was closed.')
basic_protocols.ProtocolException: The socket was closed.
WARNING:root:Client protocol with error successfully added self to global queue


















DEBUG:root:Starting client protocol (id: 1379, desc: ('127.0.0.1', 9092) -> 26: ['test002r', 'test030target', 'test043e'])

ERROR:root:Client protocol id: 1379 had an error (07:27:50.439308)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 245, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 172, in _run_iteration
    raise ProtocolException('Could not connect to SOCKS proxy, msg: %x'%(response[1],))
basic_protocols.ProtocolException: Could not connect to SOCKS proxy, msg: 5b

Feb 12 07:27:50.386 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 12 07:27:50.414 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 12 07:27:50.414 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 12 07:27:50.438 [notice] Tried for 120 seconds to get a connection to 127.0.0.1:12353. Giving up. (waiting for controller)
Feb 12 07:27:50.440 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 12 07:27:50.440 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 12 07:27:50.466 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.






DEBUG:root:Starting client protocol (id: 545, desc: ('127.0.0.1', 9158) -> 20: ['test000a', 'test030target', 'test054e'])

ERROR:root:Client protocol id: 545 had an error (07:25:41.147103)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 245, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 172, in _run_iteration
    raise ProtocolException('Could not connect to SOCKS proxy, msg: %x'%(response[1],))
basic_protocols.ProtocolException: Could not connect to SOCKS proxy, msg: 5b

Feb 12 07:25:38.260 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 9 to 172.19.156.16:5017 (A1986143EF2C1F7EF93742DDBB0AD5119EC33156) after 5924 ms. Delta 0ms
Feb 12 07:25:38.755 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 5 to 172.19.156.16:5009 (9B20E5578F75081B63326B7C8A762DBE081C8256) after 6728 ms. Delta 3ms
Feb 12 07:25:41.146 [notice] Tried for 120 seconds to get a connection to 127.0.0.1:12353. Giving up. (waiting for controller)
Feb 12 07:25:41.666 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 8 to 172.19.156.16:5006 (296F6955D60EBE2EEF910CED0C4F1F00D178951D) after 6848 ms. Delta 3ms
Feb 12 07:25:41.846 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 12 to 172.19.156.16:5010 (EB9D945D3E554868A8E5F15B375D129D20449E77) after 6028 ms. Delta 4ms
Feb 12 07:25:43.166 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 11 to 172.19.156.16:5000 (CC455FEC9679E29B17762238281AB07727FEBF47) after 6412 ms. Delta 3ms





See: connection_ap_expire_beginning()






Feb 12 22:28:22.429 [info] connection_handle_listener_read(): New SOCKS connection opened from 127.0.0.1.
Feb 12 22:28:22.638 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for controller' state. Leaving it on buffer.
Feb 12 22:28:22.658 [info] rep_hist_note_used_port(): New port prediction added. Will continue predictive circ building for 3394 more seconds.
Feb 12 22:28:22.658 [info] link_apconn_to_circ(): Looks like completed circuit to hidden service doesn't allow optimistic data for connection to 127.0.0.1
Feb 12 22:28:22.658 [info] connection_ap_handshake_send_begin(): Sending relay cell 0 on circ 4294765208 to begin stream 5930.
Feb 12 22:28:22.658 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 40, n_circ_id 4294765208


Feb 12 22:28:51.633 [info] circuit_mark_for_close_(): Circuit 4294765208 (id: 24) marked for close at src/core/or/circuituse.c:1507 (orig reason: 9, new reason: 0)

DEBUG:root:Starting client protocol (id: 844, desc: ('127.0.0.1', 9157) -> 24: ['test028r', 'test030target', 'test036e'])

ERROR:root:Client protocol id: 844 had an error (22:30:22.999643)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 246, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 172, in _run_iteration
    raise ProtocolException('Could not connect to SOCKS proxy, msg: %x'%(response[1],))
basic_protocols.ProtocolException: Could not connect to SOCKS proxy, msg: 5b





DEBUG:root:Starting client protocol (id: 1245, desc: ('127.0.0.1', 9108) -> 24: ['test014r', 'test030target', 'test045e'])

ERROR:root:Client protocol id: 1245 had an error (23:19:45.882900)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 246, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 172, in _run_iteration
    raise ProtocolException('Could not connect to SOCKS proxy, msg: %x'%(response[1],))
basic_protocols.ProtocolException: Could not connect to SOCKS proxy, msg: 5b

Feb 12 23:17:45.684 [info] connection_ap_handshake_send_begin(): Sending relay cell 0 on circ 2533565025 to begin stream 56942.
Feb 12 23:17:45.684 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 15, n_circ_id 2533565025

Feb 12 23:17:55.194 [info] update_consensus_networkstatus_downloads(): Launching microdesc standard networkstatus consensus download.
Feb 12 23:17:55.194 [info] select_primary_guard_for_circuit(): Selected primary guard test006r ($C296AF35EAD984D5419333340E1DE30AE71D8E48) for circuit.
Feb 12 23:17:55.194 [info] connection_ap_make_link(): Making internal direct tunnel to 172.19.156.16:5006 ...
Feb 12 23:17:55.194 [info] connection_ap_make_link(): ... application connection created and linked.
Feb 12 23:17:55.194 [info] directory_send_command(): Downloading consensus from 172.19.156.16:5006 using /tor/status-vote/current/consensus-microdesc/58BF94+BAF767.z
Feb 12 23:17:55.194 [warn] connection_ap_expire_beginning(): Bug: circuit->purpose == CIRCUIT_PURPOSE_C_GENERAL failed. The purpose on the circuit was Circuit made by controller; it was in state open, path_state new. (on Tor 0.4.2.6 971a6beff5a53434)
Feb 12 23:17:55.194 [info] connection_ap_expire_beginning(): We tried for 10 seconds to connect to '127.0.0.1' using exit $514B92EF502BA1FD644BBDEEDF35E2CC8F2EF5AA~test045e at 172.19.156.16. Retrying on a new circuit

Feb 12 23:18:18.285 [info] circuit_expire_old_circuits_clientside(): Closing n_circ_id 2533565025 (dirty 633 sec ago, purpose 22)
Feb 12 23:18:18.286 [info] circuit_mark_for_close_(): Circuit 2533565025 (id: 24) marked for close at src/core/or/circuituse.c:1507 (orig reason: 9, new reason: 0)

Feb 12 23:19:45.881 [notice] Tried for 120 seconds to get a connection to 127.0.0.1:12353. Giving up. (waiting for controller)






DEBUG:root:Starting client protocol (id: 336, desc: ('127.0.0.1', 9099) -> 18: ['test002r', 'test030target', 'test058e'])

ERROR:root:Client protocol id: 336 had an error (01:05:33.670825)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 246, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 172, in _run_iteration
    raise ProtocolException('Could not connect to SOCKS proxy, msg: %x'%(response[1],))
basic_protocols.ProtocolException: Could not connect to SOCKS proxy, msg: 5b

Feb 13 01:03:23.054 [info] connection_handle_listener_read(): New SOCKS connection opened from 127.0.0.1.
Feb 13 01:03:23.132 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for controller' state. Leaving it on buffer.
Feb 13 01:03:23.146 [info] channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive on 8 to 172.19.156.16:5015 (0ADE7252BDDA535282B306B0A82CBCC9FEDE2C50) after 5108 ms. Delta 2ms
Feb 13 01:03:23.152 [info] rep_hist_note_used_port(): New port prediction added. Will continue predictive circ building for 1998 more seconds.
Feb 13 01:03:23.152 [info] link_apconn_to_circ(): Looks like completed circuit to hidden service doesn't allow optimistic data for connection to 127.0.0.1
Feb 13 01:03:23.152 [info] connection_ap_handshake_send_begin(): Sending relay cell 0 on circ 3126016833 to begin stream 24424.
Feb 13 01:03:23.152 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 36, n_circ_id 3126016833

Feb 13 01:05:32.666 [info] connection_ap_expire_beginning(): Controller circuit has tried for 129 seconds to connect to '127.0.0.1' using exit $56D109A57085FEAF4B7EBC789C30E13EECEDBCC8~test058e at 17
2.19.156.16. But not giving up!
Feb 13 01:05:33.478 [info] connection_ap_process_end_not_open(): Address '127.0.0.1' refused due to 'misc error'. Considering retrying.
Feb 13 01:05:33.478 [info] client_dns_incr_failures(): Address 127.0.0.1 now has 1 resolve failures.
Feb 13 01:05:33.478 [info] exit circ (length 3): $610EC312C40076330EBB4C72522995C03D8C442A(open) $B8F98F5966E41AAB5DCDEED7ECEF637644ACF11C(open) $56D109A57085FEAF4B7EBC789C30E13EECEDBCC8(open)
Feb 13 01:05:33.670 [notice] Tried for 130 seconds to get a connection to 127.0.0.1:12353. Giving up. (waiting for controller)

Feb 13 01:06:01.782 [info] circuit_expire_old_circuits_clientside(): Closing n_circ_id 3126016833 (dirty 758 sec ago, purpose 22)
Feb 13 01:06:01.782 [info] circuit_mark_for_close_(): Circuit 3126016833 (id: 18) marked for close at src/core/or/circuituse.c:1507 (orig reason: 9, new reason: 0)






DEBUG:root:Starting client protocol (id: 1084, desc: ('127.0.0.1', 9097) -> 23: ['test021r', 'test030target', 'test045e'])

ERROR:root:Client protocol id: 1084 had an error (22:13:40.143767)
Traceback (most recent call last):
  File "/home/sengler/code/working/tor-benchmarking/dev/experiment_client.py", line 257, in _run_client
    protocol.run()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 130, in _run_iteration
    if self.protocols[self.current_protocol] is None or self.protocols[self.current_protocol].run():
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 71, in run
    finished = self._run_iteration()
  File "/home/sengler/code/working/tor-benchmarking/dev/basic_protocols.py", line 172, in _run_iteration
    raise ProtocolException('Could not connect to SOCKS proxy, msg: %x'%(response[1],))
basic_protocols.ProtocolException: Could not connect to SOCKS proxy, msg: 5b


Feb 15 22:11:40.074 [info] connection_handle_listener_read(): New SOCKS connection opened from 127.0.0.1.
Feb 15 22:11:40.288 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for controller' state. Leaving it on buffer.
Feb 15 22:11:40.308 [info] rep_hist_note_used_port(): New port prediction added. Will continue predictive circ building for 3043 more seconds.
Feb 15 22:11:40.308 [info] link_apconn_to_circ(): Looks like completed circuit to hidden service doesn't allow optimistic data for connection to 127.0.0.1
Feb 15 22:11:40.308 [info] connection_ap_handshake_send_begin(): Sending relay cell 0 on circ 3202562382 to begin stream 29645.
Feb 15 22:11:40.308 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket 4, n_circ_id 3202562382

Feb 15 22:12:16.809 [info] circuit_expire_old_circuits_clientside(): Closing n_circ_id 3202562382 (dirty 636 sec ago, purpose 22)
Feb 15 22:12:16.809 [info] circuit_mark_for_close_(): Circuit 3202562382 (id: 23) marked for close at src/core/or/circuituse.c:1507 (orig reason: 9, new reason: 0)
Feb 15 22:12:16.810 [info] circuit_free_(): Circuit 0 (id: 23) has been freed.

Feb 15 22:13:40.141 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 15 22:13:40.141 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 15 22:13:40.142 [notice] Tried for 120 seconds to get a connection to 127.0.0.1:12353. Giving up. (waiting for controller)
Feb 15 22:13:40.147 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.
Feb 15 22:13:40.147 [info] connection_edge_package_raw_inbuf(): called with package_window 0. Skipping.