Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

docker-compose built with python2 hangs in write() when writing logs to stderr (PyRDP's default) #175

Closed
obilodeau opened this issue Jan 14, 2020 · 11 comments
Closed

docker-compose built with python2 hangs in write() when writing logs to stderr (PyRDP's default) #175

obilodeau opened this issue Jan 14, 2020 · 11 comments
Labels
bug Something isn't working workaround A workaround exists for this bug

Comments

@obilodeau
Copy link
Member

obilodeau commented Jan 14, 2020 •
edited
Loading

Update

tl;dr: Run a docker-compose version that is built using Python 3 when running PyRDP in long-term mitm mode

Also, this thread contains numerous tips to debug and troubleshoot PyRDP when experiencing hard to reproduce problems.

Original description

Using current master, pyrdp-mitm hangs in the docker container. Sending a HUP signal doesn't crash or give a stracktrace which means that it could be a bug outside of the python code itself.

Sending a KILL signal from outside the container seemingly stalled the whole container. Next time I'll try from inside the container.

#174 could help debugging the issue.
@obilodeau obilodeau added the bug Something isn't working label Jan 14, 2020
@obilodeau obilodeau mentioned this issue Jan 17, 2020
Merged
@obilodeau
Copy link
Member Author

Yesterday morning I deployed the new container with twistd support and the hang reproduced. I didn't manage to get the debugger running in time (had a meeting).

This morning I figured out how to do so and got very quickly something unexpected:

> /usr/local/lib/python3.6/dist-packages/twisted/internet/asyncioreactor.py(266)run()
-> self.startRunning(installSignalHandlers=installSignalHandlers)
(Pdb) c
[2020-01-23 15:36:23,274] - INFO - Dora902450 - pyrdp.mitm.connections.tcp - New client connected from 1xx.xx.xxx.5
[2020-01-23 15:36:23,282] - INFO - Dora902450 - pyrdp.mitm.connections.x224 - Cookie: mstshash=hello
[2020-01-23 15:36:23,329] - INFO - Dora902450 - pyrdp.mitm.connections.tcp - Server connected
Jumping into debugger for post-mortem of exception '(-1, 'Unexpected EOF')':
> /usr/local/lib/python3.6/dist-packages/OpenSSL/SSL.py(1664)_raise_ssl_error()
-> raise SysCallError(-1, "Unexpected EOF")
(Pdb) bt
  /usr/local/lib/python3.6/dist-packages/twisted/protocols/tls.py(274)_flushReceiveBIO()
-> bytes = self._tlsConnection.recv(2 ** 15)
  /usr/local/lib/python3.6/dist-packages/OpenSSL/SSL.py(1809)recv()
-> self._raise_ssl_error(self._ssl, result)
> /usr/local/lib/python3.6/dist-packages/OpenSSL/SSL.py(1664)_raise_ssl_error()
-> raise SysCallError(-1, "Unexpected EOF")

I'm getting these non-stop. Like every few seconds. I wonder what the debug mode changes so that these trip the debugger but usually not.

@obilodeau
Copy link
Member Author

This seems related to bad client implementation and/or client/server incompatibilities. We get a ton of these every few seconds and found no easy way of skipping these so I need to switch strategies here.

I considered patching SSL.py to return pass instead of raising on that specific error but patching a container is difficult. @alxbl found about the faulthandler module and I'm giving this a shot.

@obilodeau
Copy link
Member Author

Trying to use faulthandler with Python's environment variable. With docker-compose, just add:

    environment:
      - PYTHONFAULTHANDLER=1

Then send a SIGABRT to the process when it is not responsive and check the docker logs.

@obilodeau
Copy link
Member Author

Process was hung again today. Sending the signal didn't produce the expected stacktrace. It points to a Python bug. Trying to attach to it with gdb gave this warning:

warning: Target and debugger are in different PID namespaces; thread lists and other data are likely unreliable.  Connect to gdbserver inside the container.

Going in the container to debug:

docker-compose exec --privileged -u root pyrdp bash
apt-get update
apt-get install gdb python3-dbg
gdb --pid 1

Running threads:

(gdb) info threads
  Id   Target Id         Frame 
* 1    Thread 0x7fe4d7243740 (LWP 1) "twistd" 0x00007fe4d6d48154 in __GI___libc_write (fd=2, buf=0x74aa80, nbytes=2)
    at ../sysdeps/unix/sysv/linux/write.c:27

Backtrace:

(gdb) bt
#0  0x00007fe4d6d48154 in __GI___libc_write (fd=2, buf=0x74aa80, nbytes=2) at ../sysdeps/unix/sysv/linux/write.c:27
#1  0x0000000000632106 in _Py_write_impl (gil_held=0, count=2, buf=0x74aa80, fd=2) at ../Python/fileutils.c:1346
#2  _Py_write_noraise () at ../Python/fileutils.c:1406
#3  0x00000000004a69a0 in faulthandler_fatal_error (signum=6) at ../Modules/faulthandler.c:350
#4  <signal handler called>
#5  0x00007fe4d6d48154 in __GI___libc_write (fd=2, buf=0x192eec0, nbytes=115) at ../sysdeps/unix/sysv/linux/write.c:27
#6  0x00000000004cb9b0 in _Py_write_impl (gil_held=1, count=<optimized out>, buf=0x192eec0, fd=2)
    at ../Python/fileutils.c:1331
#7  _Py_write (count=<optimized out>, buf=0x192eec0, fd=2) at ../Python/fileutils.c:1393
#8  _io_FileIO_write_impl (b=<optimized out>, b=<optimized out>, self=<optimized out>) at ../Modules/_io/fileio.c:857
#9  _io_FileIO_write.lto_priv.1161 () at ../Modules/_io/clinic/fileio.c.h:251
#10 0x00000000005673b1 in _PyCFunction_FastCallDict () at ../Objects/methodobject.c:209
#11 0x00000000005a5611 in _PyObject_FastCallDict () at ../Objects/abstract.c:2313
#12 0x00000000005a670a in PyObject_CallMethodObjArgs () at ../Objects/abstract.c:2759
#13 0x00000000004cd1e7 in _bufferedwriter_raw_write (len=115, start=<optimized out>, self=<optimized out>)
    at ../Objects/memoryobject.c:767
#14 _bufferedwriter_flush_unlocked (self=0x7fe4d723db48) at ../Modules/_io/bufferedio.c:1898
#15 buffered_flush_and_rewind_unlocked () at ../Modules/_io/bufferedio.c:827
#16 0x00000000004ce726 in buffered_flush.lto_priv () at ../Modules/_io/bufferedio.c:854
#17 0x00000000005674ca in _PyCFunction_FastCallDict () at ../Objects/methodobject.c:192
#18 0x00000000005a5611 in _PyObject_FastCallDict () at ../Objects/abstract.c:2313
#19 0x00000000005a68ce in callmethod (is_size_t=1, va=0x7ffebb7a7cc0, format=0x0, 
    func=<built-in method flush of _io.BufferedWriter object at remote 0x7fe4d723db48>) at ../Objects/abstract.c:2583
#20 _PyObject_CallMethodId_SizeT () at ../Objects/abstract.c:2685
#21 0x000000000050abe1 in _PyCFunction_FastCallDict (kwargs=<optimized out>, nargs=<optimized out>, 
    args=0x7fe4c645d7a0, func_obj=<built-in method flush of _io.TextIOWrapper object at remote 0x7fe4d71ea708>)
    at ../Objects/methodobject.c:192
