glassfishrobot commented 12 years ago

Build : 3.1.2 build 17 , JRockit VM 6u29., OEL6

When running HA Stress tests we are observing traffic loss when a cluster instance is restarting. There is a time gap between the time when port 8080 is up and application loading is done. Loadbalancer probably detects http port is up and starts forwarding traffic. In this particular case, the time is approx. 11 sec and the request rate is 25 reqs/instance. 325 requests failed.

The client receives a 404 during this time :

SEVERE: 4xx or 5xx Response code - 404 HttpClientSession-47926 Jan 17, 2012 10:58:01 PM com.sun.dft.glassfish.stress.ReadWriteTest$MyTestListener postInvoke SEVERE: <Unable to render embedded object: File (//www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">GlassFish v3 - Error report

HTTP Status 404 -

type Status report

message

descriptionThe requested resource () is not available.

GlassFish Server Open Source Edition 3.1.2-b17

Server log :

http://agni-1.us.oracle.com/net/asqe-logs.us.oracle.com/export1/3.1.2/Results/build17/ha/oel6_stress/stress/com.sun.dft.glassfish.stress.ReadWriteTest/testReadWrite/logs/st-cluster/instance101/logs/server.log

Environment

OEL6 + JRockit

Affected Versions

[3.1.2]

glassfishrobot commented 6 years ago

Issue Imported From: https://github.com/javaee/glassfish/issues/18267
Original Issue Raised By:@glassfishrobot
Original Issue Assigned To: @yaminikb
Original Issue Closed By:@glassfishrobot

glassfishrobot commented 12 years ago

@glassfishrobot Commented @shingwaichan said: I notice the following in the server.log:

exception or error occurred in the container during the request processing java.lang.NullPointerException at org.shoal.adapter.store.ReplicatedBackingStore.load(ReplicatedBackingStore.java:97) at org.glassfish.web.ha.session.management.ReplicationStore.loadFromBackingStore(ReplicationStore.java:407) at org.glassfish.web.ha.session.management.ReplicationStore.load(ReplicationStore.java:396) at org.apache.catalina.session.PersistentManagerBase.doSwapIn(PersistentManagerBase.java:1052) at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:1015) at org.glassfish.web.ha.session.management.ReplicationManagerBase.findSession(ReplicationManagerBase.java:151) at org.apache.catalina.connector.Request.doGetSession(Request.java:2852) at org.apache.catalina.connector.Request.getSessionInternal(Request.java:2777) at org.apache.catalina.connector.Request.unlockSession(Request.java:4201) at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:342) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231) at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:174) at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:849) at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:746) at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1045) at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:228) at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90) at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79) at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54) at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59) at com.sun.grizzly.ContextTask.run(ContextTask.java:71) at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532) at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513) at java.lang.Thread.run(Thread.java:662)

glassfishrobot commented 12 years ago

@glassfishrobot Commented @shingwaichan said: Assign to shoal team to investigate the NPE from org.shoal.adapter.store.ReplicatedBackingStore.load(ReplicatedBackingStore.java:97).

glassfishrobot commented 12 years ago

@glassfishrobot Commented @jfialli said: The reported NPE in shoal is happening AFTER the clustered instance is started and immediately stops. Here are relevant log messages. Shoal GMS has an glassfish PREPARE_SHUTDOWN event handler. As part of that handling, GMS leaves the cluster. The server initiated shutdown is at 22:52:23.747. I can not tell if someone ran "asadmin stop-instance" on the instance or if something failed in the startup of the server and then glassfish server shutdown was initiated. The NPE is not causing the server to shutdown, the NPE is occurring after the instance leaves the gms cluster. The shoal cache code is not handling quick shutdown properly but I do not think that is the main issue for this bug.

