Opened 12 years ago

Last modified 7 years ago

#604 closed defect (Fixed)

Tor 0.1.2.19 server crash on Solaris Sparc

Reported by: jaba Owned by:
Priority: High Milestone:
Component: Core Tor/Tor Version: 0.1.2.19
Severity: Keywords:
Cc: jaba, arma, nickm Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Dear Developpers,

I have successfully compiled and run openssl 0.9.8g, libevent 1.3e and tor 0.1.2.19 with gcc-4.2.2 in a Solaris 10 Sparc Zone as a Tor client.
As soon as I uncomment ORPort in torrc to enable the server it starts initializing and crashes with a "Bus Error" while checking reachability and bandwidth.
When I block port 9001 on the firewall it does not crash, but obviously not work also. :)

Trace of the startup included below, with level info and level debug at the final stage.
I do not get a core dumped.

#ulimit -a

core file size (blocks, -c) unlimited
data seg size (kbytes, -d) unlimited
file size (blocks, -f) unlimited
open files (-n) 256
pipe size (512 bytes, -p) 10
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 14117
virtual memory (kbytes, -v) unlimited

Tried to increase open files to 1024 with no difference.

Any help is greatly appreciated.
Thanks,

Jan

Feb 09 11:24:46.399 [notice] Tor v0.1.2.19. This is experimental software. Do not rely on it for strong anonymity.
Feb 09 11:24:46.404 [warn] You specified a public address '0.0.0.0' for a SOCKS proxy. Other people on the Internet might find your computer and use it as an open SOCKS proxy. Please don't allow this unless you have a good reason.
Feb 09 11:24:46.405 [notice] Choosing default nickname 'tor'
Feb 09 11:24:46.406 [notice] Your ContactInfo config option is not set. Please consider setting it, so we can contact you if your server is misconfigured or something else goes wrong.
Feb 09 11:24:46.410 [notice] Initialized libevent version 1.3e using method event ports. Good.
Feb 09 11:24:46.412 [notice] Opening OR listener on 0.0.0.0:9001
Feb 09 11:24:46.413 [notice] Opening Socks listener on 0.0.0.0:9050
Feb 09 11:24:46.413 [notice] Opening Control listener on 0.0.0.0:9051
Feb 09 11:24:46.418 [info] or_state_load(): Loaded state from "/usr/local/tor/var/state"
Feb 09 11:24:46.437 [info] crypto_seed_rng(): Seeding RNG from "/dev/urandom"
Feb 09 11:24:46.439 [info] configure_nameservers(): Parsing resolver configuration in '/etc/resolv.conf'
Feb 09 11:24:46.439 [info] eventdns: Parsing resolv.conf file /etc/resolv.conf
Feb 09 11:24:46.441 [info] eventdns: Added nameserver xxxxxxx
Feb 09 11:24:46.442 [info] eventdns: Added nameserver xxxxxxx
Feb 09 11:24:46.442 [info] eventdns: Setting maximum allowed timeouts to 3
Feb 09 11:24:46.443 [info] eventdns: Setting timeout to 5
Feb 09 11:24:46.444 [info] init_keys(): Reading/making identity key "/usr/local/tor/var/keys/secret_id_key"...
Feb 09 11:24:46.620 [info] init_keys(): Reading/making onion key "/usr/local/tor/var/keys/secret_onion_key"...
platform Tor 0.1.2.19 on SunOS sun4u
published 2008-02-09 10:24:50
opt fingerprint xxxx xxxx xxxx xxxx
uptime 0
bandwidth 3145728 6291456 0
onion-key


[...]


signing-key


[...]


opt write-history 2008-02-09 10:24:46 (900 s)
opt read-history 2008-02-09 10:24:46 (900 s)
[...]

