exceptions swallowing

[marcinnformula]

Here is an exception swallowing antipattern used: https://github.com/python-websockets/websockets/blob/main/src/websockets/legacy/server.py#L251

The outer try-except catches the inner exception raised here: https://github.com/python-websockets/websockets/blob/main/src/websockets/legacy/server.py#L241

Unhandled exceptions should not be silenced. Programming with this library is hard due to this issue.

---

For async version the exception swallowing is implemented "by design" into Python: https://bugs.python.org/issue42526

So if the legacy server is removed, this issue may not be relevant anymore.

[aaugustin]

Are you raising this as a purely theoretical point? Or did you actually encounter an issue in practice? If you did encounter an issue, what was it?

In case you missed it — we don't have a caller to which we could propagate an exception due to the inversion of control pattern which is typical in servers. The only thing we can do is log the exception and this is happening on line 238, before re-raising it on line 241.

[marcinnformula]

I spent almost whole day on debugging silenced exceptions (due to my programming errors), then on finding how to make them "loud". I'm using async websockets server, so finally I took a advice to wrap handler with try..catch, and use traceback.print_exc there.

The websocket server runs in Django environment, so logging setup could be affected by Django project itself (I didn't verified this yet). I expected the server to crash (dunno why) when programming error / unhandled exception occurs, but this is not how asyncio works in Python. Other servers (like Django) works similar way, so "loud" error message should be fine. But it must be displayed somewhere. I got literally nothing today on my stdout, which confused me a lot.

The only thing we can do is log the exception and this is happening on line 238, before re-raising it on line 241.

Regardless of the above, it will be better than complete silence. But I'm afraid that logging can be silenced outside. I have no idea what to do best so that the developer always sees that there is an exception. Introduce debug mode and also print exceptions to stdout? Not sure...

[aaugustin]

Responsibility for this issue sits with Django's logging, not with websockets.

---

With an off-the-shelf logging setup, websockets does the right thing.

For example, if you run this server:

#!/usr/bin/env python

import asyncio
from websockets.server import serve

async def echo(websocket):
    CRASH

async def main():
    async with serve(echo, "localhost", 8765):
        await asyncio.Future()  # run forever

asyncio.run(main())

and then you make a connection, you get this output:

connection handler failed
Traceback (most recent call last):
  File "/Users/myk/dev/websockets/src/websockets/legacy/server.py", line 236, in handler
    await self.ws_handler(self)
  File "/Users/myk/dev/websockets/example/echo.py", line 7, in echo
    CRASH
NameError: name 'CRASH' is not defined

---

The way Django configures logging is, unfortunately, just wrong :-( In Django's defense, the design of the logging module doesn't help either.

If you read closely the documentation, you will find this sentence:

logger will still exist, but will silently discard anything logged to it, not even propagating entries to a parent logger

The docs painfully point out that you do NOT want that behavior... but you get it by default... which is very unfortunate... and that's the problem you're hitting.

I recommend LOGGING_CONFIG = None and configuring logging manually.

(For context I happen to know a bit about Django.)

[marcinnformula]

Yes, you're right. But other servers prints errors not only via logging. Django renders a html page with a traceback, when debug mode is enabled. Other servers returns traceback in a response to request. I would suggest not rely only on the logging.

Anyway, thanks for your effort and sorry for creating an issue not closely related to the project.

I recommend LOGGING_CONFIG = None and configuring logging manually.

In this case I can't. This is a already existing project with precise logging configuration.

[aaugustin]

PS - logs of Django's HTTP server don't suffer from this issue because Django configure its logging first and doesn't give a fuck about other libraries who may need to configure their logging too, knowing that the logging stdlib module doesn't really support reconfiguring logging (you run into the issue discussed above) 🤷

[aaugustin]

In this case I can't. This is a already existing project with precise logging configuration.

You can.

Replace:

LOGGING_CONFIG = {...}

with:

LOGGING_CONFIG = None

import logging.config
logging.config.basicConfig({...}

Here's an example from a random project of mine.

dev settings

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'stdout': {
            'format': '%(asctime)s %(name)s %(levelname)s %(message)s',
            'datefmt': '%Y-%m-%dT%H:%M:%S%z',
        },
    },
    'handlers': {
        'stdout': {
            'class': 'logging.StreamHandler',
            'formatter': 'stdout',
        },
    },
    'root': {
        'handlers': ['stdout'],
        'level': 'INFO',
    },
})

prod settings

logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'stdout': {
            'format': '%(asctime)s %(name)s %(levelname)s %(message)s',
            'datefmt': '%Y-%m-%dT%H:%M:%S%z',
        },
    },
    'handlers': {
        'stdout': {
            'class': 'logging.StreamHandler',
            'formatter': 'stdout',
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler'
        }
    },
    'root': {
        'handlers': ['stdout', 'mail_admins'],
        'level': 'INFO',
    },
})

[aaugustin]

Now, if you want a one-line fix, just add 'disable_existing_loggers': False, to your LOGGING_CONFIG and that should solve it!

[aaugustin]

(At least solve the worst of it.)

[marcinnformula]

PS - logs of Django's HTTP server don't suffer from this issue because Django [configure its logging first]

Yes. I don't like the way logging is configured in Django. I remember Pyramid, where you can set everything up just the way you want . Django won the battle, though ;)

[aaugustin]

;-)

[marcinnformula]

Now, if you want a one-line fix, just add 'disable_existing_loggers': False, to your LOGGING_CONFIG and that should solve it!

Wow! Many thanks for your time and examples! I didn't expect that. I will try to improve the logging config. But I really hate it ;)