Opened 2 years ago

Last modified 2 years ago

#16348 accepted defect

Suppress exception chaining when PEP 3134 is merged

Reported by: toralf Owned by: atagar
Priority: Low Milestone:
Component: Core Tor/Stem Version:
Severity: Keywords: controller
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

with tor-0.2.6.9 and stem-1.4.1 I run (rarely) into this :

cat ioerror.stderr.old
Exception in thread Event Notifier:
Traceback (most recent call last):
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 1758, in get_network_status
    desc_content = self.get_info(query, get_bytes = True)
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 414, in wrapped
    raise exc
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 409, in wrapped
    return func(self, *args, **kwargs)
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 1113, in get_info
    raise exc
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 1066, in get_info
    stem.response.convert('GETINFO', response)
  File "/usr/lib64/python3.3/site-packages/stem/response/__init__.py", line 135, in convert
    message._parse_message(**kwargs)
  File "/usr/lib64/python3.3/site-packages/stem/response/getinfo.py", line 38, in _parse_message
    raise stem.InvalidArguments('552', 'GETINFO request contained unrecognized keywords: %s\n' % ', '.join(unrecognized_keywords), unrecognized_keywords)
stem.InvalidArguments: GETINFO request contained unrecognized keywords: ns/id/2BCDF9F0BCEFC2A44F7850F92362BA85AA226E1F


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib64/python3.3/threading.py", line 901, in _bootstrap_inner
    self.run()
  File "/usr/lib64/python3.3/threading.py", line 858, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 882, in _event_loop
    self._handle_event(event_message)
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 3480, in _handle_event
    listener(event_message)
  File "./err.py", line 47, in orconn_event
    relay = controller.get_network_status(fingerprint)
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 414, in wrapped
    raise exc
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 409, in wrapped
    return func(self, *args, **kwargs)
  File "/usr/lib64/python3.3/site-packages/stem/control.py", line 1761, in get_network_status
    raise stem.DescriptorUnavailable("Tor was unable to provide the descriptor for '%s'" % relay)
stem.DescriptorUnavailable: Tor was unable to provide the descriptor for '2BCDF9F0BCEFC2A44F7850F92362BA85AA226E1F'

while running this script :

$ cat err.py
#!/usr/bin/python3 -u

#   Toralf Foerster
#   Hamburg
#   Germany

# collect data wrt to https://trac.torproject.org/projects/tor/ticket/13603
#

import time
import functools

from stem import ORStatus, ORClosureReason
from stem.control import EventType, Controller


def main():
  class Cnt(object):
    def __init__(self, done=0, closed=0, ioerror=0):
      self.done = done
      self.closed = closed
      self.ioerror = ioerror

  c = Cnt()

  with Controller.from_port(port=9051) as controller:
    controller.authenticate()

    orconn_listener = functools.partial(orconn_event, controller, c)
    controller.add_event_listener(orconn_listener, EventType.ORCONN)

    while True:
      time.sleep(1)

def orconn_event(controller, c, event):
  if event.status == ORStatus.CLOSED:
    c.closed += 1

    if event.reason == ORClosureReason.DONE:
      c.done += 1

    if event.reason == ORClosureReason.IOERROR:
      c.ioerror += 1

      fingerprint = event.endpoint_fingerprint
      print (" %i %i %i %i %s %40s" % (c.closed, c.done, c.ioerror, event.arrived_at, time.ctime(event.arrived_at), fingerprint), end='')
      relay = controller.get_network_status(fingerprint)
      if relay:
        print (" %15s %5i %s %s" % (relay.address, relay.or_port, controller.get_info("ip-to-country/%s" % relay.address, 'unknown'), relay.nickname), end='')
      print ('', flush=True)

if __name__ == '__main__':
  main()

Child Tickets

Change History (10)

comment:1 Changed 2 years ago by atagar

Component: StemTor

