WARNING as java.io.EOFException when ActiveMQ starts

Question

am trying to start the ActiveMQ 5.11 and I see a WARNING as below:

 WARN | Transport Connection to: tcp://127.0.0.1:40890 failed: java.io.EOFException

My activemq.xml is as below:

<transportConnectors>
    <transportConnector name="openwire" uri="tcp://0.0.0.0:${JMS_PORT}" />
    <transportConnector name="stomp" uri="stomp://0.0.0.0:${JMS_STOMP_PORT}"/>
    <transportConnector name="ssl" uri="ssl://0.0.0.0:${JMS_SSL_PORT}"/>
</transportConnectors>

<sslContext>
    <sslContext
        keyStore="file:${JMS_KEY_STORE}"
        keyStorePassword="${JMS_KEY_STORE_PASSWORD}"
        trustStore="file:${JMS_TRUST_STORE}"
        trustStorePassword="${JMS_TRUST_STORE_PASSWORD}"
    />
</sslContext>

<networkConnectors>
    <networkConnector 
        name="host1 and host2" 
        uri="static://(${JMS_X_SITE_CSV_URL})?wireFormat=ssl&amp;wireFormat.maxInactivityDuration=30000"
        dynamicOnly="true"
        suppressDuplicateQueueSubscriptions = "true"
        networkTTL="1"
    />
</networkConnectors>

Here is the entire console log for this.

Java Runtime: Oracle Corporation 1.7.0_05 /usr/java/jdk1.7.0_05/jre
  Heap sizes: current=1004928k  free=994439k  max=1004928k
    JVM args: -Xmx1G -Dorg.apache.activemq.UseDedicatedTaskRunner=true -Djava.util.logging.config.file=logging.properties -Djava.security.auth.login.config=/home/dragon/activemq/conf/login.config -Dcom.sun.management.jmxremote -Djava.io.tmpdir=/home/dragon/activemq/tmp -Dactivemq.classpath=/home/dragon/activemq/conf; -Dactivemq.home=/home/dragon/activemq -Dactivemq.base=/home/dragon/activemq -Dactivemq.conf=/home/dragon/activemq/conf -Dactivemq.data=/home/dragon/activemq/data
Extensions classpath:
  [/home/dragon/activemq/lib,/home/dragon/activemq/lib/camel,/home/dragon/activemq/lib/optional,/home/dragon/activemq/lib/web,/home/dragon/activemq/lib/extra]
ACTIVEMQ_HOME: /home/dragon/activemq
ACTIVEMQ_BASE: /home/dragon/activemq
ACTIVEMQ_CONF: /home/dragon/activemq/conf
ACTIVEMQ_DATA: /home/dragon/activemq/data
Loading message broker from: xbean:activemq.xml
 INFO | Refreshing org.apache.activemq.xbean.XBeanBrokerFactory$1@a842913: startup date [Fri Oct 07 08:14:02 IST 2016]; root of context hierarchy
 INFO | PListStore:[/home/dragon/activemq/data/divinedragonbox/tmp_storage] started
 INFO | Using Persistence Adapter: KahaDBPersistenceAdapter[/home/dragon/jms_store]
 INFO | JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:15526/jmxrmi
 INFO | KahaDB is version 5
 INFO | Recovering from the journal ...
 INFO | Recovery replayed 76 operations from the journal in 0.032 seconds.
 INFO | Apache ActiveMQ 5.11.1 (divinedragonbox, ID:divinedragonbox-60914-1475824445361-0:1) is starting
 INFO | Listening for connections at: tcp://divinedragonbox:15511
 INFO | Connector openwire started
 INFO | Listening for connections at: stomp://divinedragonbox:15512
 INFO | Connector stomp started
 INFO | Listening for connections at: ssl://divinedragonbox:15571
 INFO | Connector ssl started
 INFO | Establishing network connection from vm://divinedragonbox?async=false&network=true to ssl://localhost:15571
 INFO | Connector vm://divinedragonbox started
 INFO | Network Connector DiscoveryNetworkConnector:host1 and host2:BrokerService[divinedragonbox] started
 INFO | Apache ActiveMQ 5.11.1 (divinedragonbox, ID:divinedragonbox-60914-1475824445361-0:1) started
 INFO | For help or more information please see: http://activemq.apache.org
 INFO | divinedragonbox Shutting down
 INFO | Connector vm://divinedragonbox stopped
 INFO | divinedragonbox bridge to Unknown stopped
 WARN | Transport Connection to: tcp://127.0.0.1:40890 failed: java.io.EOFException
 INFO | ActiveMQ WebConsole available at http://localhost:15521/
 INFO | Initializing Spring FrameworkServlet 'dispatcher'
 INFO | jolokia-agent: No access restrictor found at classpath:/jolokia-access.xml, access to all MBeans is allowed

