You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2017/12/11 10:52:54 UTC
[Bug 61886] New: 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
Bug ID: 61886
Summary: 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Product: Tomcat 7
Version: trunk
Hardware: PC
Status: NEW
Severity: normal
Priority: P2
Component: Catalina
Assignee: dev@tomcat.apache.org
Reporter: knst.kolinko@gmail.com
Target Milestone: ---
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)
]]]
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
--- Comment #11 from Mark Thomas <ma...@apache.org> ---
NPE on Tomcat (actually just webapp) stop should be fixed now too.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
Mark Thomas <ma...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution|--- |FIXED
--- Comment #3 from Mark Thomas <ma...@apache.org> ---
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
--- Comment #10 from Mark Thomas <ma...@apache.org> ---
I believe I've fixed the ConcurrentModificationException. Still investigating
the NPE.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
Konstantin Kolinko <kn...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|RESOLVED |REOPENED
Resolution|FIXED |---
--- Comment #4 from Konstantin Kolinko <kn...@gmail.com> ---
> 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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
--- Comment #9 from Konstantin Kolinko <kn...@gmail.com> ---
(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)
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
--- Comment #7 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 35659
--> https://bz.apache.org/bugzilla/attachment.cgi?id=35659&action=edit
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
--- Comment #5 from Konstantin Kolinko <kn...@gmail.com> ---
(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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
Konstantin Kolinko <kn...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
OS| |All
--- Comment #1 from Konstantin Kolinko <kn...@gmail.com> ---
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?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
--- Comment #2 from Mark Thomas <ma...@apache.org> ---
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
--- Comment #8 from Konstantin Kolinko <kn...@gmail.com> ---
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)
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 61886] 7.0.83 Calling [asyncComplete()] is not valid for a
request with Async state [MUST_COMPLETE]
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=61886
Mark Thomas <ma...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Resolution|--- |FIXED
Status|REOPENED |RESOLVED
--- Comment #6 from Mark Thomas <ma...@apache.org> ---
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
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org