<div dir="ltr"><div dir="ltr">During the past couple of months, we saw the python
logging exception from our previous email several times, so we had a
good chance to analyze it further. We now seem to have found a stable
way to reproduce the problem. Please refer to some details below.<br><br>In
our setup, we use the SylkServer WebRTC Gateway in conjunction with
Janus and the SylkServer Conference application, to allow the WebRTC
Clients to join SIP conferences on SylkServer. To reproduce the issue we
do the following:<br>- Connect to SylkServer from our WebRTC Client and create an account using account-add.<br>-
Create a new conference with session-create and perform ICE negotiation
with session-trickle. The session is established successfully.<br>- Wait for 2-3 hours. <br>During
this time, the Conference application plays back some pre-recorded WAV
files from the Resources folder to the connected Client, since there is
only one participant in the conference. After this continues for a
couple of hours, a stack overflow happens. In our tests, we saw two
kinds of errors in the logs in the described situation.<br><br>1. The one we described before - the cropped traceback mentioning python logging:<span class="gmail-im"><br><br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Traceback (most recent call last):<br> File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit</blockquote><br></span>2. A Twisted error reporting a stack overflow:<br><br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">CRITICAL [twisted] Unhandled Error<br>CRITICAL [twisted] Traceback (most recent call last):<br>CRITICAL [twisted] File "/usr/lib/python2.7/threading.py", line 754, in run<br>CRITICAL [twisted] self.__target(*self.__args, **self.__kwargs)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/application.py", line 141, in _run_reactor<br>CRITICAL [twisted] reactor.run(installSignalHandlers=False)<br>CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1272, in run<br>CRITICAL [twisted] self.mainLoop()<br>CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1281, in mainLoop<br>CRITICAL [twisted] self.runUntilCurrent()<br>CRITICAL [twisted] --- <exception caught here> ---<br>CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 902, in runUntilCurrent<br>CRITICAL [twisted] call.func(*call.args, **<a href="http://call.kw" target="_blank">call.kw</a>)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/api.py", line 241, in _spawn<br>CRITICAL [twisted] g.switch()<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/api.py", line 237, in _spawn_startup<br>CRITICAL [twisted] return cb(*args, **kw)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/threading/green.py", line 85, in wrapped_func<br>CRITICAL [twisted] event.send_exception(*sys.exc_info())<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/coros.py", line 203, in send_exception<br>CRITICAL [twisted] return self.send(None, args)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/coros.py", line 190, in send<br>CRITICAL [twisted] hub.schedule_call_global(0, self._do_send, self._result, self._exc, self._waiters.keys())<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/hubs/twistedr.py", line 174, in schedule_call_global<br>CRITICAL [twisted] return callLater(DelayedCall, reactor, seconds, func, *args, **kwargs)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/hubs/twistedr.py", line 62, in callLater<br>CRITICAL [twisted] seconds=reactor.seconds)<br>CRITICAL [twisted] exceptions.RuntimeError: maximum recursion depth exceeded while calling a Python object<br>CRITICAL [twisted]</blockquote><br>To
confirm that the issue is a stack overflow in both cases, we tried
increasing the stack size limits for the SylkServer process. Namely, we
first changed the soft ulimit to infinity and added the following line
in the beginning of the sylk-server main function:<br><br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">sys.setrecursionlimit(0x10000)</blockquote><br>After these changes, we could no longer reproduce either of the errors.<br><br>We
also played a little bit with the SylkServer and Python-SIPSimple code,
added logs here and there, and removed a couple of exception handlers
trying to track down the problem. This resulted in the stack overflow
exceptions happening at the logging lines that we'd added. See one of
the Twisted tracebacks below as an example.<br><br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">CRITICAL [twisted] Unhandled Error<br>CRITICAL [twisted] Traceback (most recent call last):<br>CRITICAL [twisted] File "/usr/lib/python2.7/threading.py", line 754, in run<br>CRITICAL [twisted] self.__target(*self.__args, **self.__kwargs)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/application.py", line 141, in _run_reactor<br>CRITICAL [twisted] reactor.run(installSignalHandlers=False)<br>CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1267, in run<br>CRITICAL [twisted] self.mainLoop()<br>CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1276, in mainLoop<br>CRITICAL [twisted] self.runUntilCurrent()<br>CRITICAL [twisted] --- <exception caught here> ---<br>CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 902, in runUntilCurrent<br>CRITICAL [twisted] call.func(*call.args, **<a href="http://call.kw" target="_blank">call.kw</a>)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/coros.py", line 253, in _do_acquire<br>CRITICAL [twisted] waiter.switch()<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/api.py", line 237, in _spawn_startup<br>CRITICAL [twisted] return cb(*args, **kw)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/threading/green.py", line 83, in wrapped_func<br>CRITICAL [twisted] result = func(*args, **kw)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/audio.py", line 513, in _run<br>CRITICAL [twisted] notification_center.post_notification('WavePlayerDidStart', sender=self)<br>CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/application/notification.py", line 211, in post_notification<br>CRITICAL [twisted] observer.handle_notification(notification)<br>CRITICAL [twisted] File "<string>", line 1, in handle_notification<br>CRITICAL [twisted] <br> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/threading/__init__.py", line 106, in wrapper<br>CRITICAL [twisted] func(*args, **kwargs)<br>CRITICAL [twisted] File "/srv/sylkserver/sylk/applications/conference/room.py", line 835, in handle_notification<br>CRITICAL [twisted] log.error(u'[MoH] Handling notification')<br>CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1193, in error<br>CRITICAL [twisted] self._log(ERROR, msg, args, **kwargs)<br>CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1286, in _log<br>CRITICAL [twisted] self.handle(record)<br>CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1296, in handle<br>CRITICAL [twisted] self.callHandlers(record)<br>CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1336, in callHandlers<br>CRITICAL [twisted] hdlr.handle(record)<br>CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 759, in handle<br>CRITICAL [twisted] self.emit(record)<br>CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 889, in emit<br>CRITICAL [twisted] self.handleError(record)<br>CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 812, in handleError<br>CRITICAL [twisted] None, sys.stderr)<br>CRITICAL [twisted] File "/usr/lib/python2.7/traceback.py", line 125, in print_exception<br>CRITICAL [twisted] print_tb(tb, limit, file)<br>CRITICAL [twisted] File "/usr/lib/python2.7/traceback.py", line 69, in print_tb<br>CRITICAL [twisted] line = linecache.getline(filename, lineno, f.f_globals)<br>CRITICAL [twisted] File "/usr/lib/python2.7/linecache.py", line 14, in getline<br>CRITICAL [twisted] lines = getlines(filename, module_globals)<br>CRITICAL [twisted] exceptions.RuntimeError: maximum recursion depth exceeded<br>CRITICAL [twisted] </blockquote> <br>Here, the offending log line is<br> <br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">log.error(u'[MoH] Handling notification') </blockquote><br>that we have added to the 'sylk/applications/conference/room.py'
file in the handle_notification method. The SIPSimple WavePlayer _run
function is being executed, in particular, the 'WavePlayerDidStart' is
being posted.<br><br>We were able to reproduce the issue with the latest stable software versions that we could get, namely:<br>- SylkServer v5.2.0<br>- python-sipsimple v3.4.2<br>- python-application v2.7.0<br>- python-twisted v19.2.0<br>- Python v2.7.13<br>- libwebsockets - the latest version from the v3.1 stable branch<br>- libnice v0.1.16<br>- Janus Gateway v0.7.3<br><br>Our Linux system info:<br>Operating System: Debian GNU/Linux 9 (stretch)<br>Kernel: Linux 4.9.0-6-amd64<br><br>Hope
this information helps you locate and fix the problem. Let me know if
you have any questions or if any further info from us is required.</div><div dir="ltr"><br clear="all"></div></div>