[
https://issues.jboss.org/browse/WFLY-10067?page=com.atlassian.jira.plugin...
]
Jeff Mesnil commented on WFLY-10067:
------------------------------------
I have been able to reproduce the issue by running 2 servers with the attached
configurations to be able to manually stop or kill the 1st server.
The problem does not always happen.
Sometimes when I "kill" (kill -9) the first server, the backup becomes live as
expected
However, when I restart the first server, the backup restarts itself but the process does
not finish:
{code}
09:40:29,614 INFO [org.apache.activemq.artemis.core.server] (Thread-147) AMQ221039:
Restarting as Replicating backup server after live restart
09:40:29,615 INFO [org.apache.activemq.artemis.core.server] (Thread-147) AMQ221000:
backup Message Broker is starting with configuration Broker Configuration (
clustered=true,journalDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server2/standalone/data/../../../../hornetq-journal-B/journal,bindingsDirectory=/Us
ers/jmesnil/Developer/wildfly/dist/target/server2/standalone/data/../../../../hornetq-journal-B/bindings,largeMessagesDirectory=/Users/jmesnil/Developer/wildfly
/dist/target/server2/standalone/data/../../../../hornetq-journal-B/largemessages,pagingDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server2/standalone
/data/../../../../hornetq-journal-B/paging)
09:40:29,617 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221059: Deleting old data directory
/Users/jmesnil/Developer/wildfly/dist/target/server2/standalone/data/../../../../hornetq-journal-B/bindings
as the max folders is set to 0
09:40:29,621 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221059: Deleting old data directory
/Users/jmesnil/Developer/wildfly/dist/target/server2/standalone/data/../../../../hornetq-journal-B/journal
as the max folders is set to 0
09:40:29,627 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221059: Deleting old data directory
/Users/jmesnil/Developer/wildfly/dist/target/server2/standalone/data/../../../../hornetq-journal-B/paging
as the max folders is set to 0
09:40:29,639 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221013: Using NIO Journal
09:40:29,647 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-server]. Adding protocol support for: CORE
09:40:29,650 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-amqp-protocol]. Adding protocol support for: AMQP
09:40:29,652 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
09:40:29,655 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-stomp-protocol]. Adding protocol support for: STOMP
09:44:18,257 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN000094: Received
new cluster view for channel ejb: [localhost|4] (1) [localhost]
09:44:18,283 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN100001: Node
localhost left the cluster
09:44:18,284 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN000094: Received
new cluster view for channel ejb: [localhost|4] (1) [localhost]
09:44:18,285 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN100001: Node
localhost left the cluster
09:44:18,285 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN000094: Received
new cluster view for channel ejb: [localhost|4] (1) [localhost]
09:44:18,286 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN100001: Node
localhost left the cluster
09:44:18,286 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN000094: Received
new cluster view for channel ejb: [localhost|4] (1) [localhost]
09:44:18,287 INFO [org.infinispan.CLUSTER] (thread-20,ejb,localhost) ISPN100001: Node
localhost left the cluster
{code}
The 1st server starts as live but restarts itself as a backup based on quorum vote:
{code}
$ ./bin/standalone.sh -c standalone-full-ha.xml
=========================================================================
JBoss Bootstrap Environment
JBOSS_HOME: /Users/jmesnil/Developer/wildfly/dist/target/server1
JAVA: /Library/Java/JavaVirtualMachines/jdk1.8.0_162.jdk/Contents/Home/bin/java
JAVA_OPTS: -server -Xms64m -Xmx512m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m
-Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman
-Djava.awt.headless=true
=========================================================================
09:40:21,208 INFO [org.jboss.modules] (main) JBoss Modules version 1.7.0.Final
09:40:21,553 INFO [org.jboss.msc] (main) JBoss MSC version 1.3.2.Final
09:40:21,566 INFO [org.jboss.threads] (main) JBoss Threads version 2.3.1.Final
09:40:21,722 INFO [org.jboss.as] (MSC service thread 1-2) WFLYSRV0049: WildFly Full
13.0.0.Alpha1-SNAPSHOT (WildFly Core 4.0.0.Final) starting
09:40:23,342 INFO [org.jboss.as.controller.management-deprecated] (Controller Boot
Thread) WFLYCTL0028: Attribute 'security-realm' in the resource at address
'/core-service=management/management-interface=http-interface' is deprecated, and
may be removed in a future version. See the attribute description in the output of the
read-resource-description operation to learn more about the deprecation.
09:40:23,372 INFO [org.wildfly.security] (ServerService Thread Pool -- 28) ELY00001:
WildFly Elytron version 1.2.2.Final
09:40:23,373 INFO [org.jboss.as.controller.management-deprecated] (ServerService Thread
Pool -- 12) WFLYCTL0028: Attribute 'security-realm' in the resource at address
'/subsystem=undertow/server=default-server/https-listener=https' is deprecated,
and may be removed in a future version. See the attribute description in the output of the
read-resource-description operation to learn more about the deprecation.
09:40:23,564 INFO [org.jboss.as.server] (Controller Boot Thread) WFLYSRV0039: Creating
http management service using socket-binding (management-http)
09:40:23,585 INFO [org.xnio] (MSC service thread 1-7) XNIO version 3.6.2.Final
09:40:23,596 INFO [org.xnio.nio] (MSC service thread 1-7) XNIO NIO Implementation Version
3.6.2.Final
09:40:23,637 INFO [org.wildfly.extension.io] (ServerService Thread Pool -- 47) WFLYIO001:
Worker 'default' has auto-configured to 16 core threads with 128 task threads
based on your 8 available processors
09:40:23,656 INFO [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 48)
WFLYCLINF0001: Activating Infinispan subsystem.
09:40:23,663 INFO [org.jboss.as.jsf] (ServerService Thread Pool -- 56) WFLYJSF0007:
Activated the following JSF Implementations: [main]
09:40:23,673 INFO [org.jboss.as.clustering.jgroups] (ServerService Thread Pool -- 53)
WFLYCLJG0001: Activating JGroups subsystem. JGroups version 4.0.10
09:40:23,689 INFO [org.jboss.as.jaxrs] (ServerService Thread Pool -- 50) WFLYRS0016:
RESTEasy version 3.5.0.Final
09:40:23,716 INFO [org.jboss.as.naming] (ServerService Thread Pool -- 61) WFLYNAM0001:
Activating Naming Subsystem
09:40:23,751 INFO [org.jboss.as.webservices] (ServerService Thread Pool -- 72)
WFLYWS0002: Activating WebServices Extension
09:40:23,762 INFO [org.jboss.as.connector.subsystems.datasources] (ServerService Thread
Pool -- 42) WFLYJCA0004: Deploying JDBC-compliant driver class org.h2.Driver (version
1.4)
09:40:23,773 INFO [org.jboss.as.security] (ServerService Thread Pool -- 68) WFLYSEC0002:
Activating Security Subsystem
09:40:23,784 INFO [org.wildfly.iiop.openjdk] (ServerService Thread Pool -- 49)
WFLYIIOP0001: Activating IIOP Subsystem
09:40:23,789 INFO [org.jboss.as.security] (MSC service thread 1-3) WFLYSEC0001: Current
PicketBox version=5.0.2.Final
09:40:23,803 INFO [org.wildfly.extension.undertow] (MSC service thread 1-8) WFLYUT0003:
Undertow 2.0.0.Final starting
09:40:23,842 INFO [org.jboss.remoting] (MSC service thread 1-5) JBoss Remoting version
5.0.5.Final
09:40:23,892 INFO [org.jboss.as.connector] (MSC service thread 1-1) WFLYJCA0009: Starting
JCA Subsystem (WildFly/IronJacamar 1.4.8.Final)
09:40:23,938 INFO [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-8)
WFLYJCA0018: Started Driver service with driver-name = h2
09:40:23,938 INFO [org.jboss.as.naming] (MSC service thread 1-8) WFLYNAM0003: Starting
Naming Service
09:40:23,976 INFO [org.jboss.as.mail.extension] (MSC service thread 1-1) WFLYMAIL0001:
Bound mail session [java:jboss/mail/Default]
09:40:24,108 INFO [org.jboss.as.ejb3] (MSC service thread 1-4) WFLYEJB0482: Strict pool
mdb-strict-max-pool is using a max instance size of 32 (per class), which is derived from
the number of CPUs on this host.
09:40:24,108 INFO [org.jboss.as.ejb3] (MSC service thread 1-6) WFLYEJB0481: Strict pool
slsb-strict-max-pool is using a max instance size of 128 (per class), which is derived
from thread worker pool sizing.
09:40:24,138 WARN [org.apache.activemq.artemis.core.server] (ServerService Thread Pool --
59) AMQ222269: Please use a fixed value for "journal-pool-files". Default
changed per
https://issues.apache.org/jira/browse/ARTEMIS-1628
09:40:24,140 INFO [org.apache.activemq.artemis.core.server] (ServerService Thread Pool --
59) AMQ221075: Usage of wildcardRoutingEnabled configuration property is deprecated,
please use wildCardConfiguration.enabled instead
09:40:24,180 INFO [org.wildfly.extension.undertow] (ServerService Thread Pool -- 71)
WFLYUT0014: Creating file handler for path
'/Users/jmesnil/Developer/wildfly/dist/target/server1/welcome-content' with
options [directory-listing: 'false', follow-symlink: 'false',
case-sensitive: 'true', safe-symlink-paths: '[]']
09:40:24,247 INFO [org.wildfly.extension.undertow] (MSC service thread 1-5) WFLYUT0012:
Started server default-server.
09:40:24,268 INFO [org.wildfly.extension.undertow] (MSC service thread 1-7) WFLYUT0018:
Host default-host starting
09:40:24,368 INFO [org.wildfly.extension.undertow] (MSC service thread 1-2) WFLYUT0006:
Undertow AJP listener ajp listening on 127.0.0.1:8009
09:40:24,368 INFO [org.wildfly.extension.undertow] (MSC service thread 1-8) WFLYUT0006:
Undertow HTTP listener default listening on 127.0.0.1:8080
09:40:24,376 WARN [org.jboss.as.remoting] (MSC service thread 1-5) ****** All
authentication is ANONYMOUS for org.jboss.as.remoting.RemotingHttpUpgradeService
09:40:24,386 INFO [org.jboss.modcluster] (ServerService Thread Pool -- 75)
MODCLUSTER000001: Initializing mod_cluster version 1.3.9.Final
09:40:24,406 INFO [org.jboss.modcluster] (ServerService Thread Pool -- 75)
MODCLUSTER000032: Listening to proxy advertisements on /224.0.1.105:23364
09:40:24,495 INFO [org.jboss.as.ejb3] (MSC service thread 1-8) WFLYEJB0493: EJB subsystem
suspension complete
09:40:24,613 INFO [org.jboss.as.patching] (MSC service thread 1-3) WFLYPAT0050: WildFly
Full cumulative patch ID is: base, one-off patches include: none
09:40:24,626 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread
1-6) WFLYJCA0001: Bound data source [java:jboss/datasources/ExampleDS]
09:40:24,639 INFO [org.jboss.as.server.deployment.scanner] (MSC service thread 1-6)
WFLYDS0013: Started FileSystemDeploymentService for directory
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/deployments
09:40:24,646 WARN [org.jboss.as.domain.management.security] (MSC service thread 1-2)
WFLYDM0111: Keystore
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/configuration/application.keystore
not found, it will be auto generated on first use with a self signed certificate for host
localhost
09:40:24,687 INFO [org.wildfly.iiop.openjdk] (MSC service thread 1-1) WFLYIIOP0009: CORBA
ORB Service started
09:40:24,877 INFO [org.wildfly.extension.undertow] (MSC service thread 1-6) WFLYUT0006:
Undertow HTTPS listener https listening on 127.0.0.1:8443
09:40:24,976 INFO [org.jboss.ws.common.management] (MSC service thread 1-2) JBWS022052:
Starting JBossWS 5.2.0.Final (Apache CXF 3.2.2)
09:40:24,997 WARN [org.jgroups.protocols.UDP] (ServerService Thread Pool -- 74)
JGRP000015: the receive buffer of socket MulticastSocket was set to 20.00MB, but the OS
only allocated 6.71MB. This might lead to performance problems. Please set your max
receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
09:40:24,997 WARN [org.jgroups.protocols.UDP] (ServerService Thread Pool -- 74)
JGRP000015: the receive buffer of socket MulticastSocket was set to 25.00MB, but the OS
only allocated 6.71MB. This might lead to performance problems. Please set your max
receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
09:40:25,185 INFO [org.wildfly.extension.messaging-activemq] (MSC service thread 1-7)
WFLYMSGAMQ0001: AIO wasn't located on this platform, it will fall back to using pure
Java NIO.
09:40:25,281 INFO [org.apache.activemq.artemis.core.server] (ServerService Thread Pool --
74) AMQ221000: live Message Broker is starting with configuration Broker Configuration
(clustered=true,journalDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal,bindingsDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings,largeMessagesDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/largemessages,pagingDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging)
09:40:25,793 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-1) ISPN000078: Starting JGroups channel ejb
09:40:25,794 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-2) ISPN000078: Starting JGroups channel ejb
09:40:25,793 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-5) ISPN000078: Starting JGroups channel ejb
09:40:25,793 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-3) ISPN000078: Starting JGroups channel ejb
09:40:25,802 INFO [org.infinispan.CLUSTER] (MSC service thread 1-1) ISPN000094: Received
new cluster view for channel ejb: [localhost|3] (2) [localhost, localhost]
09:40:25,802 INFO [org.infinispan.CLUSTER] (MSC service thread 1-5) ISPN000094: Received
new cluster view for channel ejb: [localhost|3] (2) [localhost, localhost]
09:40:25,802 INFO [org.infinispan.CLUSTER] (MSC service thread 1-2) ISPN000094: Received
new cluster view for channel ejb: [localhost|3] (2) [localhost, localhost]
09:40:25,802 INFO [org.infinispan.CLUSTER] (MSC service thread 1-3) ISPN000094: Received
new cluster view for channel ejb: [localhost|3] (2) [localhost, localhost]
09:40:25,818 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-1) ISPN000079: Channel ejb local address is localhost, physical addresses
are [127.0.0.1:55200]
09:40:25,818 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-2) ISPN000079: Channel ejb local address is localhost, physical addresses
are [127.0.0.1:55200]
09:40:25,818 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-3) ISPN000079: Channel ejb local address is localhost, physical addresses
are [127.0.0.1:55200]
09:40:25,818 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (MSC
service thread 1-5) ISPN000079: Channel ejb local address is localhost, physical addresses
are [127.0.0.1:55200]
09:40:25,846 INFO [org.infinispan.factories.GlobalComponentRegistry] (MSC service thread
1-1) ISPN000128: Infinispan version: Infinispan 'Gaina' 9.2.0.Final
09:40:26,587 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221055: There were too many old replicated
folders upon startup, removing
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings/oldreplica.2
09:40:26,592 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ222162: Moving data directory
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings
to
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings/oldreplica.4
09:40:26,599 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221055: There were too many old replicated
folders upon startup, removing
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal/oldreplica.2
09:40:26,602 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ222162: Moving data directory
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal
to
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal/oldreplica.4
09:40:26,605 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221055: There were too many old replicated
folders upon startup, removing
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging/oldreplica.2
09:40:26,614 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ222162: Moving data directory
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging
to
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging/oldreplica.4
09:40:26,659 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221013: Using NIO Journal
09:40:26,671 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221057: Global Max Size is being adjusted
to 1/2 of the JVM max size (-Xmx). being defined as 238,813,184
09:40:26,674 INFO [org.jboss.as.server] (Controller Boot Thread) WFLYSRV0212: Resuming
server
09:40:26,677 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0060: Http management
interface listening on
http://127.0.0.1:9990/management
09:40:26,677 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0051: Admin console
listening on
http://127.0.0.1:9990
09:40:26,677 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: WildFly Full
13.0.0.Alpha1-SNAPSHOT (WildFly Core 4.0.0.Final) started in 5938ms - Started 375 of 717
services (488 services are lazy, passive or on-demand)
09:40:26,718 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-server]. Adding protocol support for: CORE
09:40:26,719 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-amqp-protocol]. Adding protocol support for: AMQP
09:40:26,719 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
09:40:26,720 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-stomp-protocol]. Adding protocol support for: STOMP
09:40:28,240 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221109: Apache ActiveMQ Artemis Backup
Server version 2.5.0 [null] started, waiting live to fail before it gets active
09:40:29,425 INFO [org.apache.activemq.artemis.core.server] (Thread-6
(ActiveMQ-client-netty-threads)) AMQ221024: Backup server
ActiveMQServerImpl::serverUUID=baa02fcc-3cd9-11e8-95f6-b8f6b112daf7 is synchronized with
live-server.
09:40:29,530 INFO [org.apache.activemq.artemis.core.server] (Thread-5
(ActiveMQ-client-netty-threads)) AMQ221070: Restarting as backup based on quorum vote
results.
09:40:29,533 WARN [org.apache.activemq.artemis.core.client] (Thread-11
(ActiveMQ-client-global-threads)) AMQ212037: Connection failure has been detected:
AMQ119015: The connection was disconnected because of server shutdown [code=DISCONNECTED]
09:40:29,579 INFO [org.apache.activemq.artemis.core.server] (Thread-110) AMQ221002:
Apache ActiveMQ Artemis Message Broker version 2.5.0
[baa02fcc-3cd9-11e8-95f6-b8f6b112daf7] stopped, uptime 4.305 seconds
09:40:29,581 INFO [org.apache.activemq.artemis.core.server] (Thread-110) AMQ221000:
backup Message Broker is starting with configuration Broker Configuration
(clustered=true,journalDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal,bindingsDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings,largeMessagesDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/largemessages,pagingDirectory=/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging)
09:40:29,585 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221055: There were too many old replicated
folders upon startup, removing
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings/oldreplica.3
09:40:29,591 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ222162: Moving data directory
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings
to
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/bindings/oldreplica.5
09:40:29,595 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221055: There were too many old replicated
folders upon startup, removing
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal/oldreplica.3
09:40:29,603 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ222162: Moving data directory
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal
to
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/journal/oldreplica.5
09:40:29,608 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221055: There were too many old replicated
folders upon startup, removing
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging/oldreplica.3
09:40:29,618 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ222162: Moving data directory
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging
to
/Users/jmesnil/Developer/wildfly/dist/target/server1/standalone/data/../../../../hornetq-journal-A/paging/oldreplica.5
09:40:29,626 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221013: Using NIO Journal
09:40:29,631 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-server]. Adding protocol support for: CORE
09:40:29,635 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-amqp-protocol]. Adding protocol support for: AMQP
09:40:29,638 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
09:40:29,641 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found:
[artemis-stomp-protocol]. Adding protocol support for: STOMP
09:40:29,671 WARN [org.apache.activemq.artemis.core.client] (Thread-11
(ActiveMQ-client-global-threads)) AMQ212004: Failed to connect to server.
{code}
We end up with both servers being backups while server 1 should be live and server 2
should be backup.
[Artemis 2.x Upgrade] Failover does not work with HTTP
conncetors/acceptors
---------------------------------------------------------------------------
Key: WFLY-10067
URL:
https://issues.jboss.org/browse/WFLY-10067
Project: WildFly
Issue Type: Bug
Components: JMS
Affects Versions: 13.0.0.Beta1
Reporter: Erich Duda
Assignee: Jeff Mesnil
Priority: Blocker
Labels: feature-branch-blocker
Attachments: clients.log, server1.log, server2.log, test.log
Failover does not work with HTTP connectors/acceptors.
*Scenario:*
# There are two Wildfly servers configured as Live-Backup pair
# There is one JMS producer and one JMS receiver which sends/receives messages
# Live server is several times killed and restarted.
*Expectation:* Always when the Live server is killed or restarted, clients do failover or
failback.
*Reality*: Sometimes happens that clients don't do failover.
*Users impact:* One of basics feature of HA, failover, does not work properly.
*Blocker* priority was set because this is regression against previous releases of
Wildfly.
*Detail description of issue*
In the trace logs it can be seen that clients send HTTP handshake request to active
backup, but the handshake fails. All checks (and logs) say that the backup is active in
this time period. I tried to run the test with Netty connectors/acceptors and I didn't
see this issue.
{code:title=Backup log}
07:52:47,856 WARN [org.apache.activemq.artemis.core.server] (Thread-2
(ActiveMQ-IO-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@1f01f347))
AMQ222029: Could not locate page transaction 3 995, ignoring message on position
PagePositionImpl [pageNr=2, messageNr=55, recordID=-1] on address=jms.queue.testQueue
queue=jms.queue.testQueue
07:52:47,856 WARN [org.apache.activemq.artemis.core.server] (Thread-2
(ActiveMQ-IO-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@1f01f347))
AMQ222029: Could not locate page transaction 3 995, ignoring message on position
PagePositionImpl [pageNr=2, messageNr=56, recordID=-1] on address=jms.queue.testQueue
queue=jms.queue.testQueue
07:52:47,863 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221005: Deleting pending large message as
it was not completed: Pair[a=2147485068, b=2147485067]
07:52:47,863 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221005: Deleting pending large message as
it was not completed: Pair[a=2147485076, b=2147485075]
07:52:47,864 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221005: Deleting pending large message as
it was not completed: Pair[a=2147484450, b=2147484449]
07:52:47,864 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221005: Deleting pending large message as
it was not completed: Pair[a=2147485072, b=2147485071]
07:52:47,864 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221005: Deleting pending large message as
it was not completed: Pair[a=2147484454, b=2147484453]
07:52:47,866 WARN [org.apache.activemq.artemis.core.client]
(activemq-discovery-group-thread-dg-group1) AMQ212034: There are more than one servers on
the network broadcasting the same node id. You will see this message exactly once (per
node) if a node is restarted, in which case it can be safely ignored. But if it is logged
continuously it means you really do have more than one node on the same network active
concurrently with the same node id. This could occur if you have a backup node active at
the same time as its live node. nodeID=0dee81c9-2d9d-11e8-ba3f-cc3d825f79a4
07:52:47,867 INFO [org.apache.activemq.artemis.core.server] (AMQ119000: Activation for
server ActiveMQServerImpl::serverUUID=null) AMQ221007: Server is now live
{code}
{code:title=Clients log}
07:52:49,274 Thread-80 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector:726] Remote
destination: localhost/127.0.0.1:9080
07:52:49,274 Thread-79 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl:1040] Connector
towards NettyConnector [host=localhost, port=8080, httpEnabled=false,
httpUpgradeEnabled=true, useServlet=false, servletPath=/messaging/ActiveMQServlet,
sslEnabled=false, useNio=true, activemqServerName=default, httpUpgradeEndpoint=acceptor]
failed
07:52:49,275 Thread-79 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl:1081] Trying backup
config = TransportConfiguration(name=connector,
factory=org-apache-activemq-artemis-core-remoting-impl-netty-NettyConnectorFactory)
?httpUpgradeEndpoint=acceptor&activemqServerName=default&httpUpgradeEnabled=true&port=9080&host=localhost
07:52:49,275 Thread-79 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector:447] Connector
NettyConnector [host=localhost, port=9080, httpEnabled=false, httpUpgradeEnabled=true,
useServlet=false, servletPath=/messaging/ActiveMQServlet, sslEnabled=false, useNio=true,
activemqServerName=default, httpUpgradeEndpoint=acceptor] using native epoll
07:52:49,275 Thread-80 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector:797] Sending HTTP
request DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET HTTP/1.1
host: localhost
upgrade: activemq-remoting
connection: upgrade
activemqServerName: default
httpUpgradeEndpoint: acceptor
Sec-ActiveMQRemoting-Key: QWV3bCfgh75NjWH3pZV5Ew==
07:52:49,275 Thread-79 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector:601] AMQ211002:
Started EPOLL Netty Connector version 4.1.16.Final to localhost:9080
07:52:49,275 Thread-79 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector:726] Remote
destination: localhost/127.0.0.1:9080
07:52:49,276 Thread-79 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector:797] Sending HTTP
request DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET HTTP/1.1
host: localhost
upgrade: activemq-remoting
connection: upgrade
activemqServerName: default
httpUpgradeEndpoint: acceptor
Sec-ActiveMQRemoting-Key: P9xBwRk1eZP5QjDWjqYuIg==
07:52:49,276 Thread-2 (ActiveMQ-client-netty-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$HttpUpgradeHandler:876]
Received msg=DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Connection: keep-alive
Last-Modified: Thu, 22 Mar 2018 06:47:03 GMT
Content-Length: 2426
Content-Type: text/html
Accept-Ranges: bytes
Date: Thu, 22 Mar 2018 06:52:49 GMT
07:52:49,276 Thread-2 (ActiveMQ-client-netty-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$HttpUpgradeHandler:903]
AMQ214023: HTTP Handshake failed, received DefaultHttpResponse(decodeResult: success,
version: HTTP/1.1)
HTTP/1.1 200 OK
Connection: keep-alive
Last-Modified: Thu, 22 Mar 2018 06:47:03 GMT
Content-Length: 2426
Content-Type: text/html
Accept-Ranges: bytes
Date: Thu, 22 Mar 2018 06:52:49 GMT
07:52:49,276 Thread-2 (ActiveMQ-client-netty-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$HttpUpgradeHandler:876]
Received msg=DefaultHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 829, cap:
829/829, unwrapped: PooledUnsafeDirectByteBuf(ridx: 1024, widx: 1024, cap: 1024)),
decoderResult: success)
07:52:49,276 Thread-2 (ActiveMQ-client-netty-threads) DEBUG
[org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$HttpUpgradeHandler:903]
AMQ214023: HTTP Handshake failed, received DefaultHttpContent(data:
PooledSlicedByteBuf(ridx: 0, widx: 829, cap: 829/829, unwrapped:
PooledUnsafeDirectByteBuf(ridx: 1024, widx: 1024, cap: 1024)), decoderResult: success)
07:52:49,277 Thread-80 (ActiveMQ-client-global-threads) DEBUG
[org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl:1040] Connector
towards NettyConnector [host=localhost, port=9080, httpEnabled=false,
httpUpgradeEnabled=true, useServlet=false, servletPath=/messaging/ActiveMQServlet,
sslEnabled=false, useNio=true, activemqServerName=default, httpUpgradeEndpoint=acceptor]
failed
{code}
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)