[JBoss JIRA] (AS7-5224) [JBoss 7.1.0.Final] High CPU usage for single-core CPU VMWare virtual machine running Redhat 6 OS
by Rysic Rychu (JIRA)
[ https://issues.jboss.org/browse/AS7-5224?page=com.atlassian.jira.plugin.s... ]
Rysic Rychu commented on AS7-5224:
----------------------------------
I can see the same sytuation in my openSUSE. I just installed JBoss 7.1.1 to learn it and when I start it:
kamil@linux-j4ud:/opt> /opt/jboss-as-7/bin/standalone.sh &
[1] 17111
kamil@linux-j4ud:/opt> =========================================================================
JBoss Bootstrap Environment
JBOSS_HOME: /opt/jboss-as-7
JAVA: /usr/lib64/jvm/jre/bin/java
JAVA_OPTS: -server -XX:+UseCompressedOops -XX:+TieredCompilation -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Dorg.jboss.resolver.warning=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -Djboss.server.default.config=standalone.xml
=========================================================================
OpenJDK 64-Bit Server VM warning: ignoring option MaxPermSize=256m; support was removed in 8.0
01:11:48,463 INFO [org.jboss.modules] JBoss Modules version 1.1.1.GA
01:11:48,639 INFO [org.jboss.msc] JBoss MSC version 1.0.2.GA
01:11:48,691 INFO [org.jboss.as] JBAS015899: JBoss AS 7.1.1.Final "Brontes" starting
kamil@linux-j4ud:/opt>
Then I see that one core is always 100% utylized:
http://ifotos.pl/zobacz/jbosshtop_wreeqwx.png
> [JBoss 7.1.0.Final] High CPU usage for single-core CPU VMWare virtual machine running Redhat 6 OS
> -------------------------------------------------------------------------------------------------
>
> Key: AS7-5224
> URL: https://issues.jboss.org/browse/AS7-5224
> Project: Application Server 7
> Issue Type: Bug
> Components: Server
> Affects Versions: 7.1.0.Final
> Environment: -bash-4.1$ cat /proc/version
> Linux version 2.6.32-279.el6.x86_64 (mockbuild(a)x86-008.build.bos.redhat.com) (gcc version 4.4.6 20120305 (Red Hat 4.4.6-4) (GCC) ) #1 SMP Wed Jun 13 18:24:36 EDT 2012
> -bash-4.1$ cat /proc/cpuinfo
> processor : 0
> vendor_id : GenuineIntel
> cpu family : 6
> model : 44
> model name : Intel(R) Xeon(R) CPU X5650 @ 2.67GHz
> stepping : 2
> cpu MHz : 2666.761
> cache size : 12288 KB
> fpu : yes
> fpu_exception : yes
> cpuid level : 11
> wp : yes
> flags : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss syscall nx rdtscp lm constant_tsc up arch_perfmon pebs bts xtopology tsc_reliable nonstop_tsc aperfmperf unfair_spinlock pni pclmulqdq ssse3 cx16 sse4_1 sse4_2 popcnt aes hypervisor lahf_lm ida arat epb dts
> bogomips : 5333.52
> clflush size : 64
> cache_alignment : 64
> address sizes : 40 bits physical, 48 bits virtual
> power management:
> -bash-4.1$ cat /proc/meminfo
> MemTotal: 3925212 kB
> MemFree: 328048 kB
> Buffers: 21276 kB
> Cached: 3268128 kB
> SwapCached: 180 kB
> Active: 1832808 kB
> Inactive: 1475292 kB
> Active(anon): 3104 kB
> Inactive(anon): 16008 kB
> Active(file): 1829704 kB
> Inactive(file): 1459284 kB
> Unevictable: 0 kB
> Mlocked: 0 kB
> SwapTotal: 8388600 kB
> SwapFree: 8387940 kB
> Dirty: 0 kB
> Writeback: 0 kB
> AnonPages: 18624 kB
> Mapped: 12656 kB
> Shmem: 416 kB
> Slab: 220480 kB
> SReclaimable: 196296 kB
> SUnreclaim: 24184 kB
> KernelStack: 792 kB
> PageTables: 6980 kB
> NFS_Unstable: 0 kB
> Bounce: 0 kB
> WritebackTmp: 0 kB
> CommitLimit: 10351204 kB
> Committed_AS: 102640 kB
> VmallocTotal: 34359738367 kB
> VmallocUsed: 283176 kB
> VmallocChunk: 34359452028 kB
> HardwareCorrupted: 0 kB
> AnonHugePages: 0 kB
> HugePages_Total: 0
> HugePages_Free: 0
> HugePages_Rsvd: 0
> HugePages_Surp: 0
> Hugepagesize: 2048 kB
> DirectMap4k: 10240 kB
> DirectMap2M: 4184064 kB
> Reporter: Claudiu Muresan
> Assignee: Jason Greene
> Attachments: boot.log, jboss-modules-2012-08-14-shutdown.zip, jstack.thread.dump, process.args, standalone.conf, standalone.xml, top
>
>
> When starting JBoss server in standalone configuration we have 100% CPU usage.
> There are no deployments.
> Please view attached items: thread dump, standalone.conf, standalone.xml.
> The JVM version is -bash-4.1$ ./java -version
> java version "1.6.0_27"
> Java(TM) SE Runtime Environment (build 1.6.0_27-b07)
> Java HotSpot(TM) 64-Bit Server VM (build 20.2-b06, mixed mode)
> .
> Tried also with the latest JVM version (6u33) => high CPU usage.
> Tried also with 7.1.1 Final and same configuration(standalone.conf/standalone.xml) => high CPU usage.
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFCORE-494) Timestamped GC logs in domain mode
by James Livingston (JIRA)
[ https://issues.jboss.org/browse/WFCORE-494?page=com.atlassian.jira.plugin... ]
James Livingston commented on WFCORE-494:
-----------------------------------------
Two possible solutions come to mind are setting some variables when processing the options for individual server starts, such as $SERVER_START_TIMESTAMP for this use case, or adding a <gc-logging> element to the JVM configuration which abstracts across the JVM-specific details (and supports timestamps in file names).
> Timestamped GC logs in domain mode
> ----------------------------------
>
> Key: WFCORE-494
> URL: https://issues.jboss.org/browse/WFCORE-494
> Project: WildFly Core
> Issue Type: Feature Request
> Components: Domain Management
> Affects Versions: 1.0.0.Alpha15
> Reporter: James Livingston
> Assignee: Brian Stansberry
>
> In standalone mode, you can add "-Xloggc:gc.log.`date +%Y%m%d%H%M%S`" (or Windows equivalent batch scripting) to have timestamped GC logs which is useful to prevent them from being overwritten when a server is restarted. This does not work in domain mode, since JBoss obviously does not process the back-ticks like a shell interpreter.
> It would be useful to be able to get time-stamped gc logs in domain mode.
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFCORE-494) Timestamped GC logs in domain mode
by James Livingston (JIRA)
James Livingston created WFCORE-494:
---------------------------------------
Summary: Timestamped GC logs in domain mode
Key: WFCORE-494
URL: https://issues.jboss.org/browse/WFCORE-494
Project: WildFly Core
Issue Type: Feature Request
Components: Domain Management
Affects Versions: 1.0.0.Alpha15
Reporter: James Livingston
Assignee: Brian Stansberry
In standalone mode, you can add "-Xloggc:gc.log.`date +%Y%m%d%H%M%S`" (or Windows equivalent batch scripting) to have timestamped GC logs which is useful to prevent them from being overwritten when a server is restarted. This does not work in domain mode, since JBoss obviously does not process the back-ticks like a shell interpreter.
It would be useful to be able to get time-stamped gc logs in domain mode.
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (SECURITY-871) AdvancedLdapLoginModule should be able to retrieve bindCredential from Vault
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/SECURITY-871?page=com.atlassian.jira.plug... ]
RH Bugzilla Integration commented on SECURITY-871:
--------------------------------------------------
Jimmy Wilson <jawilson(a)redhat.com> changed the Status of [bug 1174871|https://bugzilla.redhat.com/show_bug.cgi?id=1174871] from ASSIGNED to ON_QA
> AdvancedLdapLoginModule should be able to retrieve bindCredential from Vault
> ----------------------------------------------------------------------------
>
> Key: SECURITY-871
> URL: https://issues.jboss.org/browse/SECURITY-871
> Project: PicketBox
> Issue Type: Bug
> Components: Negotiation
> Reporter: Derek Horton
> Assignee: Darran Lofthouse
> Fix For: Negotiation_2_3_6_Final
>
>
> AdvancedLdapLoginModule should be able to retrieve bindCredential from Vault
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFLY-1904) Usage of vault for system-properties throws java.lang.SecurityException
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/WFLY-1904?page=com.atlassian.jira.plugin.... ]
RH Bugzilla Integration commented on WFLY-1904:
-----------------------------------------------
Jimmy Wilson <jawilson(a)redhat.com> changed the Status of [bug 1174871|https://bugzilla.redhat.com/show_bug.cgi?id=1174871] from ASSIGNED to ON_QA
> Usage of vault for system-properties throws java.lang.SecurityException
> -----------------------------------------------------------------------
>
> Key: WFLY-1904
> URL: https://issues.jboss.org/browse/WFLY-1904
> Project: WildFly
> Issue Type: Bug
> Components: Security
> Affects Versions: 8.0.0.Beta1
> Reporter: Navin Surtani
> Assignee: Brian Stansberry
> Fix For: 8.1.0.CR1, 8.1.0.Final
>
>
> Steps to Reproduce: 1. add the lines in standalone.xml:-
> {code}
> <system-properties>
> <property name="javax.net.ssl.trustStore" value="/dir/truststore.jks"/>
> <property name="javax.net.ssl.trustStorePassword" value="${VAULT::blk::attr::MTBlYWUzNDEtMjI2MC00NWYzLWFiZmUtM2EyYjZkNDgyZWM4TElORV9CUkVBS215YWxpYXM=}" />
> </system-properties>
> <vault>
> <vault-option name="KEYSTORE_URL" value="/opt/jboss-eap-6.0/standalone/configuration/vault.jks"/>
> <vault-option name="KEYSTORE_PASSWORD" value="MASK-2gTQPnrWJaqrh0pURMKAOw"/>
> <vault-option name="KEYSTORE_ALIAS" value="myalias"/>
> <vault-option name="SALT" value="12345678"/>
> <vault-option name="ITERATION_COUNT" value="44"/>
> <vault-option name="ENC_FILE_DIR" value="/opt/jboss-eap-6.0/standalone/configuration/"/>
> </vault>
> {code}
> 2. start EAP6 in standalone mode
> project_key: JBPAPP6
> Usage of vault for system-properties throws java.lang.SecurityException.
> boot.log:-
> {code}
> 20:35:30,267 ERROR [org.jboss.as.controller.management-operation] JBAS014612: Operation ("add") failed - address: ([("system-property" => "javax.net.ssl.trustStorePassword")]): java.lang.SecurityException: JBAS013322: Vault is not initialized
> at org.jboss.as.security.vault.RuntimeVaultReader.retrieveFromVault(RuntimeVaultReader.java:98) [jboss-as-security-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.server.RuntimeExpressionResolver.resolvePluggableExpression(RuntimeExpressionResolver.java:45) [jboss-as-server-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.ExpressionResolverImpl.resolveExpressionsRecursively(ExpressionResolverImpl.java:58) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.ExpressionResolverImpl.resolveExpressions(ExpressionResolverImpl.java:40) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.ModelControllerImpl.resolveExpressions(ModelControllerImpl.java:455) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.OperationContextImpl.resolveExpressions(OperationContextImpl.java:689) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.operations.common.SystemPropertyAddHandler.execute(SystemPropertyAddHandler.java:112) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:397) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.AbstractOperationContext.doCompleteStep(AbstractOperationContext.java:284) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.AbstractOperationContext.completeStep(AbstractOperationContext.java:211) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.ModelControllerImpl.boot(ModelControllerImpl.java:175) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:191) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.server.ServerService.boot(ServerService.java:295) [jboss-as-server-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.server.ServerService.boot(ServerService.java:270) [jboss-as-server-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:156) [jboss-as-controller-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
> at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_37]
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFLY-4234) EjbSuspendInterceptor doesn't play well with undeploy
by Richard Achmatowicz (JIRA)
[ https://issues.jboss.org/browse/WFLY-4234?page=com.atlassian.jira.plugin.... ]
Richard Achmatowicz updated WFLY-4234:
--------------------------------------
Description:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
In this case, it seems that once the EJB components have been stopped, the cache entries for their state have been passivated before the invocation has completed.
Do we need more mechanism for such cases? Like calling some thing on undeployment which will case the control points to be paused as well as allowing active requests to finish, subject to some timeout?
was:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
In this case, it seems that once the EJB components have been stopped, the cache entries for their state have been passivated before the invocation has completed.
Do we need more mechanism for such cases?
> EjbSuspendInterceptor doesn't play well with undeploy
> ------------------------------------------------------
>
> Key: WFLY-4234
> URL: https://issues.jboss.org/browse/WFLY-4234
> Project: WildFly
> Issue Type: Bug
> Components: EJB
> Affects Versions: 9.0.0.Alpha1
> Reporter: Richard Achmatowicz
> Assignee: Stuart Douglas
>
> The scenario is performing undeployment of an EJB application in the presence of incoming requests.
> If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
> In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
> - an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
> - undeployment is initiated and suspend is called on the ControlPoint for X
> - undeployment proceeds, removing certain resources required for the invocation
> - the active invocation fails due to resources not being available
> Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
> This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
> {code}
> [0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
> 14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
> 14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
> 14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
> 14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
> 14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
> 14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
> 14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
> CLIENT: making invocation on bean: value = 1
> 14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
> 14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
> CLIENT: made invocation on bean [ node-0 ]: new value = 2
> 14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
> CLIENT: making invocation on bean: value = 2
> 14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
> 14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
> 14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> at org.jboss.threads.JBossThread.run(JBossThread.java:320)
> 14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
> 14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
> 14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
> 14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
> 14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
> 14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
> 14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
> 14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
> 14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
> 14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
> {code}
>
> Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
> In this case, it seems that once the EJB components have been stopped, the cache entries for their state have been passivated before the invocation has completed.
> Do we need more mechanism for such cases? Like calling some thing on undeployment which will case the control points to be paused as well as allowing active requests to finish, subject to some timeout?
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFLY-4234) EjbSuspendInterceptor doesn't play well with undeploy
by Richard Achmatowicz (JIRA)
[ https://issues.jboss.org/browse/WFLY-4234?page=com.atlassian.jira.plugin.... ]
Richard Achmatowicz updated WFLY-4234:
--------------------------------------
Description:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
In this case, it seems that once the EJB components have been stopped, the cache entries for their state have been passivated before the invocation has completed.
Do we need more mechanism for such cases?
was:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
Do we need more mechanism for such cases?
> EjbSuspendInterceptor doesn't play well with undeploy
> ------------------------------------------------------
>
> Key: WFLY-4234
> URL: https://issues.jboss.org/browse/WFLY-4234
> Project: WildFly
> Issue Type: Bug
> Components: EJB
> Affects Versions: 9.0.0.Alpha1
> Reporter: Richard Achmatowicz
> Assignee: Stuart Douglas
>
> The scenario is performing undeployment of an EJB application in the presence of incoming requests.
> If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
> In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
> - an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
> - undeployment is initiated and suspend is called on the ControlPoint for X
> - undeployment proceeds, removing certain resources required for the invocation
> - the active invocation fails due to resources not being available
> Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
> This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
> {code}
> [0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
> 14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
> 14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
> 14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
> 14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
> 14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
> 14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
> 14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
> CLIENT: making invocation on bean: value = 1
> 14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
> 14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
> CLIENT: made invocation on bean [ node-0 ]: new value = 2
> 14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
> CLIENT: making invocation on bean: value = 2
> 14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
> 14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
> 14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> at org.jboss.threads.JBossThread.run(JBossThread.java:320)
> 14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
> 14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
> 14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
> 14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
> 14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
> 14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
> 14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
> 14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
> 14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
> 14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
> {code}
>
> Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
> In this case, it seems that once the EJB components have been stopped, the cache entries for their state have been passivated before the invocation has completed.
> Do we need more mechanism for such cases?
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFLY-4234) EjbSuspendInterceptor doesn't play well with undeploy
by Richard Achmatowicz (JIRA)
[ https://issues.jboss.org/browse/WFLY-4234?page=com.atlassian.jira.plugin.... ]
Richard Achmatowicz updated WFLY-4234:
--------------------------------------
Description:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
Do we need more mechanism for such cases?
was:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example (I have added some of my own tracing to identify ControlPoint activities):
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
[0m14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
[0m14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
> EjbSuspendInterceptor doesn't play well with undeploy
> ------------------------------------------------------
>
> Key: WFLY-4234
> URL: https://issues.jboss.org/browse/WFLY-4234
> Project: WildFly
> Issue Type: Bug
> Components: EJB
> Affects Versions: 9.0.0.Alpha1
> Reporter: Richard Achmatowicz
> Assignee: Stuart Douglas
>
> The scenario is performing undeployment of an EJB application in the presence of incoming requests.
> If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
> In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
> - an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
> - undeployment is initiated and suspend is called on the ControlPoint for X
> - undeployment proceeds, removing certain resources required for the invocation
> - the active invocation fails due to resources not being available
> Here is one such example (I have added some of my own tracing to identify ControlPoint activities.).
> This is a log from the test in which invocations are arriving from an EJB client during undeployment. The request with input value 2 starts and at about the same time, undeployment is called. The invocation gets past the interceptor but never gets a chance to finish.
> {code}
> [0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
> 14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
> 14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
> 14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
> 14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
> 14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
> 14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
> 14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
> CLIENT: making invocation on bean: value = 1
> 14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
> 14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
> CLIENT: made invocation on bean [ node-0 ]: new value = 2
> 14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
> CLIENT: making invocation on bean: value = 2
> 14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
> 14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
> 14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> at org.jboss.threads.JBossThread.run(JBossThread.java:320)
> 14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
> 14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
> 14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
> 14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
> 14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
> 14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
> 14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
> 14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
> 14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
> 14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
> {code}
>
> Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
> Do we need more mechanism for such cases?
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFLY-4234) EjbSuspendInterceptor doesn't play well with undeploy
by Richard Achmatowicz (JIRA)
[ https://issues.jboss.org/browse/WFLY-4234?page=com.atlassian.jira.plugin.... ]
Richard Achmatowicz updated WFLY-4234:
--------------------------------------
Description:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example (I have added some of my own tracing to identify ControlPoint activities):
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
[0m14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
[0m14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
was:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example:
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
[0m14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
[0m14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
> EjbSuspendInterceptor doesn't play well with undeploy
> ------------------------------------------------------
>
> Key: WFLY-4234
> URL: https://issues.jboss.org/browse/WFLY-4234
> Project: WildFly
> Issue Type: Bug
> Components: EJB
> Affects Versions: 9.0.0.Alpha1
> Reporter: Richard Achmatowicz
> Assignee: Stuart Douglas
>
> The scenario is performing undeployment of an EJB application in the presence of incoming requests.
> If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
> In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
> - an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
> - undeployment is initiated and suspend is called on the ControlPoint for X
> - undeployment proceeds, removing certain resources required for the invocation
> - the active invocation fails due to resources not being available
> Here is one such example (I have added some of my own tracing to identify ControlPoint activities):
> {code}
> [0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
> 14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
> [0m14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
> [0m14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
> 14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
> 14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
> 14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
> 14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
> CLIENT: making invocation on bean: value = 1
> 14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
> 14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
> CLIENT: made invocation on bean [ node-0 ]: new value = 2
> 14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
> CLIENT: making invocation on bean: value = 2
> 14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
> 14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
> 14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> at org.jboss.threads.JBossThread.run(JBossThread.java:320)
> 14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
> 14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
> 14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
> 14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
> 14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
> 14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
> 14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
> 14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
> 14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
> 14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
> {code}
>
> Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0
[JBoss JIRA] (WFLY-4234) EjbSuspendInterceptor doesn't play well with undeploy
by Richard Achmatowicz (JIRA)
[ https://issues.jboss.org/browse/WFLY-4234?page=com.atlassian.jira.plugin.... ]
Richard Achmatowicz updated WFLY-4234:
--------------------------------------
Description:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example:
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
[0m14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
[0m14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
CLIENT: making invocation on bean: value = 1
14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
CLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
was:
The scenario is performing undeployment of an EJB application in the presence of incoming requests.
If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
- an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
- undeployment is initiated and suspend is called on the ControlPoint for X
- undeployment proceeds, removing certain resources required for the invocation
- the active invocation fails due to resources not being available
Here is one such example:
{code}
[0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
[0m14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
[0m14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
[0m14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
[0m[0m14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
[0m[0m14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
[0m[0m14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
[0mCLIENT: making invocation on bean: value = 1
[0m14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
[0m[0m14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
[0mCLIENT: made invocation on bean [ node-0 ]: new value = 2
14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
CLIENT: making invocation on bean: value = 2
[0m14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
[0m[0m14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
[0m[0m14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
[0m[0m14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
[0m[0m14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
[0m[0m14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
[0m[0m14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
[0m[0m14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
[0m[0m14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
[0m[0m14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
[0m[0m14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
[0m[0m14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
[0m[0m14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
[0m[31m14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
at org.jboss.threads.JBossThread.run(JBossThread.java:320)
[0m[0m14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
[0m14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
[0m14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
[0m[0m14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
[0m[0m14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
[0m[0m14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
[0m[0m14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
[0m[0m14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
[0m[0m14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
[0m[0m14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
[0m[0m14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
[0m[0m14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
[0m[0m14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
{code}
Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
> EjbSuspendInterceptor doesn't play well with undeploy
> ------------------------------------------------------
>
> Key: WFLY-4234
> URL: https://issues.jboss.org/browse/WFLY-4234
> Project: WildFly
> Issue Type: Bug
> Components: EJB
> Affects Versions: 9.0.0.Alpha1
> Reporter: Richard Achmatowicz
> Assignee: Stuart Douglas
>
> The scenario is performing undeployment of an EJB application in the presence of incoming requests.
> If my understanding of the suspend/resume mechanism is correct, in the ideal case, performing an undeployment should disable invocations arriving after undeployment has been initiated, and also allow requests active at undeployment initiation some time to complete.
> In the clustering integration test RemoteFailoverTestCase, I am seeing failures in which the foloowing sequence of events occurs:
> - an EJB invocation on EJB SFSB X gets past the EJBSuspendInterceptor
> - undeployment is initiated and suspend is called on the ControlPoint for X
> - undeployment proceeds, removing certain resources required for the invocation
> - the active invocation fails due to resources not being available
> Here is one such example:
> {code}
> [0m14:22:04,459 INFO [org.jboss.ejb.client] (main) JBoss EJB Client version 2.0.1.Final
> 14:22:04,485 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,492 INFO [org.jboss.ejb.client.remoting] (main) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)4b79c7f7,channel=jboss.ejb,nodename=node-0]} on channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080
> [0m14:22:04,500 INFO [stdout] (EJB default - 1) ControlPoint: beginRequest called
> [0m14:22:04,529 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-15) EJBCLIENT000017: Received server version 2 and marshalling strategies [river]
> 14:22:04,530 INFO [org.jboss.ejb.client.remoting] (ejb-client-cluster-node-connection-creation-3-thread-2) EJBCLIENT000013: Successful version handshake completed for receiver context EJBReceiverContext{clientContext=org.jboss.ejb.client.EJBClientContext@2ba6ac4c, receiver=Remoting connection EJB receiver [connection=org.jboss.ejb.client.remoting.ConnectionPool$PooledConnection(a)74f6ab8a,channel=jboss.ejb,nodename=node-1]} on channel Channel ID d24c9830 (outbound) of Remoting connection 759d3b52 to /127.0.0.1:8180
> 14:22:04,542 INFO [org.jboss.ejb.client] (EJB default - 1) JBoss EJB Client version 2.0.1.Final
> 14:22:04,560 INFO [stdout] (EJB default - 1) ControlPoint: requestComplete called
> 14:22:09,682 INFO [stdout] (EJB default - 2) ControlPoint: beginRequest called
> 14:22:09,702 INFO [stdout] (EJB default - 2) ControlPoint: requestComplete called
> CLIENT: making invocation on bean: value = 1
> 14:22:09,710 INFO [stdout] (EJB default - 3) ControlPoint: beginRequest called
> 14:22:09,715 INFO [stdout] (EJB default - 3) ControlPoint: requestComplete called
> CLIENT: made invocation on bean [ node-0 ]: new value = 2
> 14:22:09,717 INFO [org.jboss.as.test.clustering.NodeUtil] (main) Undeploying deployment=deployment-0
> CLIENT: making invocation on bean: value = 2
> 14:22:09,728 INFO [stdout] (EJB default - 4) ControlPoint: beginRequest called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 29) EJBComponent: stopping remote-failover-test:remote-failover-test:SlowToDestroyStatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) EJBComponent: stopping remote-failover-test:remote-failover-test:StatefulIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 67) EJBComponent: stopping remote-failover-test:remote-failover-test:SecureStatelessIncrementorBean
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 31) ControlPoint: pause called
> 14:22:09,730 INFO [stdout] (ServerService Thread Pool -- 4) EJBComponent: stopping remote-failover-test:remote-failover-test:StatelessIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 29) ControlPoint: pause called
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 11) EJBComponent: stopping remote-failover-test:remote-failover-test:ClientIncrementorBean
> 14:22:09,731 INFO [stdout] (ServerService Thread Pool -- 4) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 67) ControlPoint: pause called
> 14:22:09,732 INFO [stdout] (ServerService Thread Pool -- 11) ControlPoint: pause called
> 14:22:09,733 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,735 INFO [stdout] (EJB default - 4) ControlPoint: requestComplete called
> 14:22:09,735 ERROR [org.jboss.as.ejb3] (EJB default - 4) WFLYEJB0150: Could not write method invocation failure for method public abstract org.jboss.as.test.clustering.cluster.ejb.remote.bean.Result org.jboss.as.test.clustering.cluster.ejb.remote.bean.Incrementor.increment() on bean named SlowToDestroyStatefulIncrementorBean for appname modulename remote-failover-test distinctname due to: java.lang.NullPointerException
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.getWeakAffinity(MethodInvocationMessageHandler.java:269)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$500(MethodInvocationMessageHandler.java:69)
> at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:237)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> at org.jboss.threads.JBossThread.run(JBossThread.java:320)
> 14:22:09,736 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 2 entries in 2 milliseconds
> 14:22:09,736 INFO [org.jboss.ejb.client.remoting] (Remoting "config-based-ejb-client-endpoint" task-5) EJBCLIENT000016: Channel Channel ID ad5ee733 (outbound) of Remoting connection 29cd434b to /127.0.0.1:8080 can no longer process messages
> 14:22:09,738 INFO [org.jboss.weld.deployer] (MSC service thread 1-2) WFLYWELD0010: Stopping weld service for deployment remote-failover-test.jar
> 14:22:09,740 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped remote-failover-test.jar cache from ejb container
> 14:22:09,760 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000029: Passivating all entries to disk
> 14:22:09,761 INFO [org.infinispan.eviction.impl.PassivationManagerImpl] (ServerService Thread Pool -- 29) ISPN000030: Passivated 1 entries in 0 milliseconds
> 14:22:09,762 INFO [org.jboss.as.server.deployment] (MSC service thread 1-5) WFLYSRV0028: Stopped deployment remote-failover-test.jar (runtime-name: remote-failover-test.jar) in 36ms
> 14:22:09,764 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) WFLYCLINF0003: Stopped dist cache from ejb container
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000080: Disconnecting JGroups channel ejb
> 14:22:09,766 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC service thread 1-12) ISPN000082: Stopping the RpcDispatcher for channel ejb
> 14:22:09,772 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,ee,node-1) ISPN000094: Received new cluster view for channel ejb: [node-1|2] (1) [node-1]
> 14:22:09,807 INFO [org.jboss.as.repository] (management-handler-thread - 1) WFLYDR0002: Content removed from location /home/nrla/projects/wildfly-git-repo/testsuite/integration/clustering/target/wildfly-SYNC-tcp-0/standalone/data/content/66/642dea2bc32c3ba888dd173db2b91d18b848b0/content
> 14:22:09,807 INFO [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0009: Undeployed "remote-failover-test.jar" (runtime-name: "remote-failover-test.jar")
> {code}
>
> Looking at the use of ControlPoints within EJBs, it seems that on undeployment, the EJBComponent.stop() method calls ControlPoint.pause() only which will cause the interceptor to block any future invocations but also not prevent the undeployment from continuing, despite the fact that a request is active.
--
This message was sent by Atlassian JIRA
(v6.3.11#6341)
11 years, 6 months
- 1
- 0