Bug 57592 - numberwriter example: Response status 500, asyncOperation() not valid for request with state DISPATCHED
numberwriter example: Response status 500, asyncOperation() not valid for req...
Status: RESOLVED FIXED
Product: Tomcat 8
Classification: Unclassified
Component: Connectors
8.0.18
PC All
: P5 normal (vote)
: ----
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2015-02-18 13:51 UTC by Konstantin Kolinko
Modified: 2015-03-06 15:40 UTC (History)
0 users



Attachments
server.xml (6.88 KB, text/xml)
2015-02-18 13:53 UTC, Konstantin Kolinko
Details
localhost_access_log.2015-02-18.txt - Access Log - 8.0.20 (240 bytes, text/plain)
2015-02-18 13:54 UTC, Konstantin Kolinko
Details
catalina.2015-02-18.log - Log - 8.0.20 (32.19 KB, text/x-log)
2015-02-18 13:55 UTC, Konstantin Kolinko
Details
localhost_access_log.2015-02-18.txt - Access Log - 8.0.18 (240 bytes, text/plain)
2015-02-18 13:56 UTC, Konstantin Kolinko
Details
catalina.2015-02-18.log - Log - 8.0.18 (33.11 KB, text/x-log)
2015-02-18 13:57 UTC, Konstantin Kolinko
Details
localhost_access_log.2015-02-18.txt - Tomcat 9 @1660633 - Access Log (1.29 KB, text/plain)
2015-02-18 14:33 UTC, Konstantin Kolinko
Details
catalina.2015-02-18.log - Tomcat 9 @1660633 - Log (130.96 KB, text/x-log)
2015-02-18 14:33 UTC, Konstantin Kolinko
Details
hs_err_pid3936.log - Tomcat 9 @1660633 - Crash Log (30.20 KB, text/x-log)
2015-02-18 14:34 UTC, Konstantin Kolinko
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Kolinko 2015-02-18 13:51:28 UTC
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]
]]]
Comment 1 Konstantin Kolinko 2015-02-18 13:53:38 UTC
Created attachment 32488 [details]
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
Comment 2 Konstantin Kolinko 2015-02-18 13:54:36 UTC
Created attachment 32489 [details]
localhost_access_log.2015-02-18.txt  - Access Log - 8.0.20
Comment 3 Konstantin Kolinko 2015-02-18 13:55:20 UTC
Created attachment 32490 [details]
catalina.2015-02-18.log - Log - 8.0.20
Comment 4 Konstantin Kolinko 2015-02-18 13:56:26 UTC
Created attachment 32491 [details]
localhost_access_log.2015-02-18.txt - Access Log - 8.0.18
Comment 5 Konstantin Kolinko 2015-02-18 13:57:05 UTC
Created attachment 32492 [details]
catalina.2015-02-18.log - Log - 8.0.18
Comment 6 Konstantin Kolinko 2015-02-18 14:30:54 UTC
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.
Comment 7 Konstantin Kolinko 2015-02-18 14:33:11 UTC
Created attachment 32494 [details]
localhost_access_log.2015-02-18.txt - Tomcat 9 @1660633 - Access Log
Comment 8 Konstantin Kolinko 2015-02-18 14:33:41 UTC
Created attachment 32495 [details]
catalina.2015-02-18.log - Tomcat 9 @1660633 - Log
Comment 9 Konstantin Kolinko 2015-02-18 14:34:30 UTC
Created attachment 32496 [details]
hs_err_pid3936.log - Tomcat 9 @1660633 - Crash Log
Comment 10 Mark Thomas 2015-03-06 15:40:53 UTC
I could not reliably reproduce this. It looks like I have fixed this but do re-open it if you see it again.