I enabled the TRACE for the messages and I got the following snippets of exceptions in the log file.

2016-10-07 08:15:45,378 | TRACE | Execute[ActiveMQ ForwardingBridge StopTask] runnable: org.apache.activemq.network.DemandForwardingBridgeSupport$4@b3f451d | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,378 | TRACE | Created and running thread[ActiveMQ ForwardingBridge StopTask-5]: Thread[ActiveMQ ForwardingBridge StopTask-5,5,main] | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,379 | DEBUG | Caught exception sending shutdown | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ ForwardingBridge StopTask-5
org.apache.activemq.transport.TransportDisposedIOException: Transport disposed.
    at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:82)[activemq-broker-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.network.DemandForwardingBridgeSupport$4.run(DemandForwardingBridgeSupport.java:288)[activemq-broker-5.11.1.jar:5.11.1]
    at java.lang.Thread.run(Thread.java:722)[:1.7.0_05]
2016-10-07 08:15:45,380 | DEBUG | Stopping transport ssl://localhost/127.0.0.1:15571 | org.apache.activemq.transport.tcp.TcpTransport | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,381 | DEBUG | Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: null | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,381 | TRACE | Execute[ActiveMQ Task] runnable: org.apache.activemq.transport.tcp.TcpTransport$1@a1848dc | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,381 | TRACE | Created and running thread[ActiveMQ Task-1]: Thread[ActiveMQ Task-1,5,main] | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,382 | TRACE | Closing socket 2a9a5d77[TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: Socket[addr=localhost/127.0.0.1,port=15571,localport=40999]] | org.apache.activemq.transport.tcp.TcpTransport | ActiveMQ Task-1
2016-10-07 08:15:45,383 | DEBUG | Closed socket 2a9a5d77[TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: Socket[addr=localhost/127.0.0.1,port=15571,localport=40999]] | org.apache.activemq.transport.tcp.TcpTransport | ActiveMQ Task-1
2016-10-07 08:15:45,384 | INFO  | divinedragonbox bridge to Unknown stopped | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,384 | TRACE | serviceLocalException: disposed true ex | org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ BrokerService[divinedragonbox] Task-4
org.apache.activemq.transport.TransportDisposedIOException: peer (vm://divinedragonbox#1) stopped.
    at org.apache.activemq.transport.vm.VMTransport.stop(VMTransport.java:207)[activemq-broker-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.TransportFilter.stop(TransportFilter.java:65)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.TransportFilter.stop(TransportFilter.java:65)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.ResponseCorrelator.stop(ResponseCorrelator.java:132)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.broker.TransportConnection.doStop(TransportConnection.java:1151)[activemq-broker-5.11.1.jar:5.11.1]
    at org.apache.activemq.broker.TransportConnection$4.run(TransportConnection.java:1117)[activemq-broker-5.11.1.jar:5.11.1]
    at java.lang.Thread.run(Thread.java:722)[:1.7.0_05]
2016-10-07 08:15:45,384 | DEBUG | Stopped transport: vm://divinedragonbox#0 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,384 | TRACE | Shutdown timeout: 1 task: Transport Connection to: vm://divinedragonbox#0 | org.apache.activemq.thread.DedicatedTaskRunner | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,385 | TRACE | Run task done: Transport Connection to: vm://divinedragonbox#0 | org.apache.activemq.thread.DedicatedTaskRunner | ActiveMQ Connection Dispatcher: vm://divinedragonbox#0
2016-10-07 08:15:45,385 | DEBUG | Connection Stopped: vm://divinedragonbox#0 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[divinedragonbox] Task-4
2016-10-07 08:15:45,385 | TRACE | Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@dfe196a[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] with await termination: 0 millis | org.apache.activemq.util.ThreadPoolUtils | ActiveMQ Transport: ssl:///127.0.0.1:40999
2016-10-07 08:15:45,385 | DEBUG | Shutting down VM connectors for broker: divinedragonbox | org.apache.activemq.transport.vm.VMTransportFactory | triggerStartAsyncNetworkBridgeCreation: remoteBroker=ssl://localhost/127.0.0.1:15571, localBroker= vm://divinedragonbox#0
2016-10-07 08:15:45,385 | INFO  | Connector vm://divinedragonbox stopped | org.apache.activemq.broker.TransportConnector | triggerStartAsyncNetworkBridgeCreation: remoteBroker=ssl://localhost/127.0.0.1:15571, localBroker= vm://divinedragonbox#0
2016-10-07 08:15:45,400 | DEBUG | Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@dfe196a[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0] is shutdown: true and terminated: true took: 0.001 seconds. | org.apache.activemq.util.ThreadPoolUtils | ActiveMQ Transport: ssl:///127.0.0.1:40999
2016-10-07 08:15:45,400 | DEBUG | Transport Connection to: tcp://127.0.0.1:40999 failed: java.io.EOFException | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ Transport: ssl:///127.0.0.1:40999
java.io.EOFException
    at java.io.DataInputStream.readInt(DataInputStream.java:392)[:1.7.0_05]
    at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:258)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:221)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:213)[activemq-client-5.11.1.jar:5.11.1]
    at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)[activemq-client-5.11.1.jar:5.11.1]
    at java.lang.Thread.run(Thread.java:722)[:1.7.0_05]
