Issue Details (XML | Word | Printable)

Key: GLASSFISH-19473
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Shing Wai Chan
Reporter: sonialiu
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
glassfish

Exception thrown in the server.log while testing servlet new method onError() in ServletInputStream class

Created: 20/Dec/12 08:02 PM   Updated: 26/Mar/13 09:48 PM   Resolved: 25/Mar/13 07:30 PM
Component/s: web_container
Affects Version/s: 4.0_b68_EE7MS3
Fix Version/s: 4.0_b82_EE7MS7

Time Tracking:
Not Specified

Environment:

oel 6


Tags:
Participants: Alex Pineda, Ryan Lubke, Shing Wai Chan and sonialiu


 Description  « Hide

Build: 12/20 nightly build
Steps to reproduce the bug:
1. Install GF4.0, start domain
2. Checkout SQE workspace cvs co appserver-sqe/bootstrap.xml
(CVSROOT: :pserver:<your cvs user name>@sunsw.us.oracle.com:/m/jws
cd appserver-sqe
ant -f bootstrap.xml co-tomcat
3.set env. variables
S1AS_HOME <GF install dir>, for example: /export/sonia/v4/glassfish3/glassfish
SPS_HOME <appserver-sqe>, for example: /export/sonia/appserver-sqe
ANT_HOME <ant location>, for example: /export/sonia/ant-1.7.1
JAVA_HOME <java location>, for example: /export/sonia/jdk1.7.0
4. cd /export/sonia/appserver-sqe/pe/tomcat/servlet/product_test/servlet3_1/nonBlockingInputError, run
ant build setup deploy run
5. The test passed but the server.log showed the following exceptions:
[#|2012-12-20T11:49:51.091-0800|INFO|44.0|javax.enterprise.logging.stdout|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991091;_LevelValue=800;|--> It's in onError|#]

[#|2012-12-20T11:49:51.093-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991093;_LevelValue=1000;|java.util.concurrent.CancellationException
at org.glassfish.grizzly.http.server.io.InputBuffer.terminate(InputBuffer.java:920)
at org.glassfish.grizzly.http.server.Request.onAfterService(Request.java:563)
at org.glassfish.grizzly.http.server.HttpServerFilter.afterService(HttpServerFilter.java:307)
at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:202)
at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:265)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:134)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:781)
at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:578)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:558)
at java.lang.Thread.run(Thread.java:722

-------------The full server.log is attached ----------------------



sonialiu added a comment - 20/Dec/12 08:06 PM

[#|2012-12-20T11:49:51.093-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991093;_LevelValue=1000;|java.util.concurrent.CancellationException
at org.glassfish.grizzly.http.server.io.InputBuffer.terminate(InputBuffer.java:920)
at org.glassfish.grizzly.http.server.Request.onAfterService(Request.java:563)
at org.glassfish.grizzly.http.server.HttpServerFilter.afterService(HttpServerFilter.java:307)
at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:202)
at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:265)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:134)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:781)
at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:578)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:558)
at java.lang.Thread.run(Thread.java:722)

#]

