Opened 2 years ago

Closed 21 months ago

#23628 closed defect (not a bug)

Hibernation on period roll-over

Reported by: r1610091651@… Owned by:
Priority: Medium Milestone: Tor: 0.3.3.x-final
Component: Core Tor/Tor Version: Tor: 0.3.1.7
Severity: Major Keywords: hibernation accounting period
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Version 0.3.1.7 on Ubuntu

I've following config entries related to accounting:

AccountingMax 1639 GBytes
AccountingStart month 24 00:00

Today (24/09/17) I've discovered following log entries:

Sep 24 00:00:00.000 [notice] Configured hibernation.  This interval began at 2017-09-24 00:00:00; the scheduled wake-up time is 2017-09-28 16:44:28; we expect to exhaust our quota for this interval around 2017-10-21 20:52:28; the next interval begins at 2017-10-24 00:00:00 (all times local)
Sep 24 00:00:01.000 [notice] Commencing hibernation. We will wake up at 2017-09-28 16:44:28 local time.
Sep 24 00:00:01.000 [notice] Going dormant. Blowing away remaining connections.
Sep 24 00:20:47.000 [notice] Heartbeat: Tor's uptime is 5:59 hours, with 0 circuits open. I've sent 15.65 GB and received 15.63 GB. We are currently hibernating.
Sep 24 00:20:47.000 [notice] Circuit handshake stats since last time: 6985/6985 TAP, 162991/162991 NTor.
Sep 24 00:20:47.000 [notice] Since startup, we have initiated 0 v1 connections, 0 v2 connections, 1 v3 connections, and 10218 v4 connections; and received 23 v1 connections, 3 v2 connections, 0 v3 connections, and 8412 v4 connections.
Sep 24 01:19:36.000 [notice] New control connection opened.
Sep 24 01:22:38.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 24 01:22:38.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Sep 24 01:22:38.000 [notice] Read configuration file "/etc/tor/torrc".
Sep 24 01:22:38.000 [notice] Tor 0.3.1.7 (git-5fa14939bca67c23) opening log file.
Sep 24 01:22:38.000 [notice] Configured hibernation.  This interval began at 2017-09-24 00:00:00; the scheduled wake-up time is 2017-09-28 16:44:28; we expect to exhaust our quota for this interval around 2017-10-21 20:52:28; the next interval begins at 2017-10-24 00:00:00 (all times local)
Sep 24 01:26:25.000 [notice] New control connection opened.

...

Sep 24 01:28:55.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 24 01:28:55.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Sep 24 01:28:55.000 [notice] Read configuration file "/etc/tor/torrc".
Sep 24 01:28:55.000 [notice] Accounting period ended. This period, we will hibernate until 2017-09-28 11:00:28 UTC
Sep 24 01:28:55.000 [notice] Tor 0.3.1.7 (git-5fa14939bca67c23) opening log file.
Sep 24 01:28:56.000 [notice] Accounting period ended. This period, we will hibernate until 2017-09-28 11:00:28 UTC
Sep 24 01:28:57.000 [notice] Accounting period ended. This period, we will hibernate until 2017-09-28 11:00:28 UTC

...

Sep 24 01:30:11.000 [notice] SIGINT received while hibernating; exiting now.
Sep 24 01:32:36.000 [notice] Tor 0.3.1.7 (git-5fa14939bca67c23) opening log file.
Sep 24 01:32:36.727 [notice] Tor 0.3.1.7 (git-5fa14939bca67c23) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.2g, Zlib 1.2.8, Liblzma 5.1.0alpha, and Libzstd N/A.
Sep 24 01:32:36.728 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Sep 24 01:32:36.729 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Sep 24 01:32:36.729 [notice] Read configuration file "/etc/tor/torrc".
Sep 24 01:32:36.735 [notice] Based on detected system memory, MaxMemInQueues is set to 1480 MB. You can override this by setting MaxMemInQueues by hand.
Sep 24 01:32:36.737 [notice] Opening OR listener on ...
Sep 24 01:32:37.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip.
Sep 24 01:32:37.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
Sep 24 01:32:37.000 [notice] Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Sep 24 01:32:38.000 [notice] Your Tor server's identity key fingerprint is ...
Sep 24 01:32:38.000 [notice] Bootstrapped 0%: Starting
Sep 24 01:33:16.000 [notice] Starting with guard context "default"
Sep 24 01:33:16.000 [notice] Bootstrapped 80%: Connecting to the Tor network
Sep 24 01:33:16.000 [notice] Signaled readiness to systemd
Sep 24 01:33:16.000 [notice] Opening Control listener on /var/run/tor/control
Sep 24 01:33:16.000 [notice] Guessed our IP address as ...
Sep 24 01:33:16.000 [notice] Self-testing indicates your ORPort is reachable from the outside. Excellent. Publishing server descriptor.
Sep 24 01:33:17.000 [notice] Bootstrapped 85%: Finishing handshake with first hop
Sep 24 01:33:17.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
Sep 24 01:33:18.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Sep 24 01:33:18.000 [notice] Bootstrapped 100%: Done
Sep 24 01:33:46.000 [notice] New control connection opened.
Sep 24 01:34:18.000 [notice] Performing bandwidth self-test...done.
Sep 24 01:45:02.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 24 01:45:02.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Sep 24 01:45:02.000 [notice] Read configuration file "/etc/tor/torrc".
Sep 24 01:45:02.000 [notice] Tor 0.3.1.7 (git-5fa14939bca67c23) opening log file.
Sep 24 01:45:02.000 [notice] Configured hibernation.  This interval began at 2017-09-24 00:00:00; the scheduled wake-up time is 2017-09-28 16:44:28; we expect to exhaust our quota for this interval around 2017-10-21 20:52:28; the next interval begins at 2017-10-24 00:00:00 (all times local)
Sep 24 01:45:02.000 [notice] Not advertising Directory Service support (Reason: AccountingMax enabled)
Sep 24 01:45:03.000 [notice] Commencing hibernation. We will wake up at 2017-09-28 16:44:28 local time.
Sep 24 01:45:03.000 [notice] Going dormant. Blowing away remaining connections.

For context, Tor did not exceed previous (from 24/08-24/09) quota and was operating normally.

To me this is not what I would have expected as behaviour given the config. My exception is that the tor would reset counters at month end/beginning and continue operation in the new period. Currently Tor takes an unnecessary "nap" from 24/09 00:00 to 28/09 16:44.

What i've tried but with no success:

  • reload config
  • change pariod a few days & reload config
  • restart tor

Only currently possible work-around is disabling accounting, but for me that is only a short time solution.

Child Tickets

Change History (5)

comment:1 Changed 2 years ago by r1610091651@…

Might be related to #23635

comment:2 Changed 2 years ago by nickm

Milestone: Tor: 0.3.2.x-final

comment:3 Changed 2 years ago by nickm

Milestone: Tor: 0.3.2.x-finalTor: 0.3.3.x-final

We're likely to siginificantly revise and improve the hibernation code over the next couple of release series, so let's try to figure this out as we do.

comment:4 Changed 2 years ago by teor

Tor will hibernate for a random interval if it thinks you might exceed the quota in the period, even if you didn't exceed it in the last period.

we expect to exhaust our quota for this interval around 2017-10-21 20:52:28; the next interval begins at 2017-10-24 00:00:00

It looks like that's what is happening here: I think this is a feature, not a bug.

comment:5 Changed 21 months ago by nickm

Resolution: not a bug
Status: newclosed

And also see #23635 about improving the documentation.

Note: See TracTickets for help on using tickets.