[jboss-jira] [JBoss JIRA] (WFLY-10067) [Artemis 2.x Upgrade] Failover does not work with HTTP conncetors/acceptors
Jeff Mesnil (JIRA)
issues at jboss.org
Wed Apr 11 08:32:01 EDT 2018
[ https://issues.jboss.org/browse/WFLY-10067?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13559499#comment-13559499 ]
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 at 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 at 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)
More information about the jboss-jira
mailing list