Feb 09 11:24:50.620 [info] init_keys(): Dumping fingerprint to "/usr/local/tor/var/fingerprint"...
Feb 09 11:24:50.622 [notice] Your Tor server's identity key fingerprint is 'xxxx xxxx xxxx'
Feb 09 11:24:55.294 [info] router_load_routers_from_string(): 1690 elements to add
Feb 09 11:24:56.435 [info] router_load_routers_from_string(): 365 elements to add
[...]
Feb 09 11:24:56.806 [info] router_set_networkstatus(): Setting networkstatus cached from directory server "moria1" at 128.31.0.34:9031 (published 2008-02-08 16:14:02)
Feb 09 11:24:56.806 [info] networkstatus_list_update_recent(): Networkstatus from directory server "moria1" at 128.31.0.34:9031 (published 2008-02-08 16:14:02) is now "recent"
Feb 09 11:24:57.017 [debug] check_directory_signature(): Signed directory hash starts 4529A66E
Feb 09 11:24:57.021 [info] router_set_networkstatus(): Setting networkstatus cached from directory server "tor26" at 86.59.21.38:80 (published 2008-02-08 21:44:01)
Feb 09 11:24:57.021 [info] networkstatus_list_update_recent(): Networkstatus from directory server "tor26" at 86.59.21.38:80 (published 2008-02-08 21:44:01) is now "recent"
Feb 09 11:24:57.244 [debug] check_directory_signature(): Signed directory hash starts DE69E0AF
Feb 09 11:24:57.247 [info] router_set_networkstatus(): Setting networkstatus cached from directory server "dizum" at 194.109.206.212:80 (published 2008-02-08 22:35:27)
Feb 09 11:24:57.248 [info] networkstatus_list_update_recent(): Networkstatus from directory server "dizum" at 194.109.206.212:80 (published 2008-02-08 22:35:27) is now "recent"
Feb 09 11:24:57.458 [debug] check_directory_signature(): Signed directory hash starts FFF46957
Feb 09 11:24:57.462 [info] router_set_networkstatus(): Setting networkstatus cached from directory server "moria2" at 128.31.0.34:9032 (published 2008-02-08 16:34:41)
Feb 09 11:24:57.462 [info] networkstatus_list_update_recent(): Networkstatus from directory server "moria2" at 128.31.0.34:9032 (published 2008-02-08 16:34:41) is now "recent"
Feb 09 11:24:57.463 [info] networkstatus_list_update_recent(): Networkstatus from directory server "moria1" at 128.31.0.34:9031 (published 2008-02-08 16:14:02) is no longer "recent"
Feb 09 11:24:57.669 [debug] check_directory_signature(): Signed directory hash starts BB7A2DAC
Feb 09 11:24:57.672 [info] router_set_networkstatus(): Setting networkstatus cached from directory server "lefkada" at 140.247.60.64:80 (published 2008-02-08 22:09:03)
Feb 09 11:24:57.673 [info] networkstatus_list_update_recent(): Networkstatus from directory server "lefkada" at 140.247.60.64:80 (published 2008-02-08 22:09:03) is now "recent"
Feb 09 11:24:57.673 [info] networkstatus_list_update_recent(): Networkstatus from directory server "moria2" at 128.31.0.34:9032 (published 2008-02-08 16:34:41) is no longer "recent"
Feb 09 11:24:57.674 [info] routerstatus_list_update_from_networkstatus(): Rebuilding router status list.
Feb 09 11:24:57.692 [info] routerstatus_list_update_from_networkstatus(): Naming authorities disagree about which key goes with joestorserver. ($86D83F4F853EDFEEAD1EF3B17CE2034F8397A8F6 vs $0731DD94CD90068DAFE31DBC449F1BA36C6DF277)
[...]
Feb 09 11:24:58.637 [debug] routerstatus_list_update_from_networkstatus(): Router 'FightFascism' is listed by 5/5 directories, named by 2/3, validated by 5/5, and 3/3 recent directories think it's running.
Feb 09 11:24:58.638 [warn] Naming authorities disagree about nicknames for $C1D04F2F5E9A0FF9240638BE9805563C03A3D8CB ("PoderosoTorII" vs "PoderosoTorIII")
[...]
Feb 09 11:24:59.353 [info] circuit_predict_and_launch_new(): Have 0 clean circs (0 internal), need another exit circ.
Feb 09 11:24:59.358 [info] choose_good_exit_server_general(): Found 628 servers that might support 0/0 pending connections.
Feb 09 11:24:59.363 [info] choose_good_exit_server_general(): Chose exit server 'superbad'
[...]
Feb 09 11:24:59.670 [info] connection_dir_client_reached_eof(): Received server info (size 3265) from server '87.106.188.238:80'
Feb 09 11:24:59.674 [info] router_load_routers_from_string(): 1 elements to add
Feb 09 11:24:59.736 [info] connection_dir_client_reached_eof(): Received 1/1 routers requested from 87.106.188.238:80
[...]
Feb 09 11:24:59.846 [info] connection_dir_client_reached_eof(): Received networkstatus objects (size 382650) from server '91.121.7.211:80'
Feb 09 11:25:00.063 [info] router_set_networkstatus(): Setting networkstatus downloaded from directory server "moria1" at 128.31.0.34:9031 (published 2008-02-09 09:58:14)
Feb 09 11:25:00.079 [info] networkstatus_list_update_recent(): Networkstatus from directory server "moria1" at 128.31.0.34:9031 (published 2008-02-09 09:58:14) is now "recent"
Feb 09 11:25:00.080 [info] networkstatus_list_update_recent(): Networkstatus from directory server "tor26" at 86.59.21.38:80 (published 2008-02-08 21:44:01) is no longer "recent"
Feb 09 11:25:00.081 [info] routerstatus_list_update_from_networkstatus(): Rebuilding router status list.
Feb 09 11:25:00.108 [info] routerstatus_list_update_from_networkstatus(): Naming authorities disagree about which key goes with JoesTorServer. ($0731DD94CD90068DAFE31DBC449F1BA36C6DF277 vs $86D83F4F853EDFEEAD1EF3B17CE2034F8397A8F6)
[...]
Feb 09 11:25:01.589 [info] entry_guards_compute_status(): Summary: Entry 'rfc1149' is reachable, usable and live.
Feb 09 11:25:01.589 [info] entry_guards_compute_status(): Summary: Entry 'Bellum' is reachable, unusable and not live.
Feb 09 11:25:01.590 [info] entry_guards_compute_status(): Summary: Entry 'SuperDuperLative' is reachable, usable and live.
Feb 09 11:25:01.590 [info] entry_guards_compute_status(): Summary: Entry 'lolnode' is reachable, usable and live.
Feb 09 11:25:01.590 [debug] tor_version_is_obsolete(): Checking whether version '0.1.2.19' is in '0.1.2.19,0.2.0.11-alpha,0.2.0.12-alpha,0.2.0.15-alpha,0.2.0.18-alpha'
Feb 09 11:25:01.590 [debug] tor_version_is_obsolete(): Checking whether version '0.1.2.19' is in '0.1.2.17,0.1.2.18,0.1.2.19,0.2.0.6-alpha,0.2.0.7-alpha,0.2.0.8-alpha,0.2.0.9-alpha,0.2.0.10-alpha,0.2.0.11-alpha,0.2.0.12-alpha,0.2.0.13-alpha,0.2.0.14-alpha,0.2.0.15-alpha,0.2.0.16-alpha,0.2.0.17-alpha,0.2.0.18-alpha'
Feb 09 11:25:01.590 [debug] tor_version_is_obsolete(): Checking whether version '0.1.2.19' is in '0.1.2.19,0.2.0.11-alpha,0.2.0.12-alpha,0.2.0.15-alpha,0.2.0.18-alpha'
Feb 09 11:25:01.591 [info] routers_update_all_from_networkstatus(): 3/3 statements from version-listing directory authorities say my version is ok.
Feb 09 11:25:01.643 [debug] conn_close_if_marked(): Cleaning up connection (fd 14).
Feb 09 11:25:01.643 [debug] connection_remove(): removing socket 14 (type Directory), n_conns now 5
Feb 09 11:25:01.644 [debug] _connection_free(): closing fd 14.
Feb 09 11:25:01.644 [debug] conn_read_callback(): socket 16 wants to read.
Feb 09 11:25:01.891 [debug] connection_tls_continue_handshake(): wanted read
Feb 09 11:25:01.892 [debug] global_read_bucket now 6291456.
Feb 09 11:25:01.892 [debug] global_write_bucket now 6291456.
Feb 09 11:25:01.893 [debug] circuit_remove_handled_ports(): Port 80 is not handled.
Feb 09 11:25:01.893 [info] circuit_predict_and_launch_new(): Have 1 clean circs (0 internal), need another exit circ.
Feb 09 11:25:01.894 [debug] new_route_len(): Chosen route length 3 (1813 routers available).
Feb 09 11:25:01.898 [info] choose_good_exit_server_general(): Found 616 servers that might support 0/0 pending connections.
Feb 09 11:25:01.899 [debug] circuit_remove_handled_ports(): Port 80 is not handled.
Feb 09 11:25:01.902 [info] choose_good_exit_server_general(): Chose exit server 'almostunknown'
Feb 09 11:25:02.319 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'SuperDuperLative'
Feb 09 11:25:02.362 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'rfc1149'
Feb 09 11:25:02.473 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:02.473 [info] exit circ (length 3, exit almostunknown): rfc1149(open) keinezensurde(closed) almostunknown(closed)
Feb 09 11:25:02.474 [debug] command_process_created_cell(): Moving to next skin.
Feb 09 11:25:02.474 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:02.509 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:02.510 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:02.510 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:02.511 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:02.511 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:02.512 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:02.513 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:02.513 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:02.596 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:02.597 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:02.597 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:02.597 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:02.598 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:02.599 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:02.599 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:02.600 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:02.600 [debug] connection_edge_process_relay_cell(): Now seen 1 relay cells here.
Feb 09 11:25:02.601 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:02.633 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:02.634 [info] exit circ (length 3, exit almostunknown): rfc1149(open) keinezensurde(open) almostunknown(closed)
Feb 09 11:25:02.634 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:02.669 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:02.670 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:02.670 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:02.671 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:02.671 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:02.672 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:02.672 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:02.673 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:02.673 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:02.920 [debug] global_read_bucket now 6291456.
Feb 09 11:25:02.920 [debug] global_write_bucket now 6291456.
Feb 09 11:25:02.971 [info] circuit_predict_and_launch_new(): Have 2 clean circs (0 uptime-internal, 0 internal), need another hidserv circ.
Feb 09 11:25:02.972 [debug] new_route_len(): Chosen route length 3 (1813 routers available).
Feb 09 11:25:02.974 [debug] onion_extend_cpath(): Path is 0 long; we want 3
Feb 09 11:25:02.975 [debug] onion_extend_cpath(): Chose router rfc1149 for hop 1 (exit is aim1loxal1net)
Feb 09 11:25:02.975 [debug] onion_extend_cpath(): Path is 1 long; we want 3
Feb 09 11:25:02.976 [debug] choose_good_middle_server(): Contemplating intermediate hop: random choice.
Feb 09 11:25:02.979 [debug] onion_extend_cpath(): Chose router petspaper for hop 2 (exit is aim1loxal1net)
Feb 09 11:25:02.979 [debug] onion_extend_cpath(): Path is 2 long; we want 3
Feb 09 11:25:02.980 [debug] onion_extend_cpath(): Chose router aim1loxal1net for hop 3 (exit is aim1loxal1net)
Feb 09 11:25:02.980 [debug] onion_extend_cpath(): Path is complete: 3 steps long
Feb 09 11:25:02.981 [debug] circuit_handle_first_hop(): Looking for firsthop '88.191.14.223:9001'
Feb 09 11:25:02.981 [debug] circuit_handle_first_hop(): Conn open. Delivering first onion skin.
Feb 09 11:25:02.982 [debug] circuit_send_next_onion_skin(): First skin; sending create cell.
Feb 09 11:25:03.018 [debug] circuit_deliver_create_cell(): Chosen circID 23586.
Feb 09 11:25:03.019 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:03.019 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'rfc1149'
Feb 09 11:25:03.020 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:03.022 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:03.022 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:03.086 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:03.086 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:03.087 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:03.087 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:03.088 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:03.088 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:03.089 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:03.089 [debug] command_process_created_cell(): at OP. Finishing handshake.
Feb 09 11:25:03.122 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:03.122 [info] internal (high-uptime) circ (length 3, exit aim1loxal1net): rfc1149(open) petspaper(closed) aim1loxal1net(closed)
Feb 09 11:25:03.123 [debug] command_process_created_cell(): Moving to next skin.
Feb 09 11:25:03.123 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:03.158 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:03.159 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:03.159 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:03.160 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:03.160 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:03.161 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:03.161 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:03.162 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:03.346 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:03.346 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:03.347 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:03.347 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:03.348 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:03.348 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:03.349 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:03.349 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:03.350 [debug] connection_edge_process_relay_cell(): Now seen 2 relay cells here.
Feb 09 11:25:03.350 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:03.383 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:03.384 [info] internal (high-uptime) circ (length 3, exit aim1loxal1net): rfc1149(open) petspaper(open) aim1loxal1net(closed)
Feb 09 11:25:03.384 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:03.419 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:03.419 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:03.420 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:03.421 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:03.421 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:03.421 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:03.422 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:03.423 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:03.423 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:04.020 [debug] global_read_bucket now 6291456.
Feb 09 11:25:04.021 [debug] global_write_bucket now 6291456.
Feb 09 11:25:04.021 [info] circuit_predict_and_launch_new(): Have 3 clean circs (1 uptime-internal, 1 internal), need another hidserv circ.
Feb 09 11:25:04.022 [debug] new_route_len(): Chosen route length 3 (1813 routers available).
Feb 09 11:25:04.023 [debug] onion_extend_cpath(): Path is 0 long; we want 3
Feb 09 11:25:04.024 [debug] onion_extend_cpath(): Chose router rfc1149 for hop 1 (exit is ArnoldBros1905)
Feb 09 11:25:04.025 [debug] onion_extend_cpath(): Path is 1 long; we want 3
Feb 09 11:25:04.025 [debug] choose_good_middle_server(): Contemplating intermediate hop: random choice.
Feb 09 11:25:04.028 [debug] onion_extend_cpath(): Chose router wiredwings for hop 2 (exit is ArnoldBros1905)
Feb 09 11:25:04.029 [debug] onion_extend_cpath(): Path is 2 long; we want 3
Feb 09 11:25:04.029 [debug] onion_extend_cpath(): Chose router ArnoldBros1905 for hop 3 (exit is ArnoldBros1905)
Feb 09 11:25:04.030 [debug] onion_extend_cpath(): Path is complete: 3 steps long
Feb 09 11:25:04.030 [debug] circuit_handle_first_hop(): Looking for firsthop '88.191.14.223:9001'
Feb 09 11:25:04.031 [debug] circuit_handle_first_hop(): Conn open. Delivering first onion skin.
Feb 09 11:25:04.031 [debug] circuit_send_next_onion_skin(): First skin; sending create cell.
Feb 09 11:25:04.066 [debug] circuit_deliver_create_cell(): Chosen circID 23587.
Feb 09 11:25:04.066 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:04.067 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'rfc1149'
Feb 09 11:25:04.067 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:04.068 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:04.069 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:04.146 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:04.147 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:04.147 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.147 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.148 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:04.149 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:04.149 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:04.149 [debug] command_process_created_cell(): at OP. Finishing handshake.
Feb 09 11:25:04.183 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:04.184 [info] internal (high-uptime) circ (length 3, exit ArnoldBros1905): rfc1149(open) wiredwings(closed) ArnoldBros1905(closed)
Feb 09 11:25:04.184 [debug] command_process_created_cell(): Moving to next skin.
Feb 09 11:25:04.184 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:04.219 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:04.220 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:04.220 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:04.224 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:04.225 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:04.225 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:04.226 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:04.227 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:04.301 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:04.302 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:04.302 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.302 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.303 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:04.304 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:04.304 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:04.304 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:04.305 [debug] connection_edge_process_relay_cell(): Now seen 3 relay cells here.
Feb 09 11:25:04.305 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:04.340 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:04.341 [info] internal (high-uptime) circ (length 3, exit ArnoldBros1905): rfc1149(open) wiredwings(open) ArnoldBros1905(closed)
Feb 09 11:25:04.341 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:04.376 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:04.377 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:04.377 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:04.378 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:04.378 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:04.380 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:04.381 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:04.382 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:04.382 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:04.544 [debug] conn_read_callback(): socket 16 wants to read.
Feb 09 11:25:04.545 [debug] connection_read_to_buf(): 16: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:04.545 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.546 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.546 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:04.547 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:04.547 [debug] connection_or_process_cells_from_inbuf(): 16: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:04.548 [debug] command_process_created_cell(): at OP. Finishing handshake.
Feb 09 11:25:04.580 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:04.581 [info] exit circ (length 3, exit superbad): SuperDuperLative(open) DrazziBTorNode(closed) superbad(closed)
Feb 09 11:25:04.582 [debug] command_process_created_cell(): Moving to next skin.
Feb 09 11:25:04.582 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:04.617 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:04.617 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:04.618 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:04.618 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:04.619 [debug] connection_or_process_cells_from_inbuf(): 16: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:04.619 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:04.620 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:04.620 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.621 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.621 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:04.622 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:04.622 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:04.623 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:04.623 [debug] connection_edge_process_relay_cell(): Now seen 4 relay cells here.
Feb 09 11:25:04.624 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:04.656 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:04.657 [info] internal (high-uptime) circ (length 3, exit ArnoldBros1905): rfc1149(open) wiredwings(open) ArnoldBros1905(open)
Feb 09 11:25:04.657 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:04.657 [info] circuit_send_next_onion_skin(): circuit built!
Feb 09 11:25:04.658 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Feb 09 11:25:04.659 [notice] Now checking whether ORPort x.x.x.x:9001 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Feb 09 11:25:04.661 [info] consider_testing_reachability(): Testing reachability of my ORPort: x.x.x.x:9001.
Feb 09 11:25:04.661 [debug] new_route_len(): Chosen route length 3 (1813 routers available).
Feb 09 11:25:04.662 [info] onion_pick_cpath_exit(): Using requested exit node 'tor'
Feb 09 11:25:04.663 [debug] onion_extend_cpath(): Path is 0 long; we want 3
Feb 09 11:25:04.664 [debug] onion_extend_cpath(): Chose router rfc1149 for hop 1 (exit is tor)
Feb 09 11:25:04.664 [debug] onion_extend_cpath(): Path is 1 long; we want 3
Feb 09 11:25:04.664 [debug] choose_good_middle_server(): Contemplating intermediate hop: random choice.
Feb 09 11:25:04.683 [info] compute_preferred_testing_list(): Looking for middle server that doesn't have the reachability bug, and chose 'Gollum'. Great.
Feb 09 11:25:04.684 [debug] onion_extend_cpath(): Chose router Gollum for hop 2 (exit is tor)
Feb 09 11:25:04.685 [debug] onion_extend_cpath(): Path is 2 long; we want 3
Feb 09 11:25:04.685 [debug] onion_extend_cpath(): Chose router tor for hop 3 (exit is tor)
Feb 09 11:25:04.685 [debug] onion_extend_cpath(): Path is complete: 3 steps long
Feb 09 11:25:04.686 [debug] circuit_handle_first_hop(): Looking for firsthop '88.191.14.223:9001'
Feb 09 11:25:04.686 [debug] circuit_handle_first_hop(): Conn open. Delivering first onion skin.
Feb 09 11:25:04.687 [debug] circuit_send_next_onion_skin(): First skin; sending create cell.
Feb 09 11:25:04.722 [debug] circuit_deliver_create_cell(): Chosen circID 23588.
Feb 09 11:25:04.722 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:04.723 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE cell to 'rfc1149'
Feb 09 11:25:04.723 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:04.724 [debug] conn_write_callback(): socket 16 wants to write.
Feb 09 11:25:04.725 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:04.725 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:04.726 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:04.726 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:04.727 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:04.795 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:04.796 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:04.796 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.797 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:04.797 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:04.798 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:04.798 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:04.799 [debug] command_process_created_cell(): at OP. Finishing handshake.
Feb 09 11:25:04.831 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:04.832 [info] internal circ (length 3, exit tor): rfc1149(open) $BF39AFADE1ECAB0373459236D31C6A0E3B59CB82(closed) $795EC4D74109C3B4CD7ECB2B652AEF51F99CA5FB(closed)
Feb 09 11:25:04.833 [debug] command_process_created_cell(): Moving to next skin.
Feb 09 11:25:04.833 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:04.868 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:04.868 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:04.869 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:04.869 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:04.870 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:04.870 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:04.871 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:04.872 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:05.070 [debug] global_read_bucket now 6291456.
Feb 09 11:25:05.071 [debug] global_write_bucket now 6291456.
Feb 09 11:25:05.738 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:05.738 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:05.739 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:05.739 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:05.740 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:05.740 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:05.741 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:05.741 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:05.742 [debug] connection_edge_process_relay_cell(): Now seen 5 relay cells here.
Feb 09 11:25:05.742 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:05.775 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:05.775 [info] exit circ (length 3, exit almostunknown): rfc1149(open) keinezensurde(open) almostunknown(open)
Feb 09 11:25:05.776 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:05.776 [info] circuit_send_next_onion_skin(): circuit built!
Feb 09 11:25:05.776 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:06.080 [debug] global_read_bucket now 6291456.
Feb 09 11:25:06.452 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:06.452 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:06.452 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:06.452 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:06.453 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:06.453 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:06.453 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:06.453 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:06.453 [debug] connection_edge_process_relay_cell(): Now seen 6 relay cells here.
Feb 09 11:25:06.453 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:06.486 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:06.487 [info] internal (high-uptime) circ (length 3, exit aim1loxal1net): rfc1149(open) petspaper(open) aim1loxal1net(open)
Feb 09 11:25:06.487 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:06.488 [info] circuit_send_next_onion_skin(): circuit built!
Feb 09 11:25:06.488 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:06.553 [debug] conn_read_callback(): socket 16 wants to read.
Feb 09 11:25:06.554 [debug] connection_read_to_buf(): 16: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:06.554 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:06.554 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:06.555 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:06.556 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:06.556 [debug] connection_or_process_cells_from_inbuf(): 16: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:06.557 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:06.557 [debug] connection_edge_process_relay_cell(): Now seen 7 relay cells here.
Feb 09 11:25:06.557 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:06.590 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:06.590 [info] exit circ (length 3, exit superbad): SuperDuperLative(open) DrazziBTorNode(open) superbad(closed)
Feb 09 11:25:06.591 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:06.628 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:06.629 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:06.629 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:06.630 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:06.630 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:06.631 [debug] connection_or_process_cells_from_inbuf(): 16: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:06.631 [debug] conn_write_callback(): socket 16 wants to write.
Feb 09 11:25:06.632 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:06.632 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:06.685 [debug] conn_read_callback(): socket 11 wants to read.
Feb 09 11:25:06.686 [debug] connection_read_to_buf(): 11: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:06.686 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:06.687 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:06.688 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:06.688 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:06.688 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:06.689 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:06.689 [debug] connection_edge_process_relay_cell(): Now seen 8 relay cells here.
Feb 09 11:25:06.690 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:06.723 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:06.723 [info] internal circ (length 3, exit tor): rfc1149(open) $BF39AFADE1ECAB0373459236D31C6A0E3B59CB82(open) $795EC4D74109C3B4CD7ECB2B652AEF51F99CA5FB(closed)
Feb 09 11:25:06.724 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:06.759 [debug] circuit_send_next_onion_skin(): Sending extend relay cell.
Feb 09 11:25:06.759 [debug] relay_send_command_from_edge(): delivering 6 cell forward.
Feb 09 11:25:06.760 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:06.760 [debug] circuit_package_relay_cell(): crypting a layer of the relay cell.
Feb 09 11:25:06.761 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Feb 09 11:25:06.761 [debug] connection_or_process_cells_from_inbuf(): 11: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:06.762 [debug] conn_write_callback(): socket 11 wants to write.
Feb 09 11:25:06.763 [debug] flush_buf_tls_impl(): flushed 512 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:06.763 [debug] connection_handle_write(): After TLS write of 512: 0 read, 586 written
Feb 09 11:25:07.091 [debug] global_read_bucket now 6291456.
Feb 09 11:25:07.092 [debug] global_write_bucket now 6291456.
Feb 09 11:25:07.719 [debug] conn_read_callback(): socket 5 wants to read.
Feb 09 11:25:07.720 [debug] connection_handle_listener_read(): Connection accepted on socket 14 (child of fd 5).
Feb 09 11:25:07.721 [debug] connection_add(): new conn type OR, socket 14, n_conns 7.
Feb 09 11:25:07.721 [debug] connection_tls_start_handshake(): starting TLS handshake on fd 14
Feb 09 11:25:07.722 [debug] connection_tls_continue_handshake(): wanted read
Feb 09 11:25:07.732 [debug] conn_read_callback(): socket 14 wants to read.
Feb 09 11:25:07.798 [debug] connection_tls_continue_handshake(): wanted read
Feb 09 11:25:08.033 [debug] conn_read_callback(): socket 14 wants to read.
Feb 09 11:25:08.076 [debug] connection_tls_finish_handshake(): tls handshake done. verifying.
Feb 09 11:25:08.078 [debug] connection_or_check_valid_handshake(): The certificate seems to be valid on incoming connection with [scrubbed]:6169
Feb 09 11:25:08.079 [debug] circuit_n_conn_done(): or_conn to Gollum, status=1
Feb 09 11:25:08.080 [debug] connection_or_process_cells_from_inbuf(): 14: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:08.541 [debug] conn_read_callback(): socket 14 wants to read.
Feb 09 11:25:08.542 [debug] connection_read_to_buf(): 14: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:08.543 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:08.543 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:08.544 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:08.544 [debug] connection_read_to_buf(): After TLS read of 512: 1908 read, 1450 written
Feb 09 11:25:08.544 [debug] connection_or_process_cells_from_inbuf(): 14: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:08.545 [debug] write_to_buf(): added 1 bytes to buf (now 1 total).
Feb 09 11:25:08.545 [debug] write_to_buf(): added 8 bytes to buf (now 9 total).
Feb 09 11:25:08.546 [debug] write_to_buf(): added 186 bytes to buf (now 195 total).
Feb 09 11:25:08.546 [debug] command_process_create_cell(): success: handed off onionskin.
Feb 09 11:25:08.546 [debug] connection_or_process_cells_from_inbuf(): 14: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:08.547 [debug] conn_write_callback(): socket 15 wants to write.
Feb 09 11:25:08.570 [debug] flush_buf(): 15: flushed 195 bytes, 0 ready to flush, 0 remain.
Feb 09 11:25:08.571 [debug] conn_read_callback(): socket 16 wants to read.
Feb 09 11:25:08.572 [debug] connection_read_to_buf(): 16: starting, inbuf_datalen 0 (0 pending in tls object). at_most 4096.
Feb 09 11:25:08.572 [debug] read_to_buf_tls(): start: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:08.572 [debug] read_to_buf_tls_impl(): before: 0 on buf, 0 pending, at_most 4096.
Feb 09 11:25:08.573 [debug] read_to_buf_tls_impl(): Read 512 bytes. 512 on inbuf; 0 pending
Feb 09 11:25:08.573 [debug] connection_read_to_buf(): After TLS read of 512: 586 read, 0 written
Feb 09 11:25:08.574 [debug] connection_or_process_cells_from_inbuf(): 16: starting, inbuf_datalen 512 (0 pending in tls object).
Feb 09 11:25:08.574 [debug] circuit_receive_relay_cell(): Sending to origin.
Feb 09 11:25:08.575 [debug] connection_edge_process_relay_cell(): Now seen 9 relay cells here.
Feb 09 11:25:08.575 [debug] connection_edge_process_relay_cell(): Got an extended cell! Yay.
Feb 09 11:25:08.648 [info] circuit_finish_handshake(): Finished building circuit hop:
Feb 09 11:25:08.648 [info] exit circ (length 3, exit superbad): SuperDuperLative(open) DrazziBTorNode(open) superbad(open)
Feb 09 11:25:08.649 [debug] circuit_send_next_onion_skin(): starting to send subsequent skin.
Feb 09 11:25:08.649 [info] circuit_send_next_onion_skin(): circuit built!
Feb 09 11:25:08.650 [debug] connection_or_process_cells_from_inbuf(): 16: starting, inbuf_datalen 0 (0 pending in tls object).
Feb 09 11:25:08.692 [debug] cpuworker_main(): onion_skin_server_handshake succeeded.
Feb 09 11:25:08.693 [debug] cpuworker_main(): finished writing response.
Feb 09 11:25:08.694 [debug] conn_read_callback(): socket 15 wants to read.
Feb 09 11:25:08.694 [debug] read_to_buf_impl(): Read 229 bytes. 229 on inbuf.
Bus Error
# Feb 09 11:25:08.712 [info] cpuworker_main(): CPU worker exiting because Tor process closed connection (either rotated keys or died).