#22 _PyCFunction_FastCallKeywords (kwnames=<optimized out>, nargs=<optimized out>, stack=<optimized out>, 
    func=<optimized out>) at ../Objects/methodobject.c:294
#23 call_function.lto_priv () at ../Python/ceval.c:4851
#24 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#25 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c645d618, for file /usr/lib/python3.6/logging/__init__.py, line 978, in flush (self=<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea708>) at remote 0x7fe4d3471748>)) at ../Python/ceval.c:754
#26 _PyFunction_FastCall (globals=<optimized out>, nargs=140620555736600, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#27 fast_function.lto_priv () at ../Python/ceval.c:4968
#28 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#29 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#30 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x2529968, for file /usr/lib/python3.6/logging/__init__.py, line 998, in emit (self=<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea708>) at remote 0x7fe4d3471748>, record=<LogRecord(name='pyrdp.mitm.connections.tcp', msg='New client connected from %(clientIp)s', args={'clientIp': '8x.xx.xx.xxx'}, levelname='INFO', levelno=20, pathname='/pyrdp/pyrdp/mitm/TCPMITM.py', filename='TCPMITM.py', module='TCPMITM', exc_info=None, exc_text=None, stack_info=None, lineno=81, funcName='onClientConnection', created=<float at remote 0x7fe4c66bf8a0>, msecs=<float at remote...(truncated)) at ../Python/ceval.c:754
#31 _PyFunction_FastCall (globals=<optimized out>, nargs=38967656, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#32 fast_function.lto_priv () at ../Python/ceval.c:4968
#33 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#34 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#35 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0,
    f=Frame 0x7fe4d1d60848, for file /usr/lib/python3.6/logging/__init__.py, line 865, in handle (self=<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote
0x7fe4d71ea708>) at remote 0x7fe4d3471748>, record=<LogRecord(name='pyrdp.mitm.connections.tcp', msg='New client connected from %(clientIp)s', args={'clientIp': '8x.xx.xx.xxx'}, levelname='INFO', levelno=20, pathname='/pyrdp/pyrdp/mitm/TCPMITM.py', filename='TCPMITM.py', module='TCPMITM', exc_info=None, exc_text=None, stack_info=None, lineno=81, funcName='onClientConnection', created=<float at remote 0x7fe4c66bf8a0>, msecs=<float at...(truncated)) at ../Python/ceval.c:754
#36 _PyFunction_FastCall (globals=<optimized out>, nargs=140620749736008, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#37 fast_function.lto_priv () at ../Python/ceval.c:4968
#38 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#39 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#40 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0,
    f=Frame 0x7fe4c6482b58, for file /usr/lib/python3.6/logging/__init__.py, line 1516, in callHandlers (self=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea708>) at remote...(truncated)) at ../Python/ceval.c:754
#41 _PyFunction_FastCall (globals=<optimized out>, nargs=140620555889496, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#42 fast_function.lto_priv () at ../Python/ceval.c:4968
#43 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#44 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#45 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0,
    f=Frame 0x7fe4c640c048, for file /usr/lib/python3.6/logging/__init__.py, line 1454, in handle (self=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea708>) at remote 0x7fe...(truncated)) at ../Python/ceval.c:754
#46 _PyFunction_FastCall (globals=<optimized out>, nargs=140620555403336, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#47 fast_function.lto_priv () at ../Python/ceval.c:4968
#48 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#49 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#50 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0,
    f=Frame 0x25b6b58, for file /usr/lib/python3.6/logging/__init__.py, line 1444, in _log (self=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea708>) at remote 0x7fe4d34717...(truncated)) at ../Python/ceval.c:754
#51 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#52 0x0000000000509642 in _PyFunction_FastCallDict () at ../Python/ceval.c:5075
#53 0x0000000000595311 in _PyObject_FastCallDict (kwargs={'extra': {'sessionID': 'Buck678195'}}, nargs=4, 
    args=0x7ffebb7a8ab0, func=<function at remote 0x7fe4d3bb6510>) at ../Objects/abstract.c:2310
#54 _PyObject_Call_Prepend (kwargs={'extra': {'sessionID': 'Buck678195'}}, args=<optimized out>, obj=<optimized out>, 
    func=<function at remote 0x7fe4d3bb6510>) at ../Objects/abstract.c:2373
#55 method_call.lto_priv () at ../Objects/classobject.c:314
#56 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#57 0x000000000050d966 in do_call_core (kwdict={'extra': {'sessionID': 'Buck678195'}}, 
    callargs=(20, 'New client connected from %(clientIp)s', ({'clientIp': '8x.xx.xx.xxx'},)), 
    func=<method at remote 0x7fe4c61283c8>) at ../Python/ceval.c:5120
#58 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#59 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c645ab88, for file /usr/lib/python3.6/logging/__init__.py, line 1374, in log (self=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea708>) at remote 0x7fe4d3...(truncated)) at ../Python/ceval.c:754
#60 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#61 0x0000000000509642 in _PyFunction_FastCallDict () at ../Python/ceval.c:5075
#62 0x0000000000595311 in _PyObject_FastCallDict (kwargs={'extra': {'sessionID': 'Buck678195'}}, nargs=4, 
    args=0x7ffebb7a8e30, func=<function at remote 0x7fe4d3bb6378>) at ../Objects/abstract.c:2310
#63 _PyObject_Call_Prepend (kwargs={'extra': {'sessionID': 'Buck678195'}}, args=<optimized out>, obj=<optimized out>, 
    func=<function at remote 0x7fe4d3bb6378>) at ../Objects/abstract.c:2373
