Bug 61886

Summary: 7.0.83 Calling [asyncComplete()] is not valid for a request with Async state [MUST_COMPLETE]
Product: Tomcat 7 Reporter: Konstantin Kolinko <knst.kolinko>
Component: CatalinaAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: trunk   
Target Milestone: ---   
Hardware: PC   
OS: All   
Attachments: catalina.2018-01-08.log.txt

Description Konstantin Kolinko 2017-12-11 10:52:54 UTC
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)
]]]
Comment 1 Konstantin Kolinko 2017-12-11 12:06:33 UTC
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?
Comment 2 Mark Thomas 2017-12-11 16:48:18 UTC
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.
Comment 3 Mark Thomas 2017-12-11 17:53:16 UTC
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.
Comment 4 Konstantin Kolinko 2017-12-12 10:43:09 UTC
> 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.
Comment 5 Konstantin Kolinko 2017-12-14 16:28:11 UTC
(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.
Comment 6 Mark Thomas 2018-01-04 20:30:49 UTC
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
Comment 7 Konstantin Kolinko 2018-01-08 13:43:25 UTC
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.
Comment 8 Konstantin Kolinko 2018-01-08 14:12:27 UTC
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)
Comment 9 Konstantin Kolinko 2018-01-08 14:42:00 UTC
(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)
Comment 10 Mark Thomas 2018-01-09 21:11:06 UTC
I believe I've fixed the ConcurrentModificationException. Still investigating the NPE.
Comment 11 Mark Thomas 2018-01-09 22:00:25 UTC
NPE on Tomcat (actually just webapp) stop should be fixed now too.