Clock jumps on relay due to hostname lookup timeouts

changed milestone to %Tor: unspecified

added 032-unreached component::core tor/tor milestone::Tor: unspecified parent::21789 points::1 priority::high regression reporter::Felixix severity::normal status::reopened type::defect version::tor 0.2.9.10 labels

Trac:
Priority: Medium to High
Milestone: N/A to Tor: 0.2.9.x-final
Component: User Experience to Core Tor/Tor
Keywords: assign_to_cpuworker circuit_mark_for_close_ deleted, regression freebsd added
Version: Tor: 0.2.8.7 to Tor: 0.2.8.9

Some more informations

"assign_to_cpuworker failed" is not connected to Heartbeat. Change the heartbeat periode to 1.5h but still "assign_to_cpuworker failed" is hourly.

A reload (hup) forces "assign_to_cpuworker failed" warnings.

Observation (log notice and top) Oct 23 16:51:25.000 [warn] assign_to_cpuworker failed. Ignoring. ... Oct 23 16:51:25.000 [warn] assign_to_cpuworker failed. Ignoring. 17:48 Tor process at 90% CPU 17:49 Tor process at 43% CPU 17:50 Tor process at 7% CPU 17:51 Tor process at 5% CPU Oct 23 17:51:22.000 [warn] Your system clock just jumped 140 seconds forward; assuming established circuits no longer work. Oct 23 17:51:22.000 [warn] assign_to_cpuworker failed. Ignoring. ... Oct 23 17:51:22.000 [warn] assign_to_cpuworker failed. Ignoring. 17:52 Tor process at 68% CPU 17:53 Tor process at 71% CPU 17:54 Tor process at 77% CPU 17:55 Tor process at 79% CPU

58 minutes performing well
140 secs doing whatever and not pushing data
After ready with doing whatever back with warn clock and warn cpuworker

Openntpd with 8 servers and all with 1500-1600 secs query interval.

Taking a 5 minutes log info shows (force warning by hup; then back to notice level): Oct 23 20:15:25.000 [info] assign_onionskin_to_cpuworker: circ->p_chan gone. Failing circ. Oct 23 20:15:25.000 [warn] assign_to_cpuworker failed. Ignoring.

Trac:
Username: Felixix

I think that the root problem here is whatever causes Tor to stall and overload, eating a bunch of CPU. That would cause all of: * The "clock jumped X seconds forward" warning * The remote side to close the circuit and its channel already because we took too long... * ...leading to the duplicate close warning when we try to close it for being too old... * ...and/or leading to assign_to_cpuworker() failing because the channel isn't there any more.

I'm not sure whether this stalling problem is new in 028 or not, though: it could be that it was present previously, but that we weren't seeing it, because of the changes that 028 made to how we close circuits in #17218 (moved).

Did you see "Your system clock just jumped X seconds forward" warnings with older versions of Tor? If not, we should try to figure out why those started.

