Opened 12 years ago

Last modified 7 years ago

#648 closed defect (Duplicate)

No available nodes after network outage

Reported by: jasemandude Owned by: arma
Priority: Low Milestone: 0.2.0.x-final
Component: Core Tor/Tor Version: 0.2.0.22-rc
Severity: Keywords:
Cc: jasemandude, nickm Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Actually, it's 23-rc, but the version dropdown box doesn't have the option!

After the dial-up network has gone down for any appreciable time, when it is brought back up I lose the Tor network
and my log file gets filled with:

Tor[4292]: Failed to find node for hop 0 of our path. Discarding this circuit.
Tor[4292]: No available nodes when trying to choose node. Failing.

It can only be remedied by restarting Tor, whereupon it creates circuits just fine.

I'm wondering if it's because the external IP address has changed but Tor hasn't noticed? If so, can Tor try to
figure out if the external IP address has changed when it encounters this error and reconfigure itself?

[Automatically added by flyspray2trac: Operating System: OSX 10.5 Leopard]

Child Tickets

Change History (5)

comment:1 Changed 12 years ago by jasemandude

I've compiled 25-rc and am still getting the warnings, so this time I turned on notice, info and debug messages. It doesn't get permanently stuck without nodes like it used to, but it seems to take an inordinately long time to do something about the [Warning] notices. Six minutes of doing nothing, and nearly 10 minutes from start to build a circuit. Is this really the intended behavior?

As an analogy, if someone was punching me in the arm several times a second, I wouldn't just sit there for six minutes saying "[Warning] Someone just punched me in the arm", I'd go and find somewhere else to sit!

I hope this sheds light on what's happening.

I apologize in advance for the verbosity - I don't know what is and isn't pertinent. Please don't punch me in the arm (though maybe I deserve it)! :-)

JD


At 12:11 it started out with this (in the syslog file):

Apr 25 12:11:15 Tor[24779]: Your system clock just jumped 6388 seconds forward; assuming established circuits no longer work.

then picking up from the Vidalia log file:

Apr 25 12:11:43.942 [Warning] Failed to find node for hop 0 of our path. Discarding this circuit.
Apr 25 12:11:43.944 [Warning] No available nodes when trying to choose node. Failing.

[...etc etc...]

At 12:15 I turned on the extra log messages:

Apr 25 12:16:14.204 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:16:14.307 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:16:14.410 [Debug] circuit_remove_handled_ports(): Port 443 is not handled.
Apr 25 12:16:14.513 [Debug] circuit_remove_handled_ports(): Port 80 is not handled.
Apr 25 12:16:14.616 [Debug] circuit_remove_handled_ports(): Port 1863 is not handled.
Apr 25 12:16:14.719 [Debug] circuit_remove_handled_ports(): Port 5050 is not handled.
Apr 25 12:16:14.822 [Debug] circuit_remove_handled_ports(): Port 5190 is not handled.
Apr 25 12:16:14.925 [Info] circuit_predict_and_launch_new(): Have 0 clean circs (0 internal), need another exit circ.
Apr 25 12:16:15.029 [Debug] conn_read_callback(): socket 5 wants to read.
Apr 25 12:16:15.132 [Debug] connection_handle_listener_read(): Connection accepted on socket 19 (child of fd 5).
Apr 25 12:16:15.236 [Debug] connection_add(): new conn type Socks, socket 19, n_conns 44.
Apr 25 12:16:15.340 [Debug] conn_read_callback(): socket 19 wants to read.
Apr 25 12:16:15.444 [Debug] read_to_chunk(): Read 29 bytes. 29 on inbuf.
Apr 25 12:16:15.548 [Debug] connection_ap_handshake_process_socks(): entered.
Apr 25 12:16:15.652 [Debug] fetch_from_buf_socks(): socks4: Everything is here. Success.
Apr 25 12:16:15.756 [Debug] connection_ap_handshake_rewrite_and_attach(): Client asked for [scrubbed]:443
Apr 25 12:16:15.860 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:16:15.964 [Info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
Apr 25 12:16:16.069 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:16:16.174 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.

[... [Info] No safe circuit repeated about 30 times, then entire above cycle repeated every second or so until...]

Apr 25 12:17:27.172 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:17:27.327 [Debug] circuit_remove_handled_ports(): Port 443 is not handled.
Apr 25 12:17:27.485 [Debug] circuit_remove_handled_ports(): Port 80 is not handled.
Apr 25 12:17:27.640 [Debug] circuit_remove_handled_ports(): Port 1863 is not handled.
Apr 25 12:17:27.796 [Debug] circuit_remove_handled_ports(): Port 5050 is not handled.
Apr 25 12:17:27.953 [Debug] circuit_remove_handled_ports(): Port 5190 is not handled.
Apr 25 12:17:28.109 [Info] circuit_predict_and_launch_new(): Have 0 clean circs (0 internal), need another exit circ.
Apr 25 12:17:28.265 [Debug] conn_close_if_marked(): Cleaning up connection (fd -1).
Apr 25 12:17:28.421 [Debug] connection_remove(): removing socket -1 (type Socks), n_conns now 43
Apr 25 12:17:28.578 [Debug] conn_close_if_marked(): Cleaning up connection (fd -1).
Apr 25 12:17:28.735 [Debug] connection_remove(): removing socket -1 (type Socks), n_conns now 42
Apr 25 12:17:28.892 [Notice] Tried for 90 seconds to get a connection to [scrubbed]:0. Giving up. (waiting for circuit)
Apr 25 12:17:29.050 [Notice] Tried for 90 seconds to get a connection to [scrubbed]:80. Giving up. (waiting for circuit)
Apr 25 12:17:29.210 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:17:29.368 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.

[... above cycle repeated until TOR starts looking for circuits ... ]

Apr 25 12:17:53.430 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:17:53.603 [Debug] circuit_remove_handled_ports(): Port 443 is not handled.
Apr 25 12:17:53.775 [Debug] circuit_remove_handled_ports(): Port 80 is not handled.
Apr 25 12:17:53.947 [Debug] circuit_remove_handled_ports(): Port 1863 is not handled.
Apr 25 12:17:54.120 [Debug] circuit_remove_handled_ports(): Port 5050 is not handled.
Apr 25 12:17:54.293 [Debug] circuit_remove_handled_ports(): Port 5190 is not handled.
Apr 25 12:17:54.466 [Info] circuit_predict_and_launch_new(): Have 0 clean circs (0 internal), need another exit circ.
Apr 25 12:17:54.640 [Debug] new_route_len(): Chosen route length 3 (1934 routers available).
Apr 25 12:17:54.812 [Info] choose_good_exit_server_general(): Found 66 servers that might support 36/36 pending connections.
Apr 25 12:17:54.986 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 6892724, exit bw = 10339123, nonexit bw = 0, exit weight = 1.000000 (for exit == 1), guard bw = 9380818, nonguard bw = 958305, guard weight = 0.632615 (for guard == 0)
Apr 25 12:17:55.159 [Info] choose_good_exit_server_general(): Chose exit server 'oemloi'
Apr 25 12:17:55.333 [Debug] onion_extend_cpath(): Path is 0 long; we want 3
Apr 25 12:17:55.508 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:17:55.682 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:55.855 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:56.029 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:17:56.202 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:56.376 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:56.550 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:17:56.724 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:56.899 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:57.073 [Warning] Failed to find node for hop 0 of our path. Discarding this circuit.
Apr 25 12:17:57.247 [Info] onion_populate_cpath(): Generating cpath hop failed.
Apr 25 12:17:57.422 [Debug] circuit_increment_failure_count(): n_circuit_failures now 1.
Apr 25 12:17:57.597 [Notice] Tried for 90 seconds to get a connection to [scrubbed]:0. Giving up. (waiting for circuit)
Apr 25 12:17:57.771 [Notice] Tried for 90 seconds to get a connection to [scrubbed]:0. Giving up. (waiting for circuit)
Apr 25 12:17:57.945 [Debug] new_route_len(): Chosen route length 3 (1934 routers available).
Apr 25 12:17:58.120 [Info] choose_good_exit_server_general(): Found 278 servers that might support 34/34 pending connections.
Apr 25 12:17:58.295 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 26042342, exit bw = 39063545, nonexit bw = 0, exit weight = 1.000000 (for exit == 1), guard bw = 23379386, nonguard bw = 15684159, guard weight = 0.443049 (for guard == 0)
Apr 25 12:17:58.470 [Info] choose_good_exit_server_general(): Chose exit server 'india113'
Apr 25 12:17:58.645 [Debug] onion_extend_cpath(): Path is 0 long; we want 3
Apr 25 12:17:58.821 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:17:58.996 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:59.172 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:59.348 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:17:59.524 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:59.700 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:17:59.876 [Warning] Failed to find node for hop 0 of our path. Discarding this circuit.
Apr 25 12:18:00.052 [Info] onion_populate_cpath(): Generating cpath hop failed.
Apr 25 12:18:00.228 [Debug] circuit_increment_failure_count(): n_circuit_failures now 2.
Apr 25 12:18:00.405 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:18:00.580 [Debug] new_route_len(): Chosen route length 3 (1934 routers available).
Apr 25 12:18:00.757 [Info] choose_good_exit_server_general(): Found 278 servers that might support 34/34 pending connections.
Apr 25 12:18:00.932 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 26042342, exit bw = 39063545, nonexit bw = 0, exit weight = 1.000000 (for exit == 1), guard bw = 23379386, nonguard bw = 15684159, guard weight = 0.443049 (for guard == 0)
Apr 25 12:18:01.109 [Info] choose_good_exit_server_general(): Chose exit server 'idgtor'
Apr 25 12:18:01.286 [Debug] onion_extend_cpath(): Path is 0 long; we want 3
Apr 25 12:18:01.463 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:01.639 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:01.816 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:01.993 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:02.170 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:02.347 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:02.524 [Warning] Failed to find node for hop 0 of our path. Discarding this circuit.
Apr 25 12:18:02.701 [Info] onion_populate_cpath(): Generating cpath hop failed.
Apr 25 12:18:02.878 [Debug] circuit_increment_failure_count(): n_circuit_failures now 3.
Apr 25 12:18:03.056 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:18:03.234 [Debug] new_route_len(): Chosen route length 3 (1934 routers available).
Apr 25 12:18:03.412 [Info] choose_good_exit_server_general(): Found 66 servers that might support 34/34 pending connections.
Apr 25 12:18:03.590 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 6892724, exit bw = 10339123, nonexit bw = 0, exit weight = 1.000000 (for exit == 1), guard bw = 9380818, nonguard bw = 958305, guard weight = 0.632615 (for guard == 0)
Apr 25 12:18:03.768 [Info] choose_good_exit_server_general(): Chose exit server 'proxelsusexitnode'
Apr 25 12:18:03.946 [Debug] onion_extend_cpath(): Path is 0 long; we want 3
Apr 25 12:18:04.125 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:04.303 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:04.482 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:04.660 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:04.839 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:05.018 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:05.197 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:05.376 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:05.555 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:05.734 [Warning] Failed to find node for hop 0 of our path. Discarding this circuit.
Apr 25 12:18:05.913 [Info] onion_populate_cpath(): Generating cpath hop failed.
Apr 25 12:18:06.091 [Debug] circuit_increment_failure_count(): n_circuit_failures now 4.
Apr 25 12:18:06.270 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:18:06.449 [Debug] new_route_len(): Chosen route length 3 (1934 routers available).
Apr 25 12:18:06.629 [Info] choose_good_exit_server_general(): Found 278 servers that might support 34/34 pending connections.
Apr 25 12:18:06.808 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 26042342, exit bw = 39063545, nonexit bw = 0, exit weight = 1.000000 (for exit == 1), guard bw = 23379386, nonguard bw = 15684159, guard weight = 0.443049 (for guard == 0)
Apr 25 12:18:06.987 [Info] choose_good_exit_server_general(): Chose exit server 'scummat'
Apr 25 12:18:07.167 [Debug] onion_extend_cpath(): Path is 0 long; we want 3
Apr 25 12:18:07.346 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:07.526 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:07.706 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:07.885 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:08.065 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:08.245 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:08.425 [Warning] Failed to find node for hop 0 of our path. Discarding this circuit.
Apr 25 12:18:08.606 [Info] onion_populate_cpath(): Generating cpath hop failed.
Apr 25 12:18:08.786 [Debug] circuit_increment_failure_count(): n_circuit_failures now 5.
Apr 25 12:18:08.967 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:18:09.147 [Debug] new_route_len(): Chosen route length 3 (1934 routers available).
Apr 25 12:18:09.328 [Info] choose_good_exit_server_general(): Found 278 servers that might support 34/34 pending connections.
Apr 25 12:18:09.509 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 26042342, exit bw = 39063545, nonexit bw = 0, exit weight = 1.000000 (for exit == 1), guard bw = 23379386, nonguard bw = 15684159, guard weight = 0.443049 (for guard == 0)
Apr 25 12:18:09.690 [Info] choose_good_exit_server_general(): Chose exit server 'Unnamed'
Apr 25 12:18:09.871 [Debug] onion_extend_cpath(): Path is 0 long; we want 3
Apr 25 12:18:10.051 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:10.232 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:10.413 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:10.594 [Info] router_choose_random_node(): We couldn't find any live, guard routers; falling back to list of all routers.
Apr 25 12:18:10.775 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:10.955 [Warning] No available nodes when trying to choose node. Failing.
Apr 25 12:18:11.137 [Warning] Failed to find node for hop 0 of our path. Discarding this circuit.
Apr 25 12:18:11.318 [Info] onion_populate_cpath(): Generating cpath hop failed.
Apr 25 12:18:11.500 [Debug] circuit_increment_failure_count(): n_circuit_failures now 6.
Apr 25 12:18:11.682 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:18:11.864 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:18:12.046 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:18:12.228 [Notice] Tried for 90 seconds to get a connection to [scrubbed]:0. Giving up.

[...]

Apr 25 12:19:46.313 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:19:46.564 [Info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.
Apr 25 12:19:46.813 [Debug] circuit_remove_handled_ports(): Port 443 is not handled.
Apr 25 12:19:47.066 [Debug] circuit_remove_handled_ports(): Port 80 is not handled.
Apr 25 12:19:47.315 [Debug] circuit_remove_handled_ports(): Port 1863 is not handled.
Apr 25 12:19:47.565 [Debug] circuit_remove_handled_ports(): Port 5050 is not handled.
Apr 25 12:19:47.814 [Debug] circuit_remove_handled_ports(): Port 5190 is not handled.
Apr 25 12:19:48.063 [Info] circuit_predict_and_launch_new(): Have 0 clean circs (0 internal), need another exit circ.
Apr 25 12:19:48.312 [Debug] conn_close_if_marked(): Cleaning up connection (fd 26).
Apr 25 12:19:48.563 [Debug] connection_remove(): removing socket 26 (type Socks), n_conns now 27
Apr 25 12:20:16.305 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.308 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.310 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.311 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.313 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.314 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.316 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.318 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.320 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.322 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.325 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.327 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:16.329 [Debug] circuit_get_open_circ_or_launch(): one on the way!
Apr 25 12:20:16.332 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.

[... loads more of the "one on the way!" and "skipping one-hop" debug messages ...]

Apr 25 12:20:28.867 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:28.905 [Debug] circuit_get_open_circ_or_launch(): one on the way!
Apr 25 12:20:28.944 [Info] update_consensus_router_descriptor_downloads(): 23 router descriptors downloadable. 0 delayed; 1614 present (0 of those were in old_routers); 0 would_reject; 533 wouldnt_use; 0 in progress.
Apr 25 12:20:28.983 [Debug] launch_router_descriptor_downloads(): There are enough downloadable routerdescs to launch requests.
Apr 25 12:20:29.023 [Info] launch_router_descriptor_downloads(): Launching 3 requests for 23 routers, 8 at a time
Apr 25 12:20:29.061 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 8807290, exit bw = 13260510, nonexit bw = 6553505, exit weight = 0.501929 (for exit == 0), guard bw = 18012572, nonguard bw = 1801443, guard weight = 0.633330 (for guard == 0)
Apr 25 12:20:29.100 [Debug] directory_initiate_command(): anonymized 0, use_begindir 1.
Apr 25 12:20:29.139 [Debug] directory_initiate_command(): Initiating server descriptor fetch
Apr 25 12:20:29.178 [Info] connection_ap_make_link(): Making internal anonymized tunnel to [scrubbed]:443 ...
Apr 25 12:20:29.217 [Debug] connection_add(): new conn type Socks, socket -1, n_conns 20.
Apr 25 12:20:29.256 [Debug] onion_pick_cpath_exit(): Launching a one-hop circuit for dir tunnel.
Apr 25 12:20:29.295 [Info] onion_pick_cpath_exit(): Using requested exit node 'Lifuka'
Apr 25 12:20:29.335 [Debug] onion_extend_cpath(): Path is 0 long; we want 1
Apr 25 12:20:29.374 [Debug] onion_extend_cpath(): Chose router Lifuka for hop 1 (exit is Lifuka)
Apr 25 12:20:29.413 [Debug] onion_extend_cpath(): Path is complete: 1 steps long
Apr 25 12:20:29.453 [Debug] circuit_handle_first_hop(): Looking for firsthop '82.94.251.204:443'
Apr 25 12:20:29.493 [Debug] connection_connect(): Connecting to [scrubbed]:443.
Apr 25 12:20:29.532 [Info] get_interface_address6(): connect() failed: Invalid argument
Apr 25 12:20:29.572 [Info] get_interface_address6(): connect() failed: Invalid argument
Apr 25 12:20:29.611 [Debug] connection_connect(): Connection to [scrubbed]:443 in progress (sock 20).
Apr 25 12:20:29.651 [Debug] connection_add(): new conn type OR, socket 20, n_conns 21.
Apr 25 12:20:29.691 [Debug] circuit_handle_first_hop(): connecting in progress (or finished). Good.
Apr 25 12:20:29.731 [Info] connection_ap_make_link(): ... application connection created and linked.
Apr 25 12:20:29.772 [Debug] connection_add(): new conn type Directory, socket -1, n_conns 22.
Apr 25 12:20:29.812 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 8807290, exit bw = 13260510, nonexit bw = 6553505, exit weight = 0.501929 (for exit == 0), guard bw = 18012572, nonguard bw = 1801443, guard weight = 0.633330 (for guard == 0)
Apr 25 12:20:29.854 [Debug] directory_initiate_command(): anonymized 0, use_begindir 1.
Apr 25 12:20:29.894 [Debug] directory_initiate_command(): Initiating server descriptor fetch
Apr 25 12:20:29.935 [Info] connection_ap_make_link(): Making internal anonymized tunnel to [scrubbed]:443 ...
Apr 25 12:20:29.976 [Debug] connection_add(): new conn type Socks, socket -1, n_conns 23.
Apr 25 12:20:30.016 [Debug] onion_pick_cpath_exit(): Launching a one-hop circuit for dir tunnel.
Apr 25 12:20:30.057 [Info] onion_pick_cpath_exit(): Using requested exit node 'coffin'
Apr 25 12:20:30.098 [Debug] onion_extend_cpath(): Path is 0 long; we want 1
Apr 25 12:20:30.139 [Debug] onion_extend_cpath(): Chose router coffin for hop 1 (exit is coffin)
Apr 25 12:20:30.180 [Debug] onion_extend_cpath(): Path is complete: 1 steps long
Apr 25 12:20:30.221 [Debug] circuit_handle_first_hop(): Looking for firsthop '130.237.2.213:443'
Apr 25 12:20:30.262 [Debug] connection_connect(): Connecting to [scrubbed]:443.
Apr 25 12:20:30.304 [Info] get_interface_address6(): connect() failed: Invalid argument
Apr 25 12:20:30.345 [Info] get_interface_address6(): connect() failed: Invalid argument
Apr 25 12:20:30.386 [Debug] connection_connect(): Connection to [scrubbed]:443 in progress (sock 26).
Apr 25 12:20:30.428 [Debug] connection_add(): new conn type OR, socket 26, n_conns 24.
Apr 25 12:20:30.469 [Debug] circuit_handle_first_hop(): connecting in progress (or finished). Good.
Apr 25 12:20:30.511 [Info] connection_ap_make_link(): ... application connection created and linked.
Apr 25 12:20:30.552 [Debug] connection_add(): new conn type Directory, socket -1, n_conns 25.
Apr 25 12:20:30.594 [Debug] smartlist_choose_by_bandwidth(): Total weighted bw = 8807290, exit bw = 13260510, nonexit bw = 6553505, exit weight = 0.501929 (for exit == 0), guard bw = 18012572, nonguard bw = 1801443, guard weight = 0.633330 (for guard == 0)
Apr 25 12:20:30.636 [Debug] directory_initiate_command(): anonymized 0, use_begindir 1.
Apr 25 12:20:30.678 [Debug] directory_initiate_command(): Initiating server descriptor fetch
Apr 25 12:20:30.720 [Info] connection_ap_make_link(): Making internal anonymized tunnel to [scrubbed]:443 ...
Apr 25 12:20:30.762 [Debug] connection_add(): new conn type Socks, socket -1, n_conns 26.
Apr 25 12:20:30.805 [Debug] connection_ap_handshake_attach_circuit(): Attaching apconn to circ 5839 (stream 0 sec old).
Apr 25 12:20:30.847 [Info] exit circ (length 1): $5C3EC3DC1CD0E64016BA7C6ED308C98379645967(open)
Apr 25 12:20:30.890 [Debug] link_apconn_to_circ(): attaching new conn to circ. n_circ_id 5839.
Apr 25 12:20:30.932 [Debug] connection_ap_handshake_send_begin(): Sending relay cell to begin stream 16454.
Apr 25 12:20:30.975 [Debug] relay_send_command_from_edge(): delivering 13 cell forward.
Apr 25 12:20:31.017 [Debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Apr 25 12:20:31.060 [Debug] append_cell_to_circuit_queue(): Made a circuit active.
Apr 25 12:20:31.103 [Debug] append_cell_to_circuit_queue(): Primed a buffer.
Apr 25 12:20:31.146 [Debug] connection_or_flush_from_first_active_circuit(): Made a circuit inactive.
Apr 25 12:20:31.189 [Info] connection_ap_handshake_send_begin(): Address/port sent, ap socket -1, n_circ_id 5839
Apr 25 12:20:31.233 [Info] connection_ap_make_link(): ... application connection created and linked.
Apr 25 12:20:31.276 [Debug] connection_add(): new conn type Directory, socket -1, n_conns 27.
Apr 25 12:20:31.320 [Info] routerlist_remove_old_routers(): We have 1988 live routers and 0 old router descriptors. At most 2170 must be retained because of networkstatuses.
Apr 25 12:20:31.363 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.

[...]

Apr 25 12:20:45.773 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:45.837 [Debug] circuit_get_open_circ_or_launch(): one on the way!
Apr 25 12:20:45.902 [Debug] circuit_get_open_circ_or_launch(): one on the way!
Apr 25 12:20:45.966 [Debug] circuit_get_open_circ_or_launch(): one on the way!
Apr 25 12:20:46.031 [Debug] conn_read_callback(): socket 26 wants to read.
Apr 25 12:20:46.095 [Debug] connection_tls_finish_handshake(): tls handshake with 130.237.2.213 done. verifying.
Apr 25 12:20:46.159 [Debug] connection_or_check_valid_tls_handshake(): The certificate seems to be valid on outgoing connection with 130.237.2.213:443
Apr 25 12:20:46.224 [Debug] connection_or_process_cells_from_inbuf(): 26: starting, inbuf_datalen 0 (0 pending in tls object).
Apr 25 12:20:46.289 [Debug] conn_write_callback(): socket 26 wants to write.
Apr 25 12:20:46.354 [Debug] flush_chunk_tls(): flushed 9 bytes, 0 ready to flush, 0 remain.
Apr 25 12:20:46.419 [Debug] connection_handle_write(): After TLS write of 9: 2540 read, 1829 written
Apr 25 12:20:46.484 [Debug] conn_read_callback(): socket 20 wants to read.
Apr 25 12:20:46.549 [Debug] connection_read_to_buf(): 20: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16384.
Apr 25 12:20:46.615 [Debug] connection_read_to_buf(): After TLS read of 521: 106 read, 0 written
Apr 25 12:20:46.681 [Debug] connection_or_process_cells_from_inbuf(): 20: starting, inbuf_datalen 521 (0 pending in tls object).
Apr 25 12:20:46.746 [Info] command_process_versions_cell(): Negotiated version 2 with [scrubbed]; sending NETINFO.
Apr 25 12:20:46.811 [Debug] connection_or_process_cells_from_inbuf(): 20: starting, inbuf_datalen 512 (0 pending in tls object).
Apr 25 12:20:46.877 [Info] entry_guard_register_connect_status(): Entry guard 'Lifuka' (675F042AD2AA7B139391926B7612D29A35FF2549) is now reachable again. Good.
Apr 25 12:20:46.943 [Debug] router_set_status(): Marking router 'Lifuka' as up.
Apr 25 12:20:47.008 [Debug] circuit_n_conn_done(): or_conn to Lifuka, status=1
Apr 25 12:20:47.075 [Debug] circuit_n_conn_done(): Found circ, sending create cell.
Apr 25 12:20:47.140 [Debug] circuit_send_next_onion_skin(): First skin; sending create cell.
Apr 25 12:20:47.208 [Debug] circuit_deliver_create_cell(): Chosen circID 10258.
Apr 25 12:20:47.274 [Debug] append_cell_to_circuit_queue(): Made a circuit active.
Apr 25 12:20:47.340 [Info] circuit_send_next_onion_skin(): First hop: finished sending CREATE_FAST cell to 'Lifuka'
Apr 25 12:20:47.406 [Info] command_process_netinfo_cell(): Got good NETINFO cell from [scrubbed]; OR connection is now open, using protocol version 2
Apr 25 12:20:47.473 [Debug] connection_or_process_cells_from_inbuf(): 20: starting, inbuf_datalen 0 (0 pending in tls object).
Apr 25 12:20:47.539 [Debug] conn_write_callback(): socket 20 wants to write.
Apr 25 12:20:47.606 [Debug] flush_chunk_tls(): flushed 512 bytes, 0 ready to flush, 0 remain.
Apr 25 12:20:47.674 [Debug] connection_handle_write(): After TLS write of 512: 0 read, 90 written
Apr 25 12:20:47.740 [Debug] connection_or_flush_from_first_active_circuit(): Made a circuit inactive.
Apr 25 12:20:47.807 [Debug] conn_write_callback(): socket 20 wants to write.
Apr 25 12:20:47.874 [Debug] flush_chunk_tls(): flushed 512 bytes, 0 ready to flush, 0 remain.
Apr 25 12:20:47.941 [Debug] connection_handle_write(): After TLS write of 512: 0 read, 106 written
Apr 25 12:20:48.008 [Debug] conn_read_callback(): socket 26 wants to read.
Apr 25 12:20:48.076 [Debug] connection_read_to_buf(): 26: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16384.
Apr 25 12:20:48.143 [Debug] connection_read_to_buf(): After TLS read of 521: 586 read, 0 written
Apr 25 12:20:48.210 [Debug] connection_or_process_cells_from_inbuf(): 26: starting, inbuf_datalen 521 (0 pending in tls object).
Apr 25 12:20:48.277 [Info] command_process_versions_cell(): Negotiated version 2 with [scrubbed]; sending NETINFO.
Apr 25 12:20:48.350 [Debug] connection_or_process_cells_from_inbuf(): 26: starting, inbuf_datalen 512 (0 pending in tls object).
Apr 25 12:20:48.418 [Info] entry_guard_register_connect_status(): Entry guard 'coffin' (EFC8EC6538F7B0A49408AF5A81D40C5EBE494A44) is now reachable again. Good.
Apr 25 12:20:48.485 [Debug] router_set_status(): Marking router 'coffin' as up.
Apr 25 12:20:48.554 [Debug] circuit_n_conn_done(): or_conn to coffin, status=1
Apr 25 12:20:48.622 [Debug] circuit_n_conn_done(): Found circ, sending create cell.
Apr 25 12:20:48.690 [Debug] circuit_send_next_onion_skin(): First skin; sending create cell.
Apr 25 12:20:48.758 [Debug] circuit_deliver_create_cell(): Chosen circID 56023.
Apr 25 12:20:48.826 [Debug] append_cell_to_circuit_queue(): Made a circuit active.
Apr 25 12:20:48.894 [Info] circuit_send_next_onion_skin(): First hop: finished sending CREATE_FAST cell to 'coffin'
Apr 25 12:20:48.962 [Info] command_process_netinfo_cell(): Got good NETINFO cell from [scrubbed]; OR connection is now open, using protocol version 2
Apr 25 12:20:49.031 [Debug] connection_or_process_cells_from_inbuf(): 26: starting, inbuf_datalen 0 (0 pending in tls object).
Apr 25 12:20:49.100 [Debug] conn_write_callback(): socket 26 wants to write.
Apr 25 12:20:49.169 [Debug] flush_chunk_tls(): flushed 512 bytes, 0 ready to flush, 0 remain.
Apr 25 12:20:49.238 [Debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Apr 25 12:20:49.306 [Debug] connection_or_flush_from_first_active_circuit(): Made a circuit inactive.
Apr 25 12:20:49.377 [Debug] conn_write_callback(): socket 26 wants to write.
Apr 25 12:20:49.448 [Debug] flush_chunk_tls(): flushed 512 bytes, 0 ready to flush, 0 remain.
Apr 25 12:20:49.517 [Debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Apr 25 12:20:49.587 [Debug] conn_read_callback(): socket 20 wants to read.
Apr 25 12:20:49.656 [Debug] connection_read_to_buf(): 20: starting, inbuf_datalen 0 (0 pending in tls object). at_most 16384.
Apr 25 12:20:49.725 [Debug] connection_read_to_buf(): After TLS read of 512: 122 read, 0 written
Apr 25 12:20:49.796 [Debug] connection_or_process_cells_from_inbuf(): 20: starting, inbuf_datalen 512 (0 pending in tls object).
Apr 25 12:20:49.866 [Debug] command_process_created_cell(): at OP. Finishing handshake.
Apr 25 12:20:49.937 [Info] circuit_finish_handshake(): Finished building fast circuit hop:
Apr 25 12:20:50.014 [Info] exit circ (length 1, exit Lifuka): Lifuka(open)
Apr 25 12:20:50.085 [Debug] command_process_created_cell(): Moving to next skin.
Apr 25 12:20:50.157 [Debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Apr 25 12:20:50.227 [Info] circuit_send_next_onion_skin(): circuit built!
Apr 25 12:20:50.300 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.
Apr 25 12:20:50.370 [Debug] circuit_is_acceptable(): Skipping one-hop circuit.

comment:2 Changed 12 years ago by jasemandude

See #675 for a possible solution.

JD.

comment:3 Changed 12 years ago by arma

Closing, since bug 675 is where all the juicy stuff is.

comment:4 Changed 12 years ago by arma

flyspray2trac: bug closed.
See bug 675

comment:5 Changed 7 years ago by nickm

Component: Tor ClientTor
Note: See TracTickets for help on using tickets.