Opened 8 years ago

Closed 7 years ago

#7302 closed defect (fixed)

Hibernating v0.2.3.x nags about failure connect

Reported by: tmpname0901 Owned by:
Priority: Medium Milestone: Tor: 0.2.4.x-final
Component: Core Tor/Tor Version: Tor: 0.2.3.24-rc
Severity: Keywords: tor-relay
Cc: arma Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

A hibernating v0.2.3.x relay fills its logs with complaints about inability to establish connections.

Below the complaints are bootstrap-related because a hibernating relay was restarted. Similar complaints are seen with a constantly-running relay when the consensus becomes outdated.

A relay may spend the bulk of its accounting period issuing these warnings, after the configured bandwidth is exhausted.


Nov 01 21:09:18.000 [notice] Tor 0.2.3.24-rc (git-4f228f39ec74abfa) opening log file.
Nov 01 21:09:18.000 [notice] This version of OpenSSL has a known-good EVP counter-mode implementation. Using it.
Nov 01 21:09:18.000 [notice] OpenSSL OpenSSL 1.0.1c 10 May 2012 looks like version 0.9.8m or later; I will try SSL_OP to enable renegotiation
Nov 01 21:09:18.000 [notice] Your Tor server's identity key fingerprint is 'Unnamed XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX'
Nov 01 21:09:18.000 [notice] Configured hibernation. This interval begins at 2012-09-30 00:00:00 and ends at 2012-11-05 00:00:00. We have no prior estimate for bandwidth, so we will start out awake and hibernate when we exhaust our quota.
Nov 01 21:09:18.000 [notice] Parsing GEOIP file /usr/share/tor/geoip.
Nov 01 21:09:18.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.
Nov 01 21:09:19.000 [notice] Reloaded microdescriptor cache. Found 8634 descriptors.
Nov 01 21:09:21.000 [notice] We now have enough directory information to build circuits.
Nov 01 21:09:21.000 [notice] Bootstrapped 80%: Connecting to the Tor network.
Nov 01 21:09:22.000 [notice] Bandwidth soft limit reached; commencing hibernation. No new connections will be accepted
Nov 01 21:09:22.000 [notice] Going dormant. Blowing away remaining connections.
Nov 01 21:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 01 21:09:22.000 [notice] Heartbeat: Tor's uptime is 0:00 hours, with 3 circuits open. I've sent 0 kB and received 0 kB.
Nov 01 21:09:22.000 [notice] Bootstrapped 85%: Finishing handshake with first hop.
Nov 02 03:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 02 03:09:22.000 [notice] Heartbeat: Tor's uptime is 6:00 hours, with 43 circuits open. I've sent 1.37 MB and received 3.59 MB.
Nov 02 09:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 02 09:09:22.000 [notice] Heartbeat: Tor's uptime is 12:00 hours, with 93 circuits open. I've sent 3.82 MB and received 9.03 MB.
Nov 02 15:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 02 15:09:22.000 [notice] Heartbeat: Tor's uptime is 18:00 hours, with 141 circuits open. I've sent 7.14 MB and received 15.68 MB.
Nov 02 21:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 02 21:09:22.000 [notice] Heartbeat: Tor's uptime is 1 day 0:00 hours, with 177 circuits open. I've sent 11.14 MB and received 22.99 MB.
Nov 03 03:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 03 03:09:22.000 [notice] Heartbeat: Tor's uptime is 1 day 6:00 hours, with 202 circuits open. I've sent 15.26 MB and received 30.09 MB.
Nov 03 07:52:34.000 [warn] Problem bootstrapping. Stuck at 85%: Finishing handshake with first hop. (Connection timed out; TIMEOUT; count 10; recommendation warn)
Nov 03 07:52:34.000 [warn] 9 connections have failed:
Nov 03 07:52:34.000 [warn] 8 connections died in state connect()ing with SSL state (No SSL object)
Nov 03 07:52:34.000 [warn] 1 connections died in state handshaking (TLS) with SSL state SSLv2/v3 read server hello A in HANDSHAKE
Nov 03 07:52:35.000 [warn] Problem bootstrapping. Stuck at 85%: Finishing handshake with first hop. (Connection timed out; TIMEOUT; count 11; recommendation warn)
Nov 03 07:52:35.000 [warn] 10 connections have failed:
Nov 03 07:52:35.000 [warn] 9 connections died in state connect()ing with SSL state (No SSL object)
Nov 03 07:52:35.000 [warn] 1 connections died in state handshaking (TLS) with SSL state SSLv2/v3 read server hello A in HANDSHAKE
Nov 03 09:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 03 09:09:22.000 [notice] Heartbeat: Tor's uptime is 1 day 12:00 hours, with 250 circuits open. I've sent 19.92 MB and received 38.68 MB.
Nov 03 10:50:28.000 [warn] Problem bootstrapping. Stuck at 85%: Finishing handshake with first hop. (Connection timed out; TIMEOUT; count 12; recommendation warn)
Nov 03 10:50:28.000 [warn] 11 connections have failed:
Nov 03 10:50:28.000 [warn] 10 connections died in state connect()ing with SSL state (No SSL object)
Nov 03 10:50:28.000 [warn] 1 connections died in state handshaking (TLS) with SSL state SSLv2/v3 read server hello A in HANDSHAKE
Nov 03 10:54:26.000 [warn] Problem bootstrapping. Stuck at 85%: Finishing handshake with first hop. (DONE; DONE; count 13; recommendation warn)
Nov 03 10:54:26.000 [warn] 13 connections have failed:
Nov 03 10:54:26.000 [warn] 11 connections died in state connect()ing with SSL state (No SSL object)
Nov 03 10:54:26.000 [warn] 1 connections died in state handshaking (Tor, v3 handshake) with SSL state SSL negotiation finished successfully in OPEN
Nov 03 10:54:26.000 [warn] 1 connections died in state handshaking (TLS) with SSL state SSLv2/v3 read server hello A in HANDSHAKE
Nov 03 15:09:22.000 [notice] Heartbeat: It seems like we are not in the cached consensus.
Nov 03 15:09:22.000 [notice] Heartbeat: Tor's uptime is 1 day 18:00 hours, with 294 circuits open. I've sent 25.17 MB and received 47.26 MB.
Nov 03 15:38:11.000 [warn] Problem bootstrapping. Stuck at 85%: Finishing handshake with first hop. (Connection timed out; TIMEOUT; count 14; recommendation warn)
Nov 03 15:38:11.000 [warn] 13 connections have failed:
Nov 03 15:38:11.000 [warn] 11 connections died in state connect()ing with SSL state (No SSL object)
Nov 03 15:38:11.000 [warn] 1 connections died in state handshaking (Tor, v3 handshake) with SSL state SSL negotiation finished successfully in OPEN
Nov 03 15:38:11.000 [warn] 1 connections died in state handshaking (TLS) with SSL state SSLv2/v3 read server hello A in HANDSHAKE
Nov 03 16:47:41.000 [notice] Catching signal TERM, exiting cleanly


Child Tickets

Change History (4)

comment:1 Changed 8 years ago by nickm

Cc: arma added
Milestone: Tor: 0.2.3.x-final

Hm. The likeliest solution is to suppress the "problem bootstrapping" message and its attendent codicils when we're hibernating -- possibly heartbeats too?

Arma, this is annoying, but not a critical problem if in fact it only happens every N hours. Do you think it's worth trying to fix in 0.2.3? This could be a "fix in 0.2.4 then backport" issue.

comment:2 Changed 8 years ago by nickm

Keywords: tor-relay added
Milestone: Tor: 0.2.3.x-finalTor: 0.2.4.x-final

comment:3 Changed 7 years ago by nickm

Status: newneeds_review

I've tried the "easy thing" in branch "bug7302" in my public repo. The harder thing will be at some point to figure out what's making (doomed, since we're hibernating) circuits and connections during the hibernation. That's probably another bug though

comment:4 Changed 7 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

This still seems right to me, and it's simple, and it doesn't affect anything but heartbeats and control status message severity. Merging.

Note: See TracTickets for help on using tickets.