Additionally, we should clean up the warnings for assign_to_cpuworker() failing (that shouldn't be a warning), and the duplicate close warning. (There should be a check for whether the circuit is marked in the loop at the end of onion_pending_add().)

Replying to nickm:

I think that the root problem here is whatever causes Tor to stall and overload, eating a bunch of CPU. That would cause all of: * The "clock jumped X seconds forward" warning * The remote side to close the circuit and its channel already because we took too long... * ...leading to the duplicate close warning when we try to close it for being too old... * ...and/or leading to assign_to_cpuworker() failing because the channel isn't there any more.

The other way around. Tor is stalling for about X seconds at 5% CPU. And 58 minutes back at 70-90%. Not the typical overload. I think no circuits are handled then.

Did you see "Your system clock just jumped X seconds forward" warnings with older versions of Tor? If not, we should try to figure out why those started.

I never had those warnings before (2.6.9 - 2.7.6, see ticket text). Roll-back from 2.8.9 (like 2.8.7 before) to 2.7.6 and warnings and X seconds are gone.

Additionally, we should clean up the warnings for assign_to_cpuworker() failing (that shouldn't be a warning), and the duplicate close warning. (There should be a check for whether the circuit is marked in the loop at the end of onion_pending_add().)

I am glad I received warnings. Otherwise I might not have noticed it.

Thanks and cheers

Trac:
Username: Felixix

I agree with Nick that the mystery here is the clock jump -- the other things like the cpuworker line follow from that clock jump mystery.

In the past, we had issues where libevent thought time had passed when it hadn't. Those were only on weird platforms, like some of the BSDs, but here we are with one of those. Curious.

As I recall I did not have the clock jump issue on FreeBSD 10.3, they started appear when I upgraded to FreeBSD 11-RC1.

Since updating to 0.2.9.4-alpha the clock jump issue seems to be not so dramatic. Below 300sec where they tended to be >> 1000

Aug 25 19:56:06 tor Tor[36694]: Tor v0.2.8.7 running on FreeBSD with Libevent 2.0.22-stable, OpenSSL LibreSSL 2.4.2 and Zlib 1.2.8
...
Sep 13 15:55:02 tor Tor[36694]: Your system clock just jumped 5203 seconds forward; assuming established circuits no longer work.
Sep 13 17:22:29 tor Tor[36694]: Your system clock just jumped 5247 seconds forward; assuming established circuits no longer work.
Sep 13 18:48:00 tor Tor[36694]: Your system clock just jumped 5131 seconds forward; assuming established circuits no longer work.
Sep 13 20:20:10 tor Tor[36694]: Your system clock just jumped 5530 seconds forward; assuming established circuits no longer work.
Sep 13 22:14:32 tor Tor[36694]: Your system clock just jumped 6862 seconds forward; assuming established circuits no longer work.

[edit] OK... 15:55:02 + 5247 secs is 17:22:29...

Oct 18 11:05:09.001 [notice] Tor 0.2.9.4-alpha (git-8b0755c9bb296ae2) running on FreeBSD with Libevent 2.0.22-stable, OpenSSL LibreSSL 2.4.3 and Zlib 1.2.8.
Oct 26 19:51:11.000 [warn] Your system clock just jumped 154 seconds forward; assuming established circuits no longer work.
Oct 26 19:53:40.000 [warn] Your system clock just jumped 149 seconds forward; assuming established circuits no longer work.

And again 19:51:11 + 149 secs is 19:53:40... A LOT fewer of those though with 0.2.9

Trac:
Username: palyhomp

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?

Also, can you attach / paste your torrc here? Maybe you accidentally have 1000 onion services configured or something. :)

So far:

Tor 2.6.x and 2.7.x in a jail => ok Tor 2.8.1, 2.8.7 and 2.8.9 in a jail => warning Tor 2.8.9 on host (not in a jail) => ok

My torrc:

SocksPort 0 RunAsDaemon 1 ORPort 443 NoListen ORPort 1234 NoAdvertise DirPort 80 NoListen DirPort 5678 NoAdvertise Nickname ... RelayBandwidthRate 14000 KB RelayBandwidthBurst 50000 KB ContactInfo ... MyFamily ... ExitPolicy reject : HeartbeatPeriod 3600 seconds NUMCPUs 2 MaxMemInQueues 2 GB Log notice file /var/log/tor/tor EntryStatistics 1 ConnDirectionStatistics 1 DirPortFrontPage /var/mypage.html ExtraInfoStatistics 1 DownloadExtraInfo 1

Trac:
Username: Felixix

Your torrc looks reasonable.

I am now wondering if something about your bsd jail is preventing Tor from doing something, or starving it, or otherwise breaking things.

Trac:
Summary: Warning notice log: assign_to_cpuworker failed. Ignoring. to Clock jumps on FreeBSD relay

In particular, what changed about freebsd jails between "FreeBSD 10.3" and "FreeBSD 11-RC1"?

Replying to arma:

In particular, what changed about freebsd jails between "FreeBSD 10.3" and "FreeBSD 11-RC1"? Please notice that "https://trac.torproject.org/projects/tor/ticket/20423#comment:6" is a different machine/operator. I am on "10.1-RELEASE-p40".

@palyhomp: You are on host or jail?

Trac:
Username: Felixix

Replying to 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 '' 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 '' 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 '' 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 '' 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 '' 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 '' 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 '' 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 '' 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 '' 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.

Trac:
Username: Felixix

There is an obvious difference in the log files between 0.2.7.6 and 0.2.8.9:

0.2.8.9 in the jail, debug after reload with about 23k times resolve_my_address etc, 5-6 min Tor down to 4% CPU
0.2.7.6_1 in the same jail and keys, debug after reload with 4 times resolve_my_address etc, pushing data on 25% CPU

For now I keep it like it is. If you want me to do anything please tell me. I would be glad if I can assist/test.

0.2.8.9 in the jail, debug after reload:

Nov 03 18:35:02.000 [info] router_write_fingerprint: Dumping fingerprint to "/var/db/tor/fingerprint"... Nov 03 18:35:02.000 [notice] Your Tor server's identity key fingerprint is 'blabla fingerprint' Nov 03 18:35:02.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 03 18:35:02.000 [info] options_act: Worker-related options changed. Rotating workers. Nov 03 18:35:02.000 [debug] configure_nameservers: stat()ing /etc/resolv.conf Nov 03 18:35:02.000 [info] configure_nameservers: No change to '/etc/resolv.conf'

23484* Nov 03 18:35:02.000 [debug] resolve_my_address: Guessed local host name as 'jail1' Nov 03 18:35:02.000 [info] resolve_my_address: Could not resolve guessed local hostname 'jail1'. Trying something else. Nov 03 18:35:02.000 [info] resolve_my_address: Learned IP address '10.x.x.x' for local interface. Using that. Nov 03 18:35:02.000 [info] resolve_my_address: Address '' resolves to private IP address '10.x.x.x'. Tor servers that use the default DirAuthorities must have public IP addresses. Nov 03 18:35:02.000 [info] router_pick_published_address: Could not determine our address locally. Checking if directory headers provide any hints. Nov 03 18:35:02.000 [info] router_pick_published_address: Success: chose address 'm.y.i.p'. ...

25432* Nov 03 18:40:34.000 [debug] connection_bucket_refill_helper: or_conn->read_bucket now 1073741824.

!!! Nov 03 18:40:34.000 [warn] Your system clock just jumped 332 seconds forward; assuming established circuits no longer work.

2498* Nov 03 18:40:34.000 [debug] run_connection_housekeeping: Sending keepalive to (an.y.i.p:port)

0.2.7.6_1 in the same jail, debug after reload:

Nov 03 21:25:46.000 [info] int router_write_fingerprint(int): Dumping fingerprint to "/var/db/tor/fingerprint"... Nov 03 21:25:46.000 [notice] Your Tor server's identity key fingerprint is 'blabla fingerprint' Nov 03 21:25:46.000 [info] void cell_ewma_set_scale_factor(const or_options_t *, const networkstatus_t *): Enabled cell_ewma algorithm because of value in CircuitPriorityHalflifeMsec in consensus; scale factor is 0.793701 per 10 seconds Nov 03 21:25:46.000 [info] int options_act(const or_options_t *): Worker-related options changed. Rotating workers. Nov 03 21:25:46.000 [debug] int configure_nameservers(int): stat()ing /etc/resolv.conf Nov 03 21:25:46.000 [info] int configure_nameservers(int): No change to '/etc/resolv.conf'

4* Nov 03 21:25:46.000 [debug] int resolve_my_address(int, const or_options_t *, uint32_t *, const char **, char **): Guessed local host name as 'jail1' Nov 03 21:25:46.000 [info] int resolve_my_address(int, const or_options_t *, uint32_t *, const char **, char **): Could not resolve guessed local hostname 'jail1'. Trying something else. Nov 03 21:25:46.000 [info] int resolve_my_address(int, const or_options_t *, uint32_t *, const char **, char **): Learned IP address '10.x.x.x' for local interface. Using that. Nov 03 21:25:46.000 [info] int resolve_my_address(int, const or_options_t *, uint32_t *, const char **, char **): Address '' resolves to private IP address '10.x.x.x'. Tor servers that use the default DirAuthorities must have public IP addresses. Nov 03 21:25:46.000 [info] int router_pick_published_address(const or_options_t *, uint32_t *): Could not determine our address locally. Checking if directory headers provide any hints. Nov 03 21:25:46.000 [info] int router_pick_published_address(const or_options_t *, uint32_t *): Success: chose address 'm.y.i.p'. ...

Nov 03 21:25:46.000 [debug] void directory_initiate_command_rend(const tor_addr_t *, uint16_t, uint16_t, const char *, uint8_t, uint8_t, dir_indirection_t, const char *, const char *, size_t, time_t, const rend_data_t *): anonymized 0, use_begindir 0. ...

20* Nov 03 21:25:46.000 [debug] void connection_bucket_refill_helper(int *, int, int, int, const char *): or_conn->read_bucket now 1073741824.

Trac:
Username: Felixix

I think this is not (always) related to the clock change. I have over 70 lines of Nov 08 10:19:49.000 [warn] assign_to_cpuworker failed. Ignoring. , one immediately after another with nothing in between, most of them with the very same timestamp, in 3 buckets of :49 (seconds) :50 (seconds) and :51 (seconds).

I am on FreeBSD 10.3-RELEASE-p11 with Tor 0.2.9.4-alpha (git-8b0755c9bb296ae2) with Libevent 2.0.22-stable, OpenSSL 1.0.2j and Zlib 1.2.8.

I want to add that this relays has been running quite for some time, was in 0.2.9.1 and 0.2.8.x as well and is the first time ever it reports this.

I wonder if there is something about this freebsd user's jail that makes calls like gethostname super slow? And then this ticket would be a variant on #20610 (moved)?

Felixix, do things get better if you explicitly set an Address line in your torrc?

In 0.2.9.1-alpha, we changed how we used timers:

I wonder if your OS has a broken monotonic timer:

    - Tor now uses the operating system's monotonic timers (where
      available) for internal fine-grained timing. Previously we would
      look at the system clock, and then attempt to compensate for the
      clock running backwards. Closes ticket 18908.

