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