Django doesn't log much at high verbosity levels

[Chris Wilson]

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.

[anonymous]

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.

[Chris Wilson]

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.

[Russell Keith-Magee]

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.

[Chris Wilson]

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?

[Russell Keith-Magee]

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.

[jarshwah]

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.

[Tim Graham]

Worth exploring I guess.