2016-10-07 08:15:45,401 | DEBUG | Unregistering MBean org.apache.activemq:type=Broker,brokerName=divinedragonbox,connector=clientConnectors,connectorName=ssl,connectionViewType=remoteAddress,connectionName=tcp_//127.0.0.1_40999 | org.apache.activemq.broker.jmx.ManagementContext | ActiveMQ Transport: ssl:///127.0.0.1:40999
2016-10-07 08:15:45,401 | TRACE | Execute[ActiveMQ BrokerService[divinedragonbox] Task] runnable: org.apache.activemq.broker.TransportConnection$4@5039f4d3 | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ Transport: ssl:///127.0.0.1:40999
2016-10-07 08:15:45,401 | TRACE | Created and running thread[ActiveMQ BrokerService[divinedragonbox] Task-6]: Thread[ActiveMQ BrokerService[divinedragonbox] Task-6,8,main] | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ Transport: ssl:///127.0.0.1:40999

Can somebody tell me why are these exceptions thrown?

I can provide the entire log file if anybody needs for a deeper look.

Answer 1

So, I finally got to the root cause of this. This WARNING comes because the way networkConnector works and configured. I had posted this on the activemq community here - http://activemq.2283324.n4.nabble.com/java-io-EOFException-when-ActiveMQ-starts-td4717598.html

When networkConnector is used, activemq tries to connect to the broker configured. In my case, I was trying to self-connect to the broker and that is why it was rejecting the connection. The same was pointed by Tim in the community.

I've never tried configuring a broker with a static networkConnector connected to itself (why would I, it's a useless configuration), but it wouldn't surprise me if the broker rejected that self-connection, which could result in the EOFException you saw. It's also possible that there's something wrong with your SSL configuration as you suggested; there's no good way in a mailing list discussion to check whether your truststore trusts your keystore and the certs are being presented properly since that's all about the binary content and you shouldn't be sharing that publicly, but you could test the SSL configuration by setting up two brokers (in a test environment) that each have their JMS_X_SITE_CSV_URL pointed at each other. If that configuration gives you EOFExceptions, then switch to using the tcp transport and see what happens. If you get errors with the ssl transport but not the tcp one, there's a good chance it's something wrong with your keys.

As far as the current configuration (where you have a broker whose only networkConnection is a static:ssl: one to itself), it's not a useful configuration (having a networkConnector to yourself serves no purpose), and you proved early on in this discussion that removing it removes the WARN log line that you're concerned about. So I disagree with your statement that "I feel the configuration still seems fine." Either switch to something that serves the purpose you said you're trying to achieve (like the discovery: transport instead of the static: transport, or like listing your cross-site servers if you're going to continue using the static: transport) or take it out and eliminate the WARN line.

So, networkConnector is essentially of no use if it is a single broker system. Makes more sense in multi-broker deployments and then all the brokers are configured, except the self on each broker separately.

To still make the networkConnector configuration to work in single broker deployment, the value I had to set was - url="static://(ssl://divinedragonbox:7031)..."(Hostname instead of IP Address or localhost). That gets rid of the WARNING which comes.