#64 method_call.lto_priv () at ../Objects/classobject.c:314
#65 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#66 0x000000000050d966 in do_call_core (kwdict={'extra': {'sessionID': 'Buck678195'}}, 
    callargs=(20, 'New client connected from %(clientIp)s', {'clientIp': '8x.xx.xx.xxx'}), 
    func=<method at remote 0x7fe4c631cf48>) at ../Python/ceval.c:5120
#67 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#68 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c6482980, for file /usr/lib/python3.6/logging/__init__.py, line 1674, in log (self=<SessionLogger(logger=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea70...(truncated)) at ../Python/ceval.c:754
#69 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#70 0x0000000000509642 in _PyFunction_FastCallDict () at ../Python/ceval.c:5075
#71 0x0000000000595311 in _PyObject_FastCallDict (kwargs={}, nargs=4, args=0x7ffebb7a91b0, 
    func=<function at remote 0x7fe4d3bb7048>) at ../Objects/abstract.c:2310
#72 _PyObject_Call_Prepend (kwargs={}, args=<optimized out>, obj=<optimized out>,     func=<function at remote 0x7fe4d3bb7048>) at ../Objects/abstract.c:2373
#73 method_call.lto_priv () at ../Objects/classobject.c:314
#74 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#75 0x000000000050d966 in do_call_core (kwdict={}, 
    callargs=(20, 'New client connected from %(clientIp)s', {'clientIp': '8x.xx.xx.xxx'}), 
    func=<method at remote 0x7fe4c6232408>) at ../Python/ceval.c:5120
#76 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#77 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c64785b8, for file /usr/lib/python3.6/logging/__init__.py, line 1636, in info (self=<SessionLogger(logger=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0x7fe4d71ea7...(truncated)) at ../Python/ceval.c:754
#78 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#79 0x000000000050a080 in fast_function.lto_priv () at ../Python/ceval.c:4992
#80 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#81 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#82 0x0000000000509455 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c6469d30, for file /pyrdp/pyrdp/mitm/TCPMITM.py, line 81, in onClientConnection (self=<TCPMITM(statCounter=<StatCounter(stats={'report': <float at remote 0x7fe4d2f09b88>, 'connectionTime': <float at remote 0x7fe4c66bf858>}) at remote 0x7fe4c62eceb8>, client=<TwistedTCPLayer(log=<SessionLogger(logger=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {nam...(truncated)) at ../Python/ceval.c:754
#83 _PyFunction_FastCall (globals=<optimized out>, nargs=<optimized out>, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#84 _PyFunction_FastCallDict () at ../Python/ceval.c:5035
#85 0x0000000000595311 in _PyObject_FastCallDict (kwargs={}, nargs=1, args=0x7ffebb7a9720, 
    func=<function at remote 0x7fe4c66c56a8>) at ../Objects/abstract.c:2310
#86 _PyObject_Call_Prepend (kwargs={}, args=<optimized out>, obj=<optimized out>, 
    func=<function at remote 0x7fe4c66c56a8>) at ../Objects/abstract.c:2373
#87 method_call.lto_priv () at ../Objects/classobject.c:314
#88 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#89 0x000000000050d966 in do_call_core (kwdict={}, callargs=(), func=<method at remote 0x7fe4c6232288>)
    at ../Python/ceval.c:5120
#90 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#91 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x2779c88, for file /pyrdp/pyrdp/core/observer.py, line 56, in doCall (self=<CompositeObserver(observers=[<TCPObserver(peer=None, onConnection=<method at remote 0x7fe4c6232288>, onDisconnection=<method at remote 0x7fe4c62322c8>) at remote 0x7fe4c6205c18>]) at remote 0x7fe4c62ec860>, item='onConnection', args=(), kwargs={}, observer=<...>))
    at ../Python/ceval.c:754
#92 _PyFunction_FastCall (globals=<optimized out>, nargs=41393288, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#93 fast_function.lto_priv () at ../Python/ceval.c:4968
#94 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#95 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#96 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0,     f=Frame 0x257cb38, for file /pyrdp/pyrdp/core/observer.py, line 82, in __call__ (self=<CompositeObserverCall(composite=<CompositeObserver(observers=[<TCPObserver(peer=None, onConnection=<method at remote 0x7fe4c6232288>, onDisconnection=<method at remote 0x7fe4c62322c8>) at remote 0x7fe4c6205c18>]) at remote 0x7fe4c62ec860>, item='onConnection') at remote 0x7fe4c62ec588>, args=(), kwargs={})) at ../Python/ceval.c:754
#97 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#98 0x0000000000509642 in _PyFunction_FastCallDict () at ../Python/ceval.c:5075
#99 0x0000000000595311 in _PyObject_FastCallDict (kwargs=0x0, nargs=1, args=0x7ffebb7a9c90, 
    func=<function at remote 0x7fe4d143d0d0>) at ../Objects/abstract.c:2310
#100 _PyObject_Call_Prepend (kwargs=0x0, args=<optimized out>, obj=<optimized out>, 
    func=<function at remote 0x7fe4d143d0d0>) at ../Objects/abstract.c:2373
#101 method_call.lto_priv () at ../Objects/classobject.c:314
#102 0x000000000054b1e1 in PyObject_Call (kwargs=0x0, args=(), func=<method at remote 0x7fe4c6363788>)
    at ../Objects/abstract.c:2261
#103 slot_tp_call () at ../Objects/typeobject.c:6207
#104 0x00000000005aa6ec in _PyObject_FastCallDict (kwargs=<optimized out>, nargs=0, args=0x1fc4800, 
    func=<CompositeObserverCall(composite=<CompositeObserver(observers=[<TCPObserver(peer=None, onConnection=<method at remote 0x7fe4c6232288>, onDisconnection=<method at remote 0x7fe4c62322c8>) at remote 0x7fe4c6205c18>]) at remote 0x7fe4c62ec860>, item='onConnection') at remote 0x7fe4c62ec588>) at ../Objects/tupleobject.c:131
