Opened 19 months ago

Closed 19 months ago

Last modified 17 months ago

#30012 closed defect (implemented)

When stem receives a signal, log useful information

Reported by: teor Owned by: teor
Priority: Medium Milestone:
Component: Archived/Stem Version:
Severity: Normal Keywords: tor-needs
Cc: Actual Points:
Parent ID: #29437 Points:
Reviewer: Sponsor: Sponsor31-can


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

But that doesn't give us much information. To fix #29437, 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.)

Child Tickets

Change History (10)

comment:1 Changed 19 months ago by teor

Keywords: tor-ci-fail-sometimes added

comment:2 Changed 19 months ago by teor

Keywords: tor-ci-fail-sometimes removed

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

comment:3 Changed 19 months ago by teor

Parent ID: #29437

comment:4 Changed 19 months ago by atagar

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

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

comment:5 Changed 19 months ago by teor

Keywords: tor-needs added
Parent ID: #29437

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

comment:6 Changed 19 months ago by teor

Owner: changed from atagar to teor
Status: newassigned

See my pull request:

When I run:

$ make test-stem
$ killall -USR1 < pid>

I see:

  control.controller...                               Signal 30 received.
  File "/Users/base/stem/", line 398, in <module>
  File "/Users/base/stem/", line 239, in main
    run_result = _run_test(args, test_class, output_filters)
  File "/Users/base/stem/", line 379, in _run_test
    run_result = stem.util.test_tools.TimedTestRunner(test_results, verbosity = 2).run(suite)
  File "/Users/base/stem/stem/util/", 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/", line 176, in run
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/", line 84, in __call__
    return*args, **kwds)
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/", line 122, in run
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/unittest/", line 663, in __call__
    return*args, **kwds)
  File "/Users/base/stem/stem/util/", 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/", line 615, in run
  File "/Users/base/stem/test/", line 58, in wrapped
    return func(self, *args, **kwargs)
  File "/Users/base/stem/test/", line 58, in wrapped
    return func(self, *args, **kwargs)
  File "/Users/base/stem/test/integ/control/", 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/", line 288, in assertRaisesWith
    return self.assertRaisesRegexp(exc_type, '^%s$' % re.escape(exc_msg), func, *args, **kwargs)
  File "/Users/base/stem/stem/util/", 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/", 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/", 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/", line 178, in handle
    callable_obj(*args, **kwargs)
  File "/Users/base/stem/stem/", line 3099, in create_ephemeral_hidden_service
    response = self.msg(request)
  File "/Users/base/stem/stem/", 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/", line 170, in get
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/", line 296, in wait

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

comment:7 Changed 19 months ago by teor

Status: assignedneeds_review

comment:8 Changed 19 months ago by teor

I tried testing this in #30117.

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.

comment:9 Changed 19 months ago by atagar

Resolution: implemented
Status: needs_reviewclosed

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

comment:10 Changed 17 months ago by teor

Sponsor: Sponsor31-can

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

Note: See TracTickets for help on using tickets.