[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

Re: [tor-bugs] #20423 [Core Tor/Tor]: Clock jumps on FreeBSD relay

Subject: Re: [tor-bugs] #20423 [Core Tor/Tor]: Clock jumps on FreeBSD relay
From: "Tor Bug Tracker & Wiki" <blackhole@xxxxxxxxxxxxxx>
Date: Tue, 01 Nov 2016 09:41:44 -0000
Auto-submitted: auto-generated
Delivered-to: archiver@xxxxxxxx
Delivery-date: Tue, 01 Nov 2016 05:41:58 -0400
In-reply-to: <047.9e4756d506445d6656a139526954715e@torproject.org>
List-archive: <http://lists.torproject.org/pipermail/tor-bugs/>
List-help: <mailto:tor-bugs-request@lists.torproject.org?subject=help>
List-id: "auto: Tor bug tracker status mails" <tor-bugs.lists.torproject.org>
List-post: <mailto:tor-bugs@lists.torproject.org>
List-subscribe: <https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=subscribe>
List-unsubscribe: <https://lists.torproject.org/cgi-bin/mailman/options/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=unsubscribe>
References: <047.9e4756d506445d6656a139526954715e@torproject.org>
Reply-to: no-reply@xxxxxxxxxxxxxx, tor-assistants@xxxxxxxxxxxxxx
Sender: "tor-bugs" <tor-bugs-bounces@xxxxxxxxxxxxxxxxxxxx>

#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
_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Prev by Author: [tor-bugs] #20546 [Metrics/CollecTor]: implement CleanUtils
Next by Author: Re: [tor-bugs] #20677 [User Experience/Website]: Update alternative donation options
Previous by thread: Re: [tor-bugs] #20510 [Metrics/Metrics website]: Use metrics-lib's getHidserv* methods in Metrics' hidserv module
Next by thread: Re: [tor-bugs] #20423 [Core Tor/Tor]: Clock jumps on FreeBSD relay
Index(es):
- Author
- Thread