[Automatically added by flyspray2trac: Operating System: Solaris]

Child Tickets

Change History (19)

comment:1 Changed 12 years ago by arma

Neat!

Bus errors are usually alignment issues or sometimes endian issues. I don't think
we have very many solaris Tor servers at this point, so there may well be a bug
here.

Can you run it in gdb, and perhaps you'll get a better backtrace?

comment:2 Changed 11 years ago by nickm

Hi! Are you still around? Do the more recent Tor versions fix this problem? Did you ever try reproducing this
with a debugger?

I'd love to get Solaris working better, but we really need a stack trace to debug this one.

comment:3 Changed 11 years ago by phobos

Last chance, if the original requester is still around, please update. Thanks!

comment:4 Changed 11 years ago by jaba

Yes, I am still around and gave tor a latest try end of Oct. with release 0.2.0.31 and tor-0.2.1.6-alpha with
freshly compiled libevent-1.4.8-stable. No change, still crashes during startup exactly as reported.

Thanks for any ideas!
Jan

comment:5 Changed 11 years ago by arma

Are you on a 64 bit cpu?

Can you try checking out Tor svn from trunk and build that and see if it
works?
https://www.torproject.org/documentation.html.en#Developers

A core would be really helpful here. It should dump core if you ulimit -c unlimited.
(I see in the original report that you had already done that, so perhaps something
else is wrong?)

