Activemq Successfully connected to tcp в логах?

Question

[Алексей]

Добрый день! Может быть кто то сталкивался с записью в логах Successfully connected to tcp ?
У нас 2 брокера, конечное приложение ( использует Camel), использует строку jms.url=failover:(tcp://server1.domain.local:31616,tcp://server2.domain.local:31616) для подключения к брокерам.
Каждые 2-3 минуты прилетает сообщение в логи:
2018-10-23T08:55:31,854 | INFO | ActiveMQ Task-1 | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Successfully connected to tcp://server1.domain.local:31616
Хочется понять, почему возникает данная запись в логах. Происходит переподключение к брокеру ? обрыв связи ?
Читал интернет, прописал keepAlive - ничего не помогает.

Answer 1

[Алексей Черемисин]

Судя по коду, происходит создание коннекта. Скорее всего коннект закрывается, по каким причинам не знаю, и создается заново. Причем создается как "первое подключение" - https://github.com/apache/activemq/blob/0b71b06ac8... - строка 1052.

Comments

[Алексей]

Спасибо большое! Посмотрим настройки на стороне брокеров.

[Алексей Черемисин]

Алексей, я там вроде бы log.debug видел, попробуйте включить, может яснее будет.

[Алексей]

Алексей Черемисин, спасибо! Действительно, debug логи помогли. Судя по всему, не верно настроен failover на самих брокерах:
лог:

spoiler

2019-01-29T08:05:56,827 | DEBUG | Camel (adapter-context) thread #26 - timer://adapter-status | TaskRunnerFactory | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@3af38efb[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
2019-01-29T08:05:56,827 | DEBUG | Camel (adapter-context) thread #26 - timer://adapter-status | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Reconnect was triggered but transport is not started yet. Wait for start to connect the transport.
2019-01-29T08:05:56,827 | DEBUG | Camel (adapter-context) thread #26 - timer://adapter-status | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Started unconnected
2019-01-29T08:05:56,827 | DEBUG | Camel (adapter-context) thread #26 - timer://adapter-status | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Waking up reconnect task
2019-01-29T08:05:56,827 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | urlList connectionList:[tcp://server1.domain.local:31616, tcp://server2.domain.local:31616], from: [tcp://server1.domain.local:31616, tcp://server2.domain.local:31616]
2019-01-29T08:05:56,827 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Attempting 0th connect to: tcp://server1.domain.local:31616
2019-01-29T08:05:57,202 | DEBUG | ActiveMQ InactivityMonitor WriteCheckTimer | AbstractInactivityMonitor | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | WriteChecker: 10000ms elapsed since last write check.
2019-01-29T08:05:57,202 | DEBUG | ActiveMQ InactivityMonitor Worker | AbstractInactivityMonitor | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Running WriteCheck[tcp://192.168.12.91:31616]
2019-01-29T08:05:57,655 | DEBUG | ActiveMQ InactivityMonitor WriteCheckTimer | AbstractInactivityMonitor | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | WriteChecker: 10000ms elapsed since last write check.
2019-01-29T08:05:57,655 | DEBUG | ActiveMQ InactivityMonitor Worker | AbstractInactivityMonitor | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Running WriteCheck[tcp://192.168.12.91:31616]
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Connect fail to: tcp://server1.domain.local:31616, reason: {}
java.net.ConnectException: Connection refused: connect
at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method) ~[?:?]
at java.net.DualStackPlainSocketImpl.socketConnect(Unknown Source) [?:?]
at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source) [?:?]
at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source) [?:?]
at java.net.AbstractPlainSocketImpl.connect(Unknown Source) [?:?]
at java.net.PlainSocketImpl.connect(Unknown Source) [?:?]
at java.net.SocksSocketImpl.connect(Unknown Source) [?:?]
at java.net.Socket.connect(Unknown Source) [?:?]
at org.apache.activemq.transport.tcp.TcpTransport.connect(TcpTransport.java:525) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.transport.tcp.TcpTransport.doStart(TcpTransport.java:488) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.transport.AbstractInactivityMonitor.start(AbstractInactivityMonitor.java:169) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.transport.InactivityMonitor.start(InactivityMonitor.java:52) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.transport.TransportFilter.start(TransportFilter.java:64) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.transport.WireFormatNegotiator.start(WireFormatNegotiator.java:72) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.transport.failover.FailoverTransport.doReconnect(FailoverTransport.java:1017) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.transport.failover.FailoverTransport$2.iterate(FailoverTransport.java:148) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133) [65:org.apache.activemq.activemq-osgi:5.14.5]
at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48) [65:org.apache.activemq.activemq-osgi:5.14.5]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
at java.lang.Thread.run(Unknown Source) [?:?]
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | TcpTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Stopping transport tcp://server1.domain.local:31616
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | TaskRunnerFactory | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@2e77d584[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | TcpTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Closed socket Socket[unconnected]
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | ThreadPoolUtils | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@2e77d584[Running, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 1]
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Attempting 0th connect to: tcp://server2.domain.local:31616
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | WireFormatNegotiator | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Sending: WireFormatInfo { version=12, properties={TcpNoDelayEnabled=true, SizePrefixDisabled=false, CacheSize=1024, ProviderName=ActiveMQ, StackTraceEnabled=true, PlatformDetails=JVM: 1.8.0_162, 25.162-b12, Oracle Corporation, OS: Windows Server 2016, 10.0, amd64, CacheEnabled=true, TightEncodingEnabled=true, MaxFrameSize=9223372036854775807, MaxInactivityDuration=30000, MaxInactivityDurationInitalDelay=10000, ProviderVersion=5.14.5}, magic=[A,c,t,i,v,e,M,Q]}
2019-01-29T08:05:57,843 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 65 - org.apache.activemq.activemq-osgi - 5.14.5 | Connection established