Code

Opened 4 years ago

Closed 8 months ago

#14800 closed New feature (fixed)

Development server should NOT elide favicon from the logs

Reported by: RoySmith Owned by: Claude Paroz <claude@…>
Component: Core (Management commands) Version: master
Severity: Normal Keywords: logging
Cc: Triage Stage: Ready for checkin
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

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.

Attachments (2)

ticket-14800.patch (874 bytes) - added by kc9ddi 4 years ago.
optional-14800.diff (3.2 KB) - added by zerok 17 months ago.
Verbose logging as option

Download all attachments as: .zip

Change History (26)

Changed 4 years ago by kc9ddi

comment:1 Changed 4 years ago by kc9ddi

  • Needs documentation unset
  • Needs tests unset
  • Patch needs improvement unset

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.

comment:2 Changed 4 years ago by kc9ddi

  • Has patch set

comment:3 Changed 4 years ago by cdestigter

  • Patch needs improvement set

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.

comment:4 Changed 4 years ago by mariarchi

  • Triage Stage changed from Unreviewed to Accepted

Looks like a good idea to me.

comment:5 Changed 3 years ago by gabrielhurley

  • Component changed from django-admin.py runserver to Core (Management commands)

comment:6 Changed 3 years ago by anonymous

  • Severity set to Normal
  • Type set to New feature

comment:7 Changed 3 years ago by adrian

  • Needs documentation set

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?

comment:8 Changed 2 years ago by aaugustin

  • UI/UX unset

Change UI/UX from NULL to False.

comment:9 Changed 2 years ago by aaugustin

  • Easy pickings unset

Change Easy pickings from NULL to False.

comment:10 Changed 17 months ago by zerok

  • Owner changed from nobody to zerok
  • Status changed from new to assigned

comment:11 Changed 17 months ago by zerok

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.

Changed 17 months ago by zerok

Verbose logging as option

comment:12 Changed 17 months ago by zerok

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?

comment:13 Changed 17 months ago by zerok

  • Owner zerok deleted
  • Status changed from assigned to new

comment:14 Changed 17 months ago by 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.

comment:15 Changed 17 months ago by aaugustin

"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.

comment:16 Changed 17 months ago by RoySmith

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.

comment:17 Changed 17 months ago by aaugustin

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)

comment:18 Changed 17 months ago by 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.

comment:19 Changed 17 months ago by carljm

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.

comment:20 Changed 17 months ago by aaugustin

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.

comment:21 Changed 17 months ago by RoySmith

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

comment:22 Changed 8 months ago by claudep

  • Needs documentation unset
  • Patch needs improvement unset
  • Version changed from 1.2 to master

comment:23 Changed 8 months ago by aaugustin

  • Triage Stage changed from Accepted to Ready for checkin

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 :-)

comment:24 Changed 8 months ago by Claude Paroz <claude@…>

  • Owner set to Claude Paroz <claude@…>
  • Resolution set to fixed
  • Status changed from new to closed

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.

Add Comment

Modify Ticket

Change Properties
<Author field>
Action
as closed
as The resolution will be set. Next status will be 'closed'
The resolution will be deleted. Next status will be 'new'
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.