comment:6 Changed 11 years ago by jaba

Hi, spent the evening with it and have more info on this:

Checked out the svn. Builds fine, starts, bootstraps to 100% and crashes as soon as it gets inbound connections.
I am on Solaris 10 on a Sun Netra X1, that means UltraSparc IIe 64bit cpu.

I start tor as non-privileged user tor and the reason for not getting a core dump was directory permissions.
Unfortunately gdb 6.8 does not build cleanly on the machine to be able to get a backtrace. Will try to get a binary pkg.

comment:7 Changed 11 years ago by unixm

Hi,

I too am having the same problem. I am using a Sun Netra T1 105, with Ubuntu 7.10. I keep getting a "Bus Error" message at the same stage.

I have tried compiling and using the following versions with no success:

0.2.0.34
0.2.1.12-alpha
v0.2.1.12-alpha-dev (r18689)

Please let me know what other information you provide and how I can get it. Please forgive the fact that I haven't been using Unix/Linux for a great deal of time.

comment:8 Changed 11 years ago by unixm

I forgot to mention the "v0.2.1.12-alpha-dev (r18689)" is of course from the SVN Repository

comment:9 Changed 11 years ago by unixm

Hi Again,

I have managed to run the program in GDB, hopefully the information below will shed some light on the situation:

Starting program: /usr/local/bin/tor
[Thread debugging using libthread_db enabled]
[New Thread -136927568 (LWP 6064)]
Feb 25 09:01:52.513 [notice] Tor v0.2.1.12-alpha-dev (r18689). This is experimental software. Do not rely on it for strong anonymity. (Running on Linux sparc64)
Feb 25 09:01:52.516 [notice] Your ContactInfo config option is not set. Please consider setting it, so we can contact you if your server is misconfigured or something else goes wrong.
Feb 25 09:01:52.518 [notice] Initialized libevent version 1.3b using method epoll. Good.
Feb 25 09:01:52.518 [notice] Opening OR listener on 0.0.0.0:9001
Feb 25 09:01:52.518 [notice] Opening Directory listener on 0.0.0.0:9030
Feb 25 09:01:52.518 [notice] Opening Socks listener on 127.0.0.1:9050
Feb 25 09:01:52.520 [notice] Parsing GEOIP file.
Feb 25 09:01:53.843 [warn] You are running Tor as root. You don't need to, and you probably shouldn't.
Feb 25 09:01:55.279 [notice] Your Tor server's identity key fingerprint is 'netraserver 5A9E 63BA 3914 FCC4 CC24 7E24 8212 864E 020A 5377'
Feb 25 09:01:57.024 [notice] This version of Tor (0.2.1.12-alpha-dev) is newer than any recommended version, according to the directory authorities. Recommended versions are: 0.2.0.33,0.2.0.34,0.2.1.11-alpha,0.2.1.12-alpha
Feb 25 09:02:06.424 [notice] We now have enough directory information to build circuits.
Feb 25 09:02:06.425 [notice] Bootstrapped 80%: Connecting to the Tor network.
[New Thread -144327792 (LWP 6067)]
Feb 25 09:02:06.769 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Feb 25 09:02:07.251 [notice] Guessed our IP address as 93.97.81.47.
Feb 25 09:02:07.874 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Feb 25 09:02:11.175 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Feb 25 09:02:11.175 [notice] Bootstrapped 100%: Done.
Feb 25 09:02:11.175 [notice] Now checking whether ORPort 93.97.81.47:9001 and DirPort 93.97.81.47:9030 are reachable... (this may take up to 20 minutes -- look for log messages indicating success)