[#|2012-01-17T22:52:25.453-0800|SEVERE|glassfish3.1.2|org.apache.catalina.connector.CoyoteAdapter|_ThreadID=29;_ThreadName=Thread-2;|PWC3989: An exception or error occurred in the container during the request processing java.lang.NullPointerException at org.shoal.adapter.store.ReplicatedBackingStore.load(ReplicatedBackingStore.java:97) at org.glassfish.web.ha.session.management.ReplicationStore.loadFromBackingStore(ReplicationStore.java:407) at org.glassfish.web.ha.session.management.ReplicationStore.load(ReplicationStore.java:396) at org.apache.catalina.session.PersistentManagerBase.doSwapIn(PersistentManagerBase.java:1052) at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:1015) at org.glassfish.web.ha.session.management.ReplicationManagerBase.findSession(ReplicationManagerBase.java:151) at org.apache.catalina.connector.Request.doGetSession(Request.java:2852) at org.apache.catalina.connector.Request.getSessionInternal(Request.java:2777) at org.apache.catalina.connector.Request.unlockSession(Request.java:4201) at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:342) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231) at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:174) at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.ja3DThread-2;|PWC3989: An exception or error occurred in the container during the request processing java.lang.NullPointerException at org.shoal.adapter.store.ReplicatedBackingStore.load(ReplicatedBackingStore.java:97) at org.glassfish.web.ha.session.management.ReplicationStore.loadFromBackingStore(ReplicationStore.java:407) at org.glassfish.web.ha.session.management.ReplicationStore.load(ReplicationStore.java:396) at org.apache.catalina.session.PersistentManagerBase.doSwapIn(PersistentManagerBase.java:1052) at org.apache.catalina.session.PersistentManagerBase.swapIn(PersistentManagerBase.java:1015) at org.glassfish.web.ha.session.management.ReplicationManagerBase.findSession(ReplicationManagerBase.java:151) at org.apache.catalina.connector.Request.doGetSession(Request.java:2852) at org.apache.catalina.connector.Request.getSessionInternal(Request.java:2777) at org.apache.catalina.connector.Request.unlockSession(Request.java:4201) at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:342) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter Bug tracking, issue tracking and project management software powered by Atlassian JIRA (v4.0.2#472) | Report a problem | Request a feature | Contact administrators

glassfishrobot commented 12 years ago

@glassfishrobot Commented @jfialli said: The NPE in shoal cache in this bug report duplicates #18268 after instance shutdown is initiated"). The NPE is happening AFTER the instance is shutdown.

[#|2012-01-17T22:52:25.453-0800|SEVERE|glassfish3.1.2|org.apache.catalina.connector.CoyoteAdapter|_ThreadID=29;_ThreadName=Thread-2;|PWC3989: An exception or error occurred in the container during the request processing java.lang.NullPointerException at org.shoal.adapter.store.ReplicatedBackingStore.load(ReplicatedBackingStore.java:97)

glassfishrobot commented 12 years ago

@glassfishrobot Commented sonymanuel said: To clarify NPE is reported as a separate bug 18268. It has not connection with this particular issue.

Test scenario is as follows :

1. Deploy app. 2. Start http traffic (75 new requests per sec) 3. After 5 minutes, stop a cluster instance (asadmin stop-instance)

This shows the NPE in server logs (18268) 4. After 5 minutes, start instance. During the instance start there is traffic loss (this issue). LB probably detects http port is up and starts forwarding traffic. But the application loading is not complete. 5. After startup is complete test runs fine for few hours.

glassfishrobot commented 12 years ago

@glassfishrobot Commented @jfialli said: this bug is concerning the http traffic loss. The NPE in shoal cache is occurring after the server instance is being shutdown. This issue is already reported as GF-18268 and has nothing to do with the traffic loss. The instance is already shutdown when the NPE is occurring (as described in 18268).

The NPE is 2 seconds after server shutdown was initiated. This is exactly what #18268 after instance shutdown is initiated") in the server.log attached to this issue.

To summarize, see that server shutdown is initiated (probably by asdmin stop-instance) and then the NPE happens 2 seconds later.

|2012-01-17T22:52:23.747-0800|INFO|glassfish3.1.2|javax.enterprise.system.tools.admin.com.sun.enterprise.v3.admin.cluster|_ThreadID=22;_ThreadName=Thread-2;|

Server shutdown initiated|#]

[#|2012-01-17T22:52:25.453-0800|SEVERE|glassfish3.1.2|org.apache.catalina.connector.CoyoteAdapter|_ThreadID=29;_ThreadName=Thread-2;|PWC3989: An exception or error occurred in the container during the request processing java.lang.NullPointerException at org.shoal.adapter.store.ReplicatedBackingStore.load(ReplicatedBackingStore.java:97)

glassfishrobot commented 12 years ago

@glassfishrobot Commented sb110099 said: Upgrading to P2 as discussed with Sony .

glassfishrobot commented 12 years ago

@glassfishrobot Commented @shingwaichan said: While AppServerStartup.run, the following is called in order: (a) GrizzlyService create a GrizzlyProxy, which creates ContainerMapper and Mapper. (b) WebContainer.postConstruct is invoked and then calls Connector.start and the above mapper is set. (c) WebApplication.start is called for each web application

If the request comes before (b) or (c) are done, then ContainerMapper will process the request and hence 404 in this case.

The fix should be to let (b) and (c) finish. Then the request will be handled by CoyoteAdapter. One may need a mechanism to notify that the loading is started and done.

glassfishrobot commented 12 years ago

@glassfishrobot Commented @shingwaichan said: In this case, Grizzly should not process the request before (b) and (c) are completed.

glassfishrobot commented 12 years ago

@glassfishrobot Commented @barchetta said: As discussed in Bug Swat we will not stop the 3.1.2 release to fix this bug, therefore I am excluding it from the release. Note that these tests (HA stress) were not run on 3.1.1 so it is difficult to know if this is a regression or not, but engineering thinks that the same design problem exists in 3.1.1.

glassfishrobot commented 12 years ago

@glassfishrobot Commented oleksiys said: not sure I understand why it's assigned to Grizzly... Grizzly has no idea if any other container is going or not going to be started as part of GF startup.

glassfishrobot commented 12 years ago

@glassfishrobot Commented @shingwaichan said: One can know when other containers are started in AppServerStartup.run. The issue is in GrizzlyService (a) above. (a) has done the following: set up mapper (ii) creates ContainerMapper (iii) ContainerMapper serves requests.

need to happens before (b) above. (iii) need to happens after other containers are started.

The fix need to separate and (iii) within (a). That is why I assign the issue to Grizzly team.

glassfishrobot commented 12 years ago

@glassfishrobot Commented junesm said: Added to the 3.1.2 Release Notes:

Description

A traffic loss occurs when a clustered server instance is restarting. There is a time gap of a few seconds between when port 8080 is running and when application loading is complete. During this gap client requests are denied with a 404 error.

Workaround

None. The client must retry the request after application loading is complete.

glassfishrobot commented 12 years ago

@glassfishrobot Commented oleksiys said: Should be fixed as part of #18211 fix.

glassfishrobot commented 11 years ago

@glassfishrobot Commented tmueller said: Has this issue been resolved in 4.0?

glassfishrobot commented 11 years ago

@glassfishrobot Commented oleksiys said: It hasn't. This issue and #18211 have to be revisited for Glassfish v4.

glassfishrobot commented 11 years ago

@glassfishrobot Commented oleksiys said: fixed

Project: glassfish Revision: 62129 Author: oleksiys Date: 2013-05-30 01:27:59 UTC

Log Message:

fix issue #18267 https://java.net/jira/browse/GLASSFISH-18267

"Traffic loss during instance start between the time 8080 is up and application is loaded"

Startup AJP/JK listener only after receiving Glassfish SERVER_READY event

glassfishrobot commented 11 years ago

@glassfishrobot Commented grisdal said: The following has been added to the release notes:

Traffic loss during instance start between the time 8080 is up and application is loaded (18267)

Description A traffic loss occurs when a clustered server instance is restarting. There is a time gap of a few seconds between when port 8080 is running and when application loading is complete. During this gap client requests are denied with a 404 error.

Workaround None. The client must retry the request after application loading is complete.

glassfishrobot commented 11 years ago

@glassfishrobot Commented grisdal said: Actually, looks like the write-up was carried forward from the 3.1.2 Release Notes.

glassfishrobot commented 11 years ago

@glassfishrobot Commented oleksiys said: @Gail

can we change the description a bit like:

Traffic loss during instance start between the time AJP (Apache) connector port is up and application is loaded (18267)

Description A traffic loss occurs when a clustered server instance is restarting. There is a time gap of a few seconds between when AJP (Apache) connector port is running and when application loading is complete. During this gap client requests are denied with a 404 error.

glassfishrobot commented 11 years ago

@glassfishrobot Commented dlaudams said: A workaround:

GlassFish will not start without an enabled listener. To get around this I add a secondary listener on a different port, disable the primary listener, restart/deploy, and then enabled the primary listener when running again.

My deployment sequence looks like this:

asadmin set server.network-config.network-listeners.network-listener.http-listener-1.enabled=false asadmin undeploy asadmin stop-domain domain1 asadmin start-domain domain1 asadmin deploy --name asadmin set server.network-config.network-listeners.network-listener.http-listener-1.enabled=true

Another benefit is that post-deployment checkout can be done against the secondary port before enabling the primary port.

glassfishrobot commented 11 years ago

@glassfishrobot Commented grisdal said: Revised the Description in the release notes write-up to now read:

A traffic loss occurs when a clustered server instance is restarting. There is a time gap of a few seconds between when the AJP (Apache) connector port is running and when application loading is complete. During this gap client requests are denied with a 404 error.

I left the title as it was because that reflects the actual title of the JIRA issue.

glassfishrobot commented 11 years ago

@glassfishrobot Commented oleksiys said: Ok, thank you Gail!

glassfishrobot commented 12 years ago

@glassfishrobot Commented File: framework.log.1 Attached By: sonymanuel

glassfishrobot commented 12 years ago

@glassfishrobot Commented File: server.log Attached By: sonymanuel

glassfishrobot commented 12 years ago

@glassfishrobot Commented Issue-Links: depends on GLASSFISH-18268 is related to GLASSFISH-18211

glassfishrobot commented 12 years ago

@glassfishrobot Commented Was assigned to oleksiys

glassfishrobot commented 7 years ago

@glassfishrobot Commented This issue was imported from java.net JIRA GLASSFISH-18267

glassfishrobot commented 12 years ago

@glassfishrobot Commented Reported by sonymanuel

glassfishrobot commented 11 years ago

@glassfishrobot Commented Marked as fixed on Wednesday, May 29th 2013, 6:55:13 pm

eclipse-ee4j / glassfish

Traffic loss during instance start between the time 8080 is up and application is loaded #18267

HTTP Status 404 -

GlassFish Server Open Source Edition 3.1.2-b17

Environment

Affected Versions

|2012-01-17T22:52:23.747-0800|INFO|glassfish3.1.2|javax.enterprise.system.tools.admin.com.sun.enterprise.v3.admin.cluster|_ThreadID=22;_ThreadName=Thread-2;|

Log Message: