You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@activemq.apache.org by "chethan (JIRA)" <ji...@apache.org> on 2019/03/22 08:32:00 UTC
[jira] [Commented] (ARTEMIS-1170) HA Replication Failback Failure
- Sync Timed Out
[ https://issues.apache.org/jira/browse/ARTEMIS-1170?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16798828#comment-16798828 ]
chethan commented on ARTEMIS-1170:
-----------------------------------
Hi [~clebertsuconic],
Facing similar issue and need help.
We have planned for upgrading to v2.5.0.
[~ev.srinivas@gmail.com] were you able to overcome this ? Please let me know if any.
Email Id : schethan27@gmail.com
> HA Replication Failback Failure - Sync Timed Out
> -------------------------------------------------
>
> Key: ARTEMIS-1170
> URL: https://issues.apache.org/jira/browse/ARTEMIS-1170
> Project: ActiveMQ Artemis
> Issue Type: Bug
> Components: Broker
> Affects Versions: 2.1.0
> Reporter: Andrei Bercu
> Assignee: clebert suconic
> Priority: Major
>
> We are running artemis in a master/slave setup (1 master, 1 slave) using replication. We had artemis 2.0.0 and reported this issue: [ARTEMIS-1161|https://issues.apache.org/jira/browse/ARTEMIS-1161] . Following advice, we replaced artemis 2.0.0 with 2.1.0 and the failback still doesn't work, failing in a different form though, in about 50% of our test experiments.
> Now, during failback, master reports:
> {noformat}
> 07:11:22,962 INFO [org.apache.activemq.artemis.integration.bootstrap] AMQ101000: Starting ActiveMQ Artemis Server
> 07:11:22,975 INFO [org.apache.activemq.artemis.core.server] AMQ221000: live Message Broker is starting with configuration Broker Configuration (clustered=true,journalDirectory=/var/lib/artemis/shadowbroker/data/journal,bindingsDirectory=/var/lib/artemis/shadowbroker/data/bindings,largeMessagesDirectory=/var/lib/artemis/shadowbroker/data/largemessages,pagingDirectory=/var/lib/artemis/shadowbroker/data/paging)
> 07:11:23,416 INFO [org.apache.activemq.artemis.core.server] AMQ221055: There were too many old replicated folders upon startup, removing /var/lib/artemis/shadowbroker/data/bindings/oldreplica.313
> 07:11:23,421 INFO [org.apache.activemq.artemis.core.server] AMQ222162: Moving data directory /var/lib/artemis/shadowbroker/data/bindings to /var/lib/artemis/shadowbroker/data/bindings/oldreplica.315
> 07:11:23,423 INFO [org.apache.activemq.artemis.core.server] AMQ221055: There were too many old replicated folders upon startup, removing /var/lib/artemis/shadowbroker/data/journal/oldreplica.313
> 07:11:23,426 INFO [org.apache.activemq.artemis.core.server] AMQ222162: Moving data directory /var/lib/artemis/shadowbroker/data/journal to /var/lib/artemis/shadowbroker/data/journal/oldreplica.315
> 07:11:23,427 INFO [org.apache.activemq.artemis.core.server] AMQ221055: There were too many old replicated folders upon startup, removing /var/lib/artemis/shadowbroker/data/paging/oldreplica.252
> 07:11:23,427 INFO [org.apache.activemq.artemis.core.server] AMQ222162: Moving data directory /var/lib/artemis/shadowbroker/data/paging to /var/lib/artemis/shadowbroker/data/paging/oldreplica.254
> 07:11:23,437 INFO [org.eclipse.jetty.util.log] Logging initialized @1968ms to org.eclipse.jetty.util.log.Slf4jLog
> 07:11:23,448 INFO [org.apache.activemq.artemis.core.server] AMQ221012: Using AIO Journal
> 07:11:23,533 INFO [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-server]. Adding protocol support for: CORE
> 07:11:23,533 INFO [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-amqp-protocol]. Adding protocol support for: AMQP
> 07:11:23,534 INFO [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
> 07:11:23,534 INFO [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-mqtt-protocol]. Adding protocol support for: MQTT
> 07:11:23,534 INFO [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-openwire-protocol]. Adding protocol support for: OPENWIRE
> 07:11:23,535 INFO [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-stomp-protocol]. Adding protocol support for: STOMP
> 07:11:23,591 INFO [org.eclipse.jetty.server.Server] jetty-9.4.z-SNAPSHOT
> 07:11:23,643 INFO [org.apache.activemq.artemis.core.server] AMQ221109: Apache ActiveMQ Artemis Backup Server version 2.1.0 [null] started, waiting live to fail before it gets active
> 07:11:23,702 INFO [org.eclipse.jetty.webapp.StandardDescriptorProcessor] NO JSP Support for /jolokia, did not find org.eclipse.jetty.jsp.JettyJspServlet
> 07:11:23,713 INFO [org.eclipse.jetty.server.session] DefaultSessionIdManager workerName=node0
> 07:11:23,714 INFO [org.eclipse.jetty.server.session] No SessionScavenger set, using defaults
> 07:11:23,715 INFO [org.eclipse.jetty.server.session] Scavenging every 660000ms
> 07:11:23,764 INFO [org.eclipse.jetty.ContextHandler.jolokia] jolokia-agent: No access restrictor found, access to any MBean is allowed
> 07:11:23,910 INFO [org.eclipse.jetty.server.handler.ContextHandler] Started o.e.j.w.WebAppContext@127a7a2e{/jolokia,file:///var/lib/artemis/shadowbroker/tmp/jetty-localhost-8161-jolokia.war-_jolokia-any-6088373165208569604.dir/webapp/,AVAILABLE}{/opt/artemis/web/jolokia.war}
> 07:11:23,911 INFO [org.eclipse.jetty.server.handler.ContextHandler] Started o.e.j.s.h.ContextHandler@14008db3{/,file:///opt/artemis/web/,AVAILABLE}
> 07:11:23,925 INFO [org.eclipse.jetty.server.AbstractConnector] Started ServerConnector@28d18df5{HTTP/1.1,[http/1.1]}{localhost:8161}
> 07:11:23,926 INFO [org.eclipse.jetty.server.Server] Started @2459ms
> 07:11:23,927 INFO [org.apache.activemq.artemis] AMQ241001: HTTP Server started at http://localhost:8161
> 07:11:23,927 INFO [org.apache.activemq.artemis] AMQ241002: Artemis Jolokia REST API available at http://localhost:8161/jolokia
> 07:11:24,745 INFO [org.apache.activemq.artemis.core.server] AMQ221024: Backup server ActiveMQServerImpl::serverUUID=47e70ff8-2b2c-11e7-84d3-525400ec0962 is synchronized with live-server.
> 07:11:24,760 INFO [org.apache.activemq.artemis.core.server] AMQ221031: backup announced
> 07:12:54,442 INFO [org.apache.activemq.artemis.core.server] AMQ221037: ActiveMQServerImpl::serverUUID=47e70ff8-2b2c-11e7-84d3-525400ec0962 to become 'live'
> 07:12:54,556 WARN [org.apache.activemq.artemis.core.server] AMQ222165: No Dead Letter Address configured for queue test-load in AddressSettings
> 07:12:54,556 WARN [org.apache.activemq.artemis.core.server] AMQ222166: No Expiry Address configured for queue test-load in AddressSettings
> 07:12:54,910 INFO [org.apache.activemq.artemis.core.server] AMQ221007: Server is now live
> 07:12:54,933 INFO [org.apache.activemq.artemis.core.server] AMQ221020: Started EPOLL Acceptor at 0.0.0.0:61616 for protocols [CORE,MQTT,AMQP,STOMP,HORNETQ,OPENWIRE]
> 07:12:54,936 INFO [org.apache.activemq.artemis.core.server] AMQ221020: Started EPOLL Acceptor at 0.0.0.0:61613 for protocols [STOMP]
> {noformat}
> \* Note the logs: _Backup server ActiveMQServerImpl::serverUUID=xxx is synchronized with live-server_ / _backup announced_
> and slave reports:
> {noformat}
> 07:11:23,818 INFO [org.apache.activemq.artemis.core.server] AMQ221025: Replication: sending AIOSequentialFile:/var/lib/artemis/shadowbroker/data/journal/activemq-data-1759.amq (size=10,485,760) to replica.
> 07:11:24,352 INFO [org.apache.activemq.artemis.core.server] AMQ221025: Replication: sending NIOSequentialFile /var/lib/artemis/shadowbroker/data/bindings/activemq-bindings-1448.bindings (size=1,048,576) to replica.
> 07:11:24,366 INFO [org.apache.activemq.artemis.core.server] AMQ221025: Replication: sending NIOSequentialFile /var/lib/artemis/shadowbroker/data/bindings/activemq-bindings-1456.bindings (size=1,048,576) to replica.
> 07:11:24,389 INFO [org.apache.activemq.artemis.core.server] AMQ221025: Replication: sending NIOSequentialFile /var/lib/artemis/shadowbroker/data/bindings/activemq-bindings-1447.bindings (size=1,048,576) to replica.
> 07:12:54,399 WARN [org.apache.activemq.artemis.core.persistence.impl.journal.JournalStorageManager] AMQ119114: Replication synchronization process timed out after waiting 90,000 milliseconds: java.lang.IllegalStateException: AMQ119114: Replication synchronization process timed out after waiting 90,000 milliseconds
> at org.apache.activemq.artemis.core.replication.ReplicationManager.sendSynchronizationDone(ReplicationManager.java:607) [artemis-server-2.1.0.jar:2.1.0]
> at org.apache.activemq.artemis.core.persistence.impl.journal.JournalStorageManager.startReplication(JournalStorageManager.java:579) [artemis-server-2.1.0.jar:2.1.0]
> at org.apache.activemq.artemis.core.server.impl.SharedNothingLiveActivation$2.run(SharedNothingLiveActivation.java:171) [artemis-server-2.1.0.jar:2.1.0]
> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_92]
> 07:12:54,401 WARN [org.apache.activemq.artemis.core.client] AMQ212037: Connection failure has been detected: AMQ119014: Did not receive data from /172.23.12.5:37606 within the 60,000ms connection TTL. The connection will now be closed. [code=CONNECTION_TIMEDOUT]
> 07:12:54,401 WARN [org.apache.activemq.artemis.core.server] AMQ222092: Connection to the backup node failed, removing replication now: ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ119014: Did not receive data from /172.23.12.5:37606 within the 60,000ms connection TTL. The connection will now be closed.]
> at org.apache.activemq.artemis.core.remoting.server.impl.RemotingServiceImpl$FailureCheckAndFlushThread$2.run(RemotingServiceImpl.java:723) [artemis-server-2.1.0.jar:2.1.0]
> at org.apache.activemq.artemis.utils.OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run(OrderedExecutorFactory.java:101) [artemis-commons-2.1.0.jar:2.1.0]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_92]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_92]
> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_92]
> 07:12:54,406 WARN [org.apache.activemq.artemis.core.server] AMQ222013: Error when trying to start replication: java.lang.IllegalStateException: AMQ119114: Replication synchronization process timed out after waiting 90,000 milliseconds
> at org.apache.activemq.artemis.core.replication.ReplicationManager.sendSynchronizationDone(ReplicationManager.java:607) [artemis-server-2.1.0.jar:2.1.0]
> at org.apache.activemq.artemis.core.persistence.impl.journal.JournalStorageManager.startReplication(JournalStorageManager.java:579) [artemis-server-2.1.0.jar:2.1.0]
> at org.apache.activemq.artemis.core.server.impl.SharedNothingLiveActivation$2.run(SharedNothingLiveActivation.java:171) [artemis-server-2.1.0.jar:2.1.0]
> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_92]
> 07:12:54,412 WARN [org.apache.activemq.artemis.core.client] AMQ212037: Connection failure has been detected: AMQ119014: Did not receive data from /172.20.98.64:45224 within the 60,000ms connection TTL. The connection will now be closed. [code=CONNECTION_TIMEDOUT]
> 07:12:54,412 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8431e0ae-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,416 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8431e0ae-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,416 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8432a3ff-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,418 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8432a3ff-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,418 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 84338e60-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,421 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 84338e60-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,421 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8435b141-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,422 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8435b141-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,422 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8436e9c2-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,424 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8436e9c2-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,424 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8437fb33-3af1-11e7-ac67-0acf5bbeb077
> 07:12:54,425 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8437fb33-3af1-11e7-ac67-0acf5bbeb077
> 07:13:31,653 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8431e090-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,654 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8431e090-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,654 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8432a3e1-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,655 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8432a3e1-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,655 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 84336732-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,655 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 84336732-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,655 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 84340373-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,656 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 84340373-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,656 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 8435b124-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,656 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 8435b124-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,656 WARN [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 84367475-3af1-11e7-b91a-0acf5bbeb077
> 07:13:31,663 WARN [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 84367475-3af1-11e7-b91a-0acf5bbeb077
> {noformat}
> \* Note the logs: _Replication synchronization process timed out after waiting 90,000 milliseconds_ / _Did not receive data from /xxx:37606 within the 60,000ms connection TTL_
> Same as before, master has the following ha-policy:
> {code:xml}
> <ha-policy>
> <replication>
> <master>
> <check-for-live-server>true</check-for-live-server>
> <initial-replication-sync-timeout>90000</initial-replication-sync-timeout>
> </master>
> </replication>
> </ha-policy>
> {code}
> and slave has:
> {code:xml}
> <ha-policy>
> <replication>
> <slave>
> <allow-failback>true</allow-failback>
> <initial-replication-sync-timeout>90000</initial-replication-sync-timeout>
> </slave>
> </replication>
> </ha-policy>
> {code}
> For running the tests, we send messages using the artemis producer - command:
> {noformat}
> ./artemis producer --url "tcp://xxx:61616?ha=true&retryInterval=1000&retryIntervalMultiplier=1.0&reconnectAttempts=-1" --destination queue://test-load --message-count 60000 --user xxx --password xxx --sleep 200 --message-size 4000 --threads 5
> {noformat}
> and consume messages with the artemis consumer - command:
> {noformat}
> ./artemis consumer --url "tcp://xxx:61616?ha=true&retryInterval=1000&retryIntervalMultiplier=1.0&reconnectAttempts=-1" --destination queue://test-load --threads 5 --message-count 60000 --user xxx --password xxx
> {noformat}
> Please let us know if we can provide some other info about this new issue.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)