Alternately, I wonder if your OS previously relied on Tor compensating for the clock running backwards.

Can you please run the tor unit tests in your jail?

P.S. jumping in maybe this is helpful. I get the message on a base system (not inside a jail), the clock did not change and I do have explicitly set Address in torrc.

One correction: I have a script which monitors the log file and emails me for every warn, but it has some limits that it will not send too many duplicate messages at every 6 hours. While closely looking at the log file, I discovered that there are way more such messages than I thought:

Nov 08 10:19:51.000 [warn] assign_to_cpuworker failed. Ignoring.

cat /var/log/tor | grep assign_to_cpuworker | wc -l

There are exactly 573 messages at 10:19:49.000 ; 692 at 10:19:50.000 ; 616 at 10:19:51.000

Again, this is not a jail, Address is set and it's been a relay for long time, this is the first time this warning appears and hasn't repeated so far. Can share access on this machine if needed.

Can you please run the tor unit tests for 0.2.9.5-alpha. They have a timer unit test that uses monotonic time. We use monotonic time in tor in 0.2.9. Perhaps it is broken on your machine.

Clock jumps on relay due to hostname lookup timeouts

Child items ...

Activity

Tor 2.6.x and 2.7.x in a jail => ok Tor 2.8.1, 2.8.7 and 2.8.9 in a jail => warning Tor 2.8.9 on host (not in a jail) => ok

Tor 2.8.9 back to jail with some minutes debug Tor 2.9.x-devel in a jail

cat /var/log/tor | grep assign_to_cpuworker | wc -l