Development server should NOT elide favicon from the logs

[Roy Smith]

I just wasted a good chunk of the morning trying to figure out why one of my view methods was getting called at inappropriate times. The short story is that I had written my url mapping wrong so I was accidentally matching requests for /favicon.ico. The debugging was MUCH harder than it should have been because the /favicon.ico requests were not being logged -- I was seeing one request come in, and two view methods called! It wasn't until I pulled out the big guns (i.e. tcpdump), that the pieces fell into place.

Anyway, it seems like a serious mis-feature that BaseHTTPServer.log_message() deliberately suppresses certain requests:

    def log_message(self, format, *args):
        # Don't bother logging requests for admin images or the favicon.
        if self.path.startswith(self.admin_media_prefix) or self.path == '/favicon.ico':
	    return

Note the chain of events here: 1) I made a programming mistake, 2) the browser was magically asking for something I hadn't requested, and 3) the sever was magically suppressing the evidence that 2) was happening. It's a prototyping/teaching/debugging tool. It should be very explicit about what it's doing. If logging these things makes the output too verbose, then provide an option somewhere to suppress it, with the default being to log everything.

[kc9ddi]

Submitted a patch to address this. Requires two new settings.py boolean variables to specify whether the favicon and admin media requests should be logged.

[Craig de Stigter]

Better patch IMHO would:

• just have one setting - LOG_MEDIA_REQUESTS or similar. Two is too specific for this. If we add more files in future to this, they should be covered under the same setting.

• Include a default setting in django/conf/global_settings.py (with comment explaining what it does). Otherwise it breaks for those who don't define the setting.

[mariarchi]

Looks like a good idea to me.

[Adrian Holovaty]

I agree we should add a way to turn on media/favicon logging -- but not with a setting. The better way to do this would be with a command-line flag to the "runserver" django-admin/manage.py command. Can somebody whip up a patch?

[Aymeric Augustin]

Change UI/UX from NULL to False.

[Aymeric Augustin]

Change Easy pickings from NULL to False.

[Horst Gutmann]

Another factor here is that apparently Firebug as well as Webkit Inspector don't track the favicon in their network tabs. This seems to be independent of whether the favicon is linked to explicitly (using a <link />) or not (as fallback for old IE-behaviour).

For Firebug some background about this can be found here: ​http://comments.gmane.org/gmane.comp.mozilla.firefox.firebug/9253

Also when a favicon.ico is requested varies pretty heavily from browser to browser.

[Horst Gutmann]

Verbose logging as option

[Horst Gutmann]

optional-14800.diff is a rather short version of getting an additional logging option into the WSGIRequestHandler without using settings. Perhaps I don't think that having this as an option is worth modifying the signature of basehttp.run and doing even more dynamic subclassing than is already there.

What about just removing the filtering altogether?

[anonymous]

As the original author of this ticket (2 years ago!), I'm reading this very old thread with a certain amount of disbelief. This seems like an incredibly simple and obvious issue which is being over-analyzed to death. Runserver is a very simple tool for debugging and prototyping. It doesn't need configuration options and command-line flags. It should just log every request it gets. Simple. Easy. Obvious.

At some point, whatever project you're working on will progress to running under a real web server with real logging and you can implement whatever fancy logging filters you want. Until that time, KISS should be rule.

[Aymeric Augustin]

"favicon.ico" is explicitly excluded for the logs. This feature was developed for a reason. Arbitrarily removing it will be considered a regression by the people who rely on it. "Someone on the tracker asked to remove that feature because he had trouble debugging his code" won't satisfy them.

[Roy Smith]

OK, I did some research. The original ticket which led to this behavior was #161. I don't understand the full motivation behind this, but I'm assuming it was along the lines of "these are just static files, no need to clutter up the log with them". I disagree with that philosophy, but let's assume for the moment it's a valid concept. In my case, /favicon.png matched a pattern in my urls file and got dispatched to a view. Surely the original author of the feature never intended to elide from the logs requests which got dispatched to views?

If you wanted to logic to be, "If a request doesn't match any pattern, don't bother logging the 404 if the route looks like a static media file", there could be some justification for that. But, not logging something which matched and got dispatched is just plain wrong.

[Aymeric Augustin]

Does this mean the following fix would be sufficient to make everyone happy?

--- a/django/core/servers/basehttp.py
+++ b/django/core/servers/basehttp.py
@@ -156,7 +156,7 @@ class WSGIRequestHandler(simple_server.WSGIRequestHandler, object):
     def log_message(self, format, *args):
         # Don't bother logging requests for admin images or the favicon.
         if (self.path.startswith(self.admin_static_prefix)
-                or self.path == '/favicon.ico'):
+                or (self.path == '/favicon.ico' and args[1] == '404')):
             return
 
         msg = "[%s] %s\n" % (self.log_date_time_string(), format % args)

[anonymous]

I suppose this resolves my initial issue, in a very narrow way, but the whole thing still just feels wrong to me. Log what you get, don't apply complicated heuristics to try and guess what the user would or would not want to see in the logs. But, given that you're not going to do that, then, yes, I suppose this is better than what exists today.

[Carl Meyer]

FWIW, I agree with comment 18 that it's silly (and could be quite frustrating in debugging) for runserver to be trying to decide on behalf of the user which requests are "interesting enough" to be displayed in the log. If runserver served the request, it should log it. I don't see any strong justification for this behavior in the previous related tickets, so I'd be in favor of just getting rid of the filtering altogether. Similarly with the admin_static_prefix special-case, we've been trying for some time to remove all special-casing of admin media; it's quite ugly for the core WSGI handler to be having knowledge about a contrib app.

[Aymeric Augustin]

FWIW I don't care very much about this. I happened to be sitting next to zerok at the Utrecht sprints and merely reacted to the hyperbole in comment 14.

[Roy Smith]

My apologies for the hyperbole. BTW, the anonymous comments 14 and 18 are mine; I had just neglected to login.

[Claude Paroz]

​https://github.com/django/django/pull/1897

[Aymeric Augustin]

Claude, that pull request looks good. Let's keep it simple. I've made a few comments on the wording of the docs. It isn't necessary to add tests for a feature we're *removing*.

Roy, thanks for persisting :-)

[Claude Paroz <claude@…>]

In e7383f16b438a03ea2258a49e4889fd6e2303e53:

Fixed #14800 -- Suppressed WSGIRequestHandler message filtering

Filtering out static file requests in runserver has been judged
arbitrary and can hide some debugging-related activity.
Thanks Roy Smith for the report and Aymeric Augustin for the
review.