Bug 38483 - access log valve uses simpledateformat in tread-unsafe way
access log valve uses simpledateformat in tread-unsafe way
Status: RESOLVED FIXED
Product: Tomcat 5
Classification: Unclassified
Component: Catalina
5.0.30
Other other
: P2 normal (vote)
: ---
Assigned To: Tomcat Developers Mailing List
:
: 44748 (view as bug list)
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2006-02-01 20:21 UTC by quartz
Modified: 2009-07-12 08:42 UTC (History)
2 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description quartz 2006-02-01 20:21:25 UTC
simpledateformat is known to be not tread-safe.

Yet the valve.invoke() will result in concurrent access to the 4
simpledateformat.format() which is not thread safe (internally shares a Calendar
instance).
Comment 1 Yoav Shapira 2006-04-13 20:45:27 UTC
Good point, and I can see several fixes, not sure which one I'd like best.  This
point also applies to FastCommonAccessLogValve.  Suggestions?
Comment 2 quartz 2006-04-14 02:20:20 UTC
The dumb fix is to create a new simpledateformat every method call (a bit memory
trashing for high volume servers)

I smarter is to use threadlocal caching: the valve creates a threadlocal to put
a simpledate format. 25 thread would imply 25 simpledateformat. Only costs are
the threadlocal map lookup and a bit larger heap (more long lived objects
implies a bit longer full GC, but less young gc).
Comment 3 Peter Rossbach 2006-04-14 06:21:44 UTC
Good idea!

Can please send patch for the three Logger, AccessLoggerValve, FastCommonAccessLogValve and 
ExtendedAccessLogValve?

Comment 4 quartz 2006-04-19 19:13:28 UTC
No, I cannot provide a patch.
Simple code example: (not the real format)

	static final ThreadLocal DF_TL = new ThreadLocal() {
		protected Object initialValue() {
			return new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
		}
	};
	
	static String df(long t) {
		SimpleDateFormat DF = (SimpleDateFormat)DF_TL.get();
		return t<=0 ? "-" : DF.format(new Date(t));
	}
Comment 5 Yoav Shapira 2006-12-24 18:09:01 UTC
Peter, still interested in this?
Comment 6 Mark Thomas 2008-04-03 09:33:22 UTC
*** Bug 44748 has been marked as a duplicate of this bug. ***
Comment 7 Tony 2008-04-04 01:35:47 UTC
Is this bug going to be fixed and what additional comments you may need? As we know it's very hard to reproduce this errors.

Thanks
Comment 8 Mark Thomas 2008-04-04 02:03:22 UTC
Yes it will be fixed.

To answer the obvious next question: "When?" - when someone gets to it. There are current ~170 open bugs against TC5 and TC6. A patch will speed the process up but one that uses syncs is likely to get rejected.
Comment 9 Peter Rossbach 2008-04-04 05:26:40 UTC
The question is also: How we can fix it:
Critical section at AccessLogValve is (LL 581 (current tomcat 5.5 trunk): 
            result.append("[");
            result.append(dayFormatter.format(date));           // Day
            result.append('/');
            result.append(lookup(monthFormatter.format(date))); // Month
            result.append('/');
            result.append(yearFormatter.format(date));          // Year
            result.append(':');
            result.append(timeFormatter.format(date));          // Time
            result.append(space);
            result.append(getTimeZone(date));                   // Time Zone
            result.append("] \"");

Not only the timeFormatter is the problem :-(

Option to fix:
a) synchronize the complete formatter access
 easy to implement, but can be a performance problem
b) use a cache with some threadLocals
 can be a memory leak at shrinking request thread pools
c) use some formatter object pools
 little implementation overhead and we must also use a sync datastructure!

Peter

Comment 10 Rainer Jung 2008-04-04 05:34:35 UTC
Since we are collecting ideas:

- FastDateFormat from commons.lang
- Joda Time (also seems to be ASL licensed)

Both would add another foreign dependency but are thread safe in their formatters. I didn't look at their performance though. A concurrent microbenchmark could be adequate here.

Peter: why do you expect a leak, if we put the SimpleDateFormat into a ThreadLocal? Do we have any indication, that when shrinking the pool, any references to the removed Threads remain?
Comment 11 Tim Funk 2008-04-04 05:52:05 UTC
In this case - syncs aren't really that evil. All the syncing is occuring during the logging phase. Which occurs after the request has been served to the client.

So yes - there is a performance penalty for syncing but its not critical path which will slow the server down. With the exception that you had run out of workers - in which case you have bigger issues to deal with.
Comment 12 Niall Pemberton 2008-04-04 07:47:02 UTC
I don't see that theres a problem any more - the block that uses most (i.e. all except fileDateFormatter) of the SimpleDateFormats is now in a synchronized block:

    synchronized (this) {
        if (currentDate != date) {
            StringBuffer current = new StringBuffer(32);
            current.append('[');
            current.append(dayFormatter.format(date)); // Day
            current.append('/');
            current.append(lookup(monthFormatter.format(date))); // Month
            current.append('/');
            current.append(yearFormatter.format(date)); // Year
            current.append(':');
            current.append(timeFormatter.format(date)); // Time
            current.append(' ');
            current.append(getTimeZone(date)); // Timezone
            current.append(']');
            currentDateString = current.toString();
            currentDate = date;
        }
    }

...and fileDateFormatter is used in the rotate() method which is also synchronized

Looks to me like this was resolved in the following revision:
http://svn.apache.org/viewvc?view=rev&revision=494191

But perhaps I'm looking at the wrong version - as code I see differs from what Peter quotes (StringBuffer is called current rather than result)
Comment 13 quartz 2008-04-05 05:31:41 UTC
I would agree with the comment about using a thread safe data formatter.
After all, there is no need for anything more than threadstack variables to format a date. FastDateFormat is right on.

Note: since date formatters can't use StringBuilder, it is a good idea to get away from SimpleDateFormat and use whatever lib that can work on StringBuilder. You should probably file a RFE for FastDateFormat using StringBuilder too.
Comment 14 Peter Rossbach 2008-04-06 08:08:57 UTC
After reading all comments I agree with Tim that a simple sync fix the problem.
The use of ThreadLocal or thread safe API add complexity and new dependencies.

Vote +1 to add simple sync statements a 5.5 AccessLog valve code base
Comment 15 Mark Thomas 2009-02-04 02:39:20 UTC
The fix was applied to trunk and 6.0.x but not 5.5.x. I have proposed a patch for 5.5.x
Comment 16 Xie Xiaodong 2009-06-17 09:57:32 UTC
I think synchronize on "this" is not a good idea, since all synchronized method and those blocks which is synchronized on "this" in this class will wait for the lock. Separate those locks for different formatter will be much better. Or we can use some threadLocal field for those formatter. I think both of the options could fix this.
Comment 17 Mark Thomas 2009-07-12 08:42:31 UTC
This has been fixed in 5.5.x (along with a handful of related issues) and will be included in 5.5.28 onwards.