Отказ при отказе ActiveMQ Artemis убивает ведомого в установке с 2 узлами HA - PullRequest
Новая
       13

Отказ при отказе ActiveMQ Artemis убивает ведомого в установке с 2 узлами HA

4 голосов
/ 21 января 2020

Я использую отказоустойчивый кластер ActiveMQ Artemis 2.11.0 с 2 узлами, используя репликацию в нашей тестовой среде. Оба узла (и все подключающиеся клиенты (серверы приложений)) используют конфигурацию узлов stati c, то есть обнаружение не происходит.

В одном из моих первых тестов я установил серверы приложений под средней нагрузкой и хотел посмотреть, что произойдет в сценарии отработки отказа JMS-брокера. Сначала я остановился и через пару минут перезапустил узел slave . Все заработало как положено. Во-вторых, я остановил узел master . Вскоре после этого ведомое устройство объявило о работоспособности, и серверы приложений переключились на подчиненное устройство - на высоком уровне, то есть на реальных клиентах сервера приложений, эта операция была прозрачной.
Затем мы перезапустили master * 1009. * узел, синхронизированный с ведомым, взял на себя обязанности - , после чего ведомое устройство умерло .

Брокер каждого узла в основном настроен в соответствии с официальным JMS Replicated Failback Stati c Пример .

Выдержка из журналов исходного узла master : 

2020-01-21 14:05:13,329 INFO  [org.apache.activemq.artemis.integration.bootstrap] (main) AMQ101000: Starting ActiveMQ Artemis Server
2020-01-21 14:05:13,353 INFO  [org.apache.activemq.artemis.core.server] (main) AMQ221000: live Message Broker is starting with configuration Broker Configuration (clustered=true,journalDirectory=data/journal,bindingsDirectory=data/bindings,largeMessagesDirectory=data/large-messages,pagingDirectory=data/paging)
2020-01-21 14:05:13,648 INFO  [org.apache.activemq.artemis.core.server] (AMQ229000: Activation for server ActiveMQServerImpl::serverUUID=null) AMQ222162: Moving data directory /var/lib/artemis-master/data/bindings to /var/lib/artemis-master/data/bindings/oldreplica.1
...
2020-01-21 14:05:13,747 INFO  [org.apache.activemq.artemis.core.server] (AMQ229000: Activation for server ActiveMQServerImpl::serverUUID=null) AMQ221043: Protocol module found: [artemis-server]. Adding protocol support for: CORE
...
2020-01-21 14:05:13,810 INFO  [org.apache.activemq.artemis.core.server] (AMQ229000: Activation for server ActiveMQServerImpl::serverUUID=null) AMQ221109: Apache ActiveMQ Artemis Backup Server version 2.11.0 [null] started, waiting live to fail before it gets active
2020-01-21 14:05:13,877 INFO  [org.apache.activemq.hawtio.branding.PluginContextListener] (main) Initialized activemq-branding plugin
2020-01-21 14:05:13,928 INFO  [org.apache.activemq.hawtio.plugin.PluginContextListener] (main) Initialized artemis-plugin plugin
2020-01-21 14:05:14,577 INFO  [org.apache.activemq.artemis] (main) AMQ241001: HTTP Server started at http://172.16.2.33:8161
2020-01-21 14:05:14,577 INFO  [org.apache.activemq.artemis] (main) AMQ241002: Artemis Jolokia REST API available at http://172.16.2.33:8161/console/jolokia
2020-01-21 14:05:14,577 INFO  [org.apache.activemq.artemis] (main) AMQ241004: Artemis Console available at http://172.16.2.33:8161/console
2020-01-21 14:05:21,108 INFO  [org.apache.activemq.artemis.core.server] (Thread-4 (ActiveMQ-client-netty-threads)) AMQ221024: Backup server ActiveMQServerImpl::serverUUID=139d6d77-3c3c-11ea-b519-00505686d7ad is synchronized with live-server.
2020-01-21 14:05:21,115 INFO  [org.apache.activemq.artemis.core.server] (Thread-0 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@37858383)) AMQ221031: backup announced
2020-01-21 14:06:00,209 INFO  [org.apache.activemq.artemis.core.server] (Thread-0 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@37858383)) AMQ221066: Initiating quorum vote: LiveFailoverQuorumVote
2020-01-21 14:06:00,209 INFO  [org.apache.activemq.artemis.core.server] (Thread-0 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@37858383)) AMQ221067: Waiting 30 seconds for quorum vote results.
2020-01-21 14:06:00,209 INFO  [org.apache.activemq.artemis.core.server] (Thread-0 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@37858383)) AMQ221068: Received all quorum votes.
2020-01-21 14:06:00,210 INFO  [org.apache.activemq.artemis.core.server] (Thread-0 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@37858383)) AMQ221071: Failing over based on quorum vote results.
2020-01-21 14:06:00,229 WARN  [org.apache.activemq.artemis.core.client] (Thread-0 (ActiveMQ-client-global-threads)) AMQ212037: Connection failure to artemis-slave.local/172.16.2.34:61616 has been detected: AMQ219015: The connection was disconnected because of server shutdown [code=DISCONNECTED]
2020-01-21 14:06:00,229 WARN  [org.apache.activemq.artemis.core.client] (Thread-1 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@37858383)) AMQ212037: Connection failure to artemis-slave.local/172.16.2.34:61616 has been detected: AMQ219015: The connection was disconnected because of server shutdown [code=DISCONNECTED]
2020-01-21 14:06:00,249 INFO  [org.apache.activemq.artemis.core.server] (AMQ229000: Activation for server ActiveMQServerImpl::serverUUID=null) AMQ221037: ActiveMQServerImpl::serverUUID=139d6d77-3c3c-11ea-b519-00505686d7ad to become 'live'
2020-01-21 14:06:00,271 WARN  [org.apache.activemq.artemis.core.client] (Thread-0 (ActiveMQ-client-global-threads)) AMQ212004: Failed to connect to server.
2020-01-21 14:06:00,822 WARN  [org.apache.activemq.artemis.journal] (AMQ229000: Activation for server ActiveMQServerImpl::serverUUID=null) AMQ142015: Uncommitted transaction with id 2,147,639,299 found and discarded
...
2020-01-21 14:06:01,524 INFO  [org.apache.activemq.artemis.core.server] (AMQ229000: Activation for server ActiveMQServerImpl::serverUUID=null) AMQ221007: Server is now live
2020-01-21 14:06:01,532 INFO  [org.apache.activemq.artemis.core.server] (AMQ229000: Activation for server ActiveMQServerImpl::serverUUID=null) AMQ221020: Started EPOLL Acceptor at artemis-master.local:61616 for protocols [CORE,MQTT,AMQP,HORNETQ,STOMP,OPENWIRE]

