Re: Same request object passed to two threads

[Matthew Bellew]

This appears to fix the problem.  We are pushing to our integration server,
and hope to update our supported technologies page soon.

Thanks all,
Matt

On Thu, Dec 8, 2016 at 1:09 AM, Mark Thomas  wrote:

> On 08/12/2016 07:32, Violeta Georgieva wrote:
> > 2016-12-08 3:48 GMT+02:00 Matthew Bellew :
> >>
> >> I have narrowed this down quite a lot.  This bug is caused by the same
> >> Http11Processor being pushed on to the recycledProcessors stack twice.
> I
> >> discovered this by add a duplicates check in recycledProcessors.push()
>
> Kudos for tracking that down. That sort of bug can be difficult to find.
>
> 
>
> > May be you are facing the issue reported here [1]
> >
> > Can you test with 8.5.9 that we vote currently [2]?
>
> +1. I was going to suggest exactly the same thing.
>
> One of the strack traces I trimmed included one of the cancelledKey()
> calls we removed as part of the fix for [1] so I am 99% sure that it is
> the root cause of this problem.
>
> A quick test would be to disable sendfile with  useSendfile="false" on
> the . However, you do really need to test with 8.5.9 to
> be certain.
>
> Mark
>
> >
> > Regards,
> > Violeta
> >
> > [1] https://bz.apache.org/bugzilla/show_bug.cgi?id=60409
> > [2] http://marc.info/?l=tomcat-dev=148097070419476=2
>
>
> -
> To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: dev-h...@tomcat.apache.org
>
>

Re: Same request object passed to two threads

[Mark Thomas]

On 08/12/2016 07:32, Violeta Georgieva wrote:
> 2016-12-08 3:48 GMT+02:00 Matthew Bellew :
>>
>> I have narrowed this down quite a lot.  This bug is caused by the same
>> Http11Processor being pushed on to the recycledProcessors stack twice.  I
>> discovered this by add a duplicates check in recycledProcessors.push()

Kudos for tracking that down. That sort of bug can be difficult to find.



> May be you are facing the issue reported here [1]
> 
> Can you test with 8.5.9 that we vote currently [2]?

+1. I was going to suggest exactly the same thing.

One of the strack traces I trimmed included one of the cancelledKey()
calls we removed as part of the fix for [1] so I am 99% sure that it is
the root cause of this problem.

A quick test would be to disable sendfile with  useSendfile="false" on
the . However, you do really need to test with 8.5.9 to
be certain.

Mark

> 
> Regards,
> Violeta
> 
> [1] https://bz.apache.org/bugzilla/show_bug.cgi?id=60409
> [2] http://marc.info/?l=tomcat-dev=148097070419476=2


-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

Re: Same request object passed to two threads

[Violeta Georgieva]

; be passed to the webapp on two thread concurrently, however.  I'm not
> > guessing about that.  I added debugging code to my app and managed to
stop
> > in the debugger, and I could see two http-nio-8080-exec- threads with
the
> > same object.
> >
> > Matt
> >
> > On Tue, Dec 6, 2016 at 2:58 PM, Caldarale, Charles R <
> > chuck.caldar...@unisys.com> wrote:
> >
> >> From: Matthew Bellew [mailto:matth...@labkey.com]
> >> > Subject: Re: Same request object passed to two threads
> >>
> >> This should be on the users' mailing list, not dev.
> >>
> >> > Just realized that in the case above, I couldn't have hit the quoted
> >> code,
> >> > since neither call to AuthFilter.doFilter() had returned.
> >>
> >> > I can build and debug Tomcat, so any advice would be very welcome.
> >>
> >> Debug your webapp, not Tomcat.  In pretty much 100% of these cases, the
> >> logic in a servlet or filter of the webapp is erroneously storing the
> >> reference to the request object in a static, instance, or thread-local
> >> field, resulting in the wrong request object being used by another
thread
> >> or later in the current thread.
> >>
> >> You might try setting org.apache.catalina.connector.RECYCLE_FACADES to
> >> see if it catches the problem.
> >>
http://tomcat.apache.org/tomcat-8.5-doc/config/systemprops.html#Security
> >>
> >>  - Chuck
> >>
> >>
> >> THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE
PROPRIETARY
> >> MATERIAL and is thus for use only by the intended recipient. If you
> >> received this in error, please contact the sender and delete the
e-mail and
> >> its attachments from all computers.
> >>
> >>
> >> -
> >> To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
> >> For additional commands, e-mail: dev-h...@tomcat.apache.org
> >>
> >>
> >

Re: Same request object passed to two threads

[Matthew Bellew]

I have narrowed this down quite a lot.  This bug is caused by the same
Http11Processor being pushed on to the recycledProcessors stack twice.  I
discovered this by add a duplicates check in recycledProcessors.push()

