Opened 3 years ago

Closed 2 years ago

Last modified 8 months ago

#19966 closed defect (user disappeared)

torproxy goes south with more than 1 connection attempt per second to a hidden service

Reported by: Alan Owned by:
Priority: High Milestone: Tor: 0.3.1.x-final
Component: Core Tor/Tor Version: Tor: 0.2.8.6
Severity: Major Keywords: tor-hs, regression, triage-out-030-201612
Cc: Alan Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

I have a web service running as a tor hidden service. I have a test script that connects to the hidden service through tor proxy, sends a short string, gets a short reply, and then the hidden service closes the connection. Each time the test script connects, it uses a different socks username, so it should get a fresh tor circuit each time.

This works mostly ok with Tor v0.2.7.6 (git-7a489a6389110120) running on Windows 7 with Libevent 2.0.22-stable, OpenSSL 1.0.1t and Zlib 1.2.8. With four test scripts, it makes about 1 connection per second. Obviously, with any network, it is going to get some connection and network errors, but it recovers eventually.

With Tor v0.2.8.6 (git-4d217548e3f05569) running on Windows 7 with Libevent 2.0.22-stable, OpenSSL 1.0.1t and Zlib 1.2.8, it doesn't run so well. Up to about one connection every two seconds, it runs ok, but as soon as I go above that, tor proxy goes south and starts refusing all connections and the logging error messages shown below. This behavior makes is unsuitable/unreliable to use in a "production" environment.

It seems to not matter what version of tor I use on the hidden service side--only the version on the client side seems to matter, and that is where the errors messages are seen.

This is the contents of my torrc file, which works under v0.2.7.6 but not under v0.2.8.6.

Log notice stdout
LogMessageDomains 1
SafeLogging 0
MaxClientCircuitsPending 200
KeepalivePeriod 15
SocksTimeout 60
NewCircuitPeriod 1
LearnCircuitBuildTimeout 1
CircuitBuildTimeout 60
NumEntryGuards 20

The error messages are:

Aug 23 18:30:32.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:32.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:34.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:34.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:35.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:35.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:35.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:35.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:36.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:36.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:36.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:36.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:36.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:36.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:37.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:37.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:37.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:37.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:37.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:37.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:37.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:37.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:38.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:38.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:39.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:39.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:39.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:39.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:39.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:40.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:40.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:40.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:40.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:40.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:40.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:40.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:40.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:41.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:41.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:42.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:42.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:42.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:42.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:42.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:43.000 [warn] {REND} Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).
Aug 23 18:30:43.000 [notice] {REND} Closing stream for 'vgfdgkr7tudleiq3.onion': hidden service is unavailable (try again later).

Child Tickets

Change History (9)

comment:1 Changed 3 years ago by Alan

Cc: Alan added
Component: Core Tor/TorsocksCore Tor/Tor
Keywords: hidden service client added
Milestone: Tor: 0.2.7.x-finalTor: 0.2.9.x-final

comment:2 Changed 3 years ago by Alan

Owner: dgoulet deleted
Status: newassigned

comment:3 Changed 3 years ago by Alan

Status: assignednew

comment:4 Changed 3 years ago by Alan

Milestone: Tor: 0.2.9.x-finalTor: 0.2.8.x-final

comment:5 Changed 3 years ago by nickm

Keywords: 028-backport 029-backport added
Milestone: Tor: 0.2.8.x-finalTor: 0.3.0.x-final

comment:6 Changed 3 years ago by dgoulet

Keywords: tor-hs regression added; hidden service client 028-backport 029-backport removed

Is there any chance you can re-test that with latest either 0.2.8 version of 0.2.9? I have a vague memory about fixing such looping connecting behavior in 028 but unsure. Also, the more log you can give us the better such a debug level logs.

Thanks!

comment:7 Changed 3 years ago by dgoulet

Keywords: triage-out-030-201612 added
Milestone: Tor: 0.3.0.x-finalTor: 0.3.1.x-final

Triaged out on December 2016 from 030 to 031.

comment:8 Changed 2 years ago by dgoulet

Resolution: user disappeared
Status: newclosed

I *think* that was fixed a while back.

comment:9 Changed 8 months ago by damiengray

If I initiate onion service connections too rapidly, I see the same error progression:

Dec {redacted} [notice] We'd like to launch a circuit to handle a connection, but we already have {redacted} general-purpose client circuits pending. Waiting until some finish.
Dec {redacted} [warn] Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Dec {redacted} [warn] Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Dec {redacted} [warn] Fetching v2 rendezvous descriptor failed. Retrying at another directory.
Dec {redacted} [notice] Closing stream for '[scrubbed].onion': hidden service is unavailable (try again later).
Dec {redacted} [notice] Closing stream for '[scrubbed].onion': hidden service is unavailable (try again later).
Dec {redacted} [notice] Tried for 120 seconds to get a connection to [scrubbed]:{redacted}. Giving up. (waiting for rendezvous desc)
Dec {redacted} [notice] Tried for 120 seconds to get a connection to [scrubbed]:{redacted}. Giving up. (waiting for rendezvous desc)

I am using Tor version 0.3.4.9 (git-074ca2e0054fded1).

I believe that https://github.com/termux/termux-packages/issues/3120 reflects the same issue.

Is there any fix for this, other than limiting the connection rate?

Last edited 8 months ago by damiengray (previous) (diff)
Note: See TracTickets for help on using tickets.