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 2015/02/18 14:51:28 UTC
[Bug 57592] New: numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
Bug ID: 57592
Summary: numberwriter example: Response status 500,
asyncOperation() not valid for request with state
DISPATCHED
Product: Tomcat 8
Version: 8.0.18
Hardware: PC
Status: NEW
Severity: normal
Priority: P5
Component: Connectors
Assignee: dev@tomcat.apache.org
Reporter: knst.kolinko@gmail.com
First noted this when testing 8.0.20 release candidate, but this is also
reproducible with 8.0.18 and 8.0.17.
http://markmail.org/message/rkkdl6publsievvi
Steps to reproduce:
1) go to /examples/servlets/nonblocking/numberwriter with a web browser
2) look into access log
Expected: status 200
Actual: status 500 for APR, NIO, NIO2. (BIO is OK)
This issue depends on timing. E.g. it reproduces for me consistently with HTTP
connector, but not HTTPS connector. It does not reproduce in some other
configurations.
3) Add the following line to logging.properties to enable FINE logging for
Coyote:
org.apache.coyote.level=FINE
The following is observed in the log:
for Nio 2, Tomcat 8.0.20:
[[[
18-Feb-2015 15:51:17.155 FINE [http-nio2-127.0.0.1-8084-exec-4]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@851105:org.apache.tomcat.util.net.Nio2Channel@406c4:sun.nio.ch.WindowsAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:8084 remote=/127.0.0.1:51890]], Status in:
[OPEN_WRITE], State out: [LONG]
18-Feb-2015 15:51:17.169 FINE [http-nio2-127.0.0.1-8084-exec-10]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@851105:org.apache.tomcat.util.net.Nio2Channel@406c4:sun.nio.ch.WindowsAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:8084 remote=/127.0.0.1:51890]], Status in:
[OPEN_WRITE], State out: [ASYNC_END]
18-Feb-2015 15:51:17.170 FINE [http-nio2-127.0.0.1-8084-exec-10]
org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch Unable
to write async data.
java.lang.IllegalStateException: Calling [asyncOperation()] is not
valid for a request with Async state [DISPATCHED]
at
org.apache.coyote.AsyncStateMachine.asyncOperation(AsyncStateMachine.java:207)
at
org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1658)
at
org.apache.coyote.http11.Http11Nio2Processor.asyncDispatch(Http11Nio2Processor.java:155)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:650)
at
org.apache.coyote.http11.Http11Nio2Protocol$Http11ConnectionHandler.process(Http11Nio2Protocol.java:177)
at
org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1087)
at
org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.run(Nio2Endpoint.java:1046)
at
org.apache.tomcat.util.net.Nio2Endpoint.processSocket0(Nio2Endpoint.java:598)
at
org.apache.tomcat.util.net.Nio2Endpoint.processSocket(Nio2Endpoint.java:583)
at
org.apache.coyote.http11.InternalNio2OutputBuffer$2.completed(InternalNio2OutputBuffer.java:199)
at
org.apache.coyote.http11.InternalNio2OutputBuffer$2.completed(InternalNio2OutputBuffer.java:165)
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
at sun.nio.ch.Invoker$2.run(Invoker.java:218)
at
sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
18-Feb-2015 15:51:17.183 FINE [http-nio2-127.0.0.1-8084-exec-10]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@851105:org.apache.tomcat.util.net.Nio2Channel@406c4:sun.nio.ch.WindowsAsynchronousSocketChannelImpl[connected
local=/127.0.0.1:8084 remote=/127.0.0.1:51890]], Status in:
[OPEN_WRITE], State out: [CLOSED]
]]]
For APR connector, Tomcat 8.0.20
[[[
18-Feb-2015 15:57:47.524 FINE [http-apr-127.0.0.1-8083-exec-6]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1342088:86309568],
Status in: [OPEN_WRITE], State out: [LONG]
18-Feb-2015 15:57:47.529 FINE [http-apr-127.0.0.1-8083-exec-7]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1342088:86309568],
Status in: [OPEN_WRITE], State out: [ASYNC_END]
18-Feb-2015 15:57:47.530 FINE [http-apr-127.0.0.1-8083-exec-7]
org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch Unable
to write async data.
java.lang.IllegalStateException: Calling [asyncOperation()] is not
valid for a request with Async state [DISPATCHED]
at
org.apache.coyote.AsyncStateMachine.asyncOperation(AsyncStateMachine.java:207)
at
org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1658)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:650)
at
org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:285)
at
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2439)
at
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2428)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
18-Feb-2015 15:57:47.536 FINE [http-apr-127.0.0.1-8083-exec-7]
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@1342088:86309568],
Status in: [OPEN_WRITE], State out: [CLOSED]
]]]
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #4 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32491
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32491&action=edit
localhost_access_log.2015-02-18.txt - Access Log - 8.0.18
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
Konstantin Kolinko <kn...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
OS| |All
--- Comment #6 from Konstantin Kolinko <kn...@gmail.com> ---
Testing the current Tomcat 9 trunk @1660633
Configuration is the same, minus BIO connectors that are not implemented in
trunk.
HTTP:
8082: Nio,
8083: Apr,
8084: Nio2
HTTPS:
9443: Nio,
10443: Nio2.
None for APR.
Using Java 8u31.
HTTP connectors: response status OK (200). Seeing some EOF exceptions in FINE
logging. The one from APR connectors seems odd.
The JVM crashed when I was trying to access the Nio HTTPS connector, but the
crash is in APR connector code. It tried to process timeout on a keep-alive
request.
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #8 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32495
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32495&action=edit
catalina.2015-02-18.log - Tomcat 9 @1660633 - Log
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #7 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32494
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32494&action=edit
localhost_access_log.2015-02-18.txt - Tomcat 9 @1660633 - Access Log
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #9 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32496
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32496&action=edit
hs_err_pid3936.log - Tomcat 9 @1660633 - Crash Log
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #2 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32489
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32489&action=edit
localhost_access_log.2015-02-18.txt - Access Log - 8.0.20
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #1 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32488
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32488&action=edit
server.xml
server.xml - Tomcat 8.0.20.
Custom configuration of Connectors (different port numbers and protocols) and
of AccessLogValve (logging port number)
logging.properties:
added org.apache.coyote.level=FINE
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #3 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32490
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32490&action=edit
catalina.2015-02-18.log - Log - 8.0.20
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
--- Comment #5 from Konstantin Kolinko <kn...@gmail.com> ---
Created attachment 32492
--> https://bz.apache.org/bugzilla/attachment.cgi?id=32492&action=edit
catalina.2015-02-18.log - Log - 8.0.18
--
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 57592] numberwriter example: Response status 500,
asyncOperation() not valid for request with state DISPATCHED
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=57592
Mark Thomas <ma...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution|--- |FIXED
--- Comment #10 from Mark Thomas <ma...@apache.org> ---
I could not reliably reproduce this. It looks like I have fixed this but do
re-open it if you see it again.
--
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