Bug 52184 - Reduce log level for invalid cookies
Reduce log level for invalid cookies
Status: RESOLVED FIXED
Product: Tomcat 7
Classification: Unclassified
Component: Connectors
7.0.22
PC All
: P2 normal (vote)
: ---
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2011-11-14 22:26 UTC by Filip Hanik
Modified: 2011-12-12 22:20 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Filip Hanik 2011-11-14 22:26:00 UTC
Invalid cookies are fairly common. Firefox has them all the time. Tomcat logs fill up very quickly with this input. Tomcat doesn't log when there is an invalid HTTP request, as that would yield the same problem.co 

Nov 14, 2011 3:15:27 PM org.apache.tomcat.util.http.Cookies processCookieHeader
INFO: Cookies: Invalid cookie. Value not a token or quoted value

http://vmc-ssrc-rh56.eng.vmware.com:8080/

GET / HTTP/1.1
Host: vmc-ssrc-rh56.eng.vmware.com:8080
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:7.0.1) Gecko/20100101 Firefox/7.0.1
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip, deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Connection: keep-alive
Cookie: __utma=106857756.14479066.1321292743.1321296794.1321304211.3; __utmz=106857756.1321304211.3.2.utmcsr=communities.example.com|utmccn=(referral)|utmcmd=referral|utmcct=/community/vmtn/appplatform/testapp_fire; s_nr=1321293934221; s_vi=[CS]v1|2760A9C4851D0F77-6000010260007567[CE]
Cache-Control: max-age=0
Comment 1 Mark Thomas 2011-11-16 18:29:26 UTC
I'm against this change.

Dropping a cookie needs to logged by default. If an application is generating a lot of invalid cookies then the log level can always be increased to WARN for that logger.

Arguably the log level for dropping a cookie should be WARN anyway. It has already been dropped to INFO due to the frequency that it is observed and to allow the messages to be filtered out by setting the log level to WARN.
Comment 2 Filip Hanik 2011-11-18 17:16:46 UTC
I'd keep this open. As asking user to change their log level to avoid filling up their disks for invalid HTTP cookies is pretty much asking every admin to by default change the log level for a logger they've never heard of to avoid a DoS attack.

It's pretty much common sense. It's not an error in Tomcat, it's an invalid cookie. The logging of it, who does it benefit, the one admin that is looking for it, or the thousand admins getting invalid cookies?
Comment 3 Mark Thomas 2011-11-18 23:45:14 UTC
Changing the default log level to DEBUG is going to cause problems for system admins trying to work out why their app isn't working. Silently dropping invalid input data is not a good idea. There needs to be a warning somewhere.

An approach we have used elsewhere is to log the first instance of the problem at one level and subsequent instances at a lower level. It is a good idea to include in the first log message that further instances of the problem will be logged at a lower (disabled by default) log level. This addresses my concern that something needs to be logged and your DOS concern.
Comment 4 Konstantin Kolinko 2011-11-19 05:45:33 UTC
Tomcat should be friendly both to developers and to those using it in production. 
Its default configuration is more developer-friendly, in many places.


I think many admins do not look at INFO messages at all. So it seems reasonable to expect that the default log level in production would be set to WARNING.

From developer's point of view I am against dropping severity level of this message.


> It is a good idea to include in the first log message that further
> instances of the problem will be logged at a lower (disabled by default)
> log level.

In this case the first and subsequent messages are likely to come from different requests. I think it is better to have some time-based threshold strategy.

I wonder whether it can be dealt at the logging library level. Otherwise it would be nice to have some helper class to deal with such logging issues. (+system property to configure the threshold?)
This issue is wider, because this place is not the only one that produces "useless" INFO messages.
Comment 5 William A. Rowe Jr. 2011-11-20 03:59:56 UTC
The httpd project is currently demoting all errors generated for client 
diagnostic activity to a level lower-than [warn].  The appropriate 4xx
code is already being sent to the client, so the administrator or the
web author is free to enable various debugging aids if the reason for
that 4xx result is desired.  But for 99.9995% of the lifespan of that
running server, nobody is interested in why the client is sending a bad
URI, etc.  Most of these are not users, but friendly or malicious probes.
Comment 6 Mark Thomas 2011-12-08 20:44:10 UTC
I have implemented a solution for this that we can expand to other areas as required. The solution will be included in 7.0.24 onwards.
Comment 7 Konstantin Kolinko 2011-12-09 02:22:28 UTC
REOPENing.

The new o.a.juli.logging.UserDataHelper class is missing from extras/tomcat-juli.jar.
Consequently Tomcat fails fatally if you try to use the alternative tomcat-juli.jar from extras.


The DirectJDKLog class is also missing from extras. Apparently the changes applied to it have to be ported to commons-logging *.logging.impl.Jdk14Logger class. It is not fatal though and concerns only the accuracy of log messages.
(In practice I think it is not a big concern, because the extras tomcat-juli jar is usually used to route logging to log4j. In that case the accuracy of java.util logging is irrelevant).
Comment 8 Mark Thomas 2011-12-12 22:20:15 UTC
Thanks for the catch. This should be fixed in trunk and 7.0.x now.