#105 _PyObject_FastCallKeywords () at ../Objects/abstract.c:2496
#106 0x000000000050abb3 in call_function.lto_priv () at ../Python/ceval.c:4875
#107 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#108 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x1fc4678, for file /pyrdp/pyrdp/layer/tcp.py, line 61, in connectionMade (self=<TwistedTCPLayer(log=<SessionLogger(logger=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4d1fb4b70>, stream=<_io.TextIOWrapper at remote 0...(truncated)) at ../Python/ceval.c:754
#109 _PyFunction_FastCall (globals=<optimized out>, nargs=33310328, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#110 fast_function.lto_priv () at ../Python/ceval.c:4968
#111 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#112 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#113 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c64827a8, for file /usr/local/lib/python3.6/dist-packages/twisted/internet/protocol.py, line 514, in makeConnection (self=<TwistedTCPLayer(log=<SessionLogger(logger=<Logger(filters=[], name='pyrdp.mitm.connections.tcp', level=0, parent=<Logger(filters=[], name='pyrdp.mitm.connections', level=0, parent=<Logger(filters=[], name='pyrdp.mitm', level=0, parent=<Logger(filters=[], name='pyrdp', level=10, parent=<RootLogger(filters=[], name='root', level=30, parent=None, propagate=True, handlers=[], disabled=False) at remote 0x7fe4d3bad7f0>, propagate=True, handlers=[<StreamHandler(filters=[<LoggerNameFilter(name='', nlen=0) at remote 0x7fe4d3471fd0>], _name=None, level=20, formatter=<VariableFormatter(_style=<StrFormatStyle(_fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}') at remote 0x7fe4d34717b8>, _fmt='[{asctime}] - {levelname} - {sessionID} - {name} - {message}', datefmt=None, defaultVariables={'sessionID': 'GLOBAL'}) at remote 0x7fe4d3471a90>, lock=<_thread.RLock at remote 0x7fe4...(truncated)) at ../Python/ceval.c:754
#114 _PyFunction_FastCall (globals=<optimized out>, nargs=140620555888552, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#115 fast_function.lto_priv () at ../Python/ceval.c:4968
#116 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#117 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#118 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x250b888, for file /usr/local/lib/python3.6/dist-packages/twisted/internet/tcp.py, line 1435, in doRead (self=<Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at rem...(truncated)) at ../Python/ceval.c:754
#119 _PyFunction_FastCall (globals=<optimized out>, nargs=38844552, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#120 fast_function.lto_priv () at ../Python/ceval.c:4968
#121 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#122 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#123 0x0000000000509455 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x255b028, for file /usr/local/lib/python3.6/dist-packages/twisted/internet/asyncioreactor.py, line 136, in _readOrWrite (self=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at r...(truncated)) at ../Python/ceval.c:754
#124 _PyFunction_FastCall (globals=<optimized out>, nargs=<optimized out>, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#125 _PyFunction_FastCallDict () at ../Python/ceval.c:5035
#126 0x0000000000595311 in _PyObject_FastCallDict (kwargs={}, nargs=3, args=0x7ffebb7aa590, 
    func=<function at remote 0x7fe4d4ccc400>) at ../Objects/abstract.c:2310
#127 _PyObject_Call_Prepend (kwargs={}, args=<optimized out>, obj=<optimized out>, 
    func=<function at remote 0x7fe4d4ccc400>) at ../Objects/abstract.c:2373
#128 method_call.lto_priv () at ../Objects/classobject.c:314
#129 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#130 0x000000000050d966 in do_call_core (kwdict={}, 
    callargs=(<Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remote 0x7fe4c6249620>, 27: <SelectorKey at remote 0x7fe4c6249af0>}, _map=<_SelectorMapping(_selector=<...>) at remote ...(truncated), 
    func=<method at remote 0x7fe4d71f5448>) at ../Python/ceval.c:5120
#131 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#132 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x2602ba8, for file /usr/local/lib/python3.6/dist-packages/twisted/python/context.py, line 85, in callWithContext (self=<ContextTracker(contexts=[{<type at remote 0x1b8e9f8>: {'system': '-'}}, {<type at remote 0x1b8e9f8>: {'system': 'pyrdp.core.mitm.MITMServerFactory'}}]) at remote 0x7fe4d1dc65f8>, newContext={...}, func=<method at remote 0x7fe4d71f5448>, args=(<Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shut...(truncated)) at ../Python/ceval.c:754
#133 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#134 0x0000000000509642 in _PyFunction_FastCallDict () at ../Python/ceval.c:5075
#135 0x0000000000595311 in _PyObject_FastCallDict (kwargs={}, nargs=5, args=0x7ffebb7aa910, 
    func=<function at remote 0x7fe4d3eaeea0>) at ../Objects/abstract.c:2310
#136 _PyObject_Call_Prepend (kwargs={}, args=<optimized out>, obj=<optimized out>, 
    func=<function at remote 0x7fe4d3eaeea0>) at ../Objects/abstract.c:2373
#137 method_call.lto_priv () at ../Objects/classobject.c:314
#138 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#139 0x000000000050d966 in do_call_core (kwdict={}, 
    callargs=({<type at remote 0x1b8e9f8>: {'system': 'pyrdp.core.mitm.MITMServerFactory'}}, <method at remote 0x7fe4d71f5448>, <Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remot...(truncated), func=<method at remote 0x7fe4c62f2b08>) at ../Python/ceval.c:5120
#140 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#141 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x2608d88, for file /usr/local/lib/python3.6/dist-packages/twisted/python/context.py, line 122, in callWithContext (self=<ThreadedContextTracker(storage=<_thread._local at remote 0x7fe4d3eb8468>) at remote 0x7fe4d3eb6c88>, ctx={<type at remote 0x1b8e9f8>: {'system': 'pyrdp.core.mitm.MITMServerFactory'}}, func=<method at remote 0x7fe4d71f5448>, args=(<Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=...(truncated)) at ../Python/ceval.c:754
#142 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#143 0x0000000000509642 in _PyFunction_FastCallDict () at ../Python/ceval.c:5075
#144 0x0000000000595311 in _PyObject_FastCallDict (kwargs={}, nargs=5, args=0x7ffebb7aac90, 
    func=<function at remote 0x7fe4d3e3f158>) at ../Objects/abstract.c:2310
#145 _PyObject_Call_Prepend (kwargs={}, args=<optimized out>, obj=<optimized out>, 
    func=<function at remote 0x7fe4d3e3f158>) at ../Objects/abstract.c:2373
#146 method_call.lto_priv () at ../Objects/classobject.c:314
#147 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#148 0x000000000050d966 in do_call_core (kwdict={}, 
    callargs=({<type at remote 0x1b8e9f8>: {'system': 'pyrdp.core.mitm.MITMServerFactory'}}, <method at remote 0x7fe4d71f5448>, <Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remot...(truncated), 
    func=<method at remote 0x7fe4d5d32a88>) at ../Python/ceval.c:5120
