Ticket #11156: bug11156_60s.txt

File bug11156_60s.txt, 15.2 KB (added by asn, 6 years ago)
Line 
1Apr 05 15:03:36.000 [notice] Tor 0.2.5.2-alpha (git-ab06c19f964ac2f5) opening log file.
2Apr 05 15:03:36.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.
3Apr 05 15:03:36.000 [info] tor_lockfile_lock(): Locking "/home/f/.tor/lock"
4Apr 05 15:03:36.000 [info] entry_guards_parse_state(): Read 4.000000/6.000000 path bias for node LeifEricson
5Apr 05 15:03:36.000 [info] or_state_load(): Loaded state from "/home/f/.tor/state"
6Apr 05 15:03:36.000 [info] entry_guards_parse_state(): Read 4.000000/6.000000 path bias for node LeifEricson
7Apr 05 15:03:36.000 [info] circuit_build_times_parse_state(): Adding 0 timeouts.
8Apr 05 15:03:36.000 [info] circuit_build_times_parse_state(): Loaded 4/4 values from 4 lines in circuit time histogram
9Apr 05 15:03:36.000 [info] circuit_build_times_filter_timeouts(): We had 0 timeouts out of 4 build times, and filtered 0 above the max of 60000
10Apr 05 15:03:36.000 [info] read_file_to_str(): Could not open "/home/f/.tor/router-stability": No such file or directory
11Apr 05 15:03:36.000 [info] cell_ewma_set_scale_factor(): Disabled cell_ewma algorithm because of value in Default value
12Apr 05 15:03:36.000 [notice] Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
13Apr 05 15:03:36.000 [notice] Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
14Apr 05 15:03:36.000 [info] crypto_early_init(): OpenSSL version matches version from headers (1000106f: OpenSSL 1.0.1f 6 Jan 2014).
15Apr 05 15:03:36.000 [info] crypto_strongest_rand(): Reading entropy from "/dev/urandom"
16Apr 05 15:03:36.000 [info] crypto_global_init(): NOT using OpenSSL engine support.
17Apr 05 15:03:36.000 [info] evaluate_evp_for_aes(): This version of OpenSSL has a known-good EVP counter-mode implementation. Using it.
18Apr 05 15:03:36.000 [info] tor_tls_init(): OpenSSL OpenSSL 1.0.1f 6 Jan 2014 looks like version 0.9.8m or later; I will try SSL_OP to enable renegotiation
19Apr 05 15:03:36.000 [info] Bootstrapped 0%: Starting.
20Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority gabelmoo with signing key 09CD84F751FD6E955E0F8ADB497D5401470D697E
21Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority Faravahar with signing key 9DCD8E3F1DD1597E2AD476BBA28A1A89F3095227
22Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority moria1 with signing key 3A8218840C58F0F35B1EEFAF3C39FE46FBAC842B
23Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority tor26 with signing key 57B85409891D3FB32137F642FDEDF8B7F8CDFDCD
24Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority dizum with signing key 0E7E9C07F0969D0468AD741E172A6109DC289F3C
25Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority dannenberg with signing key 87326329007AF781F587AF5B594E540B2B6C7630
26Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority maatuska with signing key A61682F34B9BB9694AC98491FE1ABBFE61923941
27Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority turtles with signing key 9904B52336713A5ADCB13E4FB14DC919E0D45571
28Apr 05 15:03:36.000 [info] trusted_dirs_load_certs_from_string(): Adding cached certificate for directory authority urras with signing key 414E42CCA5F51E7B0C020496AB0F4B7894FCD409
29Apr 05 15:03:36.000 [info] read_file_to_str(): Could not open "/home/f/.tor/cached-consensus": No such file or directory
30Apr 05 15:03:36.000 [info] read_file_to_str(): Could not open "/home/f/.tor/unverified-consensus": No such file or directory
31Apr 05 15:03:36.000 [info] read_file_to_str(): Could not open "/home/f/.tor/unverified-microdesc-consensus": No such file or directory
32Apr 05 15:03:37.000 [info] microdesc_cache_reload(): Reloaded microdescriptor cache. Found 5597 descriptors.
33Apr 05 15:03:37.000 [info] tor_mmap_file(): File "/home/f/.tor/cached-descriptors" is empty. Ignoring.
34Apr 05 15:03:37.000 [info] router_load_routers_from_string(): 1 elements to add
35Apr 05 15:03:37.000 [info] router_add_to_routerlist(): Dropping bridge descriptor for [scrubbed] because we have no bridge configured at that address.
36Apr 05 15:03:37.000 [info] router_rebuild_store(): Rebuilding router descriptors cache
37Apr 05 15:03:37.000 [info] tor_mmap_file(): File "/home/f/.tor/cached-descriptors" is empty. Ignoring.
38Apr 05 15:03:37.000 [info] router_rebuild_store(): Reconstructing pointers into cache
39Apr 05 15:03:37.000 [info] tor_mmap_file(): Could not open "/home/f/.tor/cached-extrainfo" for mmap(): No such file or directory
40Apr 05 15:03:37.000 [info] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.
41Apr 05 15:03:37.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
42Apr 05 15:03:37.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
43Apr 05 15:03:37.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
44Apr 05 15:03:37.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
45Apr 05 15:03:37.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
46Apr 05 15:03:37.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
47Apr 05 15:03:38.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
48Apr 05 15:03:38.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
49Apr 05 15:03:38.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
50Apr 05 15:03:38.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
51Apr 05 15:03:38.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
52Apr 05 15:03:38.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
53Apr 05 15:03:38.000 [info] compute_weighted_bandwidths(): Empty routerlist passed in to consensus weight node selection for rule weight as guard
54Apr 05 15:03:38.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard
55Apr 05 15:03:38.000 [info] should_delay_dir_fetches(): Delaying dir fetches (no running bridges known)
56Apr 05 15:03:38.000 [info] or_state_save(): Saved state to "/home/f/.tor/state"
57Apr 05 15:03:38.000 [info] launch_managed_proxy(): Managed proxy at '/usr/local/bin/obfsproxy' has spawned with PID '28360'.
58Apr 05 15:03:38.000 [notice] New control connection opened from 127.0.0.1.
59Apr 05 15:03:39.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/local/bin/obfsproxy': (VERSION 1)
60Apr 05 15:03:39.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/local/bin/obfsproxy': (CMETHOD obfs3 socks5 127.0.0.1:42747)
61Apr 05 15:03:39.000 [info] parse_cmethod_line(): Transport obfs3 at 127.0.0.1:42747 with SOCKS 3. Attached to managed proxy.
62Apr 05 15:03:39.000 [info] handle_proxy_line(): Got a line from managed proxy '/usr/local/bin/obfsproxy': (CMETHODS DONE)
63Apr 05 15:03:39.000 [info] handle_methods_done(): Client managed proxy '/usr/local/bin/obfsproxy' configuration completed!
64Apr 05 15:03:39.000 [info] register_client_proxy(): Successfully registered transport obfs3
65Apr 05 15:03:40.000 [info] connection_ap_make_link(): Making internal direct tunnel to [scrubbed]:80 ...
66Apr 05 15:03:40.000 [info] onion_pick_cpath_exit(): Using requested exit node '$0000000000000000000000000000000000000000~0000000000000000000 at 83.212.101.3'
67Apr 05 15:03:40.000 [info] circuit_handle_first_hop(): Next router is [scrubbed]: Not connected. Connecting.
68Apr 05 15:03:40.000 [notice] Bootstrapped 5%: Connecting to directory server.
69Apr 05 15:03:40.000 [info] channel_register(): Channel 0x7f6ba33c27f0 (global ID 0) in state opening (1) registered with no identity digest
70Apr 05 15:03:40.000 [info] connection_ap_make_link(): ... application connection created and linked.
71Apr 05 15:03:40.000 [notice] Bootstrapped 10%: Finishing handshake with directory server.
72Apr 05 15:03:40.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
73Apr 05 15:03:40.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
74Apr 05 15:03:40.000 [info] parse_socks_client(): SOCKS 5 client: continuing without authentication
75Apr 05 15:03:40.000 [info] connection_read_proxy_handshake(): Proxy Client: connection to 83.212.101.3:80 successful
76Apr 05 15:03:40.000 [info] handle_control_authenticate(): Authenticated control connection (11)
77Apr 05 15:03:40.000 [warn] ControlPort is open, but no authentication method has been configured.  This means that any program on your computer can reconfigure your Tor.  That's bad!  You should upgrade your Tor controller as soon as possible.
78Apr 05 15:03:40.000 [notice] Tor 0.2.5.2-alpha (git-ab06c19f964ac2f5) opening log file.
79Apr 05 15:03:40.000 [info] cell_ewma_set_scale_factor(): Disabled cell_ewma algorithm because of value in Default value
80Apr 05 15:03:40.000 [info] connection_tls_continue_handshake(): Client got a v3 cert!  Moving on to v3 handshake with ciphersuite ECDHE-RSA-AES128-SHA
81Apr 05 15:03:40.000 [info] channel_tls_process_versions_cell(): Negotiated version 4 with [scrubbed]:80; Waiting for CERTS cell
82Apr 05 15:03:40.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.
83Apr 05 15:03:40.000 [notice] Learned fingerprint A09D536DD1752D542E1FBB3C9CE4449D51298239 for bridge 83.212.101.3:80 (with transport 'obfs3').
84Apr 05 15:03:40.000 [info] channel_tls_process_certs_cell(): Got some good certificates from [scrubbed]:80: Authenticated it.
85Apr 05 15:03:40.000 [notice] Bootstrapped 15%: Establishing an encrypted directory connection.
86Apr 05 15:03:40.000 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE_FAST cell to '<unnamed>'
87Apr 05 15:03:40.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 134.219.198.88.
88Apr 05 15:03:40.000 [info] circuit_finish_handshake(): Finished building circuit hop:
89Apr 05 15:03:40.000 [info] internal circ (length 1, last hop 0000000000000000000000000000000000000000): $0000000000000000000000000000000000000000(open)
90Apr 05 15:03:40.000 [info] circuit_send_next_onion_skin(): circuit built!
91Apr 05 15:03:40.000 [notice] Bootstrapped 20%: Asking for networkstatus consensus.
92Apr 05 15:03:40.000 [info] internal circ (length 1): $0000000000000000000000000000000000000000(open)
93Apr 05 15:03:40.000 [info] connection_ap_handshake_send_begin(): Sending relay cell 1 to begin stream 31336.
94Apr 05 15:03:40.000 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket -1, n_circ_id 2147488950
95Apr 05 15:03:40.000 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
96Apr 05 15:03:40.000 [info] internal circ (length 1): $0000000000000000000000000000000000000000(open)
97Apr 05 15:03:40.000 [info] connection_edge_process_relay_cell(): -1: end cell (closed normally) for stream 31336. Removing stream.
98Apr 05 15:03:40.000 [info] connection_free_(): Freeing linked Socks connection [open] with 0 bytes on inbuf, 0 on outbuf.
99Apr 05 15:03:40.000 [info] connection_dir_client_reached_eof(): Received server info (size 1180) from server '83.212.101.3:80'
100Apr 05 15:03:40.000 [info] router_load_routers_from_string(): 1 elements to add
101Apr 05 15:03:40.000 [info] rewrite_node_address_for_bridge(): Adjusted bridge routerinfo for 'LeifEricson' to match configured address 83.212.101.3:80.
102Apr 05 15:03:40.000 [notice] new bridge descriptor 'LeifEricson' (fresh): $A09D536DD1752D542E1FBB3C9CE4449D51298239~LeifEricson at 83.212.101.3
103Apr 05 15:03:40.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
104Apr 05 15:03:40.000 [notice] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.
105Apr 05 15:03:40.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
106Apr 05 15:03:40.000 [info] should_delay_dir_fetches(): Delaying dir fetches (pt proxies still configuring)
107Apr 05 15:03:40.000 [info] connection_free_(): Freeing linked Directory connection [client finished] with 0 bytes on inbuf, 0 on outbuf.
108Apr 05 15:03:41.000 [info] pt_configure_remaining_proxies(): Nothing changed for managed proxy '/usr/local/bin/obfsproxy' after HUP: not restarting.
109---- BUG ----
110Apr 05 15:04:39.000 [info] update_consensus_networkstatus_downloads(): Launching microdesc networkstatus consensus download.
111Apr 05 15:04:39.000 [info] connection_ap_make_link(): Making internal direct tunnel to [scrubbed]:80 ...
112Apr 05 15:04:39.000 [info] onion_pick_cpath_exit(): Using requested exit node '$A09D536DD1752D542E1FBB3C9CE4449D51298239~LeifEricson at 83.212.101.3'
113Apr 05 15:04:39.000 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE_FAST cell to '$A09D536DD1752D542E1FBB3C9CE4449D51298239~LeifEricson at 83.212.101.3'
114Apr 05 15:04:39.000 [info] connection_ap_make_link(): ... application connection created and linked.
115Apr 05 15:04:39.000 [info] directory_send_command(): Downloading consensus from 83.212.101.3 using /tor/status-vote/current/consensus-microdesc/14C131+27B6B5+49015F+585769+805509+D586D1+E8A9C4+ED03BB+EFCBE7.z
116Apr 05 15:04:39.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
117Apr 05 15:04:39.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer.
118Apr 05 15:04:39.000 [info] circuit_finish_handshake(): Finished building circuit hop:
119Apr 05 15:04:39.000 [info] internal circ (length 1, last hop LeifEricson): $A09D536DD1752D542E1FBB3C9CE4449D51298239(open)
120Apr 05 15:04:39.000 [info] circuit_send_next_onion_skin(): circuit built!
121Apr 05 15:04:39.000 [info] internal circ (length 1): $A09D536DD1752D542E1FBB3C9CE4449D51298239(open)
122Apr 05 15:04:39.000 [info] connection_ap_handshake_send_begin(): Sending relay cell 1 to begin stream 34136.
123Apr 05 15:04:39.000 [info] connection_ap_handshake_send_begin(): Address/port sent, ap socket -1, n_circ_id 2147488951
124Apr 05 15:04:39.000 [info] connection_edge_process_relay_cell_not_open(): 'connected' received after 0 seconds.
125Apr 05 15:04:39.000 [info] internal circ (length 1): $A09D536DD1752D542E1FBB3C9CE4449D51298239(open)
126Apr 05 15:04:39.000 [notice] Bootstrapped 25%: Loading networkstatus consensus.