@SuppressWarnings("sync-override") // Size may exceed cache size a bit
public boolean push(Processor processor, String source) {
int cacheSize = handler.getProtocol().getProcessorCache();
boolean offer = cacheSize == -1 ? true : size.get() < cacheSize;
//avoid over growing our cache or add after we have stopped
boolean result = false;
if (offer) {
+synchronized (this)
+{
+for (int i=0 ; i<=index ; i++)
+assert processor != stack[i];
result = super.push(processor);
+}
if (result) {
size.incrementAndGet();
}
}
if (!result) handler.unregister(processor);
return result;
}


A bit more hacking showed that the processor would be pushed first via
ConnectionHandler.release(*SocketWrapperBase*) called from
Pooler.cancelledKey() (NOTE: AbstractProtocolJava line numbers don't line
up with 8.5.8 because of debug code)

at
org.apache.coyote.AbstractProtocol$RecycledProcessors.push(AbstractProtocol.java:1116)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.release(AbstractProtocol.java:1002)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.release(AbstractProtocol.java:1016)
at
org.apache.tomcat.util.net.NioEndpoint$Poller.cancelledKey(NioEndpoint.java:730)
at
org.apache.tomcat.util.net.NioEndpoint$Poller.processSendfile(NioEndpoint.java:966)
at
org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.processSendfile(NioEndpoint.java:1305)
at
org.apache.coyote.http11.Http11Processor.breakKeepAliveLoop(Http11Processor.java:1611)
at
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:852)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)

The second push of the same processor happens via the "normal"
ConnectionHandler.release(*Processor*) called from
ConnectionHandler.process()

at
org.apache.coyote.AbstractProtocol$ConnectionHandler.release(AbstractProtocol.java:1002)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:927)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked <0x62c2> (a
org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)


I don't know understand the whole processSendFile() and state=SENDFILE
logic.  One suspicious thing comparing the two stack traces is that
ConnectionHandler.process() does not check the return result from
connections.remove().  Maybe

a) ConnectionHandler.process() should only call release(processor) if the
connections.remove(socket)==processor?
or
b) release(socket) shouldn't call recycledProcessors.push()?

Matt


On Tue, Dec 6, 2016 at 3:53 PM, Matthew Bellew <matth...@labkey.com> wrote:

> Thanks for the pointer to org.apache.catalina.connector.RECYCLE_FACADES.
> I will try running our integration server with that set both ways and
> compare.
>
> I don't see how an application bug could cause the same RequestFacade to
> be passed to the webapp on two thread concurrently, however.  I'm not
> guessing about that.  I added debugging code to my app and managed to stop
> in the debugger, and I could see two http-nio-8080-exec- threads with the
> same object.
>
> Matt
>
> On Tue, Dec 6, 2016 at 2:58 PM, Caldarale, Charles R <
> chuck.caldar...@unisys.com> wrote:
>
>> From: Matthew Bellew [mailto:matth...@labkey.com]
>> > Subject: Re: Same request object passed to two threads
>>
>> This should be on the users' mailing list, not dev.
>>
>> > Just realized that in the case above, I couldn't have hit the quoted
>> code,
>> > since neither call to AuthFilter.doFilter() had returned.
>>
>> > I can build and debug Tomcat, so any advice 

Re: Same request object passed to two threads

[Matthew Bellew]

Thanks for the pointer to org.apache.catalina.connector.RECYCLE_FACADES.  I
will try running our integration server with that set both ways and compare.

I don't see how an application bug could cause the same RequestFacade to be
passed to the webapp on two thread concurrently, however.  I'm not guessing
about that.  I added debugging code to my app and managed to stop in the
debugger, and I could see two http-nio-8080-exec- threads with the same
object.

Matt

On Tue, Dec 6, 2016 at 2:58 PM, Caldarale, Charles R <
chuck.caldar...@unisys.com> wrote:

> From: Matthew Bellew [mailto:matth...@labkey.com]
> > Subject: Re: Same request object passed to two threads
>
> This should be on the users' mailing list, not dev.
>
> > Just realized that in the case above, I couldn't have hit the quoted
> code,
> > since neither call to AuthFilter.doFilter() had returned.
>
> > I can build and debug Tomcat, so any advice would be very welcome.
>
> Debug your webapp, not Tomcat.  In pretty much 100% of these cases, the
> logic in a servlet or filter of the webapp is erroneously storing the
> reference to the request object in a static, instance, or thread-local
> field, resulting in the wrong request object being used by another thread
> or later in the current thread.
>
> You might try setting org.apache.catalina.connector.RECYCLE_FACADES to
> see if it catches the problem.
> http://tomcat.apache.org/tomcat-8.5-doc/config/systemprops.html#Security
>
>  - Chuck
>
>
> THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY
> MATERIAL and is thus for use only by the intended recipient. If you
> received this in error, please contact the sender and delete the e-mail and
> its attachments from all computers.
>
>
> -
> To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: dev-h...@tomcat.apache.org
>
>