#149 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#150 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x26d1f18, for file /usr/local/lib/python3.6/dist-packages/twisted/python/log.py, line 86, in callWithContext (ctx={'system': 'pyrdp.core.mitm.MITMServerFactory'}, func=<method at remote 0x7fe4d71f5448>, args=(<Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <Selecto...(truncated)) at ../Python/ceval.c:754
#151 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#152 0x0000000000589471 in PyEval_EvalCodeEx (closure=<optimized out>, kwdefs=<optimized out>, defcount=0, defs=0x0, 
    kwcount=0, kws=0x7fe4d7203060, argcount=<optimized out>, args=0x7fe4c622c8d0, locals=0x0, 
    globals=<optimized out>, _co=<optimized out>) at ../Python/ceval.c:4187
#153 function_call.lto_priv () at ../Objects/funcobject.c:604
#154 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#155 0x000000000050d966 in do_call_core (kwdict={}, 
    callargs=({'system': 'pyrdp.core.mitm.MITMServerFactory'}, <method at remote 0x7fe4d71f5448>, <Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remote 0x7fe4c6249620>, 27: <Select...(truncated), 
    func=<function at remote 0x7fe4d3eaebf8>) at ../Python/ceval.c:5120
#156 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#157 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x26df738, for file /usr/local/lib/python3.6/dist-packages/twisted/python/log.py, line 103, in callWithLogger (logger=<Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey...(truncated)) at ../Python/ceval.c:754
#158 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#159 0x00000000005893bb in PyEval_EvalCodeEx (closure=<optimized out>, kwdefs=<optimized out>, defcount=0, defs=0x0, 
    kwcount=0, kws=0x0, argcount=<optimized out>, args=0x7fe4c6458470, locals=0x0, globals=<optimized out>, 
    _co=<optimized out>) at ../Python/ceval.c:4187
#160 function_call.lto_priv () at ../Objects/funcobject.c:604
#161 0x00000000005a067e in PyObject_Call () at ../Objects/abstract.c:2261
#162 0x000000000050d966 in do_call_core (kwdict=0x0, 
    callargs=(<Port(reactor=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remote 0x7fe4c6249620>, 27: <SelectorKey at remote 0x7fe4c6249af0>}, _map=<_SelectorMapping(_selector=<...>) at remote ...(truncated), 
    func=<function at remote 0x7fe4d3e5f2f0>) at ../Python/ceval.c:5120
