Channels: using django with channels overrides django's logging configuration

[hoefling]

OS

$ uname -a
Linux lenovo-L440 4.9.7-gentoo #1 SMP Fri Feb 3 14:23:19 CET 2017 x86_64 Intel(R) Core(TM) i3-4100M CPU @ 2.50GHz GenuineIntel GNU/Linux

Runtime

$ emerge --info
Portage 2.3.3 (python 3.5.2-final-0, default/linux/amd64/13.0/desktop/plasma, gcc-5.4.0, glibc-2.23-r3, 4.9.7-gentoo x86_64)
=================================================================
System uname: Linux-4.9.7-gentoo-x86_64-Intel-R-_Core-TM-_i3-4100M_CPU_@_2.50GHz-with-gentoo-2.3
KiB Mem:     8064332 total,   1367052 free
KiB Swap:    8388604 total,   8388604 free
Timestamp of repository gentoo: Fri, 03 Feb 2017 19:30:01 +0000
sh bash 4.3_p48-r1
ld GNU ld (Gentoo 2.25.1 p1.1) 2.25.1
distcc 3.2rc1 x86_64-pc-linux-gnu [enabled]
app-shells/bash:          4.3_p48-r1::gentoo
dev-java/java-config:     2.2.0-r3::gentoo
dev-lang/perl:            5.22.3_rc4::gentoo
dev-lang/python:          2.7.12::gentoo, 3.5.2::gentoo, 3.6.0::gentoo
dev-util/cmake:           3.7.2::gentoo
dev-util/pkgconfig:       0.28-r2::gentoo
sys-apps/baselayout:      2.3::gentoo
sys-apps/openrc:          0.22.4::gentoo
sys-apps/sandbox:         2.10-r1::gentoo
sys-devel/autoconf:       2.13::gentoo, 2.69::gentoo
sys-devel/automake:       1.14.1::gentoo, 1.15::gentoo
sys-devel/binutils:       2.25.1-r1::gentoo
sys-devel/gcc:            5.4.0::gentoo
sys-devel/gcc-config:     1.7.3::gentoo
sys-devel/libtool:        2.4.6-r2::gentoo
sys-devel/make:           4.2.1::gentoo
sys-kernel/linux-headers: 4.4::gentoo (virtual/os-headers)
sys-libs/glibc:           2.23-r3::gentoo

Package versions

(venv) $ pip list
Package        Version
-------------- -------
appdirs        1.4.0  
asgiref        1.0.0  
autobahn       0.17.1 
channels       1.0.3  
constantly     15.1.0 
daphne         1.0.2  
Django         1.10.5 
incremental    16.10.1
packaging      16.8   
pip            9.0.1  
pyparsing      2.1.10 
setuptools     34.1.0 
six            1.10.0 
Twisted        16.6.0 
txaio          2.6.0  
wheel          0.29.0 
zope.interface 4.3.3

Now, here are the steps to reproduce from scratch:

$ virtualenv /tmp/venv --python=python3.5
$ source /tmp/venv/bin/activate
$ pip install django channels asgi-ipc
$ mkdir /tmp/channels-test
$ cd /tmp/channels-test
$ django-admin startproject myproj
$ cd myproj
$ # first example from django doc: https://docs.djangoproject.com/en/1.10/topics/logging/#examples
$ # a django root logger that prints to file only 
$ printf "LOGGING = {\n    \'version\': 1,\n    \'disable_existing_loggers\': False,\n    \'formatters\': {\n        \'verbose\': {\n            \'format\': \'%%(asctime)s : %%(levelname)s : %%(module)s : %%(message)s\'\n        },\n    },\n    \'handlers\': {\n        \'file\': {\n            \'level\': \'DEBUG\',\n            \'class\': \'logging.FileHandler\',\n            \'filename\': \'/tmp/server.log\',\n            \'formatter\': \'verbose\',\n        },\n    },\n    \'loggers\': {\n        \'django\': {\n            \'handlers\': [\'file\'],\n            \'level\': \'DEBUG\',\n            \'propagate\': True,\n        },\n    },\n}\n" >> myproj/settings.py
$ # turn off DEBUG, set ALLOWED_HOSTS
$ sed -i 's/DEBUG = True/DEBUG = False/; s/ALLOWED_HOSTS = \[\]/ALLOWED_HOSTS = ["*"]/' myproj/settings.py
$ # clean up old log, run server in bg. When server stops, print server log contents
$ rm -f /tmp/server.log && python manage.py runserver && printf "\n---- log file contents ---\n" && cat /tmp/server.log &
# server prints the greeting, all the logs will be written to log file
[1] 9038
Performing system checks...