Program received signal SIGBUS, Bus error.
[Switching to Thread -136927568 (LWP 6064)]
assign_onionskin_to_cpuworker (cpuworker=0x8b2418, circ=0x2d1290,

onionskin=0x2d1340 "@'\231\233ð«ÛVt\177\fÜ\005OUöÏ(\005EÑË\212S\216ð\206Ç\005SÊÎk¢\177³*s?\222¡AÞ\226ÜÁ-À]öºËkÕ~\036Ìè\"'¨)͹ãâtÝ\204wn6òâMæ\"VâôDàðß´¯,Æî)ùh\024@å¯\vÅkº\026\vÜ\017\f\227\vÒâ\226ééPìû_A/\001Iå\216$tùvÕ³ ã\2340\a\005«Ö8H\017\227¨\017&.û×) M\r¯/M\223\022\035ËجQ³ì·\222y¯$üpâ£\227$po¿ÖU\235YwÂ!;\236º") at cpuworker.c:66

66 *(uint64_t *)tag = conn_id;

comment:10 Changed 11 years ago by unixm

Hi,

Is this currently being looked into at all?

comment:11 Changed 11 years ago by nickm

It's an open bug, so yes. The backtrace above looks like it'll be easy to fix; it seems that the code was
making unwarranted alignment assumptions in tag_pack().

comment:12 Changed 11 years ago by nickm

Does svn revision 18743 on trunk work any better? If not, does it segfault in the same place, or something
different? It should at least fix the crash from your Wednesday, 25 Feb 2009, 10:02am post.

comment:13 Changed 11 years ago by unixm

Hi There,

I have tried it on 18739, and got this result:

Starting program: /usr/local/bin/tor
[Thread debugging using libthread_db enabled]
[New Thread -136845648 (LWP 21725)]
Mar 02 19:18:21.740 [notice] Tor v0.2.1.12-alpha-dev (r18739). This is experimental software. Do not rely on it for strong anonymity. (Running on Linux sparc64)
Mar 02 19:18:21.745 [notice] Initialized libevent version 1.3b using method epoll. Good.
Mar 02 19:18:21.745 [notice] Opening OR listener on 0.0.0.0:9001
Mar 02 19:18:21.746 [notice] Opening Directory listener on 0.0.0.0:9030
Mar 02 19:18:21.746 [notice] Opening Socks listener on 127.0.0.1:9050
Mar 02 19:18:21.748 [notice] Parsing GEOIP file.
Mar 02 19:18:23.091 [warn] You are running Tor as root. You don't need to, and you probably shouldn't.
Mar 02 19:18:24.685 [notice] Your Tor server's identity key fingerprint is 'netraserver 5A9E 63BA 3914 FCC4 CC24 7E24 8212 864E 020A 5377'
Mar 02 19:18:26.487 [notice] This version of Tor (0.2.1.12-alpha-dev) is newer than any recommended version, according to the directory authorities. Recommended versions are: 0.2.0.33,0.2.0.34,0.2.1.11-alpha,0.2.1.12-alpha
Mar 02 19:18:36.483 [notice] We now have enough directory information to build circuits.
Mar 02 19:18:36.484 [notice] Bootstrapped 80%: Connecting to the Tor network.
[New Thread -144721008 (LWP 21728)]
Mar 02 19:18:36.716 [notice] Guessed our IP address as 93.97.81.47.
Mar 02 19:18:39.920 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Mar 02 19:18:41.567 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Mar 02 19:18:42.610 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Mar 02 19:18:42.610 [notice] Bootstrapped 100%: Done.
Mar 02 19:18:42.611 [notice] Now checking whether ORPort 93.97.81.47:9001 and DirPort 93.97.81.47:9030 are reachable... (this may take up to 20 minutes -- look for log messages indicating success)

