Why activemq resource adapter causes java.io.EOFException with too many connections on broker side ?

Solution Unverified - Updated -

Issue

2015-03-13 08:14:25,916 | WARN | .0.1:64416@61622 | Transport | ivemq.broker.TransportConnection  245 | 123 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-611423 | Transport Connection to: tcp://127.0.0.1:64416 failed: java.io.EOFException
2015-03-13 08:16:35,941 | WARN | .0.1:49738@61622 | Transport | ivemq.broker.TransportConnection  245 | 123 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-611423 | Transport Connection to: tcp://127.0.0.1:49738 failed: java.io.EOFException
2015-03-13 08:18:45,985 | WARN | .0.1:54732@61622 | Transport | ivemq.broker.TransportConnection  245 | 123 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-611423 | Transport Connection to: tcp://127.0.0.1:54732 failed: java.io.EOFException
2015-03-13 08:20:56,025 | WARN | .0.1:59733@61622 | Transport | ivemq.broker.TransportConnection  245 | 123 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-611423 | Transport Connection to: tcp://127.0.0.1:59733 failed: java.io.EOFException
  • This WARN message is reproducible even if we use activemq-rar-5.9.0.redhat-610379.rar OR activemq-rar-5.9.0.redhat-611412.rar
15:31:24,399 | WARN  | .0.1:40097@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40097 failed: java.io.EOFException
15:31:24,415 | WARN  | .0.1:40099@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40099 failed: java.io.EOFException
15:31:24,422 | WARN  | .0.1:40100@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40100 failed: java.io.EOFException


15:33:34,437 | WARN  | .0.1:40098@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40098 failed: java.io.EOFException
15:33:34,444 | WARN  | .0.1:40151@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40151 failed: java.net.SocketException: Connection reset
15:33:34,451 | WARN  | .0.1:40152@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40152 failed: java.io.EOFException


15:35:44,467 | WARN  | .0.1:40150@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40150 failed: java.io.EOFException
15:35:44,479 | WARN  | .0.1:40210@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40210 failed: java.io.EOFException
15:35:44,482 | WARN  | .0.1:40211@61616 | Transport                        | 131 - org.apache.activemq.activemq-osgi - 5.9.0.redhat-610379 | Transport Connection to: tcp://127.0.0.1:40211 failed: java.io.EOFException
  • There are no other jms clients in the system. It looks like the activemq-rar resource adapter fails to close the connection properly. Probably the socket is closed without shutting down the ActiveMQ Connection?
  • It looks like activemq-rar does not close connections to the broker properly. Is there a patch or other recommendations how to deal with the issue ?

  • The JBoss EAP side (where the resource adapter is deployed) following logging appears:

