Runserver doesn't use `LOGGING` configuration

[Flavio Curella]

this is slightly related to https://code.djangoproject.com/ticket/25523

All output in core.servers.basehttp (and possibly fastcgi - I haven't checked that yet) uses sys.stderr.write, bypassing the logging subsystem.

In order to have it use the LOGGING settings, I can see 3 options:

a) make it always use logger.info(msg) and change the default LOGGING settings appropriately
b) make it always use both sys.stdout.write and logger.info
c) add an option to runserver to switch behaviour

I'm willing to work on the patch (in fact, I have option 2) already working), I just need to know if this is something we want and what direction we want to go.

[Carl Meyer]

I've always wondered why the runserver output didn't use logging; it seems like an obvious candidate for it. I may be missing something (in which case hopefully someone else will chime in), but it seems to me that option (a) -- replace stderr.write(...) with logging calls, and adjust the default logging config so they are still shown -- is the right one.

One reason I can think of why perhaps this hasn't been done is the color used to mark different response status codes in the runserver output? I would think it should be possible to preserve that with the right custom logging handler, though.

[Simon Charette]

I've always wondered why the runserver output didn't use logging; it seems like an obvious candidate for it. I may be missing something (in which case hopefully someone else will chime in), but it seems to me that option (a) -- replace stderr.write(...) with logging calls, and adjust the default logging config so they are still shown -- is the right one.

While I can find the exact discussion I remember there was concerns about performance.

One reason I can think of why perhaps this hasn't been done is the color used to mark different response status codes in the runserver output? I would think it should be possible to preserve that with the right custom logging handler, though.

Appropriate formatters should do!

[Tim Graham]

See also #21429 -- BaseCommand should use logging instead of custom output wrappers.

[Claude Paroz]

I guess the current behavior is simply due to Python itself using sys.stderr in http.server.BaseHTTPRequestHandler.log_message.

[Flavio Curella]

I've done some preliminary work on ​https://github.com/django/django/pull/5560

Let me know if anything problematic jumps to the eye, otherwise I can proceed with tests and docs.

[Flavio Curella]

Since runserver is not supposed to be used in production, I'm really concerned about performance. I've namespaced the logger so the formatter should never be called in production (assuming no-one uses runserver in production)

I've done some profiling anyway, and here are the results:

on master, DEBUG = False:

ab -k -n 15000 http://127.0.0.1:8000/:

Concurrency Level:      1
Time taken for tests:   22.961 seconds
Complete requests:      15000
Failed requests:        0
Non-2xx responses:      15000
Keep-Alive requests:    0
Total transferred:      3435000 bytes
HTML transferred:       1110000 bytes
Requests per second:    653.28 [#/sec] (mean)
Time per request:       1.531 [ms] (mean)
Time per request:       1.531 [ms] (mean, across all concurrent requests)
Transfer rate:          146.09 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       5
Processing:     1    1   0.4      1      29
Waiting:        1    1   0.3      1      28
Total:          1    2   0.4      1      29
ERROR: The median and mean for the total time are more than twice the standard
       deviation apart. These results are NOT reliable.

on master, DEBUG = True:

ab -k -n 15000 http://127.0.0.1:8000/:

Concurrency Level:      1
Time taken for tests:   23.380 seconds
Complete requests:      15000
Failed requests:        0
Keep-Alive requests:    0
Total transferred:      28725000 bytes
HTML transferred:       26505000 bytes
Requests per second:    641.57 [#/sec] (mean)
Time per request:       1.559 [ms] (mean)
Time per request:       1.559 [ms] (mean, across all concurrent requests)
Transfer rate:          1199.81 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       4
Processing:     1    1   0.8      1      98
Waiting:        1    1   0.8      1      98
Total:          1    2   0.8      1      98
WARNING: The median and mean for the total time are not within a normal deviation
        These results are probably not that reliable.

Post-patch, DEBUG = False:

ab -k -n 15000 http://127.0.0.1:8000/:

Concurrency Level:      1
Time taken for tests:   20.975 seconds
Complete requests:      15000
Failed requests:        0
Non-2xx responses:      15000
Keep-Alive requests:    0
Total transferred:      3435000 bytes
HTML transferred:       1110000 bytes
Requests per second:    715.14 [#/sec] (mean)
Time per request:       1.398 [ms] (mean)
Time per request:       1.398 [ms] (mean, across all concurrent requests)
Transfer rate:          159.93 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       5
Processing:     1    1   0.5      1      52
Waiting:        1    1   0.5      1      52
Total:          1    1   0.5      1      52

Post-patch, DEBUG = True:

ab -k -n 15000 http://127.0.0.1:8000/:

Concurrency Level:      1
Time taken for tests:   24.314 seconds
Complete requests:      15000
Failed requests:        0
Keep-Alive requests:    0
Total transferred:      28725000 bytes
HTML transferred:       26505000 bytes
Requests per second:    616.92 [#/sec] (mean)
Time per request:       1.621 [ms] (mean)
Time per request:       1.621 [ms] (mean, across all concurrent requests)
Transfer rate:          1153.71 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   1.3      0     139
Processing:     1    2   2.9      1     127
Waiting:        1    1   2.4      1     127
Total:          1    2   3.2      1     140

Note that the patch skips the formatter if DEBUG is False by using the require_debug_true filter.

Without the filter, the results are:

Post-patch, DEBUG = False, no filter:

ab -k -n 15000 http://127.0.0.1:8000/:

Concurrency Level:      1
Time taken for tests:   21.105 seconds
Complete requests:      15000
Failed requests:        0
Non-2xx responses:      15000
Keep-Alive requests:    0
Total transferred:      3435000 bytes
HTML transferred:       1110000 bytes
Requests per second:    710.72 [#/sec] (mean)
Time per request:       1.407 [ms] (mean)
Time per request:       1.407 [ms] (mean, across all concurrent requests)
Transfer rate:          158.94 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       6
Processing:     1    1   0.3      1      29
Waiting:        1    1   0.3      1      29
Total:          1    1   0.4      1      29

Post-patch, DEBUG = True, no filter:

ab -k -n 15000 http://127.0.0.1:8000/:

Concurrency Level:      1
Time taken for tests:   23.068 seconds
Complete requests:      15000
Failed requests:        0
Keep-Alive requests:    0
Total transferred:      28725000 bytes
HTML transferred:       26505000 bytes
Requests per second:    650.24 [#/sec] (mean)
Time per request:       1.538 [ms] (mean)
Time per request:       1.538 [ms] (mean, across all concurrent requests)
Transfer rate:          1216.02 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0      12
Processing:     1    1   0.5      1      59
Waiting:        1    1   0.5      1      59
Total:          1    2   0.6      1      59
WARNING: The median and mean for the total time are not within a normal deviation
        These results are probably not that reliable.

[Simon Charette]

Thanks for the benchmarks.

Here's ​the discussion I was referring to when I raised the performance argument point.

However, there's a cost - we'd be adding the requirement for a logging configuration for something that is only ever used during development. So we'd end up complicating the process of deploying the devserver, which is one of those things that is supposed to Just Work™ out of the box.

I *think* this would also mean losing the colorisation of devserver messages, and for me, colorisation of output of the devserver is a higher priority than the need to filter specific lines out of devserver output (don't quote me on this one though -- it might be possible to preserve colorisation. Some experimentation may be required).

It's also a feature that can be achieved using pipes and grep, which would be more in line with the broader Unix philosophy.

In summary: I don't personally see a particularly compelling case for this feature. However, the real test will be whether you can come up with an implementation that doesn't overly complicate the deployment of the devserver for the case that *most* users need it - a simple server that Just Works™.

#21949 is also a related ticket.

[Carl Meyer]

I don't actually see a performance concern mentioned there. There are three concerns:

1. Adding complexity to out-of-the-box local-dev experience. I think this is a non-issue, if the default logging config results in the same behavior we have currently. No additional setup should be needed.

2. Losing colorization of devserver messages. I agree this would be a problem, but as mentioned above we should be able to preserve this with a custom formatter.

3. "It's a feature that can be achieved with pipes and grep" -- this objection could apply to any use of the logging framework in Django. It doesn't really make sense to allow much of Django's logging output to be configured using Python's logging framework, but in this specific case prevent that and require using totally different techniques instead.

[Andrei Fokau]

It would be great if we could place the response code at the beginning of the log message ;)

so it is

[07/Nov/2015 17:37:05] HTTP/1.1 200 "GET /inbox/" 216874
[07/Nov/2015 17:37:05] HTTP/1.1 304 "GET /static/CACHE/css/f090a416387d.css" 0
[07/Nov/2015 17:37:05] HTTP/1.1 304 "GET /static/CACHE/css/df20af4b0d04.css" 0
[07/Nov/2015 17:37:05] HTTP/1.1 304 "GET /static/img/logo.svg" 0

instead of

[07/Nov/2015 17:37:05] "GET /inbox/ HTTP/1.1" 200 216874
[07/Nov/2015 17:37:05] "GET /static/CACHE/css/f090a416387d.css HTTP/1.1" 304 0
[07/Nov/2015 17:37:05] "GET /static/CACHE/css/df20af4b0d04.css HTTP/1.1" 304 0
[07/Nov/2015 17:37:05] "GET /static/img/logo.svg HTTP/1.1" 304 0

[Andrei Fokau]

It would also be great to have response time in the log message, see #25704

[Andrei Fokau]

1. I believe it would be better to use django.server instead of django.request.runserver for logger name:

INFO    django.server: [07/Nov/2015 20:38:22] "GET / HTTP/1.1" 200 2

vs

INFO    django.request.runserver: [07/Nov/2015 20:38:22] "GET / HTTP/1.1" 200 2

2. The date-time should probably not be a part of the message since it's usually configured in formatter. However, by default python logs without time info. Maybe LOGGING dict in global_settings.py can have django.server logging config...

2015-11-07 20:38:22,627 INFO  django.server: [07/Nov/2015 20:38:22] "GET / HTTP/1.1" 200 2

[Andrei Fokau]

I've just realized that this feature will finally allow to filter out 2xx/3xx static/media requests using logging filters instead of messing in the Django source code. This is great! :)

[Flavio Curella]

According to ​https://docs.djangoproject.com/en/1.8/topics/logging/#django-request-logger, the logger should be under django.request. Additionally, 4xx should warning and 5xx should be errors.

[Andrei Fokau]

As far as I see, django.request is used for application and we probably want to distinguish between those log messages and the ones made by server...

[Andrei Fokau]

I have moved server time in ​https://github.com/fcurella/django/pull/3 so it's not hardcoded in message and used in formatters format.

Discard my comment about global_settings, DEFAULT_LOGGING is the right place :)

[Flavio Curella]

As far as I see, django.request is used for application and we probably want to distinguish between those log messages and the ones made by server

That's the reason why I went with django.request.runserver instead of just django.request.

That said, we can pick a new namespace and update the docs accordingly. I'd like more consensus on which one to use.

[Andrei Fokau]

My changes are merged now and the log message is not changed with this PR, so the behavior is preserved and I think it's time to merge it as soon as we agree on the logger name.

I will play with the log message order and parts in #25704

[Flavio Curella]

I've noticed just now that Django 1.9 deprecates the django.request logger (​https://docs.djangoproject.com/en/1.9/releases/1.9/#changes-to-the-default-logging-configuration) , so we can use anything under django.*.

Any suggestion?

[Flavio Curella]

according to the ​release notes, Django 1.9 drops django.request, but the topic guide on logging ​still mentions it and does not mention the deprecation.

If I keep the logger name as django.request.runserver (or django.request), I'm invalidating the release note. If I change it to something else, I should proably remove that paragraph from the logging guide.

[Tim Graham]

You can still log using django.request -- they'll just propagate to the django logger. I'll give the PR a detailed review later as I am a bit swamped due to activity from Django Under the Hood sprints. :-)

[Claude Paroz]

What about logging to django.runserver? I don't see what we gain by using a sublogger of django.request. Those messages are for different components anyway.

[Tim Graham]

(I was advocating for either choice myself.)

[Andrei Fokau]

Wouldn't it feel strange if the logger has runserver in it's name? As I see it, user starts the server using runserver command. The logging is done by the server, not the command which started the server. The server could be started via something else, not related to runserver command. So django.server would fit better from my point of view and also looks/sounds better.

django.request deals with application level logging so using it (or its sublogger) for the server which runs the application is not what one would expect.

Personally, I don't see any disadvantage of django.server but since I am (seemingly) the only one advocating for it, I wonder why one would not prefer it?

[Andrei Fokau]

according to the ​release notes, Django 1.9 drops django.request, but the topic guide on logging ​still mentions it and does not mention the deprecation.

@fcurella, I believe Django 1.9 does not drop django.request, just skips special config for it, see #24526 and ​https://github.com/django/django/pull/4389/

[Claude Paroz]

I'm fine with django.server logger, too. Your explanation makes sense.

[Flavio Curella]

I've updated my PR to use django.server. Let me know what else needs to be done :)

[Claude Paroz]

Unchecking Patch needs improvement will restack the patch on review queues.

[Tim Graham]

I have some concerns that anyone ​disabling logging will be confused why runserver doesn't log anymore. They'll need instructions for how to reenable it. Do the benefits of this change outweigh the costs to these users?

If we end up replacing the runserver machinery with something like gunicorn (#21978), I wonder if the logging situation would change again (i.e. would our version of WSGIRequestHandler be obsolete?). I don't know how close that change is to happening (maybe it will never happen), but I just wanted to raise these points for consideration so we can focus our time and avoid needlessly annoying our users by making conflicting changes in one area over several consecutive releases.

[Tim Graham]

Assuming we do want to move forward with this, I've reviewed the pull request.

[Carl Meyer]

The release notes should of course mention the change. I don't think we need detailed instructions for how to re-enable it for people who may have disabled the default logging config; it's enough to say (something like) "runserver now logs each request to the django.server logger instead of outputting it directly to console; if your logging config overrides Django's defaults, see the default logging config (link) for an example of how to configure runserver logging with color output."

Disabling Django's default logging config is an advanced usage, anybody doing that should know enough about logging to configure things appropriately from there. (And really, a manual logging config that silently discards logging output from unknown loggers by default is kind of broken; someone with such a setup shouldn't be surprised to be missing some logging output.)

Also, we're talking about a development convenience here, not something that breaks production code-paths, so the backwards-compatibility concern level is lower.

I think the benefits of this change are major, in terms of added flexibility to filter and customize runserver logging output without needing to hack core Django code.

And any possibility of replacing runserver remains quite remote AFAICS -- there are a lot of hard questions there that remain unanswered, and I'm not aware of anyone actively working on answering them. I certainly don't think it's anywhere near imminent enough to provide justification for halting all improvements to runserver.

So IMO this change is definitely worth moving forward.

[Tim Graham <timograham@…>]

In 0bc5cd62:

Fixed #25684 -- Made runserver use logging for request/response output.

Thanks andreif for the contributing to the patch.

[Tim Graham <timograham@…>]

In f0a84112:

Refs #25684 -- Silenced logging output in servers tests.

[Mark Tranchant]

Replying to Tim Graham <timograham@…>:

In 0bc5cd62:

Fixed #25684 -- Made runserver use logging for request/response output.

Thanks andreif for the contributing to the patch.

Since upgrading to 1.10, my test suite (from manage.py test) now kicks up this error from ServerFormatter.format() method, which was part of this commit. Doesn't affect my tests. Not sure how to flag this error: here, or new ticket?

Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit
    msg = self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 734, in format
    return fmt.format(record)
  File "/home/my-venv/lib/python2.7/site-packages/django/utils/log.py", line 173, in format
    if args[1][0] == '2':
IndexError: tuple index out of range
Logged from file basehttp.py, line 85

[Tim Graham]

New ticket with steps to reproduce.

[Hayden Crocker]

Replying to marktranchant:

Did this new ticket get created? I can't find it, would be good to have somewhere to post workarounds even if it's already been addressed.

[Tim Graham]

I haven't seen a new ticket. Please open one with steps to reproduce.

[jonathan-golorry]

I'm not really sure what's going on so I don't want to open a ticket myself, but I'm consistently getting Mark's "Logged from file basehttp.py" error with DjangoRestFramework when closing a tab of the browsable API while it's uploading a file.

[Mariusz Felisiak <felisiak.mariusz@…>]

In cdd4ff67:

Refs #25684 -- Removed double newline from request/response output of runserver.

Follow up to 0bc5cd628042bf0a44df60a93085a4f991a84dfb.