Program received signal SIGBUS, Bus error.
[Switching to Thread -136845648 (LWP 21725)]
assign_onionskin_to_cpuworker (cpuworker=0x6fed98, circ=0x64d6a0,

onionskin=0x7e36e8 "¢HlðÀ\002\236}\217¾ii\aHT~¸\a²|\223VZ.Ý¥=mÌX}i$áäYh\030;©\211\026ölv$»¥ÜL\205¢ÅO.îR\025v\213Ño¬æ\206»\215~Ãrmp&W­~\002ïæW¦øðú\200ÛØ\003%\027\025qH$6\005\020CHn³Rö\020,¯\212×\"\232±À\2143\202\207Ó£Ï\234\001o#
#ë\n5Ï\023̶¶Kg\aV\bSÞ\203\0249\026sã¶6\035Mk\035Ö\001\004°\205z\222̼8\200;­}Ç\231¥\bãIä\açßv'\220ÀþØø\220þý") at cpuworker.c:66

66 *(uint64_t *)tag = conn_id;
(gdb)

I am going to try the 18743 now

comment:14 Changed 11 years ago by unixm

Hi,

I think its working now, hasn't come up with a "Bus Error" at all. See Below:

Mar 02 19:30:48.949 [notice] Tor v0.2.1.12-alpha-dev (r18744). This is experimental software. Do not rely on it for strong anonymity. (Running on Linux sparc64)
Mar 02 19:30:48.956 [notice] Initialized libevent version 1.3b using method epoll. Good.
Mar 02 19:30:48.956 [notice] Opening OR listener on 0.0.0.0:9001
Mar 02 19:30:48.957 [notice] Opening Directory listener on 0.0.0.0:9030
Mar 02 19:30:48.957 [notice] Opening Socks listener on 127.0.0.1:9050
Mar 02 19:30:48.960 [notice] Parsing GEOIP file.
Mar 02 19:30:50.322 [warn] You are running Tor as root. You don't need to, and you probably shouldn't.
Mar 02 19:30:53.230 [notice] Your Tor server's identity key fingerprint is 'netraserver 5A9E 63BA 3914 FCC4 CC24 7E24 8212 864E 020A 5377'
Mar 02 19:30:55.087 [notice] This version of Tor (0.2.1.12-alpha-dev) is newer than any recommended version, according to the directory authorities. Recommended versions are: 0.2.0.33,0.2.0.34,0.2.1.11-alpha,0.2.1.12-alpha
Mar 02 19:31:05.755 [notice] We now have enough directory information to build circuits.
Mar 02 19:31:05.756 [notice] Bootstrapped 80%: Connecting to the Tor network.
Mar 02 19:31:06.031 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Mar 02 19:31:06.138 [notice] Guessed our IP address as 93.97.81.47.
Mar 02 19:31:06.960 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Mar 02 19:31:10.849 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Mar 02 19:31:10.850 [notice] Bootstrapped 100%: Done.
Mar 02 19:31:10.850 [notice] Now checking whether ORPort 93.97.81.47:9001 and DirPort 93.97.81.47:9030 are reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Mar 02 19:31:15.862 [notice] Self-testing indicates your ORPort is reachable from the outside. Excellent. Publishing server descriptor.
Mar 02 19:31:28.311 [notice] Performing bandwidth self-test...done.
Mar 02 19:31:35.935 [notice] Self-testing indicates your DirPort is reachable from the outside. Excellent.

comment:15 Changed 11 years ago by nickm

Cool! I think that's one bug fixed. If others show up, please let us know.

comment:16 Changed 11 years ago by unixm

well it seems to be working from what I can see. Thanks very much for fixing that. Very Nice :)

comment:17 Changed 11 years ago by nickm

Okay. I've marked this for backport into 0.2.0.x, and it'll already go into the next 0.2.1.x release.

Since the known case for 0.2.1.x is fixed, I'm closing this bug. Please open a new bug if there's a similar crash
but the stack trace points to somewhere different.

comment:18 Changed 11 years ago by nickm

flyspray2trac: bug closed.

comment:19 Changed 7 years ago by nickm

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