Accounting Start Time Set to Year 2064

added component::core tor/tor priority::high reporter::BarkerJr resolution::fixed status::closed tor-relay type::defect labels

Trac:
Milestone: N/A to Tor: 0.2.2.x-final

Trac:
Priority: normal to major

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.

Trac:
Username: BarkerJr

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

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

Trac:
Username: BarkerJr

Trac:
Username: boboper's secretary

2146.diff

Trac:
Username: boboper's secretary

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

Trac:
Username: boboper's secretary

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

Trac:
Milestone: Tor: 0.2.2.x-final to Tor: 0.2.1.x-final

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.

Trac:
Status: new to needs_review

Replying to Sebastian:

BarkerJr: The issue is fixed for you, yes?

Looks good to me.

Trac:
Username: BarkerJr

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. :)

Trac:
Actualpoints: N/A to N/A
Points: N/A to N/A

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.

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 (moved) and #2152 (moved). I was also thinking of #1511 (moved), but it looks like that's scheduled to go in once #2146 (moved) goes in.

Right now I'm thinking the best we can do for users here is not to backport this (or #1511 (moved)) 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.

So can we close this?

I believe so. Closing.

Trac:
Status: needs_review to closed
Resolution: N/A to fixed

Trac:
Keywords: N/A deleted, tor-relay added

Trac:
Component: Tor Relay to Tor

Accounting Start Time Set to Year 2064

Child items ...

Activity