#163 _PyEval_EvalFrameDefault () at ../Python/ceval.c:3404
#164 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x2664ba8, for file /usr/lib/python3.6/asyncio/events.py, line 145, in _run (self=<Handle at remote 0x7fe4c6447b88>)) at ../Python/ceval.c:754
#165 _PyFunction_FastCall (globals=<optimized out>, nargs=40258472, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#166 fast_function.lto_priv () at ../Python/ceval.c:4968
#167 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#168 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#169 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x26a1e78, for file /usr/lib/python3.6/asyncio/base_events.py, line 1451, in _run_once (self=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remote 0x7fe4c6249620>, 27: <SelectorKey at remote 0x7fe4c6249af0>}, _map=<_S...(truncated)) at ../Python/ceval.c:754
#170 _PyFunction_FastCall (globals=<optimized out>, nargs=40509048, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#171 fast_function.lto_priv () at ../Python/ceval.c:4968
#172 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#173 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#174 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c645f848, for file /usr/lib/python3.6/asyncio/base_events.py, line 438, in run_forever (self=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remote 0x7fe4c6249620>, 27: <SelectorKey at remote 0x7fe4c6249af0>}, _m...(truncated)) at ../Python/ceval.c:754
#175 _PyFunction_FastCall (globals=<optimized out>, nargs=140620555745352, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#176 fast_function.lto_priv () at ../Python/ceval.c:4968
#177 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#178 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#179 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c64633c8, for file /usr/local/lib/python3.6/dist-packages/twisted/internet/asyncioreactor.py, line 267, in run (self=<AsyncioSelectorReactor(_asyncioEventloop=<_UnixSelectorEventLoop(_timer_cancelled_count=0, _closed=False, _stopping=False, _ready=<collections.deque at remote 0x7fe4d18884c0>, _scheduled=[], _default_executor=None, _internal_fds=1, _thread_id=140620838745920, _clock_resolution=<float at remote 0x7fe4d2f09678>, _exception_handler=None, _debug=False, slow_callback_duration=<float at remote 0x7fe4d2f09468>, _current_handle=None, _task_factory=None, _coroutine_wrapper_set=False, _asyncgens=<WeakSet(data=set(), _remove=<function at remote 0x7fe4d1da4840>, _pending_removals=[], _iterating=set()) at remote 0x7fe4d1dc6da0>, _asyncgens_shutdown_called=False, _selector=<EpollSelector(_fd_to_key={4: <SelectorKey at remote 0x7fe4d1874fc0>, 6: <SelectorKey at remote 0x7fe4d4cd6048>, 14: <SelectorKey at remote 0x7fe4c644a888>, 15: <SelectorKey at remote 0x7fe4c644a8e0>, 17: <SelectorKey at remot...(truncated)) at ../Python/ceval.c:754
#180 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#181 0x000000000050a080 in fast_function.lto_priv () at ../Python/ceval.c:4992
#182 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#183 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#184 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x25209a8, for file /usr/local/lib/python3.6/dist-packages/twisted/application/app.py, line 312, in runReactorWithLogging (config=<ServerOptions(stdout=<_io.TextIOWrapper at remote 0x7fe4d71ea630>, opts=<...>, defaults={'savestats': 0, 'no_save': 0, 'encrypted': 0, 'nodaemon': 0, 'originalname': 0, 'syslog': 0, 'euid': 0, 'logfile': None, 'logger': None, 'profile': None, 'profiler': 'cprofile', 'file': 'twistd.tap', 'python': None, 'source': None, 'rundir': '.', 'prefix': 'twisted', 'pidfile': 'twistd.pid', 'chroot': None, 'uid': None, 'gid': None, 'umask': None}, longOpt=['savestats', 'no_save', 'encrypted', 'nodaemon', 'originalname', 'syslog', 'euid', 'logfile=', 'logger=', 'profile=', 'profiler=', 'file=', 'python=', 'source=', 'rundir=', 'prefix=', 'pidfile=', 'chroot=', 'uid=', 'gid=', 'umask=', 'help', 'version', 'help-reactors', 'reactor=', 'debug', 'spew'], shortOpt='oenl:p:f:y:s:d:u:g:r:b', docs={'savestats': 'save the Stats object rather than the text output of the profiler.', 'no_save': 'do ...(truncated)) at ../Python/ceval.c:754
#185 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#186 0x000000000050a080 in fast_function.lto_priv () at ../Python/ceval.c:4992
#187 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#188 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#189 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4c6451bb8, for file /usr/local/lib/python3.6/dist-packages/twisted/application/app.py, line 399, in startReactor (self=<UnixApplicationRunner(config=<ServerOptions(stdout=<_io.TextIOWrapper at remote 0x7fe4d71ea630>, opts=<...>, defaults={'savestats': 0, 'no_save': 0, 'encrypted': 0, 'nodaemon': 0, 'originalname': 0, 'syslog': 0, 'euid': 0, 'logfile': None, 'logger': None, 'profile': None, 'profiler': 'cprofile', 'file': 'twistd.tap', 'python': None, 'source': None, 'rundir': '.', 'prefix': 'twisted', 'pidfile': 'twistd.pid', 'chroot': None, 'uid': None, 'gid': None, 'umask': None}, longOpt=['savestats', 'no_save', 'encrypted', 'nodaemon', 'originalname', 'syslog', 'euid', 'logfile=', 'logger=', 'profile=', 'profiler=', 'file=', 'python=', 'source=', 'rundir=', 'prefix=', 'pidfile=', 'chroot=', 'uid=', 'gid=', 'umask=', 'help', 'version', 'help-reactors', 'reactor=', 'debug', 'spew'], shortOpt='oenl:p:f:y:s:d:u:g:r:b', docs={'savestats': 'save the Stats object rather than the text output of the pro...(truncated)) at ../Python/ceval.c:754
#190 _PyFunction_FastCall (globals=<optimized out>, nargs=140620555688888, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#191 fast_function.lto_priv () at ../Python/ceval.c:4968
#192 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#193 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#194 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x205ba58, for file /usr/local/lib/python3.6/dist-packages/twisted/scripts/_twistd_unix.py, line 268, in postApplication (self=<UnixApplicationRunner(config=<ServerOptions(stdout=<_io.TextIOWrapper at remote 0x7fe4d71ea630>, opts=<...>, defaults={'savestats': 0, 'no_save': 0, 'encrypted': 0, 'nodaemon': 0, 'originalname': 0, 'syslog': 0, 'euid': 0, 'logfile': None, 'logger': None, 'profile': None, 'profiler': 'cprofile', 'file': 'twistd.tap', 'python': None, 'source': None, 'rundir': '.', 'prefix': 'twisted', 'pidfile': 'twistd.pid', 'chroot': None, 'uid': None, 'gid': None, 'umask': None}, longOpt=['savestats', 'no_save', 'encrypted', 'nodaemon', 'originalname', 'syslog', 'euid', 'logfile=', 'logger=', 'profile=', 'profiler=', 'file=', 'python=', 'source=', 'rundir=', 'prefix=', 'pidfile=', 'chroot=', 'uid=', 'gid=', 'umask=', 'help', 'version', 'help-reactors', 'reactor=', 'debug', 'spew'], shortOpt='oenl:p:f:y:s:d:u:g:r:b', docs={'savestats': 'save the Stats object rather than the text output of the ...(truncated)) at ../Python/ceval.c:754
#195 _PyFunction_FastCall (globals=<optimized out>, nargs=33929816, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#196 fast_function.lto_priv () at ../Python/ceval.c:4968
#197 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#198 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#199 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x7fe4d1482c18, for file /usr/local/lib/python3.6/dist-packages/twisted/application/app.py, line 385, in run (self=<UnixApplicationRunner(config=<ServerOptions(stdout=<_io.TextIOWrapper at remote 0x7fe4d71ea630>, opts=<...>, defaults={'savestats': 0, 'no_save': 0, 'encrypted': 0, 'nodaemon': 0, 'originalname': 0, 'syslog': 0, 'euid': 0, 'logfile': None, 'logger': None, 'profile': None, 'profiler': 'cprofile', 'file': 'twistd.tap', 'python': None, 'source': None, 'rundir': '.', 'prefix': 'twisted', 'pidfile': 'twistd.pid', 'chroot': None, 'uid': None, 'gid': None, 'umask': None}, longOpt=['savestats', 'no_save', 'encrypted', 'nodaemon', 'originalname', 'syslog', 'euid', 'logfile=', 'logger=', 'profile=', 'profiler=', 'file=', 'python=', 'source=', 'rundir=', 'prefix=', 'pidfile=', 'chroot=', 'uid=', 'gid=', 'umask=', 'help', 'version', 'help-reactors', 'reactor=', 'debug', 'spew'], shortOpt='oenl:p:f:y:s:d:u:g:r:b', docs={'savestats': 'save the Stats object rather than the text output of the profiler.', ...(truncated)) at ../Python/ceval.c:754
#200 _PyFunction_FastCall (globals=<optimized out>, nargs=140620740439064, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#201 fast_function.lto_priv () at ../Python/ceval.c:4968
#202 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#203 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#204 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x1bfc418, for file /usr/local/lib/python3.6/dist-packages/twisted/scripts/twistd.py, line 25, in runApp (config=<ServerOptions(stdout=<_io.TextIOWrapper at remote 0x7fe4d71ea630>, opts=<...>, defaults={'savestats': 0, 'no_save': 0, 'encrypted': 0, 'nodaemon': 0, 'originalname': 0, 'syslog': 0, 'euid': 0, 'logfile': None, 'logger': None, 'profile': None, 'profiler': 'cprofile', 'file': 'twistd.tap', 'python': None, 'source': None, 'rundir': '.', 'prefix': 'twisted', 'pidfile': 'twistd.pid', 'chroot': None, 'uid': None, 'gid': None, 'umask': None}, longOpt=['savestats', 'no_save', 'encrypted', 'nodaemon', 'originalname', 'syslog', 'euid', 'logfile=', 'logger=', 'profile=', 'profiler=', 'file=', 'python=', 'source=', 'rundir=', 'prefix=', 'pidfile=', 'chroot=', 'uid=', 'gid=', 'umask=', 'help', 'version', 'help-reactors', 'reactor=', 'debug', 'spew'], shortOpt='oenl:p:f:y:s:d:u:g:r:b', docs={'savestats': 'save the Stats object rather than the text output of the profiler.', 'no_save': 'do not save state on...(truncated)) at ../Python/ceval.c:754
#205 _PyFunction_FastCall (globals=<optimized out>, nargs=29344792, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#206 fast_function.lto_priv () at ../Python/ceval.c:4968
#207 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#208 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#209 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x1bf9348, for file /usr/local/lib/python3.6/dist-packages/twisted/application/app.py, line 674, in run (runApp=<function at remote 0x7fe4d5d72488>, ServerOptions=<type at remote 0x1bf8398>, config=<ServerOptions(stdout=<_io.TextIOWrapper at remote 0x7fe4d71ea630>, opts=<...>, defaults={'savestats': 0, 'no_save': 0, 'encrypted': 0, 'nodaemon': 0, 'originalname': 0, 'syslog': 0, 'euid': 0, 'logfile': None, 'logger': None, 'profile': None, 'profiler': 'cprofile', 'file': 'twistd.tap', 'python': None, 'source': None, 'rundir': '.', 'prefix': 'twisted', 'pidfile': 'twistd.pid', 'chroot': None, 'uid': None, 'gid': None, 'umask': None}, longOpt=['savestats', 'no_save', 'encrypted', 'nodaemon', 'originalname', 'syslog', 'euid', 'logfile=', 'logger=', 'profile=', 'profiler=', 'file=', 'python=', 'source=', 'rundir=', 'prefix=', 'pidfile=', 'chroot=', 'uid=', 'gid=', 'umask=', 'help', 'version', 'help-reactors', 'reactor=', 'debug', 'spew'], shortOpt='oenl:p:f:y:s:d:u:g:r:b', docs={'savestats': 'save the Stats o...(truncated)) at ../Python/ceval.c:754
#210 _PyFunction_FastCall (globals=<optimized out>, nargs=29332296, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#211 fast_function.lto_priv () at ../Python/ceval.c:4968
#212 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#213 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#214 0x0000000000509d48 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x1aa4af8, for file /usr/local/lib/python3.6/dist-packages/twisted/scripts/twistd.py, line 31, in run ())
    at ../Python/ceval.c:754