И тот же период времени подчиненный узел: 

2020-01-21 14:05:18,894 INFO  [org.apache.activemq.artemis.core.server] (Thread-14) AMQ221025: Replication: sending AIOSequentialFile:/var/lib/artemis-slave/data/journal/activemq-data-367.amq (size=10,485,760) to replica.
...
2020-01-21 14:05:19,978 INFO  [org.apache.activemq.artemis.core.server] (Thread-14) AMQ221025: Replication: sending AIOSequentialFile:/var/lib/artemis-slave/data/journal/activemq-data-374.amq (size=10,485,760) to replica.
2020-01-21 14:05:20,037 INFO  [org.apache.activemq.artemis.core.server] (Thread-14) AMQ221025: Replication: sending AIOSequentialFile:/var/lib/artemis-slave/data/journal/activemq-data-375.amq (size=10,485,760) to replica.
2020-01-21 14:05:20,154 INFO  [org.apache.activemq.artemis.core.server] (Thread-14) AMQ221025: Replication: sending NIOSequentialFile /var/lib/artemis-slave/data/bindings/activemq-bindings-5.bindings (size=1,048,576) to replica.
...
2020-01-21 14:05:20,163 INFO  [org.apache.activemq.artemis.core.server] (Thread-14) AMQ221025: Replication: sending NIOSequentialFile /var/lib/artemis-slave/data/bindings/activemq-bindings-7.bindings (size=1,048,576) to replica.
2020-01-21 14:05:38,157 WARN  [org.apache.activemq.artemis.core.client] (Thread-7 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@37858383)) AMQ212037: Connection failure to /172.16.2.112:51866 has been detected: AMQ229014: Did not receive data from /172.16.2.112:51866 within the 30,000ms connection TTL. The connection will now be closed. [code=CONNECTION_TIMEDOUT]
2020-01-21 14:05:50,168 WARN  [org.apache.activemq.artemis.core.server] (Thread-14) AMQ222010: Critical IO Error, shutting down the server. file=NULL, message=AMQ229114: Replication synchronization process timed out after waiting 30,000 milliseconds: ActiveMQReplicationTimeooutException[errorType=REPLICATION_TIMEOUT_ERROR message=AMQ229114: Replication synchronization process timed out after waiting 30,000 milliseconds]
    at org.apache.activemq.artemis.core.replication.ReplicationManager.sendSynchronizationDone(ReplicationManager.java:654) [artemis-server-2.11.0.jar:2.11.0]
    at org.apache.activemq.artemis.core.persistence.impl.journal.JournalStorageManager.startReplication(JournalStorageManager.java:699) [artemis-server-2.11.0.jar:2.11.0]
    at org.apache.activemq.artemis.core.server.impl.SharedNothingLiveActivation$2.run(SharedNothingLiveActivation.java:178) [artemis-server-2.11.0.jar:2.11.0]
    at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_222]

