channels: Cant see traceback

Hey guys 🙂 ,

I think I found what’s the issue 🔥 🎉

So, what I did:

1. I created a super basic django project (as @carltongibson suggested) and start reproducing the bug - https://github.com/HackSoftware/django-channels-playground
2. I couldn’t reproduce in this clean state ❌
3. So I reproduce it in the project we first hit it and started slicing things from the code
4. I turned out that django-debug-toolbar was causing the issue in our case 😦 So it’s not a channels issue

I searched in the other issues and found this - https://github.com/django/channels/issues/1193 (there’s a suggested quickfix there)

I started debugging the django-debug-toolbar code to find the root of the problem and turned out that this class is causing it - https://github.com/jazzband/django-debug-toolbar/blob/87eb27ffb2d0aea60b8b139360ece4d9fc91b47e/debug_toolbar/utils.py#L222

It’s used by a code hooked to the python logging module and collects only the logs from the current thread (which channels is not part from) 😞

https://github.com/django/channels/issues/1340#issuecomment-539957522 - this was solving the problem because the print is forcing a message to the standart output rather than using the python logging module

Hope this will help someone ^

Same here

backend:

WebSocket HANDSHAKING /webrtc/ [127.0.0.1:38882]
WebSocket DISCONNECT /webrtc/ [127.0.0.1:38882]
WebSocket HANDSHAKING /webrtc/ [127.0.0.1:39086]
WebSocket DISCONNECT /webrtc/ [127.0.0.1:39086]
WebSocket HANDSHAKING /webrtc/ [127.0.0.1:39114]
WebSocket DISCONNECT /webrtc/ [127.0.0.1:39114]
WebSocket HANDSHAKING /webrtc/ [127.0.0.1:39208]
WebSocket DISCONNECT /webrtc/ [127.0.0.1:39208]

frontend:

WebSocket connection to 'ws://localhost:8000/webrtc/' failed: Error during WebSocket handshake: Unexpected response code: 500

We’re not using the debug toolbar. However, it certainly could be an issue with other middleware.

+1 have problem

Hi @Ivo-Donchev — Thanks for the follow-up! Super. (I’ll leave this open for now, because I want to step through it myself when I have the moment.)

OK, so there’s clearly logging lacking here.

Question: if you dig-in, or use @Ivo-Donchev’s suggestion, where are the errors occurring? Can we add logging in the right places there to surface the issues?

(Anyone want to put together a minimal project that replicates this that we can play with?)

We just ran into a comparable issue. On a test system, it was due to a missing HOSTS entry for the Redis server. We’re seeing the same behavior on a prototype production system but it sounds like what we’re seeing is so non-specific that the actual error could be pretty much anything in the consumer.

EDIT: To be clear, we’re getting the slightly more interesting:

24.13.66.23:443 - - [22/Oct/2019:11:31:12] "WSCONNECTING /ws" - -
24.13.66.23:443 - - [22/Oct/2019:11:31:12] "WSCONNECT /ws" - -
24.13.66.23:443 - - [22/Oct/2019:11:31:12] "WSDISCONNECT /ws" - -
# ... rinse repeate

EDIT2: In our prototype production instance (AWS), the problem was that TransitEncyption defaults to “true” in the Elasticache Redis template we were using. We weren’t using rediss:// and were accessing the server using a CNAME that didn’t match the certificate.

Obviously, the details are less important than the fact that none of these error are bubbling up into logging (Django or otherwise).

I’m having the same issue: if anything inside the socket fails there’s no stacktrace in the logs.

@LukenAgile42 We’ve implemented a really simple class decorator (just for easier debugging locally) that basically catches any exception inside the current class and prints the stacktrace:

def debuggable_function_decorator(func):
    from functools import wraps
    import traceback

    @wraps(func)
    def wrapper(*arg, **kwargs):
        try:
            return func(*arg, **kwargs)
        except Exception as exc:
            print(traceback.format_exc())
            raise

    return wrapper


def debuggable_class_decorator(cls):
    for attr, value in vars(cls).items():
        if callable(value):
            setattr(cls, attr, debuggable_function_decorator(value))

    return cls


class debugmeta(type):
    def __new__(cls, clsname, bases, clsdict):
        return debuggable_class_decorator(
            super().__new__(cls, clsname, bases, clsdict)
        )


class SomeConsumer(metaclass=debugmeta, JsonWebsocketConsumer):
    pass

However it would be great if someone take a look ! 🙂