Opened 4 years ago

Closed 3 years ago

Last modified 10 months ago

#9379 closed defect (duplicate)

Tor descriptor fetching is unreliable

Reported by: atagar Owned by:
Priority: Medium Milestone:
Component: Core Tor/Tor Version:
Severity: Keywords:
Cc: karsten, wfn Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Hi all. This last weekend I wrote a little script to validate tor's descriptors every hour and ensure that all of the directory authorities are reachable. All the script does is...

  • Download and validate the server descriptors from a random authority.
  • Download and validate the extrainfo descriptors from a random authority.
  • Download and validate the present consensus from each authority.

This is all well and good, but I've found that downloading from Tor's directory authorities is surprisingly flaky. The most troubled authority looks to be maatuska, though all of them manifest issues (especially for server/extrainfo descriptors, which is by far the larger requests)...

atagar@odin:~/Desktop/tor/tor-utils$ grep "Unable to download descriptors" logs/descriptor_checker.stem_debug | cut -f 9 -d ' ' | sort | uniq -c | sort -rn
     58 'http://171.25.193.9:443/tor/status-vote/current/consensus.z'
     29 'http://171.25.193.9:443/tor/status-vote/current/consensus.z':
     15 'http://76.73.17.194:9030/tor/server/all.z'
     15 'http://208.83.223.34:443/tor/server/all.z'
     12 'http://76.73.17.194:9030/tor/extra/all.z'
     10 'http://171.25.193.9:443/tor/server/all.z'
     10 'http://128.31.0.39:9131/tor/extra/all.z'
      9 'http://171.25.193.9:443/tor/extra/all.z'
      8 'http://208.83.223.34:443/tor/extra/all.z'
      8 'http://154.35.32.5:80/tor/server/all.z'
      8 'http://128.31.0.39:9131/tor/server/all.z'
      6 'http://208.83.223.34:443/tor/status-vote/current/consensus.z'
      6 'http://193.23.244.244:80/tor/server/all.z'
      5 'http://193.23.244.244:80/tor/extra/all.z'
      5 'http://154.35.32.5:80/tor/extra/all.z'
      4 'http://212.112.245.170:80/tor/extra/all.z'
      4 'http://208.83.223.34:443/tor/server/all.z':
      3 'http://76.73.17.194:9030/tor/server/all.z':
      3 'http://208.83.223.34:443/tor/status-vote/current/consensus.z':
      3 'http://208.83.223.34:443/tor/extra/all.z':
      3 'http://193.23.244.244:80/tor/server/all.z':
      3 'http://154.35.32.5:80/tor/extra/all.z':
      2 'http://76.73.17.194:9030/tor/status-vote/current/consensus.z'
      2 'http://76.73.17.194:9030/tor/extra/all.z':
      2 'http://171.25.193.9:443/tor/server/all.z':
      2 'http://171.25.193.9:443/tor/extra/all.z':
      2 'http://128.31.0.39:9131/tor/server/all.z':
      1 'http://76.73.17.194:9030/tor/status-vote/current/consensus.z':
      1 'http://212.112.245.170:80/tor/server/all.z'
      1 'http://212.112.245.170:80/tor/extra/all.z':
      1 'http://154.35.32.5:80/tor/server/all.z':
      1 'http://128.31.0.39:9131/tor/extra/all.z':

Stem attempts three requests before giving up, and very frequently hits that limit. Some errors are connection resets and timeouts, but the most frequent is a 'successful' connection where the compressed content is simply truncated (and hence corrupt). Karsten, Kostas, and I ran into this earlier too on tor-dev@...

