Issue Details (XML | Word | Printable)

Key: GLASSFISH-8042
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Critical Critical
Assignee: Justin Lee
Reporter: meenap
Votes: 0
Watchers: 4
Operations

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

Interruption of Idle HTTP Thread

Created: 28/Apr/09 11:48 AM   Updated: 26/Nov/10 12:06 AM   Resolved: 21/Sep/09 02:21 PM
Component/s: grizzly-kernel
Affects Version/s: V3
Fix Version/s: V3

Time Tracking:
Not Specified

File Attachments: 1. Text File server.log (399 kB) 28/Apr/09 11:52 AM - meenap

Environment:

Operating System: All
Platform: Sun

Issue Links:
Dependency
 

Issuezilla Id: 8,042
Tags:
Participants: Dhiru Pandey, jfarcand, Justin Lee, meenap and oleksiys


 Description  « Hide

Application: Web application, Nilebookstore
JDK 1.6.0_13 B03
Build: Glassfish B46 SDK B02 (java_ee_sdk-6-preview-b02-unix.sh)
Solaris 10 X86

When running longevity testing using Nilebookstore app, the following exceptions
are observed a few times in the middle of the run. The first exception is seen
after about 10.5 hours into the run. This is the first time this exception is
seen. There are about 66 client errors which happened when these exceptions
happened in the server logs. Please see the attached server log for all the
different exceptions.

At about 65 hours into the run, checked the application and it was working fine.
So the following errors have happened intermittently during the 3 days test.

[#|2009-04-25T03:05:44.403-0700|WARNING|glassfish|com.sun.grizzly.config.GrizzlyServiceListener|_ThreadID=16;_ThreadName=Thread-1;|Interrupting
idle Thread: http8080-WorkerThread(3)|#]

[#|2009-04-25T03:05:44.413-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|java.sql.SQLException:
Io
exception: Operation interrupted|#]

[#|2009-04-25T03:05:44.413-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:134)|#]

[#|2009-04-25T03:05:44.413-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:179)|#]

[#|2009-04-25T03:05:44.413-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:333)|#]

[#|2009-04-25T03:05:44.413-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
oracle.jdbc.driver.OracleStatement.doExecuteQuery(OracleStatement.java:2529)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:2672)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
oracle.jdbc.driver.OracleStatement.executeQuery(OracleStatement.java:572)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
NileBookStore.servlets.ShoppingCartServlet.processRequest(ShoppingCartServlet.java:59)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
NileBookStore.servlets.ShoppingCartServlet.doGet(ShoppingCartServlet.java:162)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1461)|#]

[#|2009-04-25T03:05:44.414-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:293)|#]
[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:187)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:656)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:97)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:85)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:185)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:351)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:249)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:140)|#]

