Release candidate of 7.0.83 - Java 8u152 - NIO connector - Compression enabled - Running with Security Manager <Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol" connectionTimeout="20000" redirectPort="8443" useSendfile="false" compression="force" compressionMinSize="1" /> I noted the following error in catalina.2017-12-11.log while running the async examples (for sake of smoke-testing): There are two log messages. The first INFO one is OK (though why we are logging it at all?), the second one is WARNING and is unexpected. [[[ дек 11, 2017 1:38:44 PM org.apache.coyote.AbstractProcessor setErrorState INFO: An error occurred in processing while on a non-container thread. The connection will be closed immediately java.io.IOException: Программа на вашем хост-компьютере разорвала установленное подключение (English Translation: "The program on your host computer has broken the established connection") at sun.nio.ch.SocketDispatcher.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:51) at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) at sun.nio.ch.IOUtil.write(IOUtil.java:65) at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:125) at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:174) at org.apache.coyote.http11.InternalNioOutputBuffer.writeToSocket(InternalNioOutputBuffer.java:164) at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:243) at org.apache.coyote.http11.InternalNioOutputBuffer.flush(InternalNioOutputBuffer.java:95) at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:828) at org.apache.coyote.Response.action(Response.java:171) at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:366) at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:334) at org.apache.catalina.connector.CoyoteWriter.flush(CoyoteWriter.java:98) at async.AsyncStockServlet.writeStock(AsyncStockServlet.java:102) at async.AsyncStockServlet.tick(AsyncStockServlet.java:82) at async.Stockticker.run(Stockticker.java:84) at java.lang.Thread.run(Thread.java:748) дек 11, 2017 1:38:44 PM org.apache.catalina.core.AsyncContextImpl setErrorState WARNING: onError() failed for listener of type [org.apache.catalina.core.AsyncListenerWrapper] java.lang.IllegalStateException: Calling [asyncComplete()] is not valid for a request with Async state [MUST_COMPLETE] at org.apache.coyote.AsyncStateMachine.doComplete(AsyncStateMachine.java:291) at org.apache.coyote.AsyncStateMachine.asyncComplete(AsyncStateMachine.java:275) at org.apache.coyote.http11.Http11NioProcessor.actionInternal(Http11NioProcessor.java:516) at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:946) at org.apache.coyote.Request.action(Request.java:345) at org.apache.catalina.core.AsyncContextImpl.complete(AsyncContextImpl.java:103) at async.AsyncStockServlet.onError(AsyncStockServlet.java:118) at org.apache.catalina.core.AsyncListenerWrapper.fireOnError(AsyncListenerWrapper.java:54) at org.apache.catalina.core.AsyncContextImpl.setErrorState(AsyncContextImpl.java:455) at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:298) at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1713) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:616) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1775) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1734) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748) ]]]
1) The second exception happens in error handling in example async.AsyncStockServlet.onError(AsyncStockServlet.java:118) This is implemented as @Override public void onError(AsyncEvent event) throws IOException { event.getAsyncContext().complete(); } 2) Javadoc in AsyncStateMachine * MUST_COMPLETE - ServletRequest.startAsync() followed by complete() have * been called during a single Servlet.service() method. The * complete() will be processed as soon as the request * finishes. It says that both startAsync() and complete() have been called by Servlet.service() method. How is it? There is no such code in AsyncStockServlet. 3) Can we ignore duplicate complete() calls?
I can repeat this. I'm looking into why it happens. The spec is clear about when it is legal to call this method, but unclear as to what to do if it is called illegally. Generally that means the container can handle it however it pleases. I'd lean towards an error of some kind because the API is being used incorrectly. I'm not sure at this point how long it will take to figure out what is going on. From experience it will either be a few minutes or a few days.
When I started to investigate this I was getting unexpected 500 responses if I accessed the example directly. The root cause of that was an AccessControlException retying to load an anonymous inner class generated by the compiler when enums are used with switch. Fixing that appears to have fixed this bug too. With the necessary classes pre-loaded, I can't recreate this. It is speculation but I suspect what was happening was that the AccessControlException was causing errors in the error handling and Tomcat's attempts to clean up after this were causing the ISE.
> Fixing that appears to have fixed this bug too. Confirmed. I cannot reproduce the WARNING message now. Good. The first message (INFO) is easy to reproduce: 1. go to http://localhost:8080/examples/async/stockticker 2. press F5, ESC repeatedly I think it should be controlled via UserDataHelper, or reduced to DEBUG.
(In reply to Konstantin Kolinko from comment #4) > > Fixing that appears to have fixed this bug too. > > Confirmed. I cannot reproduce the WARNING message now. Good. I added some debug/logging code to AsyncStockServlet and can reproduce this WARNING easily. This does happen without a SecurityManager. Two conclusions here: 1. AsyncStockServlet.onError() is: public void onError(AsyncEvent event) throws IOException { event.getAsyncContext().complete(); } This WARNING happens because the complete() call here fails with an IllegalStateException. If the call above were wrapped with try/catch, no warning would be printed. 2. There is a typo in AsyncContextImpl.setErrorState() > listener.fireOnError(errorEvent); > } catch (Throwable t2) { > ExceptionUtils.handleThrowable(t); > log.warn("onError() failed for listener of type [" + > listener.getClass().getName() + "]", t2); It should be handleThrowable(t2) instead of (t) above. Logging a warning here looks excessive.
The ISE was triggered by a bug in the async stock servlet. Multiple threads were trying to complete the AsyncContext. This has been fixed. Logging errors in non-container threads at INFO has been dropped to debug. The application in notified of the error via the standard async error handling so debug is sufficient here. The typo in AsyncContextImpl.setErrorState() has been fixed. Logging failed listener methods at WARN is consistent with listener handling elsewhere in Tomcat. There are examples of it being logged at ERROR. I believe all the remaining issues in this report have been resolved. Fixed in: - trunk for 9.0.3 onwards - 8.5.x for 8.5.25 onwards - 8.0.x for 8.0.49 onwards - 7.0.x for 7.0.84 onwards
Created attachment 35659 [details] catalina.2018-01-08.log.txt Testing current Tomcat 9.0-dev @r1820558. Generally - OK. A NullPointerException when stopping Tomcat, in AsyncContextImpl.fireOnComplete(AsyncContextImpl.java:116) I am attaching the log file here.
Testing current Tomcat 8.5-dev @r1820546 A ConcurrentModificationException is printed on the console, but not in the logs. Nothing interesting in the logs. Not attaching them here. 08-Jan-2018 17:08:49.566 INFO [http-nio-8080-exec-1] async.AsyncStockServlet.<init> AsyncStockServlet created java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:859) at java.util.ArrayList$Itr.next(ArrayList.java:831) at async.Stockticker.run(Stockticker.java:83) at java.lang.Thread.run(Thread.java:745) java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:859) at java.util.ArrayList$Itr.next(ArrayList.java:831) at async.Stockticker.run(Stockticker.java:83) at java.lang.Thread.run(Thread.java:745) java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:859) at java.util.ArrayList$Itr.next(ArrayList.java:831) at async.Stockticker.run(Stockticker.java:83) at java.lang.Thread.run(Thread.java:745)
(In reply to Konstantin Kolinko from comment #8) > Testing current Tomcat 8.5-dev @r1820546 That ConcurrentModificationException was when running with Java 7u80. With Java 8u152 it also occurs. Line numbers are a bit different, java.util.ConcurrentModificationException at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:909) at java.util.ArrayList$Itr.next(ArrayList.java:859) at async.Stockticker.run(Stockticker.java:83) at java.lang.Thread.run(Thread.java:748)
I believe I've fixed the ConcurrentModificationException. Still investigating the NPE.
NPE on Tomcat (actually just webapp) stop should be fixed now too.