#25684 closed New feature (fixed)
Runserver doesn't use `LOGGING` configuration
Reported by: | Flavio Curella | Owned by: | Flavio Curella |
---|---|---|---|
Component: | Error reporting | Version: | dev |
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 )
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 (45)
comment:1 by , 9 years ago
Description: | modified (diff) |
---|
comment:2 by , 9 years ago
Description: | modified (diff) |
---|
comment:3 by , 9 years ago
Version: | 1.8 → master |
---|
comment:4 by , 9 years ago
Keywords: | runserver logging added |
---|
comment:5 by , 9 years ago
Owner: | set to |
---|---|
Status: | new → assigned |
comment:6 by , 9 years ago
Triage Stage: | Unreviewed → Accepted |
---|
comment:7 by , 9 years ago
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 by , 9 years ago
See also #21429 -- BaseCommand should use logging instead of custom output wrappers.
comment:9 by , 9 years ago
I guess the current behavior is simply due to Python itself using sys.stderr
in http.server.BaseHTTPRequestHandler.log_message
.
comment:10 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
I don't actually see a performance concern mentioned there. There are three concerns:
- 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.
- 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.
- "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 by , 9 years ago
Has patch: | set |
---|---|
Patch needs improvement: | set |
comment:15 by , 9 years ago
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
comment:16 by , 9 years ago
It would also be great to have response time in the log message, see #25704
comment:17 by , 9 years ago
- I believe it would be better to use
django.server
instead ofdjango.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
- 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 inglobal_settings.py
can havedjango.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 by , 9 years ago
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! :)
comment:19 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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 by , 9 years ago
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:29 by , 9 years ago
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 by , 9 years ago
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:32 by , 9 years ago
I've updated my PR to use django.server
. Let me know what else needs to be done :)
comment:33 by , 9 years ago
Patch needs improvement: | unset |
---|
Unchecking Patch needs improvement
will restack the patch on review queues.
comment:34 by , 9 years ago
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 by , 9 years ago
Patch needs improvement: | set |
---|
Assuming we do want to move forward with this, I've reviewed the pull request.
comment:36 by , 9 years ago
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 by , 9 years ago
Patch needs improvement: | unset |
---|
follow-up: 40 comment:38 by , 9 years ago
Resolution: | → fixed |
---|---|
Status: | assigned → closed |
In 0bc5cd62:
follow-up: 42 comment:40 by , 8 years ago
Replying to Tim Graham <timograham@…>:
In 0bc5cd62:
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
comment:42 by , 8 years ago
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:44 by , 8 years ago
Mark's "Logged from file basehttp.py" error may have been fixed in #27271
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.