2020-01-21 14:05:50,171 WARN  [org.apache.activemq.artemis.core.server] (Thread-14) AMQ222251: Unable to start replication: ActiveMQReplicationTimeooutException[errorType=REPLICATION_TIMEOUT_ERROR message=AMQ229114: Replication synchronization process timed out after waiting 30,000 milliseconds]
    at org.apache.activemq.artemis.core.replication.ReplicationManager.sendSynchronizationDone(ReplicationManager.java:654) [artemis-server-2.11.0.jar:2.11.0]
    at org.apache.activemq.artemis.core.persistence.impl.journal.JournalStorageManager.startReplication(JournalStorageManager.java:699) [artemis-server-2.11.0.jar:2.11.0]
    at org.apache.activemq.artemis.core.server.impl.SharedNothingLiveActivation$2.run(SharedNothingLiveActivation.java:178) [artemis-server-2.11.0.jar:2.11.0]
    at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_222]

2020-01-21 14:06:00,175 WARN  [org.apache.activemq.artemis.core.client] (Thread-14) AMQ212041: Timed out waiting for netty channel to close
2020-01-21 14:06:00,226 ERROR [org.apache.activemq.artemis.core.journal.impl.JournalImpl] (Thread-35 (ActiveMQ-IO-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$7@6a6afff2)) appendRollbackRecord:java.lang.IllegalStateException: Cannot find tx with id 2147634792: java.lang.IllegalStateException: Cannot find tx with id 2147634792
    at org.apache.activemq.artemis.core.journal.impl.JournalImpl$10.run(JournalImpl.java:1372) [artemis-journal-2.11.0.jar:2.11.0]
    at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:42) [artemis-commons-2.11.0.jar:2.11.0]
    at org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:31) [artemis-commons-2.11.0.jar:2.11.0]
    at org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:66) [artemis-commons-2.11.0.jar:2.11.0]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_222]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_222]
    at org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118) [artemis-commons-2.11.0.jar:2.11.0]

Моя интерпретация:

  1. Ведомый в настоящее время активен
  2. Мастер запускается и повторно синхронизируется с подчиненным. Сетевая репликация занимает около 1,2 секунды для передачи ~ 100 МБ данных.
  3. (Сообщение AMQ212037: Connection failure to /172.16.2.112:51866 has been detected - это соединение с серверами приложений, которое истекло из-за неактивности, я полагаю. Это происходит довольно часто, и я думаю, что это вызвано при неактивных пулированных соединениях серверов приложений)
  4. В 14:05:21,108 мастер объявляет «Сервер резервного копирования ... синхронизирован с live-сервером», который я интерпретирую как «Репликация успешна, мы можем переключиться назад». За ним сразу следует AMQ221031: backup announced, что звучит замечательно.
  5. В 14:05:50,168, ровно через 30 секунд после успешной отправки последнего файла, ведомый сообщает о «критической ошибке ввода-вывода» AMQ229114: Replication synchronization process timed out after waiting 30,000 milliseconds и немедленно отключается. (Примечание: регистрация на уровне WARN, на мой взгляд, является преуменьшением ...)
  6. Мастер не сообщает об ошибке на своей стороне в это время, скорее, через пару секунд после этого он, кажется, замечает подчиненный сервер отключается и запускает мастер-выборы, которые заканчиваются более или менее немедленно, после чего мастер становится новым живым сервером. Мне также кажется, что это правильное поведение.
  7. (я не очень понимаю последствия части "транзакции" в обоих журналах.)

Как мне диагностировать ( и - на самом деле даже лучше - смягчить) проблему? В журналах отсутствует важная информация?

Спасибо

Обновление 2020-01-27

Наша проблема очень похожа на описанную здесь: https://issues.apache.org/jira/browse/ARTEMIS-1170

Кроме серверов приложений, мы используем клиенты Artemis с поддержкой JTA. Может ли это быть источником проблем?

...