Opened 10 years ago

Last modified 10 years ago

#21949 new New feature

Django doesn't log much at high verbosity levels

Reported by: Chris Wilson Owned by: nobody
Component: Core (Other) Version: 1.6
Severity: Normal Keywords: logging
Cc: Triage Stage: Accepted
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

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.

Change History (8)

comment:1 by anonymous, 10 years ago

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.

comment:2 by Chris Wilson, 10 years ago

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.

comment:3 by Russell Keith-Magee, 10 years ago

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.

comment:4 by Chris Wilson, 10 years ago

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.
  1. 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.
  1. Is there a repeatable request benchmark for signals that I could use to provide the same information for logging?

comment:5 by Russell Keith-Magee, 10 years ago

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 this mailing list thread; there 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.

comment:6 by jarshwah, 10 years ago

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.

comment:7 by AeroNotix, 10 years ago

Keywords: logging added

comment:8 by Tim Graham, 10 years ago

Component: UncategorizedCore (Other)
Triage Stage: UnreviewedAccepted

Worth exploring I guess.

Note: See TracTickets for help on using tickets.
Back to Top