raiden icon indicating copy to clipboard operation
raiden copied to clipboard

Fix logging error of asyncio related exceptions in integration tests

Open ezdac opened this issue 4 years ago • 0 comments

Since quite some time, the integration tests show logging errors of WebRTC / asyncio related task failures (e.g. in this CI run )

This seems to happen in teardown of still pending coroutines related to asyncio (WebRTC, aioice). No matter if this is intended or not, the structlog handlers seem not to be able to log the exceptions properly:

--- Logging error ---
Traceback (most recent call last):
  File "/home/circleci/venv-3.7-LINUX/lib/python3.7/site-packages/structlog/stdlib.py", line 514, in format
    logger = self.logger if self.logger is not None else record._logger
AttributeError: 'LogRecord' object has no attribute '_logger'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1025, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 869, in format
    return fmt.format(record)
  File "/home/circleci/venv-3.7-LINUX/lib/python3.7/site-packages/structlog/stdlib.py", line 548, in format
    ed = proc(logger, meth_name, ed)
  File "/home/circleci/venv-3.7-LINUX/lib/python3.7/site-packages/structlog/processors.py", line 256, in __call__
    return self._stamper(event_dict)
  File "/home/circleci/venv-3.7-LINUX/lib/python3.7/site-packages/structlog/processors.py", line 301, in stamper_fmt
    event_dict[key] = now().strftime(fmt)
ImportError: sys.meta_path is None, Python is likely shutting down
Call stack:
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 1645, in call_exception_handler
    self.default_exception_handler(context)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 1619, in default_exception_handler
    logger.error('\n'.join(log_lines), exc_info=exc_info)
Message: 'Task was destroyed but it is pending!\ntask: <Task pending coro=<Connection.check_start() done, defined at /home/circleci/venv-3.7-LINUX/lib/python3.7/site-packages/aioice/ice.py:704> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fee20109d10>()]>>'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/logging/handlers.py", line 69, in emit
    if self.shouldRollover(record):
  File "/usr/local/lib/python3.7/logging/handlers.py", line 183, in shouldRollover
    self.stream = self._open()
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1116, in _open
    return open(self.baseFilename, self.mode, encoding=self.encoding)
NameError: name 'open' is not defined
Call stack:
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 1645, in call_exception_handler
    self.default_exception_handler(context)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 1619, in default_exception_handler
    logger.error('\n'.join(log_lines), exc_info=exc_info)
Message: 'Task was destroyed but it is pending!\ntask: <Task pending coro=<Connection.check_start() done, defined at /home/circleci/venv-3.7-LINUX/lib/python3.7/site-packages/aioice/ice.py:704> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fee20109d10>()]>>'
Arguments: ()

ezdac avatar Jan 26 '21 15:01 ezdac