Ticket #11156: bug_11156.txt

File bug_11156.txt, 13.2 KB (added by asn, 5 years ago)
Line 
1Mar 28 17:50:30.000 [notice] Tor 0.2.5.2-alpha (git-7aa21920481fc4f0) opening new log file.
2Mar 28 17:50:30.000 [warn] Your log may contain sensitive information: you're logging more than "notice". Please log safely. Don't log unless it serves an important reason, and overwrite the log afterwards.
3Mar 28 17:50:30.000 [info] tor_lockfile_lock(): Locking "/tmp/tortmpsX3mA6/lock"
4Mar 28 17:50:30.000 [info] or_state_load(): Initialized state
5Mar 28 17:50:30.000 [info] circuit_build_times_parse_state(): Adding 0 timeouts.
6Mar 28 17:50:30.000 [info] circuit_build_times_parse_state(): Loaded 0/0 values from 0 lines in circuit time histogram
7Mar 28 17:50:30.000 [info] or_state_save(): Saved state to "/tmp/tortmpsX3mA6/state"
8Mar 28 17:50:30.000 [info] read_file_to_str(): Could not open "/tmp/tortmpsX3mA6/router-stability": No such file or directory
9Mar 28 17:50:30.000 [warn]  Rolling in optiosn_act()
10Mar 28 17:50:30.000 [info] init_cookie_authentication(): Generated auth cookie file in '"/tmp/tortmpsX3mA6/control_auth_cookie"'.
11Mar 28 17:50:30.000 [info] cell_ewma_set_scale_factor(): Disabled cell_ewma algorithm because of value in Default value
12Mar 28 17:50:30.000 [notice] Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
13Mar 28 17:50:30.000 [notice] Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
14Mar 28 17:50:30.000 [warn] You are running Tor as root. You don't need to, and you probably shouldn't.
15Mar 28 17:50:30.000 [info] crypto_early_init(): OpenSSL version matches version from headers (1000105f: OpenSSL 1.0.1e 11 Feb 2013).
16Mar 28 17:50:30.000 [info] crypto_strongest_rand(): Reading entropy from "/dev/urandom"
17Mar 28 17:50:30.000 [info] crypto_global_init(): NOT using OpenSSL engine support.
18Mar 28 17:50:30.000 [info] evaluate_evp_for_aes(): This version of OpenSSL has a known-good EVP counter-mode implementation. Using it.
19Mar 28 17:50:30.000 [info] tor_tls_init(): OpenSSL OpenSSL 1.0.1e 11 Feb 2013 looks like version 0.9.8m or later; I will try SSL_OP to enable renegotiation
20Mar 28 17:50:30.000 [info] Bootstrapped 0%: Starting.
21Mar 28 17:50:30.000 [info] read_file_to_str(): Could not open "/tmp/tortmpsX3mA6/cached-certs": No such file or directory
22Mar 28 17:50:30.000 [info] read_file_to_str(): Could not open "/tmp/tortmpsX3mA6/cached-consensus": No such file or directory
23Mar 28 17:50:30.000 [info] read_file_to_str(): Could not open "/tmp/tortmpsX3mA6/unverified-consensus": No such file or directory
24Mar 28 17:50:30.000 [info] read_file_to_str(): Could not open "/tmp/tortmpsX3mA6/cached-microdesc-consensus": No such file or directory
25Mar 28 17:50:30.000 [info] read_file_to_str(): Could not open "/tmp/tortmpsX3mA6/unverified-microdesc-consensus": No such file or directory
26Mar 28 17:50:30.000 [info] tor_mmap_file(): Could not open "/tmp/tortmpsX3mA6/cached-microdescs" for mmap(): No such file or directory
27Mar 28 17:50:30.000 [info] read_file_to_str(): Could not open "/tmp/tortmpsX3mA6/cached-microdescs.new": No such file or directory
28Mar 28 17:50:30.000 [info] microdesc_cache_reload(): Reloaded microdescriptor cache. Found 0 descriptors.
29Mar 28 17:50:30.000 [info] tor_mmap_file(): Could not open "/tmp/tortmpsX3mA6/cached-descriptors" for mmap(): No such file or directory
30Mar 28 17:50:30.000 [info] tor_mmap_file(): Could not open "/tmp/tortmpsX3mA6/cached-extrainfo" for mmap(): No such file or directory
31Mar 28 17:50:30.000 [info] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.
32Mar 28 17:50:30.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
33Mar 28 17:50:30.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
34Mar 28 17:50:30.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
35Mar 28 17:50:30.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
36Mar 28 17:50:30.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
37Mar 28 17:50:30.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
38Mar 28 17:50:31.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
39Mar 28 17:50:31.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
40Mar 28 17:50:31.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
41Mar 28 17:50:31.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
42Mar 28 17:50:31.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
43Mar 28 17:50:31.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
44Mar 28 17:50:31.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
45Mar 28 17:50:31.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
46Mar 28 17:50:31.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
47Mar 28 17:50:31.000 [info] launch_managed_proxy(): Managed proxy at '/usr/local/bin/obfsproxy' has spawned with PID '26612'.
48Mar 28 17:50:32.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/local/bin/obfsproxy': (VERSION 1)
49Mar 28 17:50:32.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/local/bin/obfsproxy': (CMETHOD obfs3 socks5 127.0.0.1:49563)
50Mar 28 17:50:32.000 [info] parse_cmethod_line(): Transport obfs3 at 127.0.0.1:49563 with SOCKS 3. Attached to managed proxy.
51Mar 28 17:50:32.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/local/bin/obfsproxy': (CMETHODS DONE)
52Mar 28 17:50:32.000 [info] handle_methods_done(): Client managed proxy '/usr/local/bin/obfsproxy' configuration completed!
53Mar 28 17:50:32.000 [info] register_client_proxy(): Successfully registered transport obfs3
54Mar 28 17:50:33.000 [info] connection_ap_make_link(): Making internal direct tunnel to [scrubbed]:80 ...
55Mar 28 17:50:33.000 [info] onion_pick_cpath_exit(): Using requested exit node '$0000000000000000000000000000000000000000~0000000000000000000 at 83.212.101.3'
56Mar 28 17:50:33.000 [info] circuit_handle_first_hop(): Next router is [scrubbed]: Not connected. Connecting.
57Mar 28 17:50:33.000 [notice] Bootstrapped 5%: Connecting to directory server.
58Mar 28 17:50:33.000 [info] channel_register(): Channel 0x7f147bf1e0f0 (global ID 0) in state opening (1) registered with no identity digest
59Mar 28 17:50:33.000 [info] connection_ap_make_link(): ... application connection created and linked.
60Mar 28 17:50:33.000 [notice] Bootstrapped 10%: Finishing handshake with directory server.
61Mar 28 17:50:33.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
62Mar 28 17:50:33.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
63Mar 28 17:50:33.000 [notice] New control connection opened from 127.0.0.1.
64Mar 28 17:50:33.000 [info] handle_control_authenticate(): Authenticated control connection (13)
65Mar 28 17:50:33.000 [info] handle_control_takeownership(): Control connection 13 has taken ownership of this Tor instance.
66Mar 28 17:50:33.000 [warn] RESETCONF! (asn's debug log)
67Mar 28 17:50:33.000 [notice] Tor 0.2.5.2-alpha (git-7aa21920481fc4f0) opening log file.
68Mar 28 17:50:33.000 [warn]  options_act() (asn's debug log)
69Mar 28 17:50:33.000 [info] cell_ewma_set_scale_factor(): Disabled cell_ewma algorithm because of value in Default value
70Mar 28 17:50:33.000 [info] parse_socks_client(): SOCKS 5 client: continuing without authentication
71Mar 28 17:50:33.000 [info] connection_read_proxy_handshake(): Proxy Client: connection to 83.212.101.3:80 successful
72Mar 28 17:50:34.000 [info] connection_tls_continue_handshake(): Client got a v3 cert!  Moving on to v3 handshake with ciphersuite ECDHE-RSA-AES128-SHA
73Mar 28 17:50:34.000 [info] channel_tls_process_versions_cell(): Negotiated version 4 with [scrubbed]:80; Waiting for CERTS cell
74Mar 28 17:50:34.000 [info] connection_or_client_learned_peer_id(): Connected to router $A09D536DD1752D542E1FBB3C9CE4449D51298239 at 83.212.101.3:80 without knowing its key. Hoping for the best.
75Mar 28 17:50:34.000 [notice] Learned fingerprint A09D536DD1752D542E1FBB3C9CE4449D51298239 for bridge 83.212.101.3:80 (with transport 'obfs3').
76Mar 28 17:50:34.000 [info] channel_tls_process_certs_cell(): Got some good certificates from [scrubbed]:80: Authenticated it.
77Mar 28 17:50:34.000 [notice] Bootstrapped 15%: Establishing an encrypted directory connection.
78Mar 28 17:50:34.000 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE_FAST cell to '<unnamed>'
79Mar 28 17:50:34.000 [info] channel_tls_process_netinfo_cell(): Got good NETINFO cell from [scrubbed]:80; OR connection is now open, using protocol version 4. Its ID digest is A09D536DD1752D542E1FBB3C9CE4449D51298239. Our address is apparently 83.212.122.95.
80Mar 28 17:50:34.000 [info] circuit_finish_handshake(): Finished building circuit hop:
81Mar 28 17:50:34.000 [info] internal circ (length 1, last hop 0000000000000000000000000000000000000000): $0000000000000000000000000000000000000000(open)
82Mar 28 17:50:34.000 [info] circuit_send_next_onion_skin(): circuit built!
83Mar 28 17:50:34.000 [notice] Bootstrapped 20%: Asking for networkstatus consensus.
84Mar 28 17:50:34.000 [info] internal circ (length 1): $0000000000000000000000000000000000000000(open)
85Mar 28 17:50:34.000 [info] connection_ap_handshake_send_begin(): Sending relay cell 1 to begin stream 35646.
86Mar 28 17:50:34.000 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket -1, n_circ_id 2147490296
87Mar 28 17:50:34.000 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
88Mar 28 17:50:34.000 [info] internal circ (length 1): $0000000000000000000000000000000000000000(open)
89Mar 28 17:50:34.000 [info] connection_edge_process_relay_cell(): -1: end cell (closed normally) for stream 35646. Removing stream.
90Mar 28 17:50:34.000 [info] connection_free_(): Freeing linked Socks connection [open] with 0 bytes on inbuf, 0 on outbuf.
91Mar 28 17:50:34.000 [info] connection_dir_client_reached_eof(): Received server info (size 1180) from server '83.212.101.3:80'
92Mar 28 17:50:34.000 [info] router_load_routers_from_string(): 1 elements to add
93Mar 28 17:50:34.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
94Mar 28 17:50:34.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
95Mar 28 17:50:34.000 [info] rewrite_node_address_for_bridge(): Adjusted bridge routerinfo for 'LeifEricson' to match configured address 83.212.101.3:80.
96Mar 28 17:50:34.000 [info] add_an_entry_guard(): Chose $A09D536DD1752D542E1FBB3C9CE4449D51298239~LeifEricson at 83.212.101.3 as new entry guard.
97Mar 28 17:50:34.000 [info] log_entry_guards(): LeifEricson [A09D536DD1752D542E1FBB3C9CE4449D51298239] (not fast/stable, made-contact)
98Mar 28 17:50:34.000 [notice] new bridge descriptor 'LeifEricson' (fresh): $A09D536DD1752D542E1FBB3C9CE4449D51298239~LeifEricson at 83.212.101.3
99Mar 28 17:50:34.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
100Mar 28 17:50:34.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
101Mar 28 17:50:34.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
102Mar 28 17:50:34.000 [notice] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.
103Mar 28 17:50:34.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
104Mar 28 17:50:34.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
105Mar 28 17:50:34.000 [info] connection_free_(): Freeing linked Directory connection [client finished] with 0 bytes on inbuf, 0 on outbuf.
106Mar 28 17:50:34.000 [info] pt_configure_remaining_proxies(): Nothing changed for managed proxy '/usr/local/bin/obfsproxy' after HUP: not restarting.
107Mar 28 17:50:35.000 [notice] Interrupt: exiting cleanly.
108Mar 28 17:50:35.000 [info] or_state_save(): Saved state to "/tmp/tortmpsX3mA6/state"
109Mar 28 17:50:35.000 [info] tor_process_handle_destroy(): Terminated process with PID '26612'.
110Mar 28 17:50:35.000 [info] buf_shrink_freelists(): Cleaned freelist for 4096-byte chunks: original length 3, kept 0, dropped 3. New length is 0
111Mar 28 17:50:35.000 [info] buf_shrink_freelists(): Cleaned freelist for 8192-byte chunks: original length 0, kept 0, dropped 0. New length is 0
112Mar 28 17:50:35.000 [info] buf_shrink_freelists(): Cleaned freelist for 16384-byte chunks: original length 0, kept 0, dropped 0. New length is 0
113Mar 28 17:50:35.000 [info] buf_shrink_freelists(): Cleaned freelist for 32768-byte chunks: original length 1, kept 0, dropped 1. New length is 0
114Mar 28 17:50:35.000 [info] tor_lockfile_unlock(): Unlocking "/tmp/tortmpsX3mA6/lock"