Opened 4 years ago

Closed 3 years ago

Last modified 3 years ago

#25684 closed New feature (fixed)

Runserver doesn't use `LOGGING` configuration

Reported by: Flavio Curella Owned by: Flavio Curella
Component: Error reporting Version: master
Severity: Normal Keywords: runserver logging
Cc: Triage Stage: Accepted
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description (last modified by 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.

Change History (44)

comment:1 Changed 4 years ago by Flavio Curella

Description: modified (diff)

comment:2 Changed 4 years ago by Flavio Curella

Description: modified (diff)

comment:3 Changed 4 years ago by Flavio Curella

Version: 1.8master

comment:4 Changed 4 years ago by Flavio Curella

Keywords: runserver logging added

comment:5 Changed 4 years ago by Flavio Curella

Owner: set to Flavio Curella
Status: newassigned

comment:6 Changed 4 years ago by Carl Meyer

Triage Stage: UnreviewedAccepted

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.

comment:7 Changed 4 years ago by 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!

comment:8 Changed 4 years ago by Tim Graham

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

comment:9 Changed 4 years ago by Claude Paroz

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

comment:10 Changed 4 years ago by 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.

comment:11 Changed 4 years ago by 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.

comment:12 Changed 4 years ago by 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.

comment:13 Changed 4 years ago by 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.
  1. 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.
  1. "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.

comment:14 Changed 4 years ago by Claude Paroz

Has patch: set
Patch needs improvement: set

comment:15 Changed 4 years ago by 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
Last edited 4 years ago by Andrei Fokau (previous) (diff)

comment:16 Changed 4 years ago by Andrei Fokau

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

comment:17 Changed 4 years ago by 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
  1. 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

comment:18 Changed 4 years ago by 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! :)

Last edited 4 years ago by Andrei Fokau (previous) (diff)

comment:19 Changed 4 years ago by 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.

comment:20 Changed 4 years ago by 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...

comment:21 Changed 4 years ago by 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 :)

comment:22 Changed 4 years ago by 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.

comment:23 Changed 4 years ago by 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

comment:24 Changed 4 years ago by 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?

comment:25 Changed 4 years ago by 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.

comment:26 Changed 4 years ago by 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. :-)

comment:27 Changed 4 years ago by 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.

comment:28 Changed 4 years ago by Tim Graham

(I was advocating for either choice myself.)

comment:29 Changed 4 years ago by 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?

comment:30 Changed 4 years ago by 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/

comment:31 Changed 4 years ago by Claude Paroz

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

comment:32 Changed 4 years ago by Flavio Curella

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

comment:33 Changed 4 years ago by Claude Paroz

Patch needs improvement: unset

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

comment:34 Changed 3 years ago by 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.

comment:35 Changed 3 years ago by Tim Graham

Patch needs improvement: set

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

comment:36 Changed 3 years ago by 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.

comment:37 Changed 3 years ago by Flavio Curella

Patch needs improvement: unset

comment:38 Changed 3 years ago by Tim Graham <timograham@…>

Resolution: fixed
Status: assignedclosed

In 0bc5cd62:

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

Thanks andreif for the contributing to the patch.

comment:39 Changed 3 years ago by Tim Graham <timograham@…>

In f0a84112:

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

comment:40 in reply to:  38 ; Changed 3 years ago by 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
Last edited 3 years ago by Mark Tranchant (previous) (diff)

comment:41 Changed 3 years ago by Tim Graham

New ticket with steps to reproduce.

comment:42 in reply to:  40 Changed 3 years ago by 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.

comment:43 Changed 3 years ago by Tim Graham

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

comment:44 Changed 3 years ago by jonathan-golorry

Mark's "Logged from file basehttp.py" error may have been fixed in #27271

Last edited 3 years ago by jonathan-golorry (previous) (diff)
Note: See TracTickets for help on using tickets.
Back to Top