Opened 9 years ago

Closed 9 years ago

Last modified 7 years ago

#2146 closed defect (fixed)

Accounting Start Time Set to Year 2064

Reported by: BarkerJr Owned by:
Priority: High Milestone:
Component: Core Tor/Tor Version:
Severity: Keywords: tor-relay
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

0.2.2.17

BarkerJrCoast1

I updated the AccountingMax to change it from 200GB to 150GB on Saturday and sent it the HUP signal. Then, on midnight Sunday night, it logged:

Nov 01 00:00:00.624 [notice] Configured hibernation. This interval began at 2010-11-01 00:00:00; the scheduled wake-up time is 2064-07-16 22:16:43; we expect to exhaust our quota for this interval around 2010-12-01 00:00:00; the next interval begins at 2010-12-01 00:00:00 (all times local)
Nov 01 00:00:00.641 [notice] Accounting period ended. This period, we will hibernate until 2064-07-16 22:16:43 GMT

Child Tickets

Attachments (1)

2146.diff (999 bytes) - added by boboper's secretary 9 years ago.

Download all attachments as: .zip

Change History (19)

comment:1 Changed 9 years ago by arma

Milestone: Tor: 0.2.2.x-final

comment:2 Changed 9 years ago by arma

Priority: normalmajor

comment:3 Changed 9 years ago by BarkerJr

Here is the info-level logging for accounting:

Nov 23 20:49:35.863 [info] read_bandwidth_usage(): Reading bandwidth accounting data from state file
Nov 23 20:49:35.863 [info] read_bandwidth_usage(): Successfully read bandwidth accounting info from state written at 2010-11-23 20:45:37 for interval starting at 2010-11-01 00:00:00. We have been active for 1942451 seconds in this interval. At the start of the interval, we expected to use about 24814 KB per second. (139049984 bytes read so far, 7458816 bytes written so far)
Nov 23 20:49:35.863 [info] configure_accounting(): Continuing accounting interval.

comment:4 Changed 9 years ago by nickm

ok, that doesn't say much yet. But if the bug ever comes back, info logs like this should help track it down.

comment:5 Changed 9 years ago by BarkerJr

I deleted the state file on BarkerJrCoast1 on Nov 23 and restarted it. Here are the logs. You can see that it happened again. It also occurred on BarkerJrGarden1 and 2.

Nov 23 21:40:25.142 [notice] Catching signal TERM, exiting cleanly.
Nov 23 21:41:21.437 [notice] Tor 0.2.2.18-alpha (git-910de7dfac82f314) opening log file.
Nov 23 21:41:21.437 [info] read_bandwidth_usage(): Reading bandwidth accounting data from state file
Nov 23 21:41:21.437 [info] read_bandwidth_usage(): Successfully read bandwidth accounting info from state written at 1970-01-01 00:00:00 for interval starting at 1970-01-01 00:00:00.  We have been active for 0 seconds in this interval.  At the start of the interval, we expected to use about 0 KB per second. (0 bytes read so far, 0 bytes written so far)
Nov 23 21:41:21.437 [info] configure_accounting(): Starting new accounting interval.
Nov 23 21:41:21.437 [info] reset_accounting(): Starting new accounting interval.
Nov 23 21:41:21.454 [notice] OpenSSL OpenSSL 1.0.0a 1 Jun 2010 looks like version 0.9.8m or later; I will try SSL_OP to enable renegotiation
Nov 23 21:41:21.487 [warn] I have no descriptor for the router named "BarkerJrNet" in my declared family; I'll use the nickname as is, but this may confuse clients.
Nov 23 21:41:21.487 [warn] I have no descriptor for the router named "BarkerJrParis1a" in my declared family; I'll use the nickname as is, but this may confuse clients.
Nov 23 21:41:21.487 [warn] I have no descriptor for the router named "BarkerJrCoast2" in my declared family; I'll use the nickname as is, but this may confuse clients.
Nov 23 21:41:21.487 [warn] I have no descriptor for the router named "BarkerJrParis1b" in my declared family; I'll use the nickname as is, but this may confuse clients.
Nov 23 21:41:21.487 [warn] I have no descriptor for the router named "BarkerJrGarden1" in my declared family; I'll use the nickname as is, but this may confuse clients.
Nov 23 21:41:21.487 [warn] I have no descriptor for the router named "BarkerJrGarden2" in my declared family; I'll use the nickname as is, but this may confuse clients.
Nov 23 21:41:21.490 [notice] Your Tor server's identity key fingerprint is 'BarkerJrCoast1 74491A4B863D2D38342B2E92361EF53DEEB4EAEF'
Nov 23 21:41:21.490 [notice] Configured hibernation.  This interval begins at 2010-10-31 00:00:00 and ends at 2010-10-31 00:00:00.  We have no prior estimate for bandwidth, so we will start out awake and hibernate when we exhaust our quota.
Nov 23 21:41:21.490 [info] configure_accounting(): Accounting interval moved by 3.33%; that's fine.
Nov 23 21:41:21.490 [notice] Configured hibernation.  This interval begins at 2010-10-31 00:00:00 and ends at 2010-12-01 00:00:00.  We have no prior estimate for bandwidth, so we will start out awake and hibernate when we exhaust our quota.
Nov 23 21:41:21.490 [notice] Parsing GEOIP file.
Nov 23 21:41:22.112 [notice] We now have enough directory information to build circuits.
Nov 23 21:41:22.112 [notice] Bootstrapped 80%: Connecting to the Tor network.
Nov 23 21:41:26.323 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Nov 23 21:41:27.442 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Nov 23 21:41:33.454 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Nov 23 21:41:33.454 [notice] Bootstrapped 100%: Done.
Nov 23 21:41:33.454 [notice] Now checking whether ORPort 74.207.249.11:9001 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
Nov 23 21:42:38.276 [notice] Self-testing indicates your ORPort is reachable from the outside. Excellent. Publishing server descriptor.
Nov 23 21:43:25.603 [notice] We're missing a certificate from authority with signing key F7C7B9191C74C0BA07363C84D37BBAD3A8A6C6D8: launching request.
Nov 23 21:43:25.603 [notice] We're missing a certificate from authority with signing key 604834622B54F2D9BA39B34AC53924546733AA60: launching request.
Nov 23 21:43:25.932 [notice] We're missing a certificate from authority with signing key F7C7B9191C74C0BA07363C84D37BBAD3A8A6C6D8: launching request.
Nov 23 21:43:25.932 [notice] We're missing a certificate from authority with signing key 604834622B54F2D9BA39B34AC53924546733AA60: launching request.
Nov 23 21:43:30.233 [notice] Performing bandwidth self-test...done.
Nov 23 23:36:06.719 [notice] Circuit build measurement period of 60000ms is more than twice the maximum build time we have ever observed. Capping it to 31456ms.
Nov 23 23:36:06.719 [notice] Based on 100 circuit times, it looks like we don't need to wait so long for circuits to finish. We will now assume a circuit is too slow to use after waiting 5 seconds.
Nov 25 17:24:12.199 [notice] Bandwidth soft limit reached; commencing hibernation.
Nov 25 17:26:55.290 [notice] Going dormant. Blowing away remaining connections.
Dec 01 00:00:00.363 [info] configure_accounting(): Accounting interval elapsed; starting a new one
Dec 01 00:00:00.394 [info] reset_accounting(): Starting new accounting interval.
Dec 01 00:00:00.394 [notice] Configured hibernation.  This interval began at 2010-12-01 00:00:00; the scheduled wake-up time is 2020-09-21 18:01:33; we expect to exhaust our quota for this interval around 2011-01-01 00:00:00; the next interval begins at 2011-01-01 00:00:00 (all times local)
Dec 01 00:00:00.394 [notice] Accounting period ended. This period, we will hibernate until 2020-09-21 18:01:33 GMT
# Tor state file last generated on 2010-12-03 00:48:02 local time
# Other times below are in GMT
# You *do not* need to edit this file.

