When stem receives a signal, log useful information

In #30011 (moved), when stem hangs in Tor's CI, we kill it.

But that doesn't give us much information. To fix #29437 (moved), we need stem to log a backtrace when it receives a signal. (Or switch into debug mode, or something.)

You can pick any signal you like: maybe SIGUSR2 for debug logs, and SIGABRT for a stacktrace? (If you want stem to be like tor.)

Trac:
Parent Ticket: #29437 (moved)

added component::archived/stem owner::teor parent::29437 priority::medium resolution::implemented severity::normal sponsor::31-can status::closed tor-needs type::defect labels

Trac:
Keywords: N/A deleted, tor-ci-fail-sometimes added

This ticket isn't urgent any more, because we think we have a fix in #30021 (moved).

Trac:
Keywords: tor-ci-fail-sometimes deleted, N/A added

Trac:
Parent: #29437 (moved) to N/A

Hi teor. Quick search suggested we might be able to add a signal handler...

https://stackoverflow.com/questions/132058/showing-the-stack-trace-from-a-running-python-application

I won't be able to get to this any time soon, but certainly worthwhile to experiment with at some point.

We're still seeing stem timeouts after the fixes in #29437 (moved), so we need a stacktrace to debug this issue.

Trac:
Parent: N/A to #29437 (moved)
Keywords: N/A deleted, tor-needs added

See my pull request: https://github.com/torproject/stem/pull/11

When I run:

$ make test-stem
...
$ killall -USR1 <run_tests.py pid>

I see:

  control.controller...                               Signal 30 received.
Traceback:
  File "/Users/base/stem/run_tests.py", line 398, in <module>
    main()
  File "/Users/base/stem/run_tests.py", line 239, in main
    run_result = _run_test(args, test_class, output_filters)
  File "/Users/base/stem/run_tests.py", line 379, in _run_test
    run_result = stem.util.test_tools.TimedTestRunner(test_results, verbosity = 2).run(suite)
  File "/Users/base/stem/stem/util/test_tools.py", line 308, in run
    return super(TimedTestRunner, self).run(test)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/runner.py", line 176, in run
    test(result)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/suite.py", line 122, in run
    test(result)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/case.py", line 663, in __call__
    return self.run(*args, **kwds)
  File "/Users/base/stem/stem/util/test_tools.py", line 258, in run
    result = super(type(self), self).run(result)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/case.py", line 615, in run
    testMethod()
  File "/Users/base/stem/test/require.py", line 58, in wrapped
    return func(self, *args, **kwargs)
  File "/Users/base/stem/test/require.py", line 58, in wrapped
    return func(self, *args, **kwargs)
  File "/Users/base/stem/test/integ/control/controller.py", line 538, in test_with_invalid_ephemeral_hidden_service_port
    self.assertRaisesWith(stem.ProtocolError, exc_msg, controller.create_ephemeral_hidden_service, ports)
  File "/Users/base/stem/stem/util/test_tools.py", line 288, in assertRaisesWith
    return self.assertRaisesRegexp(exc_type, '^%s$' % re.escape(exc_msg), func, *args, **kwargs)
  File "/Users/base/stem/stem/util/test_tools.py", line 298, in assertRaisesRegexp
    return super(original_type, self).assertRaisesRegexp(exc_type, exc_msg, func, *args, **kwargs)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/case.py", line 1338, in deprecated_func
    return original_func(*args, **kwargs)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/case.py", line 1285, in assertRaisesRegex
    return context.handle('assertRaisesRegex', args, kwargs)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/case.py", line 178, in handle
    callable_obj(*args, **kwargs)
  File "/Users/base/stem/stem/control.py", line 3099, in create_ephemeral_hidden_service
    response = self.msg(request)
  File "/Users/base/stem/stem/control.py", line 654, in msg
    response = self._reply_queue.get()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/queue.py", line 170, in get
    self.not_empty.wait()
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 296, in wait
    waiter.acquire()

The control.controller test doesn't hang for me, but the stacktrace looks promising.

Trac:
Status: new to assigned
Owner: atagar to teor

Trac:
Status: assigned to needs_review

I tried testing this in #30117 (moved).

We'll need to propagate the signal to the child processes to get a good backtrace. And we might need a backtrace in non-test processes as well.

This is a great patch, thanks teor! Moved this a tad but otherwise looks perfect. Merged.

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

Setting as sponsor 31 can, because we use these jobs to make sure our refactoring works.

Trac:
Sponsor: N/A to Sponsor31-can

closed

mentioned in issue #30117 (moved)

mentioned in issue #29437 (moved)

mentioned in issue tpo/core/tor#30117 (closed)