[Django] #21949: Django doesn't log much at high verbosity levels
Django
-------------------------------+--------------------
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------+--------------------
I'd expect that Django would log something like:
* At INFO level, at least one line per request (similar to runserver
output)
* At DEBUG level, enough information to recreate the request
However, it doesn't appear to:
* There are only two logger.debug statements, both logging database SQL
commands
* There are no logger.info [logger.info] statements at all
* Turning on DEBUG logging for everything seems to log only SQL statements
and errors
* The django.request logger only seems to be used for errors and warnings
I'd like to add more info and debug logging to django.request as stated
above. Is that likely to be accepted?
Reasons for doing this:
* It's hard to interpret the Django logs if they don't contain a record of
each request. E.g. you have an error message in the logs. Which request
caused it?
* It's hard to tell that logging is configured properly if, at DEBUG
level, only SQL queries are showing up. This is not expected behaviour.
* As @russellm says, Apache can be configured to log full request details
including POST data (although how is a mystery to me). But not everyone
uses Apache. I'm not sure that Nginx and Lighttpd can be configured thus.
* I would hope that the impact is minimal to zero if logging is set to
INFO or higher.
--
Ticket URL: <https://code.djangoproject.com/ticket/21949>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by anonymous):
* needs_better_patch: => 0
* needs_tests: => 0
* needs_docs: => 0
Comment:
Regarding this point... "At DEBUG level, enough information to recreate
the request" I think you'd probably want to introduce *some* constraints
on how much request data would be logged. Logging uploads or very large
POST/PUT requests probably isn't feasible/desirable. Including the
request headers and the body up to a certain bytes limit might be
reasonable.
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:1>
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by gcc):
I'm assuming that people would NOT enable DEBUG level logging unless
they're trying to debug a problem, in which case they probably do want to
log everything.
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:2>
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by russellm):
Regarding your specific points here:
1) In the case of an error, the error handler *does* contain a full
record of the request, including the URL, all GET and POST arguments, a
summary of the FILES, the WSGI environment, all settings (redacted for
passwords, etc), and the stack trace that resulted. By default this is
sent via email, but it's handled via a logger, so you can point it at a
file, or an external web service (like Sentry) if you want to. Is there a
compelling case for dumping this data for *successful* requests?
2) "We need more DEBUG messages so we can tell that logging is configured
correctly" doesn't strike me as a very strong argument.
3) You should probably be looking at gunicorn or uWSGI as the piece
responsible for extra logging, but point taken. mod_dumpio is the magic
keyword for apache. However, as pointed out in (1), full request
information *is* provided in the case of
4) I'd hope that too, but nothing is free; data trumps everything. It
would be helpful to have some good real-world metrics to guide this, and
other discussions. We've got indicative impact numbers for signals (which
is the other extension point that is asked for regularly); it would be
good to have similar numbers for logging.
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:3>
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by gcc):
Hi Russell,
1. A request may "appear" to be successful, but it turns out much later
that it actually didn't do what we expected. In that case we want to
reproduce the problem as easily as possible. But yes, the existing
mechanics for dumping a request on error should probably be used for
logging successful requests at debug level.
2. I have an expectation, based not on any law but on much positive
experience, that applications should have a verbose mode where they log
what they are actually doing, and at least log *something* whenever they
are poked, so that you can tell that they haven't hung. This is very
helpful for post mortem debugging, especially on systems that we don't
have direct access to for security reasons, or that we can't take down to
insert breakpoints into.
4. Is there a repeatable request benchmark for signals that I could use to
provide the same information for logging?
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:4>
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by russellm):
Regarding 4: The benchmark is essentially "Do it lots of times in a loop,
average over the number of calls, and compare to other useful benchmarks
(like the cost of a single function call)"
Jacob's benchmark for signals was presented in
[https://groups.google.com/d/msg/django-
developers/WjmDniqo31M/xWhAn2RvooYJ this mailing list thread]; there
[https://gist.github.com/jacobian/25892 a gist that contains the benchmark
code].
It won't be a 1-for-1 substitution for a logging benchmark, but it should
be possible to work up something analogous.
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:5>
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by smeatonj):
> I have an expectation, based not on any law but on much positive
experience, that applications should have a verbose mode where they log
what they are actually doing, and at least log *something* whenever they
are poked, so that you can tell that they haven't hung.
I somewhat agree, but can't this be accomplished by application authors
putting logging in their code? I wouldn't mind seeing some very basic
logging in core, which would help identify user problems, but I think it'd
be unnecessarily costly to dump everything django is doing.
As a request passes through the many layers, a single log message should
be enough, depending on the verbosity level anyway. INFO should say
something like "Request Received" and *maybe* "Response Sent". DEBUG might
have "Processing Middleware", "URL {0} Selected", "View {0} called",
"Template {0} loaded".
Additionally, it should be easier for site authors to dump the debug page
content to logs, even if an error wasn't generated.
But, as Russel has pointed out, you'd definitely want to benchmark the
extra logging in any case.
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:6>
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Component: Uncategorized | Version: 1.6
Keywords: logging | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by AeroNotix):
* keywords: => logging
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:7>
Django
Reporter: gcc | Owner: nobody
Type: New feature | Status: new
Severity: Normal | Resolution:
Keywords: logging | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by timo):
* component: Uncategorized => Core (Other)
* stage: Unreviewed => Accepted
Comment:
Worth exploring I guess.
--
Ticket URL: <https://code.djangoproject.com/ticket/21949#comment:8>