[SIP Beyond VoIP] Sylkserver logging exception issue

Penelope Vennisse studio.pqv9 at gmail.com
Fri Jul 26 13:51:30 CEST 2019


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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ag-projects.com/pipermail/sipbeyondvoip/attachments/20190726/d1f494fb/attachment.html>


More information about the SIPBeyondVoIP mailing list