[tor-bugs] #20423 [Core Tor/Tor]: Clock jumps on FreeBSD relay
Tor Bug Tracker & Wiki
blackhole at torproject.org
Tue Nov 1 09:41:44 UTC 2016
#20423: Clock jumps on FreeBSD relay
--------------------------------+------------------------------------
Reporter: Felixix | Owner:
Type: defect | Status: new
Priority: High | Milestone: Tor: 0.2.9.x-final
Component: Core Tor/Tor | Version: Tor: 0.2.8.9
Severity: Normal | Resolution:
Keywords: regression freebsd | Actual Points:
Parent ID: | Points:
Reviewer: | Sponsor:
--------------------------------+------------------------------------
Comment (by Felixix):
Replying to [comment:7 arma]:
> If you log at loglevel debug for a bit, can you check if there are
things that happen in between? Or is your Tor really waking up, doing some
stuff, then getting distracted for 150 seconds, then waking up again?
----
"[debug] resolve_my_address: Guessed local host name as 'jail1'" is
*22924* times.
No other logs between "Nov 01 07:57:07" and "Nov 01 08:02:32". This is
key.
Here is the stalling observed with "top":
2016-11-01_09-05-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:03 31.98% tor
2016-11-01_09-04-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:02 25.98% tor
2016-11-01_09-03-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:02 37.99% tor
2016-11-01_09-02-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:02 3.96% tor
2016-11-01_09-01-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:02 3.96% tor
2016-11-01_09-00-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:02 3.96% tor
2016-11-01_08-59-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:01 1.95% tor
2016-11-01_08-58-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:01 3.96% tor
2016-11-01_08-57-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:01 19.97% tor
2016-11-01_08-56-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:01 31.98% tor
2016-11-01_08-55-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:00 23.97% tor
2016-11-01_08-54-00: 19130 12 _tor 2 20 0 247M 222M
uwait 3:00 23.97% tor
----
Some of the log:
Nov 01 07:57:07.000 [notice] Tor 0.2.8.9 opening new log file.
Nov 01 07:57:07.000 [warn] Your log may contain sensitive information -
you're logging more than "notice". Don't log unless it serves an important
reason. Overwrite the log afterwards.
Nov 01 07:57:07.000 [debug] tor_disable_debugger_attach: Attemping to
disable debugger attachment to Tor for unprivileged users.
...
Nov 01 07:57:07.000 [info] cell_ewma_set_scale_factor: Enabled cell_ewma
algorithm because of value in CircuitPriorityHalflifeMsec in consensus;
scale factor is 0.793701 per 10 seconds
Nov 01 07:57:07.000 [info] options_act: Worker-related options changed.
Rotating workers.
Nov 01 07:57:07.000 [debug] configure_nameservers: stat()ing
/etc/resolv.conf
Nov 01 07:57:07.000 [info] configure_nameservers: No change to
'/etc/resolv.conf'
Nov 01 07:57:07.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 07:57:07.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 07:57:07.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 07:57:07.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 07:57:07.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 07:57:07.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 07:57:07.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 07:57:07.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 07:57:07.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 07:57:07.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 07:57:07.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 07:57:07.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 07:57:07.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 07:57:07.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 07:57:07.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 07:57:07.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 07:57:07.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 07:57:07.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 07:57:07.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 07:57:07.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 07:57:07.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 07:57:07.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 07:57:07.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 07:57:07.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 07:57:07.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 07:57:07.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 07:57:07.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 07:57:07.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 07:57:07.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 07:57:07.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
... grep "Guessed local host name as" == 22924 times ...
Nov 01 08:02:32.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 08:02:32.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 08:02:32.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 08:02:32.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 08:02:32.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 08:02:32.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 08:02:32.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 08:02:32.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 08:02:32.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 08:02:32.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 08:02:32.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 08:02:32.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 08:02:32.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 08:02:32.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 08:02:32.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 08:02:32.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 08:02:32.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 08:02:32.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 08:02:32.000 [debug] resolve_my_address: Guessed local host name as
'jail1'
Nov 01 08:02:32.000 [info] resolve_my_address: Could not resolve guessed
local hostname 'jail1'. Trying something else.
Nov 01 08:02:32.000 [info] resolve_my_address: Learned IP address
'10.0.1.1' for local interface. Using that.
Nov 01 08:02:32.000 [info] resolve_my_address: Address '<guessed from
interfaces>' resolves to private IP address '10.0.1.1'. Tor servers that
use the default DirAuthorities must have public IP addresses.
Nov 01 08:02:32.000 [info] router_pick_published_address: Could not
determine our address locally. Checking if directory headers provide any
hints.
Nov 01 08:02:32.000 [info] router_pick_published_address: Success: chose
address 'mmm.yyy.iii.ppp'.
Nov 01 08:02:32.000 [debug] file_status: stat()ing
/var/db/tor/keys/ed25519_signing_secret_key_encrypted
Nov 01 08:02:32.000 [debug] check_private_dir: stat()ing /var/db/tor
Nov 01 08:02:32.000 [debug] check_private_dir: stat()ing /var/db/tor/keys
Nov 01 08:02:32.000 [debug] file_status: stat()ing
/var/db/tor/keys/ed25519_master_id_public_key
Nov 01 08:02:32.000 [debug] file_status: stat()ing
/var/db/tor/keys/ed25519_master_id_secret_key_encrypted
Nov 01 08:02:32.000 [debug] configure_nameservers: stat()ing
/etc/resolv.conf
Nov 01 08:02:32.000 [info] configure_nameservers: No change to
'/etc/resolv.conf'
Nov 01 08:02:32.000 [debug] scheduler_evt_callback: Scheduler event
callback called
Nov 01 08:02:32.000 [debug] scheduler_run: We have a chance to run the
scheduler
Nov 01 08:02:32.000 [debug] scheduler_run: Scheduler saw pending channel
27509 at 0x80988d640 with 64 cells writeable
Nov 01 08:02:32.000 [debug] channel_tls_get_overhead_estimate_method:
Estimated overhead ratio for TLS chan 27509 is 1.013652
Nov 01 08:02:32.000 [debug] channel_write_packed_cell: Writing
packed_cell_t 0x80f10e280 to channel 0x80988d640 with global ID 27509
Nov 01 08:02:32.000 [debug] channel_tls_get_overhead_estimate_method:
Estimated overhead ratio for TLS chan 27509 is 1.013652
Nov 01 08:02:32.000 [debug] channel_update_xmit_queue_size: Increasing
queue size for channel 27509 by 521 from 0 to 521
Nov 01 08:02:32.000 [debug] channel_update_xmit_queue_size: Increasing
global queue size by 521 for channel 27509, new size is 61727
Nov 01 08:02:32.000 [debug] scheduler_adjust_queue_size: Queue size
adjustment by +521 for channel 27509
Nov 01 08:02:32.000 [debug] scheduler_adjust_queue_size: Queue heuristic
is now 521
...
Lots of:
Nov 01 08:02:33.000 [debug] conn_read_callback: socket 795 wants to read.
Nov 01 08:02:33.000 [debug] connection_read_to_buf: 795: starting,
inbuf_datalen 0 (0 pending in tls object). at_most 16448.
Nov 01 08:02:33.000 [debug] connection_read_to_buf: After TLS read of 514:
543 read, 0 written
Nov 01 08:02:33.000 [debug] connection_or_process_cells_from_inbuf: 795:
starting, inbuf_datalen 514 (0 pending in tls object).
Nov 01 08:02:33.000 [debug] connection_or_process_cells_from_inbuf: 795:
starting, inbuf_datalen 0 (0 pending in tls object).
...
Nov 01 08:02:33.000 [debug] scheduler_adjust_queue_size: Queue size
adjustment by -528 for channel 1147
Nov 01 08:02:33.000 [debug] scheduler_adjust_queue_size: Queue heuristic
is now 0
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
global_read_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
global_write_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
global_relayed_read_bucket now 10240000.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
global_relayed_write_bucket now 10240000.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
or_conn->read_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
or_conn->read_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
or_conn->read_bucket now 1073741824.
... 2604 times: Nov 01 08:02:33.000 [debug]
connection_bucket_refill_helper: or_conn->read_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
or_conn->read_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
or_conn->read_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
or_conn->read_bucket now 1073741824.
Nov 01 08:02:33.000 [debug] connection_bucket_refill_helper:
or_conn->read_bucket now 1073741824.
Nov 01 08:02:33.000 [warn] Your system clock just jumped 326 seconds
forward; assuming established circuits no longer work.
Finally the warning.
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/20423#comment:12>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list