atagar@odin:~/Desktop/tor/tor-utils$ grep "Unable to download descriptors" logs/descriptor_checker.stem_debug | cut -f 10- -d ' ' | sort | uniq -c | sort -nr
     56 (2 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
     44 (2 retries remaining): <urlopen error [Errno 111] Connection refused>
     36 (1 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
     33 <urlopen error [Errno 111] Connection refused>
     33 (1 retries remaining): <urlopen error [Errno 111] Connection refused>
     22 Error -5 while decompressing data: incomplete or truncated stream
      6 (2 retries remaining): [Errno 104] Connection reset by peer
      4 [Errno 104] Connection reset by peer
      4 (1 retries remaining): [Errno 104] Connection reset by peer
      1 <urlopen error timed out>
      1 (2 retries remaining): <urlopen error timed out>
      1 (2 retries remaining): timed out
      1 (1 retries remaining): <urlopen error timed out>

I could simply up the retry count to something ridiculously high (say, ten?) to address these issues but it would be better if we figured out the root cause.

Any thoughts on how best to approach this?

Thanks! -Damian

Child Tickets

Change History (10)

comment:1 Changed 4 years ago by karsten

Wow, didn't expect this to be so bad. I agree that it would be good to figure out the root cause.

I wonder, can we get info-level or even debug-level logs of a directory authority or directory mirror that is returning a truncated descriptor content? In theory, you could use your script to download from a directory mirror, right? Can you find a directory mirror that logs on debug level that you then request server or extra-info descriptors from?

comment:2 Changed 4 years ago by atagar

Huh. The thick plottens. I recalled while writing this module that fetching plaintext descriptors was pretty reliable so I decided to test that...

atagar@odin:~/Desktop/tor/tor-utils$ cat puller.py 
import stem.descriptor.remote
import stem.util.log

stem.util.log.log_to_stdout(stem.util.log.TRACE)

while True:
  query = stem.descriptor.remote.Query(
    '/tor/server/all',
    block = True,
    timeout = 60,
  )

  if not query.error:
    print "Results downloaded: %i" % len(list(query))
  else:
    print "Got an error: %s" % query.error

When I run the above...

atagar@odin:~/Desktop/tor/tor-utils$ python puller.py 
08/04/2013 12:10:03 [TRACE] Descriptors retrieved from 'http://212.112.245.170:80/tor/server/all' in 37.85s
Results downloaded: 5768
08/04/2013 12:10:57 [TRACE] Descriptors retrieved from 'http://86.59.21.38:80/tor/server/all' in 36.47s
Results downloaded: 5767
08/04/2013 12:11:51 [TRACE] Descriptors retrieved from 'http://212.112.245.170:80/tor/server/all' in 37.28s
Results downloaded: 5765
08/04/2013 12:12:44 [TRACE] Descriptors retrieved from 'http://208.83.223.34:443/tor/server/all' in 35.98s
Results downloaded: 5766

... but when I change the resource to 'all.z'...

atagar@odin:~/Desktop/tor/tor-utils$ python puller.py 
08/04/2013 12:02:38 [DEBUG] Unable to download descriptors from 'http://208.83.223.34:443/tor/server/all.z' (2 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/04/2013 12:02:59 [TRACE] Descriptors retrieved from 'http://154.35.32.5:80/tor/server/all.z' in 21.75s
Results downloaded: 5763
08/04/2013 12:03:37 [DEBUG] Unable to download descriptors from 'http://194.109.206.212:80/tor/server/all.z' (2 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/04/2013 12:03:55 [DEBUG] Unable to download descriptors from 'http://194.109.206.212:80/tor/server/all.z' (1 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/04/2013 12:03:55 [DEBUG] Unable to download descriptors from 'http://171.25.193.9:443/tor/server/all.z': <urlopen error [Errno 111] Connection refused>
Got an error: <urlopen error [Errno 111] Connection refused>
08/04/2013 12:03:56 [DEBUG] Unable to download descriptors from 'http://171.25.193.9:443/tor/server/all.z' (2 retries remaining): <urlopen error [Errno 111] Connection refused>
08/04/2013 12:03:56 [DEBUG] Unable to download descriptors from 'http://171.25.193.9:443/tor/server/all.z' (1 retries remaining): <urlopen error [Errno 111] Connection refused>
08/04/2013 12:04:14 [TRACE] Descriptors retrieved from 'http://86.59.21.38:80/tor/server/all.z' in 18.09s
Results downloaded: 5762
08/04/2013 12:04:49 [TRACE] Descriptors retrieved from 'http://86.59.21.38:80/tor/server/all.z' in 18.10s
Results downloaded: 5763
08/04/2013 12:06:16 [DEBUG] Unable to download descriptors from 'http://76.73.17.194:9030/tor/server/all.z' (2 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/04/2013 12:07:09 [DEBUG] Unable to download descriptors from 'http://194.109.206.212:80/tor/server/all.z' (1 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/04/2013 12:07:37 [DEBUG] Unable to download descriptors from 'http://128.31.0.39:9131/tor/server/all.z': Error -5 while decompressing data: incomplete or truncated stream
Got an error: Error -5 while decompressing data: incomplete or truncated stream
08/04/2013 12:07:38 [DEBUG] Unable to download descriptors from 'http://171.25.193.9:443/tor/server/all.z' (2 retries remaining): <urlopen error [Errno 111] Connection refused>
08/04/2013 12:07:58 [DEBUG] Unable to download descriptors from 'http://194.109.206.212:80/tor/server/all.z' (1 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/04/2013 12:08:46 [DEBUG] Unable to download descriptors from 'http://76.73.17.194:9030/tor/server/all.z': Error -5 while decompressing data: incomplete or truncated stream
Got an error: Error -5 while decompressing data: incomplete or truncated stream

The issue definitely seems to be related to the compression.

In theory, you could use your script to download from a directory mirror, right?

Yup.

Can you find a directory mirror that logs on debug level that you then request server or extra-info descriptors from?

Presently the only relay I have any level of access to is amunet, and we definitely don't want to log at debug level there.

Cheers! -Damian

comment:3 Changed 4 years ago by atagar

Switching my monitors over to the plaintext resources (commit). Let me know if you need anything else from my end.

comment:4 Changed 4 years ago by atagar

Now that maatuska is back up I re-ran the above puller with compression. The 'truncated stream' errors look to be the only frequent issue...

atagar@odin:~/Desktop/tor/tor-utils$ python puller.py 
08/05/2013 08:39:43 [DEBUG] Unable to download descriptors from 'http://194.109.206.212:80/tor/server/all.z' (2 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/05/2013 08:40:00 [DEBUG] Unable to download descriptors from 'http://208.83.223.34:443/tor/server/all.z' (1 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/05/2013 08:40:25 [DEBUG] Unable to download descriptors from 'http://128.31.0.39:9131/tor/server/all.z': Error -5 while decompressing data: incomplete or truncated stream
Got an error: Error -5 while decompressing data: incomplete or truncated stream
08/05/2013 08:40:44 [TRACE] Descriptors retrieved from 'http://212.112.245.170:80/tor/server/all.z' in 18.61s
Results downloaded: 5814
08/05/2013 08:41:19 [TRACE] Descriptors retrieved from 'http://86.59.21.38:80/tor/server/all.z' in 18.06s
Results downloaded: 5813
08/05/2013 08:42:28 [DEBUG] Unable to download descriptors from 'http://76.73.17.194:9030/tor/server/all.z' (2 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/05/2013 08:42:46 [DEBUG] Unable to download descriptors from 'http://194.109.206.212:80/tor/server/all.z' (1 retries remaining): Error -5 while decompressing data: incomplete or truncated stream
08/05/2013 08:43:05 [TRACE] Descriptors retrieved from 'http://212.112.245.170:80/tor/server/all.z' in 18.82s
Results downloaded: 5813
08/05/2013 08:43:41 [DEBUG] Unable to download descriptors from 'http://194.109.206.212:80/tor/server/all.z' (2 retries remaining): Error -5 while decompressing data: incomplete or truncated stream

comment:5 Changed 4 years ago by nickm

Milestone: Tor: 0.2.???

comment:6 Changed 3 years ago by wfn

Cc: wfn added

See #11648, too.

comment:7 Changed 3 years ago by nickm

The undecompressible stuff has been fixed (#11648); but it looks like there is more going on here?

comment:8 Changed 3 years ago by atagar

Resolution: duplicate
Status: newclosed

I don't believe so, but I won't be able to check until the authorities upgrade to use the fix. Resolving as a duplicate of #11648 - thanks!

comment:9 Changed 11 months ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:10 Changed 10 months ago by nickm

Milestone: Tor: 0.3.???

Milestone deleted

Note: See TracTickets for help on using tickets.