https://bz.apache.org/bugzilla/show_bug.cgi?id=58646
--- Comment #15 from Alexander Malyshev <anmalys...@mail.ru> ---
Ok, finally I was able to reproduce it with logs.
I associated ID with each request object and I added logging to
AbstractHttp11Processor class to process() and recycle() methods.
In process() method I added the following log in the very beginning:
getLog().info("Starting to process request with id " + this.request.id + ".
Calling method is:\n" + java.lang.Thread.currentThread().getStackTrace()[3]);
and the following log later then request path is parsed (copying a few above
lines as well to make it clean):
if ((!getInputBuffer().parseRequestLine(this.keptAlive)) &&
(handleIncompleteRequestLineRead()))
{
break;
}
getLog().info("Processing " + this.request.method() + " request to " +
this.request.requestURI() + ".");
In the recycle() method I added log in the very beginning:
getLog().info("Recycling processor with id " + this.request.id + ". Calling
method is:\n" + java.lang.Thread.currentThread().getStackTrace()[2]);
What I got is that 2 different Tomcat threads started to process the same
request (logs are ordered properly):
Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-23
org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-23
org.apache.coyote.http11.Http11NioProcessor
INFO: Processing POST request to /viewer/rest/live_viewer/.
Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-17
org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-17
org.apache.coyote.http11.Http11NioProcessor
INFO: Processing POST request to /viewer/rest/live_viewer/.
Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-17
org.apache.coyote.http11.Http11NioProcessor
INFO: Error parsing HTTP request header
Note: further occurrences of HTTP header parsing errors will be logged at
DEBUG level.
java.lang.IllegalStateException: Unexpected state: headers already parsed.
Buffer not recycled?
at
org.apache.coyote.http11.AbstractNioInputBuffer.parseHeaders(AbstractNioInputBuffer.java:375)
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1029)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
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)
Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-23
com.avaya.acc.wcs.logic.api.GetPresentationTocCommand
INFO: Processing LIVE_VIEWER event for client with Participant ID null
Last log is aour app log and means that http-nio-135.60.87.68-443-exec-23
thread processed request successfully.
I think there is a synchronization issue somethere in tomcat code which makes
it possible for 2 threads to process the same request object simultaneously.
Here is another exception - but the reason seem to be the same:
Jan 15, 2016 MSK 04:52:14.028 PM http-nio-135.60.87.68-443-exec-16
org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
Jan 15, 2016 MSK 04:52:14.028 PM http-nio-135.60.87.68-443-exec-16
org.apache.coyote.http11.Http11NioProcessor
INFO: Processing GET request to /wcsws/WebSocket.
Jan 15, 2016 MSK 04:52:14.028 PM http-nio-135.60.87.68-443-exec-1
org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
Jan 15, 2016 MSK 04:52:14.029 PM http-nio-135.60.87.68-443-exec-1
org.apache.coyote.http11.Http11NioProcessor
INFO: Processing GET request to /wcsws/WebSocket.
Jan 15, 2016 MSK 04:52:14.029 PM http-nio-135.60.87.68-443-exec-1
org.apache.coyote.http11.Http11NioProcessor
INFO: Recycling processor with id 13. Calling method is:
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:218)
Jan 15, 2016 MSK 04:52:14.029 PM http-nio-135.60.87.68-443-exec-16
org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/wcsws].[default]
SEVERE: Servlet.service() for servlet [default] in context with path [/wcsws]
threw exception
java.lang.NullPointerException
at
org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1505)
at org.apache.catalina.connector.Request.access$000(Request.java:118)
at org.apache.catalina.connector.Request$3.set(Request.java:3380)
at org.apache.catalina.connector.Request.setAttribute(Request.java:1462)
at
org.apache.catalina.connector.RequestFacade.setAttribute(RequestFacade.java:539)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:272)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
at com.avaya.acc.base.web.valves.StingerValve.invoke(StingerValve.java:150)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at
com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve.invoke(MCPTomcatAccessLogValve.java:269)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1100)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
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)
Jan 15, 2016 MSK 04:52:14.040 PM http-nio-135.60.87.68-443-exec-16
org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error processing request
java.lang.NullPointerException
at
org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1505)
at org.apache.catalina.connector.Request.setAttribute(Request.java:1495)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:158)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at
com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve.invoke(MCPTomcatAccessLogValve.java:269)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1100)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
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)
Jan 15, 2016 MSK 04:52:14.040 PM http-nio-135.60.87.68-443-exec-16
org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error finishing response
java.lang.NullPointerException
at
org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:236)
at
org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:191)
at
org.apache.coyote.http11.InternalNioOutputBuffer.commit(InternalNioOutputBuffer.java:179)
at
org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:741)
at org.apache.coyote.Response.action(Response.java:177)
at
org.apache.coyote.http11.AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:369)
at
org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1813)
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1152)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
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)
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
