Troubleshooting Django Channels channel_layer

TroubleshootingDjangoChannelschannel_layer.md

Troubleshooting Django Channels channel_layer

This post will focus on troubleshooting and debugging the channel layer of any Django Channels application. For this post a local Redis backend is used.

Initial Requirements

It is assumed for the purpose of this example that a working Django Channels application is running, and that a proxy service is running that is able to upgrade the HTTP connection to a WebSocket connection. A Redis server is also required.

The Example Application

For this example an Apache server is serving both Django as WSGI and Django Channels as a Reverse Proxy. For more on this check out earlier posts. We set up the Reverse Proxy in Apache by loading the proxy modules and passing the URLs "/proxy/" to our Channels backend as HTTP and "/ws/" as a WebSocket connection.

<VirtualHost *:80>
LoadModule proxy_module modules/mod_proxy.so
LoadModule proxy_http_module modules/mod_proxy_http.so
LoadModule proxy_wstunnel_module modules/mod_proxy_wstunnel.so
ProxyPass "/proxy/" "http://127.0.0.1:8080/"
ProxyPassReverse "/proxy/" "http://127.0.0.1:8080/"
ProxyPass "/ws/" "ws://127.0.0.1:8080/"
ProxyPassReverse "/ws/" "ws://127.0.0.1:8080/"
[...]

We create a consumer to handle HTTP requests and WebSocket messages and "echo" them straight back again.

def http_consumer(message):
    response = HttpResponse("Hello world! You asked for %s" % message.content['path'])
    for chunk in AsgiHandler.encode_response(response):
        message.reply_channel.send(chunk)

def ws_message(message):
    message.reply_channel.send({"text": 'server echo "%s" -- "%s"' % (message.content['path'], message.content['text'])})

and add the appropriate routes

route("http.request", consumers.http_consumer),
route("websocket.receive", consumers.ws_message, path=r"^/ws/echo/$"),

Setting up a Local Redis Server

Setting up a local Redis environment is as easy as following their installation guide.

Testing HTTP Connections

We are going to test the setup with a running and working Redis backend, a stopped Redis and a restarted Redis to see the different effects.

Working Setup

When the channel layer works as expected we can visit our server at /proxy/<any_url> and get the following expected result in the browser. and the log output

## Daphne log
[time] DEBUG HTTP GET request for http.response!HIMUSMhjxHpQ
[time] DEBUG HTTP 200 response started for http.response!HIMUSMhjxHpQ
[time] DEBUG HTTP close for http.response!HIMUSMhjxHpQ
[time] DEBUG HTTP response complete for http.response!HIMUSMhjxHpQ

## Workers log
[time] - DEBUG - worker - Got message on http.request (reply http.response!HIMUSMhjxHpQ)
[time] - DEBUG - runworker - http.request
[time] - DEBUG - worker - Dispatching message on http.request to chicago.consumers.http_consumer

Stopped Redis Server

We stop the server by running redis-cli shutdown and then visit our web server again at /proxy/<any_url>. We see that Django does not handle the request well and Apache responds with 502 (Proxy Error). The logs show a curious output. Daphne has not logged anything, but the workers raise an Exception (as expected).

## Daphne log
# Nothing to see in this log

## Workers log
[...]
redis.exceptions.ConnectionError: Error 111 connecting to 127.0.0.1:6379\. Connection refused.

Restarted Redis Server

We start the server again by redis-serve and visit our web server again to see if Daphne and the workers have recovered. Success! Both Daphne and the workers show no signs of ever having been affected.

Testing WebSocket Connections

Now it is time to test the WebSocket connections to see if they behave in a similar fassion to the HTTP connections.

Working Setup

With a test-page loaded on our server that can connect and serve websocket connection in JavaScript we try to connect, send, receive and close. Lines with the "$" prefix are print-outs from JS while ">"  are sent from the Django Channel backend. This setup works as expected.

## Daphne log
[time] DEBUG WebSocket open for websocket.send!DRJxHJtZXYPy
[time] DEBUG Upgraded connection http.response!iLTousObXJDR to WebSocket websocket.send!DRJxHJtZXYPy
[time] DEBUG WebSocket incoming frame on websocket.send!DRJxHJtZXYPy
[time] DEBUG Sent WebSocket packet to client for websocket.send!DRJxHJtZXYPy
[time] DEBUG Sent WebSocket packet to client for websocket.send!DRJxHJtZXYPy
[time] DEBUG WebSocket closed for websocket.send!DRJxHJtZXYPy

## Workers log
[time] - DEBUG - worker - Got message on websocket.connect (reply websocket.send!DRJxHJtZXYPy)
[time] - DEBUG - runworker - websocket.connect
[time] - DEBUG - worker - Dispatching message on websocket.connect to chicago.consumers.ws_connect
[time] - DEBUG - worker - Got message on websocket.receive (reply websocket.send!DRJxHJtZXYPy)
[time] - DEBUG - runworker - websocket.receive
[time] - DEBUG - worker - Dispatching message on websocket.receive to chicago.consumers.ws_message

Stopped Redis Server

When there is no active channel layer the JS WebSocket is not able to connect and prompts ERR_INVALID_HTTP_RESPONSE from Daphne.

WebSocket connection to 'ws://127.0.0.1:4567/ws/echo/?session_key=121uqdzg67atmefvxdqvehl8l8q6askq' failed: Error during WebSocket handshake: net::ERR_INVALID_HTTP_RESPONSE.

In the Daphne log on the other hand there is no sign that something is wrong. Only the workers raise an exception.

## Daphne log
# Nothing to see in this log

## Workers log
redis.exceptions.ConnectionError: Error 111 connecting to 127.0.0.1:6379\. Connection refused.

Restarted Redis Server

When the server is restarted and a websocket connection is attempted very little happens and very little information is offered. The JS socket seems open and a message is sent, but nothing is received. The Daphne and workers logs both show inadequate information.

## Daphne log
[time] DEBUG WebSocket open for websocket.send!jWITqUuvjjuW
[time] DEBUG Upgraded connection http.response!OmAPSNRwyajT to WebSocket websocket.send!jWITqUuvjjuW
[time] DEBUG WebSocket incoming frame on websocket.send!jWITqUuvjjuW

## Workers log
[time] - DEBUG - runworker - websocket.connect
[time] - DEBUG - worker - Dispatching message on websocket.connect to chicago.consumers.ws_connect
[time] - DEBUG - worker - Got message on websocket.receive (reply websocket.send!jWITqUuvjjuW)
[time] - DEBUG - runworker - websocket.receive
[time] - DEBUG - worker - Dispatching message on websocket.receive to chicago.consumers.ws_message
[time] - DEBUG - worker - Got message on websocket.connect (reply websocket.send!jWITqUuvjjuW)
[time] - DEBUG - runworker - websocket.connect
[time] - DEBUG - worker - Dispatching message on websocket.connect to chicago.consumers.ws_connect

It would seem that Daphne is able to send information to the channel layer which the workers are able to process and then return, but Daphne is in turn not able to read from the channel layer. When Daphne is restarted, everything is back to normal. This seems to be a bug in Daphne.

Conclusion

Now the question is: find and fix the bug in Daphne, or create a Supervisord config that is able to restart Daphne if Redis crashes? Update: A Supervisord solution is documented here.