[Server:testServer] 08:14:15,894 DEBUG [org.apache.activemq.transport.AbstractInactivityMonitor] [ActiveMQ InactivityMonitor WriteCheckTimer] WriteChecker: 10001ms elapsed since last write check.
[Server:testServer] 08:14:15,894 DEBUG [org.apache.activemq.transport.AbstractInactivityMonitor] [ActiveMQ InactivityMonitor Worker] Running WriteCheck[tcp://127.0.0.1:61622]
[Server:testServer] 08:14:25,890 DEBUG [org.apache.activemq.transport.AbstractInactivityMonitor] [ActiveMQ InactivityMonitor ReadCheckTimer] 30000ms elapsed since last read check.
[Server:testServer] 08:14:25,894 DEBUG [org.apache.activemq.transport.AbstractInactivityMonitor] [ActiveMQ InactivityMonitor WriteCheckTimer] WriteChecker: 10000ms elapsed since last write check.
[Server:testServer] 08:14:25,894 DEBUG [org.apache.activemq.transport.AbstractInactivityMonitor] [ActiveMQ InactivityMonitor Worker] Running WriteCheck[tcp://127.0.0.1:61622]
[Server:testServer] 08:14:25,913 DEBUG [org.apache.activemq.util.ThreadPoolUtils] [Periodic Recovery] Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@71d2bb4c[Terminated, poolsize = 0, active threads = 0, queued tasks = 0, completed tasks = 0] is shutdown: true and terminated: true took: 0.000 seconds.
[Server:testServer] 08:14:25,914 DEBUG [org.apache.activemq.util.ThreadPoolUtils] [Periodic Recovery] Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@465262b0[Terminated, poolsize = 0, active threads = 0, queued tasks = 0, completed tasks = 11] is shutdown: true and terminated: false took: 0.000 seconds.
[Server:testServer] 08:14:25,914 DEBUG [org.apache.activemq.transport.tcp.TcpTransport] [Periodic Recovery] Stopping transport tcp://localhost/127.0.0.1:61622@64416
[Server:testServer] 08:14:25,915 DEBUG [org.apache.activemq.thread.TaskRunnerFactory] [Periodic Recovery] Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.ThreadPoolExecutor@4acd34e1[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
[Server:testServer] 08:14:25,916 DEBUG [org.apache.activemq.transport.tcp.TcpTransport] [ActiveMQ Task-1] Closed socket Socket[addr=localhost/127.0.0.1,port=61622,localport=64416]
[Server:testServer] 08:14:25,916 DEBUG [org.apache.activemq.util.ThreadPoolUtils] [Periodic Recovery] Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@4acd34e1[Running,pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 1]
[Server:testServer] 08:14:25,918 DEBUG [org.apache.activemq.transport.WireFormatNegotiator] [Periodic Recovery] Sending: WireFormatInfo { version=10, properties={MaxFrameSize=9223372036854775807, CacheSize=1024, CacheEnabled=true, Host=localhost, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
[Server:testServer] 08:14:25,919 DEBUG [org.apache.activemq.TransactionContext] [Periodic Recovery] recover(16777216)
[Server:testServer] 08:14:25,920 DEBUG [org.apache.activemq.transport.InactivityMonitor] [ActiveMQ Transport: tcp://localhost/127.0.0.1:61622@49738] Using min of local: WireFormatInfo { version=10, properties={MaxFrameSize=9223372036854775807, CacheSize=1024, CacheEnabled=true, Host=localhost, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]} and remote: WireFormatInfo { version=10, properties={CacheSize=1024, MaxFrameSize=9223372036854775807, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
[Server:testServer] 08:14:25,921 DEBUG [org.apache.activemq.transport.WireFormatNegotiator] [ActiveMQ Transport: tcp://localhost/127.0.0.1:61622@49738] Received WireFormat: WireFormatInfo { version=10, properties={CacheSize=1024, MaxFrameSize=9223372036854775807, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
[Server:testServer] 08:14:25,921 DEBUG [org.apache.activemq.transport.WireFormatNegotiator] [ActiveMQ Transport: tcp://localhost/127.0.0.1:61622@49738] tcp://localhost/127.0.0.1:61622@49738 beforenegotiation: OpenWireFormat{version=10, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=9223372036854775807}
[Server:testServer] 08:14:25,921 DEBUG [org.apache.activemq.transport.WireFormatNegotiator] [ActiveMQ Transport: tcp://localhost/127.0.0.1:61622@49738] tcp://localhost/127.0.0.1:61622@49738 after negotiation: OpenWireFormat{version=10, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=9223372036854775807}
[Server:testServer] 08:14:25,927 DEBUG [org.apache.activemq.TransactionContext] [Periodic Recovery] recover(16777216)=[]
[Server:testServer] 08:14:35,928 DEBUG [org.apache.activemq.TransactionContext] [Periodic Recovery] recover(8388608)
[Server:testServer] 08:14:35,928 DEBUG [org.apache.activemq.TransactionContext] [Periodic Recovery] recover(8388608)=[]
  • Will this cause activemq-rar to generates too many connections? Or too many connections in the TIME_WAIT state as there are many java.io.EOFException logged on the broker side?

  • The resource adapter configuration is using the following "ServerUrl" to connect to the activemq broker.

      <config-property name="ServerUrl">
         tcp://localhost:61621?jms.rmIdFromConnectionId=true
      </config-property>

Environment

  • Red Hat JBoss A-MQ
    • 6.1.0
  • Red Hat JBoss Fuse
    • 6.1.0

Subscriber exclusive content

A Red Hat subscription provides unlimited access to our knowledgebase of over 48,000 articles and solutions.

Current Customers and Partners

Log in for full access

Log In
Close

Welcome! Check out the Getting Started with Red Hat page for quick tours and guides for common tasks.