[SIP Beyond VoIP] Sylkserver logging exception issue
Dan Pascu
dan at ag-projects.com
Mon Aug 5 11:02:39 CEST 2019
Thanks for the detailed analysis. For the moment I'm swamped by other things I need to do, but I'll get back to check this later when I have the time.
On 26 Jul 2019, at 14:51, Penelope Vennisse wrote:
> 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.
>
> 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:
> - Connect to SylkServer from our WebRTC Client and create an account using account-add.
> - Create a new conference with session-create and perform ICE negotiation with session-trickle. The session is established successfully.
> - Wait for 2-3 hours.
> 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.
>
> 1. The one we described before - the cropped traceback mentioning python logging:
>
> Traceback (most recent call last):
> File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit
>
> 2. A Twisted error reporting a stack overflow:
>
> CRITICAL [twisted] Unhandled Error
> CRITICAL [twisted] Traceback (most recent call last):
> CRITICAL [twisted] File "/usr/lib/python2.7/threading.py", line 754, in run
> CRITICAL [twisted] self.__target(*self.__args, **self.__kwargs)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/application.py", line 141, in _run_reactor
> CRITICAL [twisted] reactor.run(installSignalHandlers=False)
> CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1272, in run
> CRITICAL [twisted] self.mainLoop()
> CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1281, in mainLoop
> CRITICAL [twisted] self.runUntilCurrent()
> CRITICAL [twisted] --- <exception caught here> ---
> CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 902, in runUntilCurrent
> CRITICAL [twisted] call.func(*call.args, **call.kw)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/api.py", line 241, in _spawn
> CRITICAL [twisted] g.switch()
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/api.py", line 237, in _spawn_startup
> CRITICAL [twisted] return cb(*args, **kw)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/threading/green.py", line 85, in wrapped_func
> CRITICAL [twisted] event.send_exception(*sys.exc_info())
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/coros.py", line 203, in send_exception
> CRITICAL [twisted] return self.send(None, args)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/coros.py", line 190, in send
> CRITICAL [twisted] hub.schedule_call_global(0, self._do_send, self._result, self._exc, self._waiters.keys())
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/hubs/twistedr.py", line 174, in schedule_call_global
> CRITICAL [twisted] return callLater(DelayedCall, reactor, seconds, func, *args, **kwargs)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/hubs/twistedr.py", line 62, in callLater
> CRITICAL [twisted] seconds=reactor.seconds)
> CRITICAL [twisted] exceptions.RuntimeError: maximum recursion depth exceeded while calling a Python object
> CRITICAL [twisted]
>
> 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:
>
> sys.setrecursionlimit(0x10000)
>
> After these changes, we could no longer reproduce either of the errors.
>
> 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.
>
> CRITICAL [twisted] Unhandled Error
> CRITICAL [twisted] Traceback (most recent call last):
> CRITICAL [twisted] File "/usr/lib/python2.7/threading.py", line 754, in run
> CRITICAL [twisted] self.__target(*self.__args, **self.__kwargs)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/application.py", line 141, in _run_reactor
> CRITICAL [twisted] reactor.run(installSignalHandlers=False)
> CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1267, in run
> CRITICAL [twisted] self.mainLoop()
> CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 1276, in mainLoop
> CRITICAL [twisted] self.runUntilCurrent()
> CRITICAL [twisted] --- <exception caught here> ---
> CRITICAL [twisted] File "/usr/local/lib/python2.7/dist-packages/twisted/internet/base.py", line 902, in runUntilCurrent
> CRITICAL [twisted] call.func(*call.args, **call.kw)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/coros.py", line 253, in _do_acquire
> CRITICAL [twisted] waiter.switch()
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/eventlib/api.py", line 237, in _spawn_startup
> CRITICAL [twisted] return cb(*args, **kw)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/threading/green.py", line 83, in wrapped_func
> CRITICAL [twisted] result = func(*args, **kw)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/audio.py", line 513, in _run
> CRITICAL [twisted] notification_center.post_notification('WavePlayerDidStart', sender=self)
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/application/notification.py", line 211, in post_notification
> CRITICAL [twisted] observer.handle_notification(notification)
> CRITICAL [twisted] File "<string>", line 1, in handle_notification
> CRITICAL [twisted]
> CRITICAL [twisted] File "/usr/lib/python2.7/dist-packages/sipsimple/threading/__init__.py", line 106, in wrapper
> CRITICAL [twisted] func(*args, **kwargs)
> CRITICAL [twisted] File "/srv/sylkserver/sylk/applications/conference/room.py", line 835, in handle_notification
> CRITICAL [twisted] log.error(u'[MoH] Handling notification')
> CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1193, in error
> CRITICAL [twisted] self._log(ERROR, msg, args, **kwargs)
> CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1286, in _log
> CRITICAL [twisted] self.handle(record)
> CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1296, in handle
> CRITICAL [twisted] self.callHandlers(record)
> CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 1336, in callHandlers
> CRITICAL [twisted] hdlr.handle(record)
> CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 759, in handle
> CRITICAL [twisted] self.emit(record)
> CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 889, in emit
> CRITICAL [twisted] self.handleError(record)
> CRITICAL [twisted] File "/usr/lib/python2.7/logging/__init__.py", line 812, in handleError
> CRITICAL [twisted] None, sys.stderr)
> CRITICAL [twisted] File "/usr/lib/python2.7/traceback.py", line 125, in print_exception
> CRITICAL [twisted] print_tb(tb, limit, file)
> CRITICAL [twisted] File "/usr/lib/python2.7/traceback.py", line 69, in print_tb
> CRITICAL [twisted] line = linecache.getline(filename, lineno, f.f_globals)
> CRITICAL [twisted] File "/usr/lib/python2.7/linecache.py", line 14, in getline
> CRITICAL [twisted] lines = getlines(filename, module_globals)
> CRITICAL [twisted] exceptions.RuntimeError: maximum recursion depth exceeded
> CRITICAL [twisted]
>
> Here, the offending log line is
>
> log.error(u'[MoH] Handling notification')
>
> 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.
>
> We were able to reproduce the issue with the latest stable software versions that we could get, namely:
> - SylkServer v5.2.0
> - python-sipsimple v3.4.2
> - python-application v2.7.0
> - python-twisted v19.2.0
> - Python v2.7.13
> - libwebsockets - the latest version from the v3.1 stable branch
> - libnice v0.1.16
> - Janus Gateway v0.7.3
>
> Our Linux system info:
> Operating System: Debian GNU/Linux 9 (stretch)
> Kernel: Linux 4.9.0-6-amd64
>
> 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.
>
> _______________________________________________
> SIPBeyondVoIP mailing list
> SIPBeyondVoIP at lists.ag-projects.com
> https://lists.ag-projects.com/mailman/listinfo/sipbeyondvoip
--
Dan
More information about the SIPBeyondVoIP
mailing list