You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Borut Hadžialić <bo...@gmail.com> on 2007/07/16 10:33:13 UTC
Did anyone had problems with JspWriter in Tomcat 5.5.17?
Hi list,
I have spent last 15 working hours trying to figure out the cause of a
strange bug. Home page on one of our web sites sometimes gets
generated with no content - as a blank page, the response buffer
having size 0. We use caching filter (modified CachingFilter from
Ehcache 1.3.0) which uses a response wrapper to capture responses to
make caching possible. The response wrapper internaly uses standard
classes ByteArrayOutputStream and PrintWriter from the Java API.
The page cache time-to-live is set to 1 day. When the page is
generated first time by jsps and tiles it is put into cache, and
served for next 24 hours from the cache. After 24 hours it gets
generated again.
The manifestation of the bug is that randomly, the homepage gets
generated as a blank page, about once in every 3 cache refreshes. When
it occurs, the ByteArrayOutputStream has size 0, after the generation
of the page has completed.
Generating the homepage involves pulling some data from the database,
which changes rarely, about once every week. I put cache time to live
300 seconds to eliminate the posibility that corrupt data from
database causes errors in page generation. With 300 second time to
live the problem was still there. The data in database does not change
between good and faulty page generations. Home page is relatively
simple - it does not involve pulling data from other data sources. It
just reads some data the database and uses that data to make some
html, using jsp.
After turning on logging on database calls, all filters, and using a
PrintWriter decorator inside our response wraper that echoes all print
statements to the log, I found out something strange -
A correct page generation logs some database calls (by the database
logger), then a chunk of html (by the logging PrintWriter decorator,
as a result of flushing JspWriter after enough out.write calls have
been made), then some more database calls, then some more html.. and
the page gets generated.
** A faulty generation (the one that produces a blank page) logs
exactly same database calls as a correct page generation, but the log
entries produced by the echoing PrintWriter are missing! **, like as
jsps are executing normally, but something is wrong with the JspWriter
out object.
I am suspecting that somehow JspWriter writes somewhere else, not
where it should. It should write into response wrapper's buffer,
though the echoing/logging PrintWriter. But there is no PrintWriter
echo and no bytes in response wrapper buffer... more exactly,
*sometimes* there is no PrintWriter echo and no bytes in response
wrapper buffer.
I have read all the code that makes up the life cycle of PageContext
and JspWriter on the docjar site (not sure for what version of
Tomcat), and couldn't find anything that would help me solve this.
http://www.docjar.com/html/api/org/apache/jasper/runtime/JspWriterImpl.java.html
http://www.docjar.com/html/api/org/apache/jasper/runtime/PageContextImpl.java.html
http://www.docjar.com/html/api/org/apache/jasper/runtime/JspFactoryImpl.java.html
After adding some more logging statements I found out that 1 instance
of JspWritter and 1 instance of PageContext are used shared across all
page generations (site has low traffic and rarely 2 requests in same
time). Same JspWritter and PageContext instances sometimes
participate in good page and faulty page generations.
I was hoping that someone on this list might know something that could
help me find out why is this happening. Please help.
--
Why?
Because YES!
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Did anyone had problems with JspWriter in Tomcat 5.5.17?
Posted by Borut Hadžialić <bo...@gmail.com>.
I forgot to write information about our environment:
Os: Red Hat 4.1 (Linux 2.6.9-42.EL) on i386
Jvm: Sun's Java HotSpot(TM) Client VM version 1.5.0_07-b03
Tomcat 5.5.17
We also use Spring, Informix db, iBatis, Jsp (tiles) and Ehcache 1.3.0
We have made 5 sites for now with these same technologies. The bug
only occurrs on the home page on the least visited site.. Other sites
are visited very often (we have to use load balancing on 4 servers)
And 1 more important thing - when the caching filter is turned off,
pages always get generated fine. But.. the code that creates the
wrapper is same for all apps/pages, and works fine in other apps.
--
Why?
Because YES!
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Did anyone had problems with JspWriter in Tomcat 5.5.17?
Posted by Borut Hadžialić <bo...@gmail.com>.
I found the cause of the problem.
Tomcat's implementation of javax.servlet.http.HttpServlet implements
the doGet method like this:
protected void doHead(HttpServletRequest req, HttpServletResponse resp)
throws ServletException, IOException
{
NoBodyResponse response = new NoBodyResponse(resp);
doGet(req, response);
response.setContentLength();
}
The problem occurs when a HTTP HEAD request arrives for a page that
isn't in the page cache.
When a HTTP HEAD request is received for a page that is not in the
cache, the caching filter prepares a response wrapper that will
capture the request (content generated by the application's servlets),
puts that wrapper in the place of the real response, for the filters
and servlets next in the chain, and gives the execution to the next
filter/servlet in chain..
But, for HTTP HEAD requests, the caching wrapper never gets to the
servlets that generate content, because the above method wraps it in
NoBodyResponse, a response wrapper that throws away everything that is
writen to it, like /dev/null does... servlets write content to
NoBodyResponse, and the content is lost.
On the way back, the caching filter inspects the response wrapper it
created, sees 200 response code, and decides that the page was
generated well, and caches it... (the content doesn't get cached
because NoBodyResponse didnt forward it to the response it wrapped -
caching filter's response wrapper)
I will fix my caching filter to watch for this special case, and that
will solve the problem in our applications... but I wonder if it is
okay that Tomcat (silently) wraps the response inside a wrapper like
NoBodyResponse that eats content.. or was it my fault that I didn't
explicitly make difference between GET and HEAD requests when thinking
about caching, probably because of lack of expirience..
--
Why?
Because YES!
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Did anyone had problems with JspWriter in Tomcat 5.5.17?
Posted by rpr_listas <rp...@telefonica.net>.
Hi Borut.
I don't know the ehcache framework. What is the method used to prevent
the thread collision?
If I had this error, would try to make the most simple example to
reproduce it. A simple wrapper and singleton class could be a good
beginnin. Then grow the example until the error reproduces.
Best regards.
Ricardo
Borut Hadžialić escribió:
> The caching filter uses a BlockingCache. A miss (get that returns
> null) locks that entry/key, and other threads that try to get the page
> from the cache using the same key, must wait until the thread that
> locked the entry puts something into the cache and releases the lock.
> Lock are released implicitly when cache put method is called, by the
> thread that locked it. All this is implemented inside Ehcache. We
> havent observed any thread deadlock problems (using JMX to monitor
> servers)
>
> Lock implementation is net.sf.ehcache.constructs.concurrent.Mutex
> which is a copy of Doug Lea's mutex class from standard Java API,
> copied and imported into Ehcache.
>
>
>
> On 7/16/07, rpr_listas <rp...@telefonica.net> wrote:
>> Hello, Borut.
>>
>> Are you sure that there are no other thread writing in the cache at
>> this moment? How do you prevent this case?
>>
>> Best regards.
>> Ricardo
>>
>>
>> Borut Hadžialić escribió:
>> > Hi list,
>> >
>> > I have spent last 15 working hours trying to figure out the cause of a
>> > strange bug. Home page on one of our web sites sometimes gets
>> > generated with no content - as a blank page, the response buffer
>> > having size 0. We use caching filter (modified CachingFilter from
>> > Ehcache 1.3.0) which uses a response wrapper to capture responses to
>> > make caching possible. The response wrapper internaly uses standard
>> > classes ByteArrayOutputStream and PrintWriter from the Java API.
>> >
>> > The page cache time-to-live is set to 1 day. When the page is
>> > generated first time by jsps and tiles it is put into cache, and
>> > served for next 24 hours from the cache. After 24 hours it gets
>> > generated again.
>> >
>> > The manifestation of the bug is that randomly, the homepage gets
>> > generated as a blank page, about once in every 3 cache refreshes. When
>> > it occurs, the ByteArrayOutputStream has size 0, after the generation
>> > of the page has completed.
>> >
>> > Generating the homepage involves pulling some data from the database,
>> > which changes rarely, about once every week. I put cache time to live
>> > 300 seconds to eliminate the posibility that corrupt data from
>> > database causes errors in page generation. With 300 second time to
>> > live the problem was still there. The data in database does not change
>> > between good and faulty page generations. Home page is relatively
>> > simple - it does not involve pulling data from other data sources. It
>> > just reads some data the database and uses that data to make some
>> > html, using jsp.
>> >
>> > After turning on logging on database calls, all filters, and using a
>> > PrintWriter decorator inside our response wraper that echoes all print
>> > statements to the log, I found out something strange -
>> >
>> > A correct page generation logs some database calls (by the database
>> > logger), then a chunk of html (by the logging PrintWriter decorator,
>> > as a result of flushing JspWriter after enough out.write calls have
>> > been made), then some more database calls, then some more html.. and
>> > the page gets generated.
>> >
>> > ** A faulty generation (the one that produces a blank page) logs
>> > exactly same database calls as a correct page generation, but the log
>> > entries produced by the echoing PrintWriter are missing! **, like as
>> > jsps are executing normally, but something is wrong with the JspWriter
>> > out object.
>> >
>> > I am suspecting that somehow JspWriter writes somewhere else, not
>> > where it should. It should write into response wrapper's buffer,
>> > though the echoing/logging PrintWriter. But there is no PrintWriter
>> > echo and no bytes in response wrapper buffer... more exactly,
>> > *sometimes* there is no PrintWriter echo and no bytes in response
>> > wrapper buffer.
>> >
>> > I have read all the code that makes up the life cycle of PageContext
>> > and JspWriter on the docjar site (not sure for what version of
>> > Tomcat), and couldn't find anything that would help me solve this.
>> >
>> >
>> http://www.docjar.com/html/api/org/apache/jasper/runtime/JspWriterImpl.java.html
>>
>> >
>> >
>> http://www.docjar.com/html/api/org/apache/jasper/runtime/PageContextImpl.java.html
>>
>> >
>> >
>> http://www.docjar.com/html/api/org/apache/jasper/runtime/JspFactoryImpl.java.html
>>
>> >
>> >
>> > After adding some more logging statements I found out that 1 instance
>> > of JspWritter and 1 instance of PageContext are used shared across all
>> > page generations (site has low traffic and rarely 2 requests in same
>> > time). Same JspWritter and PageContext instances sometimes
>> > participate in good page and faulty page generations.
>> >
>> > I was hoping that someone on this list might know something that could
>> > help me find out why is this happening. Please help.
>> >
>> >
>>
>>
>> ---------------------------------------------------------------------
>> To start a new topic, e-mail: users@tomcat.apache.org
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
>
>
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Did anyone had problems with JspWriter in Tomcat 5.5.17?
Posted by Borut Hadžialić <bo...@gmail.com>.
The caching filter uses a BlockingCache. A miss (get that returns
null) locks that entry/key, and other threads that try to get the page
from the cache using the same key, must wait until the thread that
locked the entry puts something into the cache and releases the lock.
Lock are released implicitly when cache put method is called, by the
thread that locked it. All this is implemented inside Ehcache. We
havent observed any thread deadlock problems (using JMX to monitor
servers)
Lock implementation is net.sf.ehcache.constructs.concurrent.Mutex
which is a copy of Doug Lea's mutex class from standard Java API,
copied and imported into Ehcache.
On 7/16/07, rpr_listas <rp...@telefonica.net> wrote:
> Hello, Borut.
>
> Are you sure that there are no other thread writing in the cache at
> this moment? How do you prevent this case?
>
> Best regards.
> Ricardo
>
>
> Borut Hadžialić escribió:
> > Hi list,
> >
> > I have spent last 15 working hours trying to figure out the cause of a
> > strange bug. Home page on one of our web sites sometimes gets
> > generated with no content - as a blank page, the response buffer
> > having size 0. We use caching filter (modified CachingFilter from
> > Ehcache 1.3.0) which uses a response wrapper to capture responses to
> > make caching possible. The response wrapper internaly uses standard
> > classes ByteArrayOutputStream and PrintWriter from the Java API.
> >
> > The page cache time-to-live is set to 1 day. When the page is
> > generated first time by jsps and tiles it is put into cache, and
> > served for next 24 hours from the cache. After 24 hours it gets
> > generated again.
> >
> > The manifestation of the bug is that randomly, the homepage gets
> > generated as a blank page, about once in every 3 cache refreshes. When
> > it occurs, the ByteArrayOutputStream has size 0, after the generation
> > of the page has completed.
> >
> > Generating the homepage involves pulling some data from the database,
> > which changes rarely, about once every week. I put cache time to live
> > 300 seconds to eliminate the posibility that corrupt data from
> > database causes errors in page generation. With 300 second time to
> > live the problem was still there. The data in database does not change
> > between good and faulty page generations. Home page is relatively
> > simple - it does not involve pulling data from other data sources. It
> > just reads some data the database and uses that data to make some
> > html, using jsp.
> >
> > After turning on logging on database calls, all filters, and using a
> > PrintWriter decorator inside our response wraper that echoes all print
> > statements to the log, I found out something strange -
> >
> > A correct page generation logs some database calls (by the database
> > logger), then a chunk of html (by the logging PrintWriter decorator,
> > as a result of flushing JspWriter after enough out.write calls have
> > been made), then some more database calls, then some more html.. and
> > the page gets generated.
> >
> > ** A faulty generation (the one that produces a blank page) logs
> > exactly same database calls as a correct page generation, but the log
> > entries produced by the echoing PrintWriter are missing! **, like as
> > jsps are executing normally, but something is wrong with the JspWriter
> > out object.
> >
> > I am suspecting that somehow JspWriter writes somewhere else, not
> > where it should. It should write into response wrapper's buffer,
> > though the echoing/logging PrintWriter. But there is no PrintWriter
> > echo and no bytes in response wrapper buffer... more exactly,
> > *sometimes* there is no PrintWriter echo and no bytes in response
> > wrapper buffer.
> >
> > I have read all the code that makes up the life cycle of PageContext
> > and JspWriter on the docjar site (not sure for what version of
> > Tomcat), and couldn't find anything that would help me solve this.
> >
> > http://www.docjar.com/html/api/org/apache/jasper/runtime/JspWriterImpl.java.html
> >
> > http://www.docjar.com/html/api/org/apache/jasper/runtime/PageContextImpl.java.html
> >
> > http://www.docjar.com/html/api/org/apache/jasper/runtime/JspFactoryImpl.java.html
> >
> >
> > After adding some more logging statements I found out that 1 instance
> > of JspWritter and 1 instance of PageContext are used shared across all
> > page generations (site has low traffic and rarely 2 requests in same
> > time). Same JspWritter and PageContext instances sometimes
> > participate in good page and faulty page generations.
> >
> > I was hoping that someone on this list might know something that could
> > help me find out why is this happening. Please help.
> >
> >
>
>
> ---------------------------------------------------------------------
> To start a new topic, e-mail: users@tomcat.apache.org
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
--
Why?
Because YES!
Re: Did anyone had problems with JspWriter in Tomcat 5.5.17?
Posted by Borut Hadžialić <bo...@gmail.com>.
The problem seem to happen before writing to the cache. Jsps write to
response wrapper's buffer.. well, when they do page gets generated
fine, when they don't we get a blank home page served and put in the
cache.
On 7/16/07, rpr_listas <rp...@telefonica.net> wrote:
> Hello, Borut.
>
> Are you sure that there are no other thread writing in the cache at
> this moment? How do you prevent this case?
>
> Best regards.
> Ricardo
>
>
--
Why?
Because YES!
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Did anyone had problems with JspWriter in Tomcat 5.5.17?
Posted by rpr_listas <rp...@telefonica.net>.
Hello, Borut.
Are you sure that there are no other thread writing in the cache at
this moment? How do you prevent this case?
Best regards.
Ricardo
Borut Hadžialić escribió:
> Hi list,
>
> I have spent last 15 working hours trying to figure out the cause of a
> strange bug. Home page on one of our web sites sometimes gets
> generated with no content - as a blank page, the response buffer
> having size 0. We use caching filter (modified CachingFilter from
> Ehcache 1.3.0) which uses a response wrapper to capture responses to
> make caching possible. The response wrapper internaly uses standard
> classes ByteArrayOutputStream and PrintWriter from the Java API.
>
> The page cache time-to-live is set to 1 day. When the page is
> generated first time by jsps and tiles it is put into cache, and
> served for next 24 hours from the cache. After 24 hours it gets
> generated again.
>
> The manifestation of the bug is that randomly, the homepage gets
> generated as a blank page, about once in every 3 cache refreshes. When
> it occurs, the ByteArrayOutputStream has size 0, after the generation
> of the page has completed.
>
> Generating the homepage involves pulling some data from the database,
> which changes rarely, about once every week. I put cache time to live
> 300 seconds to eliminate the posibility that corrupt data from
> database causes errors in page generation. With 300 second time to
> live the problem was still there. The data in database does not change
> between good and faulty page generations. Home page is relatively
> simple - it does not involve pulling data from other data sources. It
> just reads some data the database and uses that data to make some
> html, using jsp.
>
> After turning on logging on database calls, all filters, and using a
> PrintWriter decorator inside our response wraper that echoes all print
> statements to the log, I found out something strange -
>
> A correct page generation logs some database calls (by the database
> logger), then a chunk of html (by the logging PrintWriter decorator,
> as a result of flushing JspWriter after enough out.write calls have
> been made), then some more database calls, then some more html.. and
> the page gets generated.
>
> ** A faulty generation (the one that produces a blank page) logs
> exactly same database calls as a correct page generation, but the log
> entries produced by the echoing PrintWriter are missing! **, like as
> jsps are executing normally, but something is wrong with the JspWriter
> out object.
>
> I am suspecting that somehow JspWriter writes somewhere else, not
> where it should. It should write into response wrapper's buffer,
> though the echoing/logging PrintWriter. But there is no PrintWriter
> echo and no bytes in response wrapper buffer... more exactly,
> *sometimes* there is no PrintWriter echo and no bytes in response
> wrapper buffer.
>
> I have read all the code that makes up the life cycle of PageContext
> and JspWriter on the docjar site (not sure for what version of
> Tomcat), and couldn't find anything that would help me solve this.
>
> http://www.docjar.com/html/api/org/apache/jasper/runtime/JspWriterImpl.java.html
>
> http://www.docjar.com/html/api/org/apache/jasper/runtime/PageContextImpl.java.html
>
> http://www.docjar.com/html/api/org/apache/jasper/runtime/JspFactoryImpl.java.html
>
>
> After adding some more logging statements I found out that 1 instance
> of JspWritter and 1 instance of PageContext are used shared across all
> page generations (site has low traffic and rarely 2 requests in same
> time). Same JspWritter and PageContext instances sometimes
> participate in good page and faulty page generations.
>
> I was hoping that someone on this list might know something that could
> help me find out why is this happening. Please help.
>
>
---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org