System check identified no issues (0 silenced).

You have 13 unapplied migration(s). Your project may not work properly until you apply the migrations for app(s): admin, auth, contenttypes, sessions.
Run 'python manage.py migrate' to apply them.

February 03, 2017 - 21:22:33
Django version 1.10.5, using settings 'myproj.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
# make a request. Note that since the server doesn't log to console, nothing is printed 
$ curl -s http://127.0.0.1:8000/ > /dev/null
$ # kill the server now
$ fg
$ ^C
---- log file contents ---
2017-12-19 14:20:40,979 : WARNING : base : Not Found: /
2017-12-19 14:20:40,980 : WARNING : basehttp : "GET / HTTP/1.1" 404 74

This is the expected output (log contents). The request log line is found in file, correctly formatted. Now attach the channels app with some dummy settings:

$ # add channels to INSTALLED_APPS
$ sed -i "/django.contrib.staticfiles/a \ \ \ \ 'channels'," myproj/settings.py
$ # define some simple settings for channels
$ printf "\nCHANNEL_LAYERS = {\n    'default': {\n        'BACKEND': 'asgi_ipc.IPCChannelLayer',\n        'CONFIG': {\n            'prefix': 'dashboard-backend-dev',\n        },\n        'ROUTING': 'myproj.routing.channel_routing',\n    },\n}\n" >> myproj/settings.py
$ # write routing file
$ printf "from channels.routing import route\n\ndef ws_message(message):\n    message.reply_channel.send({\n        'text': message.content['text'],\n    })\n\nchannel_routing = [\n    route('websocket.receive', ws_message),\n]\n" > myproj/routing.py
$ # write asgi conf
$ printf "import os\nfrom channels.asgi import get_channel_layer\nos.environ.setdefault('DJANGO_SETTINGS_MODULE', 'myproj.settings')\nCHANNEL_LAYER = get_channel_layer()" > myproj/asgi.py

and run the same steps again:

$ python manage.py runworker &
$ rm -f /tmp/server.log && daphne -b 0.0.0.0 -p 8000 myproj.asgi:CHANNEL_LAYER && printf "\n---- log file contents ---\n" && cat /tmp/server.log &
2017-12-19 15:07:58,439 INFO     Starting server at tcp:port=8000:interface=0.0.0.0, channel layer myproj.asgi:CHANNEL_LAYER.
2017-12-19 15:07:58,440 INFO     HTTP/2 support not enabled (install the http2 and tls Twisted extras)
2017-12-19 15:07:58,441 INFO     Using busy-loop synchronous mode on channel layer
2017-12-19 15:07:58,441 INFO     Listening on endpoint tcp:port=8000:interface=0.0.0.0

First issue: channels prints on console instead of log file. Even worse:

$ curl -s http://127.0.0.1:8000/ > /dev/null
127.0.0.1:52516 - - [19/Dec/2017:15:08:06] "GET /" 404 74

The django server logger starts printing to console instead of the log file.

$ fg
^C
---- log file contents ---

The log line from above is missing in the log file.

[andrewgodwin]

This is deliberate - runserver is overridden so that logs go to the console as it's for development only. If you want to log to a file, you'll want to run Daphne standalone.

[thomasf]

I already log to the console using runserver but severely more compacted format with custom logger extensions (ansi colors and custom traceback highligting formatter) which now are ignored because of this overriding. Now everything looks like crap..

I think it's a lousy default,, Now I have to work around this imposed logging configuration..

[thomasf]

I just added this at the top of my manage.py, it will have to do for now,.,

import channels.log

def get_channels_logger(*args, **kwargs):
    return logging.getLogger("channels")

channels.log.setup_logger = get_channels_logger

edit: it doesnt work for anything but the first startup messages.. doh. I'll have to get back at it..

[hoefling]

Yepp, this was also the message I tried to broadcast. The logging to file was just an example; basically, once you add channels to the installed apps, you can forget django's logging configuration completely.

[andrewgodwin]

If you would like to see this fixed, patches are welcome - it's not as easy as just adding in logging configuration, though.

[thomasf]

Great!..

I will work something out after I've spent some time getting used to channels and have daphne running in production.

612 is also related to the issue of problematic logging behavior.