[#|2009-04-25T03:05:44.415-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:740)|#]

[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:631)|#]

[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:900)|#]

[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:162)|#]

[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:136)|#]

[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:103)|#]

[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:89)|#]
[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:76)|#]

[#|2009-04-25T03:05:44.416-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:53)|#]

[#|2009-04-25T03:05:44.417-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:57)|#]

[#|2009-04-25T03:05:44.417-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at com.sun.grizzly.ContextTask.run(ContextTask.java:69)|#]

[#|2009-04-25T03:05:44.417-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)|#]

[#|2009-04-25T03:05:44.417-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)|#]

[#|2009-04-25T03:05:44.417-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|
at java.lang.Thread.run(Thread.java:619)|#]

[#|2009-04-25T03:05:44.417-0700|SEVERE|glassfish|null|_ThreadID=17;_ThreadName=Thread-1;|java.sql.SQLException:
Protocol violation|#]



meenap added a comment - 28/Apr/09 11:52 AM

Created an attachment (id=2678)
Server Log file which contains all the different exceptions


jfarcand added a comment - 28/Apr/09 12:53 PM

This is the expected behavior. In v3, Grizzly now kills connector/jdbc threads
that are idles for more than 15 minutes. But its seems the merge of
grizzly-config removed the 15 minutes (grizzly has 5 minutes). So this fix needs
to be re-added:

Author: jfarcand
Date: 2009-03-10 21:41:09+0000
New Revision: 25248

Modified:

trunk/v3/core/kernel/src/main/java/com/sun/enterprise/v3/services/impl/GrizzlyListenerConfigurator.java

Log:
Avoid timing out idle Threads when the debugger is on.

Collaborative works with Jerome Dochez

Modified:
trunk/v3/core/kernel/src/main/java/com/sun/enterprise/v3/services/impl/GrizzlyListenerConfigurator.java
Url:
https://glassfish-svn.dev.java.net/source/browse/glassfish-svn/trunk/v3/core/kernel/src/main/java/com/sun/enterprise/v3/services/impl/GrizzlyListenerConfigurator.java?view=diff&rev=25248&p1=trunk/v3/core/kernel/src/main/java/com/sun/enterprise/v3/services/impl/GrizzlyListenerConfigurator.java&p2=trunk/v3/core/kernel/src/main/java/com/sun/enterprise/v3/services/impl/GrizzlyListenerConfigurator.java&r1=25247&r2=25248
==============================================================================

trunk/v3/core/kernel/src/main/java/com/sun/enterprise/v3/services/impl/GrizzlyListenerConfigurator.java
(original)
+++
trunk/v3/core/kernel/src/main/java/com/sun/enterprise/v3/services/impl/GrizzlyListenerConfigurator.java
2009-03-10 21:41:09+0000
@@ -45,6 +45,7 @@
import com.sun.grizzly.arp.AsyncHandler;
import com.sun.grizzly.arp.AsyncFilter;
import com.sun.logging.LogDomains;
+import java.lang.management.ManagementFactory;
import java.util.LinkedList;

import java.util.concurrent.TimeUnit;
@@ -155,10 +156,22 @@
configureComet(grizzlyEmbeddedHttp);
}

  • // Idle Threads cannot be alive more than 15 minutes....
  • // Must be 5 minutes, but until we officially supports that feature
  • // Set it to 15 minutes so debugging session are killed
  • grizzlyEmbeddedHttp.setTransactionTimeout(15 * 60 * 1000);
    + List<String> l = ManagementFactory.getRuntimeMXBean().getInputArguments();
    + boolean debugMode = false;
    + for (String s: l)
    Unknown macro: {+ if (s.trim().startsWith("-Xrunjdwp}

    +
    + if (!debugMode){ + // Idle Threads cannot be alive more than 15 minutes by default + grizzlyEmbeddedHttp.setTransactionTimeout(15 * 60 * 1000); + } else { + // Disable the mechanism + grizzlyEmbeddedHttp.setTransactionTimeout(-1); + }
    }

Re-assign to Justin so he can re-add it. Meena, you can increase the value by
adding -Dcom.sun.grizzly.idleThreadTimeout=XXX.

Justin, we also need to expose that property in grizzly-config.


Justin Lee added a comment - 29/Apr/09 02:28 PM

fixed in grizzly-config 1.0.3. integration pending trunk unfreeze.


Justin Lee added a comment - 29/Apr/09 02:36 PM

tracking this


meenap added a comment - 01/May/09 01:00 PM

Is this fix in promoted B47 SDK B03 ? If not, please let me know which build
this fix will be available.


meenap added a comment - 19/May/09 01:09 PM

Tested on B47b SDK B03b but still seeing this same issue again. Can you tell me
where is the fix for this issue ?


Justin Lee added a comment - 20/May/09 08:16 AM

taking a look now


Justin Lee added a comment - 24/Jun/09 11:08 AM

when was the last time this was tested on the trunk builds? I just stepped
through the code and can confirm that we are indeed setting the timeout to -1
which should disable it.


Justin Lee added a comment - 30/Jun/09 08:55 AM

new devtest confirms this fix for 5 sec thread timeouts for both debug and
non-debug VMs


meenap added a comment - 29/Jul/09 11:35 AM

Build 55
JDK1.6.0_14 B08
Solaris 10 X86
App: Nilebookstore in SSL Mode

Re-opening this bug as I am seeing this issue again during longevity testing in
Nilebookstore ssl mode testing. It happened only once and after about 57 hours.
When this warning message was seen, at the same time there were about 2318
client errors. The application links were not accessible at this time.

[#|2009-07-26T09:47:52.792-0700|INFO|glassfish|org.jvnet.hk2.osgiadapter|_ThreadID=16;_ThreadName=Thread-1;org.glassfish.connectors.work-management
[106];|Started bundle org.glassfish.connectors.work-management [106]|#]

[#|2009-07-28T19:11:59.142-0700|WARNING|glassfish|com.sun.grizzly.config.GrizzlyServiceListener|_ThreadID=17;_ThreadName=Thread-1;|Interrupting
idle Thread: http8181-WorkerThread(1)|#]


meenap added a comment - 29/Jul/09 12:20 PM

To clarify things:

The original issue that happened in Nilebookstore non-ssl mode (http) is fixed
and verified in B55. I am seeing the same WARNING message in Nilebookstore SSL
Mode (https) in B55.


Dhiru Pandey added a comment - 29/Jul/09 01:54 PM

Added Alexey


Justin Lee added a comment - 07/Aug/09 01:39 PM

investigating now


Justin Lee added a comment - 14/Aug/09 08:32 AM

found a minor regression that might apply here.


Justin Lee added a comment - 19/Aug/09 07:00 PM

I haven't been able to track down anything on this one. Clearly the setting
works because it made it that far. But just as clearly, that thread died/was
killed for some reason. I didn't see anything in the logs at all. Could the OS
have claimed that socket back?


oleksiys added a comment - 20/Aug/09 01:50 AM

Justin, do we have specifically thread interruption test for HTTPS listener?
I know it should work the same way as HTTP, but just in case we missed something...


Justin Lee added a comment - 20/Aug/09 09:00 AM

We don't. the time out settings are applied generically to the SelectorThread


Justin Lee added a comment - 15/Sep/09 07:56 AM

Is this still an issue? My tests indicate that things are copacetic but what do
the endurance tests show?


meenap added a comment - 21/Sep/09 02:20 PM

The last NileBookStore (SSL) run I did was on B57 on RH. During 7 days run, this
issue was not seen. Marking this issue as verified.


meenap added a comment - 21/Sep/09 02:21 PM

Closing this issue.