#215 _PyFunction_FastCall (globals=<optimized out>, nargs=27937528, args=<optimized out>, co=<optimized out>)
    at ../Python/ceval.c:4933
#216 fast_function.lto_priv () at ../Python/ceval.c:4968
#217 0x000000000050aa7d in call_function.lto_priv () at ../Python/ceval.c:4872
#218 0x000000000050c5b9 in _PyEval_EvalFrameDefault () at ../Python/ceval.c:3335
#219 0x0000000000508245 in PyEval_EvalFrameEx (throwflag=0, 
    f=Frame 0x19100f8, for file /usr/local/bin/twistd, line 11, in <module> ()) at ../Python/ceval.c:754
#220 _PyEval_EvalCodeWithName.lto_priv.1836 () at ../Python/ceval.c:4166
#221 0x000000000050b403 in PyEval_EvalCodeEx (closure=0x0, kwdefs=0x0, defcount=0, defs=0x0, kwcount=0, kws=0x0, 
    argcount=0, args=0x0, locals=<optimized out>, globals=<optimized out>, _co=<optimized out>)
    at ../Python/ceval.c:4187
#222 PyEval_EvalCode (co=<optimized out>, globals=<optimized out>, locals=<optimized out>) at ../Python/ceval.c:731
#223 0x0000000000635222 in run_mod () at ../Python/pythonrun.c:1025
#224 0x00000000006352d7 in PyRun_FileExFlags () at ../Python/pythonrun.c:978
#225 0x0000000000638a8f in PyRun_SimpleFileExFlags () at ../Python/pythonrun.c:419
#226 0x0000000000638c65 in PyRun_AnyFileExFlags () at ../Python/pythonrun.c:81
#227 0x0000000000639631 in run_file (p_cf=0x7ffebb7ace0c, filename=<optimized out>, fp=<optimized out>)
    at ../Modules/main.c:340
#228 Py_Main () at ../Modules/main.c:810
#229 0x00000000004b0f40 in main (argc=14, argv=0x7ffebb7ad008) at ../Programs/python.c:69

Python backtrace:

(gdb) py-bt
Traceback (most recent call first):
  <built-in method write of _io.FileIO object at remote 0x7fe4d7180630>
  <built-in method flush of _io.BufferedWriter object at remote 0x7fe4d723db48>
  <built-in method flush of _io.TextIOWrapper object at remote 0x7fe4d71ea708>
  File "/usr/lib/python3.6/logging/__init__.py", line 978, in flush
    self.stream.flush()
  File "/usr/lib/python3.6/logging/__init__.py", line 998, in emit
    self.flush()
  File "/usr/lib/python3.6/logging/__init__.py", line 865, in handle
    self.emit(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1516, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1454, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1444, in _log
    self.handle(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1374, in log
    self._log(level, msg, args, **kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1674, in log
    self.logger.log(level, msg, *args, **kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1636, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/pyrdp/pyrdp/mitm/TCPMITM.py", line 81, in onClientConnection
    self.log.info("New client connected from %(clientIp)s", {"clientIp": ip})
  File "/pyrdp/pyrdp/core/observer.py", line 56, in doCall
    getattr(observer, item)(*args, **kwargs)
  File "/pyrdp/pyrdp/core/observer.py", line 82, in __call__
    self.composite.doCall(self.item, args, kwargs)
  File "/pyrdp/pyrdp/layer/tcp.py", line 61, in connectionMade
    self.observer.onConnection()
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/protocol.py", line 514, in makeConnection
    self.connectionMade()
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/tcp.py", line 1435, in doRead
    protocol.makeConnection(transport)
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/asyncioreactor.py", line 136, in _readOrWrite
    why = method()
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/local/lib/python3.6/dist-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/lib/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/usr/lib/python3.6/asyncio/base_events.py", line 1451, in _run_once
    handle._run()
  File "/usr/lib/python3.6/asyncio/base_events.py", line 438, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.6/dist-packages/twisted/internet/asyncioreactor.py", line 267, in run
    self._asyncioEventloop.run_forever()
  File "/usr/local/lib/python3.6/dist-packages/twisted/application/app.py", line 312, in runReactorWithLogging
    reactor.run()
  File "/usr/local/lib/python3.6/dist-packages/twisted/application/app.py", line 399, in startReactor
    self.config, oldstdout, oldstderr, self.profiler, reactor)
  File "/usr/local/lib/python3.6/dist-packages/twisted/scripts/_twistd_unix.py", line 268, in postApplication
    self.startReactor(None, self.oldstdout, self.oldstderr)
  File "/usr/local/lib/python3.6/dist-packages/twisted/application/app.py", line 385, in run
    self.postApplication()
  File "/usr/local/lib/python3.6/dist-packages/twisted/scripts/twistd.py", line 25, in runApp
    runner.run()
  File "/usr/local/lib/python3.6/dist-packages/twisted/application/app.py", line 674, in run
    runApp(config)
  File "/usr/local/lib/python3.6/dist-packages/twisted/scripts/twistd.py", line 31, in run
    app.run(runApp, ServerOptions)
  File "/usr/local/bin/twistd", line 11, in <module>
    sys.exit(run())

Python code where we are stalled:

(gdb) py-list
 973            Flushes the stream.
 974            """
 975            self.acquire()
 976            try:
 977                if self.stream and hasattr(self.stream, "flush"):
>978                    self.stream.flush()
 979            finally:
 980                self.release()
 981    
 982        def emit(self, record):
 983            """

I'm not sure what to think of this. Is this our bug or an upstream bug?

@alxbl
Copy link
Collaborator

alxbl commented Jan 26, 2020 •
edited
Loading

I had a bit of time to read through the callstack and I think I have an idea of what the problem might be: @obilodeau mentioned while showing me the issue that the docker-compose output hung, depsite PyRDP still working properly.

The callstack for python is blocking in the FileIO.write method after flush() has been called, during logging of a new connection:

  <built-in method write of _io.FileIO object at remote 0x7fe4d7180630>         <----------------- Blocking Write
  <built-in method flush of _io.BufferedWriter object at remote 0x7fe4d723db48> <----------------- Flush to disk
  <built-in method flush of _io.TextIOWrapper object at remote 0x7fe4d71ea708>
  File "/usr/lib/python3.6/logging/__init__.py", line 978, in flush
    self.stream.flush()
  File "/usr/lib/python3.6/logging/__init__.py", line 998, in emit
    self.flush()
  File "/usr/lib/python3.6/logging/__init__.py", line 865, in handle
    self.emit(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1516, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1454, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1444, in _log
    self.handle(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1374, in log
    self._log(level, msg, args, **kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1674, in log
    self.logger.log(level, msg, *args, **kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1636, in info
    self.log(INFO, msg, *args, **kwargs)
  File "/pyrdp/pyrdp/mitm/TCPMITM.py", line 81, in onClientConnection
    self.log.info("New client connected from %(clientIp)s", {"clientIp": ip})  <-------------------------- New connection Logger
[...]

And looking at the native stack, we're stuck in libc's write() call as well, which is blocking.

#0  0x00007fe4d6d48154 in __GI___libc_write (fd=2, buf=0x74aa80, nbytes=2) at ../sysdeps/unix/sysv/linux/write.c:27
#1  0x0000000000632106 in _Py_write_impl (gil_held=0, count=2, buf=0x74aa80, fd=2) at ../Python/fileutils.c:1346
#2  _Py_write_noraise () at ../Python/fileutils.c:1406
#3  0x00000000004a69a0 in faulthandler_fatal_error (signum=6) at ../Modules/faulthandler.c:350
#4  <signal handler called> <--- Signal Interrupt after noticing the hang
#5  0x00007fe4d6d48154 in __GI___libc_write (fd=2, buf=0x192eec0, nbytes=115) at ../sysdeps/unix/sysv/linux/write.c:27

My theory is this: The docker-compose output stops flushing its stdout buffer, meaning that all the logs pile up in the buffer, eventually triggering the flush(), but since docker-compose is no longer flushing its stdout, write blocks forever.

The issue could be either the actual flushing to disk (I'm not sure if logging to disk is enabled?) or flushing to the docker-compose stdout.

Next Steps
I think we should start by disabling docker-compose logging and see if this fixes the issue. If it doesn't, then we'll have to investigate logging to disk.

@alxbl
Copy link
Collaborator

alxbl commented Jan 26, 2020

After a bit of searching through docker-compose issues, I've found this which has the exact same symptoms as us but on stderr. It's likely to be the issue we're experiencing. I would try running without log output to see if the issue still happens so that we can confirm the root cause.

docker/compose#6018

@alxbl alxbl changed the title Seemingly random hangs PyRDP hangs in write() when writing logs to stdout Jan 26, 2020
@obilodeau
Copy link
Member Author

Congrats @alxbl you found it! I still had a hung process being debugged by gdb at hand, I hit cont and I did:

$ tail -F /proc/<pid>/fd/2

and then the logging to mitm.json started resuming and I could connect to the mitm again! Note that tailing fd/1 didn't do anything. Also, tailing stderr doesn't return anything...?

Trying to think of a fix, I don't think it's going to be as simple as docker-compose up -d since docker logs are being filled in the background anyways.

I wonder why it's not happening with all the other containers that we run...

@alxbl
Copy link
Collaborator

alxbl commented Jan 26, 2020

I think PyRDP most likely doesn't output anything in stderr, so it's empty (or has been drained before the process blocked.) As for which containers are affected, we'll have to wait for a root-cause analysis from the compose team, or we could try the proposed fixes from the issue history (Although I haven't had the time to read through all of the history attentively yet.)

In any case we should keep an eye on the progress of the linked issue.

@alxbl alxbl changed the title PyRDP hangs in write() when writing logs to stdout PyRDP hangs in write() when writing logs to stderr Jan 27, 2020
@obilodeau
Copy link
Member Author

We looked more closely at the problem this morning with @alxbl. The StreamHandler configuration of PyRDP does log to stderr by default so the upstream docker-compose bug is valid. We can see that the parent process of PyRDP (containerd) connects stderr using a FIFO pipe. We are unsure why tailing stderr fixes the issue and yields no output but it does. In any case, clearly the write() is blocked because the pipe is full of unread logs.

Looking at the culprit commit highlighted by upstream bug: docker/docker-py@e9f31e1#diff-008bbf7c1c902c0264d9678151eadc64L26

We took a look at our docker-compose version running on that system:

# docker-compose version                                                                                                     
docker-compose version 1.23.2, build 1110ad0                                                                                                                   
docker-py version: 3.6.0                                                                                                                                       
CPython version: 2.7.17                                                                                                                                        
OpenSSL version: OpenSSL 1.1.1  11 Sep 2018

It is using Python 2. Taking a look at the current latest version:

# docker-compose version
docker-compose version 1.25.3, build d4d1b42b
docker-py version: 4.1.0
CPython version: 3.7.5
OpenSSL version: OpenSSL 1.1.0l  10 Sep 2019

Uses Python 3. So, for now, we are going to try to run it with this new upstream version and see if it fixes our problem.

@obilodeau
Copy link
Member Author

The process is still running on the server and logging requests. This looks good.

@obilodeau obilodeau added the workaround A workaround exists for this bug label Feb 3, 2020
@obilodeau
Copy link
Member Author

I'm considering this fixed now since there is an upstream fix where the problem is.

Workaround: Use a version of docker-compose built using Python 3 to avoid the upstream issue

@obilodeau obilodeau changed the title PyRDP hangs in write() when writing logs to stderr docker-compose built with python2 hangs in write() when writing logs to stderr (PyRDP's default) Feb 3, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working workaround A workaround exists for this bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@obilodeau @alxbl