AccountingBytesReadInInterval 11662336
AccountingBytesWrittenInInterval 710656
AccountingExpectedUsage 1203
AccountingIntervalStart 2010-12-01 00:00:00
AccountingSecondsActive 175521
# Tor state file last generated on 2010-11-28 06:57:50 local time
# Other times below are in GMT
# You *do not* need to edit this file.

AccountingBytesReadInInterval 158880638976
AccountingBytesWrittenInInterval 161063241728
AccountingIntervalStart 2010-10-31 00:00:00
AccountingSecondsActive 378854
AccountingSecondsToReachSoftLimit 157369
AccountingSoftLimitHitAt 2010-11-25 17:24:12
AccountingBytesAtSoftLimit 160539709592

Changed 9 years ago by boboper's secretary

Attachment: 2146.diff added

comment:6 Changed 9 years ago by boboper's secretary

Mr.boboper asked to attach this. I leave it here.

comment:7 Changed 9 years ago by nickm

Milestone: Tor: 0.2.2.x-finalTor: 0.2.1.x-final

Looks good to me; merging to 0.2.2 and master, and marking as backportable to 0.2.1.

comment:8 Changed 9 years ago by Sebastian

Status: newneeds_review

BarkerJr: The issue is fixed for you, yes?

I did a trivial backport, see branch bug2146_maint021 in my repo. I think we should do the backport here soon.

comment:9 in reply to:  8 Changed 9 years ago by BarkerJr

Replying to Sebastian:

BarkerJr: The issue is fixed for you, yes?

Looks good to me.

comment:10 Changed 9 years ago by arma

sebastian's bug2146_maint021 looks ok to me. I got distracted looking at

-    time_to_exhaust_bw = GUESS_TIME_TO_USE_BANDWIDTH;

and

-
-    format_iso_time(buf, interval_wakeup_time);

because they look like they change behavior, but in fact they're being taken out because they are no-ops, yes?

In general we should probably leave noops like these in oldstable -- you never know when you're going to end up wrong. :)

comment:11 Changed 9 years ago by arma

That said, it looks like a variant of this patch has been in 0.2.2 and master for a while. And I remember there are some new unsolved bug reports on 0.2.2 and master about hibernation problems.

We should confirm that we don't think those bugs are related to this change.

comment:12 in reply to:  11 Changed 9 years ago by arma

Replying to arma:

We should confirm that we don't think those bugs are related to this change.

In particular, I'm thinking of #2003 and #2152. I was also thinking of #1511, but it looks like that's scheduled to go in once #2146 goes in.

comment:13 Changed 9 years ago by nickm

Right now I'm thinking the best we can do for users here is _not_ to backport this (or #1511) to 0.2.1. Our chances of getting it wrong are high enough, and the workaround ("upgrade to 0.2.2.x") is simple enough that we should call this "won't fix" in the 0.2.1. series.

comment:14 Changed 9 years ago by Sebastian

So can we close this?

comment:15 Changed 9 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

I believe so. Closing.

comment:16 Changed 7 years ago by nickm

Keywords: tor-relay added

comment:17 Changed 7 years ago by nickm

Component: Tor RelayTor

comment:18 Changed 7 years ago by nickm

Milestone: Tor: 0.2.1.x-final

Milestone Tor: 0.2.1.x-final deleted

Note: See TracTickets for help on using tickets.