[#|2012-12-20T11:49:51.103-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991103;_LevelValue=1000;| at org.glassfish.grizzly.http.server.io.InputBuffer.terminate(InputBuffer.java:920)|#]

[#|2012-12-20T11:49:51.103-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991103;_LevelValue=1000;| at org.glassfish.grizzly.http.server.Request.onAfterService(Request.java:563)|#]

[#|2012-12-20T11:49:51.103-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991103;_LevelValue=1000;| at org.glassfish.grizzly.http.server.HttpServerFilter.afterService(HttpServerFilter.java:307)|#]

[#|2012-12-20T11:49:51.104-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991104;_LevelValue=1000;| at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:202)|#]

[#|2012-12-20T11:49:51.104-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991104;_LevelValue=1000;| at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)|#]

[#|2012-12-20T11:49:51.104-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991104;_LevelValue=1000;| at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:265)|#]

[#|2012-12-20T11:49:51.104-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991104;_LevelValue=1000;| at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)|#]

[#|2012-12-20T11:49:51.104-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991104;_LevelValue=1000;| at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:134)|#]

[#|2012-12-20T11:49:51.104-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991104;_LevelValue=1000;| at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)|#]

[#|2012-12-20T11:49:51.105-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991105;_LevelValue=1000;| at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)|#]

[#|2012-12-20T11:49:51.105-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991105;_LevelValue=1000;| at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:781)|#]

[#|2012-12-20T11:49:51.105-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991105;_LevelValue=1000;| at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)|#]

[#|2012-12-20T11:49:51.105-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991105;_LevelValue=1000;| at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)|#]

[#|2012-12-20T11:49:51.105-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991105;_LevelValue=1000;| at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)|#]

[#|2012-12-20T11:49:51.106-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991106;_LevelValue=1000;| at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)|#]

[#|2012-12-20T11:49:51.106-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991106;_LevelValue=1000;| at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:578)|#]

[#|2012-12-20T11:49:51.106-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991106;_LevelValue=1000;| at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:558)|#]

[#|2012-12-20T11:49:51.106-0800|SEVERE|44.0|javax.enterprise.logging.stderr|_ThreadID=78;_ThreadName=http-listener-1(1);_TimeMillis=1356032991106;_LevelValue=1000;| at java.lang.Thread.run(Thread.java:722)|#]


sonialiu added a comment - 03/Jan/13 08:40 PM

The test is no longer valid due to Servlet3.1 spec change, close the bug.


sonialiu added a comment - 08/Jan/13 06:41 PM

I have modified the test based on the Servlet3.1 Spec change, now I ran the test again, I still saw the same exception in the server.log. Reopen the bug.


Ryan Lubke added a comment - 15/Jan/13 11:12 PM

This is the stacktrace I'm seeing:

[#|2013-01-15T15:10:38.491-0800|WARNING|glassfish 4.0|org.glassfish.grizzly.filterchain.DefaultFilterChain|_ThreadID=23;_ThreadName=http-listener-1-0;_TimeMillis=1358291438491;_LevelValue=900;|Exception during FilterChain execution
java.lang.IllegalStateException: Request already released from asynchronous mode
        at org.apache.catalina.connector.Request.asyncComplete(Request.java:4380)
        at org.apache.catalina.connector.AsyncContextImpl.complete(AsyncContextImpl.java:268)
        at com.sun.s1wsqe.tomcat.servlet31.TestServlet$ReadListenerImpl.onError(TestServlet.java:73)
        at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.processError(InputBuffer.java:512)
        at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.onError(InputBuffer.java:488)
        at org.glassfish.grizzly.http.server.io.InputBuffer.terminate(InputBuffer.java:920)
        at org.glassfish.grizzly.http.server.Request.onAfterService(Request.java:563)
        at org.glassfish.grizzly.http.server.HttpServerFilter.afterService(HttpServerFilter.java:307)
        at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:232)
        at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:273)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:134)
        at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
        at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
        at org.glassfish.grizzly.filterchain.FilterChainContext$1.run(FilterChainContext.java:194)
        at org.glassfish.grizzly.filterchain.FilterChainContext.resume(FilterChainContext.java:218)
        at org.glassfish.grizzly.http.server.Response.resume(Response.java:1777)
        at org.apache.catalina.connector.Request.asyncComplete(Request.java:4388)
        at org.apache.catalina.connector.Request.errorDispatchAndComplete(Request.java:4471)
        at org.apache.catalina.connector.Request.asyncTimeout(Request.java:4410)
        at org.apache.catalina.connector.Request.processTimeout(Request.java:4434)
        at org.apache.catalina.connector.Request.access$000(Request.java:155)
        at org.apache.catalina.connector.Request$7.onTimeout(Request.java:4311)
        at org.glassfish.grizzly.http.server.Response$SuspendTimeout.onTimeout(Response.java:2006)
        at org.glassfish.grizzly.http.server.Response$DelayQueueWorker.doWork(Response.java:2055)
        at org.glassfish.grizzly.http.server.Response$DelayQueueWorker.doWork(Response.java:2050)
        at org.glassfish.grizzly.utils.DelayedExecutor$DelayedRunnable.run(DelayedExecutor.java:158)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)

Ryan Lubke added a comment - 15/Jan/13 11:22 PM

Assigning to Shing-Wai.

Based on the stacktrace, AsyncContext.complete() is being called twice. Once by the container (early in the stacktrace) and then again by the test's ReadHandler implementation.

I don't have the latest specification available to see if the spec requires that the handler call AsyncContext.complete() or not. Shing-Way should know for sure. If they shouldn't be, then it's a test bug, otherwise, it appears to be a container bug.


Shing Wai Chan added a comment - 18/Jan/13 01:06 AM

In Grizzly, the ReadHandler#onError is called before the completion handler. Need further investigation.


Shing Wai Chan added a comment - 23/Jan/13 07:41 PM

The async complete was invoked one more time by the container as #onError is called "after" async complete (completion handler in Grizzly) now. We need to investigate whether the async complete should be invoked later.


Shing Wai Chan added a comment - 31/Jan/13 12:08 AM

After updating packages on the testing machine, the test pass occasionally.

In NIOConnectionImpl, the default timeout for readTimeout, writeTimeout is 30 seconds.
The given test case has a sleep for 30 seconds.
If I change the sleep to 20 seconds, then the test passes.
This explains the issue.

In this case, the server should expose a way to set the timeout.


Alex Pineda added a comment - 15/Feb/13 09:26 PM

Request issue be resolved in GF 4.0 release.


Shing Wai Chan added a comment - 25/Mar/13 07:30 PM

This is due to mismatch the following:
a) during timeout, Grizzly will invoke the completion handler and #onError in a different order
b) a mismatch between ReadListener in Servlet and ReadHandler in Grizzly.

A fix / workaround has been check in to GlassFish side as follows:

Sending web-core/src/main/java/org/apache/catalina/connector/OutputBuffer.java
Sending web-core/src/main/java/org/apache/catalina/connector/Request.java
Sending web-core/src/main/java/org/apache/catalina/connector/Response.java
Transmitting file data ....
Committed revision 60774.


sonialiu added a comment - 26/Mar/13 04:50 PM

When I ran this test using latest nightly build(03/24) and I got the following exception in the client side
run:
[java] URL is http://localhost:8080//tomcat-servlet31-nonblockinginputNeg/nonBlockingInput
[java] Sleeping 60 sec
[java] java.io.IOException: Server returned HTTP response code: 500 for URL: http://localhost:8080//tomcat-servlet31-nonblockinginputNeg/nonBlockingInput
[java] at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1625)
[java] at WebTest.main(Unknown Source)
[java] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[java] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[java] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[java] at java.lang.reflect.Method.invoke(Method.java:601)
[java] at org.apache.tools.ant.taskdefs.ExecuteJava.run(ExecuteJava.java:217)
[java] at org.apache.tools.ant.taskdefs.ExecuteJava.execute(ExecuteJava.java:152)
[java] at org.apache.tools.ant.taskdefs.Java.run(Java.java:764)
[java] at org.apache.tools.ant.taskdefs.Java.executeJava(Java.java:218)
[java] at org.apache.tools.ant.taskdefs.Java.executeJava(Java.java:132)
[java] at org.apache.tools.ant.taskdefs.Java.execute(Java.java:105)
[java] at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
[java] at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
[java] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[java] at java.lang.reflect.Method.invoke(Method.java:601)
[java] at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:106)
[java] at org.apache.tools.ant.Task.perform(Task.java:348)
[java] at org.apache.tools.ant.Target.execute(Target.java:357)
[java] at org.apache.tools.ant.Target.performTasks(Target.java:385)
[java] at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1337)
[java] at org.apache.tools.ant.Project.executeTarget(Project.java:1306)
[java] at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41)
[java] at org.apache.tools.ant.Project.executeTargets(Project.java:1189)
[java] at org.apache.tools.ant.Main.runBuild(Main.java:758)
[java] at org.apache.tools.ant.Main.startAnt(Main.java:217)
[java] at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257)
[java] at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104)


sonialiu added a comment - 26/Mar/13 09:48 PM

Tried 03/26 nightly build and did not see the 500 error. Close the bug.