RE: Same request object passed to two threads

[Caldarale, Charles R]

From: Matthew Bellew [mailto:matth...@labkey.com] 
> Subject: Re: Same request object passed to two threads

This should be on the users' mailing list, not dev.

> Just realized that in the case above, I couldn't have hit the quoted code,
> since neither call to AuthFilter.doFilter() had returned.

> I can build and debug Tomcat, so any advice would be very welcome.

Debug your webapp, not Tomcat.  In pretty much 100% of these cases, the logic 
in a servlet or filter of the webapp is erroneously storing the reference to 
the request object in a static, instance, or thread-local field, resulting in 
the wrong request object being used by another thread or later in the current 
thread.

You might try setting org.apache.catalina.connector.RECYCLE_FACADES to see if 
it catches the problem.
http://tomcat.apache.org/tomcat-8.5-doc/config/systemprops.html#Security

 - Chuck


THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY 
MATERIAL and is thus for use only by the intended recipient. If you received 
this in error, please contact the sender and delete the e-mail and its 
attachments from all computers.


-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

Re: Same request object passed to two threads

[Matthew Bellew]

Just realized that in the case above, I couldn't have hit the quoted code,
since neither call to AuthFilter.doFilter() had returned.

I can build and debug Tomcat, so any advice would be very welcome.

Matt

On Tue, Dec 6, 2016 at 2:20 PM, Matthew Bellew  wrote:

> I have an intermittent bug that I've been trying to trying to track down
> for a long time.  The symptom is that the same tomcat request object is
> being processed by two different threads.  The symptom is a random crash
> when one thread returns and recycles the request, and the other thread
> access the request object, usually causing an NPE.
>
> Note, there are no background threads going on here.  I see my top-most
> filter AuthFilter.doFilter() is being called once with a Tomcat
> RequestFacade object, and before that thread returns, AuthFilter.doFilter()
> is called again on another thread with the exact == RequestFacade object.
>
> Google hasn't given me any leads (beyond "don't pass a request do another
> thread".  I'm not).
>
> My suspicion at this point centers around this code, though I have not
> spent a much time in Tomcat internals.   In Tomcat 8.5.8 
> AbstractProtocol.ConnectionHandler.process()
> around line 889.
>
> wrapper.registerReadInterest();
> } else if (state == SocketState.SENDFILE) {
> // Sendfile in progress. If it fails, the socket will be
> // closed. If it works, the socket will be re-added to the
> // poller
> connections.remove(socket);
> Thread t = threads.remove(socket); assert t == Thread.currentThread();
> release(processor);
> } else if (state == SocketState.UPGRADED) {
> // Don't add sockets back to the poller if this was a
>
> My reading of this is that when state == SENDFILE, the request is not
> complete in some sense.  However, the processor is being released to be
> recycled.  Is this OK for the processor to be picked up by another thread
> at this point?
>
> Thanks for any help,
> Matt
>

Same request object passed to two threads

[Matthew Bellew]

I have an intermittent bug that I've been trying to trying to track down
for a long time.  The symptom is that the same tomcat request object is
being processed by two different threads.  The symptom is a random crash
when one thread returns and recycles the request, and the other thread
access the request object, usually causing an NPE.

Note, there are no background threads going on here.  I see my top-most
filter AuthFilter.doFilter() is being called once with a Tomcat
RequestFacade object, and before that thread returns, AuthFilter.doFilter()
is called again on another thread with the exact == RequestFacade object.

Google hasn't given me any leads (beyond "don't pass a request do another
thread".  I'm not).

My suspicion at this point centers around this code, though I have not
spent a much time in Tomcat internals.   In Tomcat 8.5.8
AbstractProtocol.ConnectionHandler.process() around line 889.

wrapper.registerReadInterest();
} else if (state == SocketState.SENDFILE) {
// Sendfile in progress. If it fails, the socket will be
// closed. If it works, the socket will be re-added to the
// poller
connections.remove(socket);
Thread t = threads.remove(socket); assert t == Thread.currentThread();
release(processor);
} else if (state == SocketState.UPGRADED) {
// Don't add sockets back to the poller if this was a

My reading of this is that when state == SENDFILE, the request is not
complete in some sense.  However, the processor is being released to be
recycled.  Is this OK for the processor to be picked up by another thread
at this point?

Thanks for any help,
Matt