Hi toralf, reassigning this to the Tor component. Tor is emitting an ORCONN event before it's able to provide the descriptor via a GETINFO request. Think this is normal, though certainly weird and possibly an issue with tor (why can tor emit these for things it itself doesn't have descriptor information for?).

By the way, you have a conditional that checks if 'relay' exists or not. Assuming you simply want to skip the print if there's no descriptor information available all you gotta do is provide a default...

relay = controller.get_network_status(fingerprint, None)

if relay:
  print (" %15s %5i %s %s" % (relay.address, relay.or_port, controller.get_info("ip-to-country/%s" % relay.address, 'unknown'), relay.nickname), end='')

comment:2 Changed 2 years ago by toralf

Hi atagar,
thx for "None" hint - so I can easily avoid to use try ... except

comment:3 Changed 2 years ago by nickm

It's totally normal for tor to be able to emit an ORCONN event before it has a descriptor. That could happen for these reasons, I think:

  • Initial connection to directory in order to fetch a consensus over a tunneled connection.
  • Incoming connection from another relay that we don't know about yet.

Seems like not-a-bug to me?

comment:4 Changed 2 years ago by toralf

So a not-a-bug-in-tor-but-worth-an-enhancement-in-stem feature ?

comment:5 Changed 2 years ago by atagar

Component: TorStem

Thanks Nick, reassigning back to Stem.

What do you think should be improved in Stem, toralf? One bit I find odd is that you cite two stacktraces above - the DescriptorUnavailable one looks right to me but I'm unsure why you got a second.

comment:6 Changed 2 years ago by toralf

Hhm, in the mean while I do think, that there's really no bug - the stack trace was probably forced by myself by not using "None" as an arg.
This runs now since a while w/o problems :

      fingerprint = event.endpoint_fingerprint
      print (" %i %i %i %i %s %40s" % (c.closed, c.done, c.ioerror, event.arrived_at, time.ctime(event.arrived_at), fingerprint), end='')
      relay = controller.get_network_status(fingerprint, None)
      if (relay):
        print (" %15s %5i %s %s" % (relay.address, relay.or_port, controller.get_info("ip-to-country/%s" % relay.address, 'unknown'), relay.nickname))
      else:
        print ('', flush=True)

so I tend to close this today if there's no issue in this area.

comment:7 Changed 2 years ago by atagar

Resolution: worksforme
Status: newclosed

Ok, sounds good. I'm still a bit unsure about the double stacktrace (that part looks wrong), so feel free to reopen if there's an issue around that. The 'None' bit is just providing a default return value - just about every getter method on the Controller allows for one to let you do something more elegant than a try/catch.

comment:8 Changed 2 years ago by toralf

The 'None' is rally good - I just repalcing all my try/except with that where possible.

BTW, the doubled stack trace can be easily reproduced by :

#!/usr/bin/python3 -u

import time
from stem.control import Controller

def main():
  with Controller.from_port(port = 9051) as controller:
    controller.authenticate()

    # force a double stack trace
    #
    desc = controller.get_microdescriptor('idonotexist')

if __name__ == '__main__':
  main()

Last edited 2 years ago by toralf (previous) (diff)

comment:9 Changed 2 years ago by atagar

Resolution: worksforme
Status: closedreopened

Thanks! Reopening, I'll take a peek later.

comment:10 Changed 2 years ago by atagar

Keywords: controller added
Priority: normalminor
Status: reopenedaccepted
Summary: raise stem.InvalidArguments('552', 'GETINFO request contained unrecognized keywords:Suppress exception chaining when PEP 3134 is merged
Version: Tor: unspecified

Figured it out, and unfortunately I can't do anything about it yet. Trouble is that python3 added exception chaining. Under python2 you only get the useful stacktrace but with python3 you get the internal one too.

At present there isn't a method for suppressing this. There's a proposal for adding suppression but it isn't yet merged, and even after it is this will be an ongoing annoyance for python 3.x before the addition.

Keeping this open so we circle back to take advantage of suppression when it's added.

Note: See TracTickets for help on using tickets.