You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by Steve Hill <sh...@futurelogix.co.uk> on 2017/08/31 20:18:37 UTC
Broken Pipe Connecting
We are running ActiveMQ in Master/Slave configuration. Currently
mqarms02p is the Master. Earlier today we ran into a situation where we
lost access to ActiveMQ and on reviewing the client side logs we see the
information below cycle continuously.
Is there anything we can enable on the server side to better log what
happened from the server perspective? Unfortunately in this instance
the logs had already rolled so we could not see anything, however from
previously experience we know almost nothing shows up.
The server was online and other clients were using it without incident
Any ideas as to what happened and how we can prevent this occurring in
future?
08-31 11:46:02 DEBUG - Attempting 0th connect to: tcp://mqarms01p:61616
08-31 11:46:02 TRACE - Starting connection check task for:
tcp://mqarms01p:61616
08-31 11:46:02 DEBUG - Connect fail to: tcp://mqarms01p:61616, reason:
java.net.ConnectException: Connection refused
08-31 11:46:02 TRACE - Stopping connection check task for:
tcp://mqarms01p:61616
08-31 11:46:02 DEBUG - Stopping transport tcp://mqarms01p:61616
08-31 11:46:02 DEBUG - Initialized TaskRunnerFactory[ActiveMQ Task]
using ExecutorService:
java.util.concurrent.ThreadPoolExecutor@1f0f564[Running, pool size = 0,
active threads = 0, queued tasks = 0, completed tasks = 0]
08-31 11:46:02 TRACE - Execute[ActiveMQ Task] runnable:
org.apache.activemq.transport.tcp.TcpTransport$1@727e793a
08-31 11:46:02 TRACE - Created thread[ActiveMQ Task-1]: Thread[ActiveMQ
Task-1,5,main]
08-31 11:46:02 TRACE - Closing socket Socket[unconnected]
08-31 11:46:02 DEBUG - Closed socket Socket[unconnected]
08-31 11:46:02 DEBUG - Forcing shutdown of ExecutorService:
java.util.concurrent.ThreadPoolExecutor@1f0f564[Running, pool size = 1,
active threads = 0, queued tasks = 0, completed tasks = 1]
08-31 11:46:02 TRACE - Shutdown of ExecutorService:
java.util.concurrent.ThreadPoolExecutor@1f0f564[Shutting down, pool size
= 1, active threads = 0, queued tasks = 0, completed tasks = 1] is
shutdown: true and terminated: false.
08-31 11:46:02 DEBUG - Attempting 0th connect to: tcp://mqarms02p:61616
08-31 11:46:02 TRACE - Starting connection check task for:
tcp://mqarms02p:61616
08-31 11:46:02 DEBUG - Sending: WireFormatInfo { version=12,
properties={MaxFrameSize=9223372036854775807, CacheSize=1024,
ProviderVersion=5.14.3, CacheEnabled=true, ProviderName=ActiveMQ,
SizePrefixDisabled=false, PlatformDetails=JVM: 1.7.0_80, 24.80-b11,
Oracle Corporation, OS: Linux, 2.6.32-358.6.2.el6.x86_64, amd64,
MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true,
MaxInactivityDuration=30000, TightEncodingEnabled=true,
StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
08-31 11:46:02 TRACE - Starting connection check task for:
tcp://mqarms02p/172.16.101.116:61616@47626
08-31 11:46:02 TRACE - TCP consumer thread for
tcp://mqarms02p/172.16.101.116:61616@47626 starting
08-31 11:46:02 TRACE - Stopping connection check task for:
tcp://mqarms02p/172.16.101.116:61616@47626
08-31 11:46:02 DEBUG - Using min of local: WireFormatInfo { version=12,
properties={MaxFrameSize=9223372036854775807, CacheSize=1024,
ProviderVersion=5.14.3, CacheEnabled=true, ProviderName=ActiveMQ,
SizePrefixDisabled=false, PlatformDetails=JVM: 1.7.0_80, 24.80-b11,
Oracle Corporation, OS: Linux, 2.6.32-358.6.2.el6.x86_64, amd64,
MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true,
MaxInactivityDuration=30000, TightEncodingEnabled=true,
StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]} and remote:
WireFormatInfo { version=12, properties={MaxFrameSize=104857600,
CacheSize=1024, ProviderVersion=5.14.3, CacheEnabled=true,
ProviderName=ActiveMQ, SizePrefixDisabled=false,
MaxInactivityDurationInitalDelay=10000, PlatformDetails=JVM: 1.8.0_111,
25.111-b15, Oracle Corporation, OS: Linux, 3.8.13-68.3.3.el6uek.x86_64,
amd64, TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
08-31 11:46:02 DEBUG - Received WireFormat: WireFormatInfo { version=12,
properties={MaxFrameSize=104857600, CacheSize=1024,
ProviderVersion=5.14.3, CacheEnabled=true, ProviderName=ActiveMQ,
SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000,
PlatformDetails=JVM: 1.8.0_111, 25.111-b15, Oracle Corporation, OS:
Linux, 3.8.13-68.3.3.el6uek.x86_64, amd64, TcpNoDelayEnabled=true,
MaxInactivityDuration=30000, TightEncodingEnabled=true,
StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
08-31 11:46:02 DEBUG - tcp://mqarms02p/172.16.101.116:61616@47626 before
negotiation: OpenWireFormat{version=12, cacheEnabled=false,
stackTraceEnabled=false, tightEncodingEnabled=false,
sizePrefixDisabled=false, maxFrameSize=9223372036854775807}
08-31 11:46:02 DEBUG - tcp://mqarms02p/172.16.101.116:61616@47626 after
negotiation: OpenWireFormat{version=12, cacheEnabled=true,
stackTraceEnabled=true, tightEncodingEnabled=true,
sizePrefixDisabled=false, maxFrameSize=104857600}
08-31 11:46:02 DEBUG - conn: ID:tnsags01p.xxxx.com-53927-1504137796960-5:1
08-31 11:46:02 DEBUG - session:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1441358
08-31 11:46:02 DEBUG - restore consumer:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1441358:1 in pull mode
pending recovery, overriding prefetch: 1000
08-31 11:46:02 DEBUG - consumer:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1441358:1
08-31 11:46:02 DEBUG - session:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:-1
08-31 11:46:02 DEBUG - restore consumer:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:-1:1 in pull mode pending
recovery, overriding prefetch: 1000
08-31 11:46:02 DEBUG - consumer:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:-1:1
08-31 11:46:02 DEBUG - session:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1442703
08-31 11:46:02 DEBUG - producer:
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1442703:1
08-31 11:46:02 DEBUG - Connection established
08-31 11:46:02 INFO - Successfully reconnected to tcp://mqarms02p:61616
08-31 11:46:02 TRACE - Running task iteration 0 -
org.apache.activemq.transport.failover.FailoverTransport$2@112605fd
08-31 11:46:02 TRACE - Run task done:
org.apache.activemq.transport.failover.FailoverTransport$2@112605fd
08-31 11:46:02 TRACE - Run task done:
org.apache.activemq.transport.failover.FailoverTransport$2@112605fd
08-31 11:46:02 TRACE - Received ConnectionControl: ConnectionControl
{commandId = 0, responseRequired = false, suspend = false, resume =
false, close = false, exit = false, faultTolerant = false,
connectedBrokers = , reconnectTo = , token = null, rebalanceConnection =
false}
08-31 11:46:02 DEBUG - Send oneway attempt: 17752 failed for command:
ActiveMQObjectMessage {commandId = 7234566, responseRequired = true,
messageId = ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1442703:1:1,
originalDestination = null, originalTransactionId = null, producerId =
ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1442703:1, destination =
queue://routing_mia_client, transactionId = null, expiration = 0,
timestamp = 1504192175689, arrival = 0, brokerInTime = 0, brokerOutTime
= 0, correlationId = null, replyTo = null, persistent = true, type =
null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId
= null, compressed = false, userID = null, content =
org.apache.activemq.util.ByteSequence@1558c374, marshalledProperties =
null, dataStructure = null, redeliveryCounter = 0, size = 0, properties
= null, readOnlyProperties = true, readOnlyBody = true, droppable =
false, jmsXGroupFirstForConsumer = false}
08-31 11:46:02 TRACE - tcp://mqarms02p:61616 handleTransportFailure:
java.net.SocketException: Broken pipe
java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at
java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
at
org.apache.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:96)
at java.io.DataOutputStream.write(DataOutputStream.java:107)
at
org.apache.activemq.openwire.v12.BaseDataStreamMarshaller.tightMarshalByteSequence2(BaseDataStreamMarshaller.java:431)
at
org.apache.activemq.openwire.v12.MessageMarshaller.tightMarshal2(MessageMarshaller.java:182)
at
org.apache.activemq.openwire.v12.ActiveMQMessageMarshaller.tightMarshal2(ActiveMQMessageMarshaller.java:89)
at
org.apache.activemq.openwire.v12.ActiveMQObjectMessageMarshaller.tightMarshal2(ActiveMQObjectMessageMarshaller.java:89)
at
org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWireFormat.java:235)
at
org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:193)
at
org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:335)
at
org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:317)
at
org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:94)
at
org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:116)
at
org.apache.activemq.transport.failover.FailoverTransport.oneway(FailoverTransport.java:668)
Re: Broken Pipe Connecting
Posted by Tim Bain <tb...@alumni.duke.edu>.
A broken pipe means that the other side of the socket closed it and then
your side tried to write to it. So the question is then, what do you see in
the broker's logs when this is happening? That might indicate why it's
disconnecting you right after sending the ConnectionControl message to you.
Tim
On Aug 31, 2017 2:18 PM, "Steve Hill" <sh...@futurelogix.co.uk> wrote:
> We are running ActiveMQ in Master/Slave configuration. Currently
> mqarms02p is the Master. Earlier today we ran into a situation where we
> lost access to ActiveMQ and on reviewing the client side logs we see the
> information below cycle continuously.
>
> Is there anything we can enable on the server side to better log what
> happened from the server perspective? Unfortunately in this instance the
> logs had already rolled so we could not see anything, however from
> previously experience we know almost nothing shows up.
>
> The server was online and other clients were using it without incident
>
> Any ideas as to what happened and how we can prevent this occurring in
> future?
>
> 08-31 11:46:02 DEBUG - Attempting 0th connect to: tcp://mqarms01p:61616
> 08-31 11:46:02 TRACE - Starting connection check task for:
> tcp://mqarms01p:61616
> 08-31 11:46:02 DEBUG - Connect fail to: tcp://mqarms01p:61616, reason:
> java.net.ConnectException: Connection refused
> 08-31 11:46:02 TRACE - Stopping connection check task for:
> tcp://mqarms01p:61616
> 08-31 11:46:02 DEBUG - Stopping transport tcp://mqarms01p:61616
> 08-31 11:46:02 DEBUG - Initialized TaskRunnerFactory[ActiveMQ Task] using
> ExecutorService: java.util.concurrent.ThreadPoolExecutor@1f0f564[Running,
> pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
> 08-31 11:46:02 TRACE - Execute[ActiveMQ Task] runnable:
> org.apache.activemq.transport.tcp.TcpTransport$1@727e793a
> 08-31 11:46:02 TRACE - Created thread[ActiveMQ Task-1]: Thread[ActiveMQ
> Task-1,5,main]
> 08-31 11:46:02 TRACE - Closing socket Socket[unconnected]
> 08-31 11:46:02 DEBUG - Closed socket Socket[unconnected]
> 08-31 11:46:02 DEBUG - Forcing shutdown of ExecutorService:
> java.util.concurrent.ThreadPoolExecutor@1f0f564[Running, pool size = 1,
> active threads = 0, queued tasks = 0, completed tasks = 1]
> 08-31 11:46:02 TRACE - Shutdown of ExecutorService:
> java.util.concurrent.ThreadPoolExecutor@1f0f564[Shutting down, pool size
> = 1, active threads = 0, queued tasks = 0, completed tasks = 1] is
> shutdown: true and terminated: false.
> 08-31 11:46:02 DEBUG - Attempting 0th connect to: tcp://mqarms02p:61616
> 08-31 11:46:02 TRACE - Starting connection check task for:
> tcp://mqarms02p:61616
> 08-31 11:46:02 DEBUG - Sending: WireFormatInfo { version=12,
> properties={MaxFrameSize=9223372036854775807, CacheSize=1024,
> ProviderVersion=5.14.3, CacheEnabled=true, ProviderName=ActiveMQ,
> SizePrefixDisabled=false, PlatformDetails=JVM: 1.7.0_80, 24.80-b11, Oracle
> Corporation, OS: Linux, 2.6.32-358.6.2.el6.x86_64, amd64,
> MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true,
> MaxInactivityDuration=30000, TightEncodingEnabled=true,
> StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
> 08-31 11:46:02 TRACE - Starting connection check task for: tcp://mqarms02p/
> 172.16.101.116:61616@47626
> 08-31 11:46:02 TRACE - TCP consumer thread for tcp://mqarms02p/172.16.101.
> 116:61616@47626 starting
> 08-31 11:46:02 TRACE - Stopping connection check task for: tcp://mqarms02p/
> 172.16.101.116:61616@47626
> 08-31 11:46:02 DEBUG - Using min of local: WireFormatInfo { version=12,
> properties={MaxFrameSize=9223372036854775807, CacheSize=1024,
> ProviderVersion=5.14.3, CacheEnabled=true, ProviderName=ActiveMQ,
> SizePrefixDisabled=false, PlatformDetails=JVM: 1.7.0_80, 24.80-b11, Oracle
> Corporation, OS: Linux, 2.6.32-358.6.2.el6.x86_64, amd64,
> MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true,
> MaxInactivityDuration=30000, TightEncodingEnabled=true,
> StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]} and remote:
> WireFormatInfo { version=12, properties={MaxFrameSize=104857600,
> CacheSize=1024, ProviderVersion=5.14.3, CacheEnabled=true,
> ProviderName=ActiveMQ, SizePrefixDisabled=false,
> MaxInactivityDurationInitalDelay=10000, PlatformDetails=JVM: 1.8.0_111,
> 25.111-b15, Oracle Corporation, OS: Linux, 3.8.13-68.3.3.el6uek.x86_64,
> amd64, TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
> TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
> 08-31 11:46:02 DEBUG - Received WireFormat: WireFormatInfo { version=12,
> properties={MaxFrameSize=104857600, CacheSize=1024,
> ProviderVersion=5.14.3, CacheEnabled=true, ProviderName=ActiveMQ,
> SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000,
> PlatformDetails=JVM: 1.8.0_111, 25.111-b15, Oracle Corporation, OS: Linux,
> 3.8.13-68.3.3.el6uek.x86_64, amd64, TcpNoDelayEnabled=true,
> MaxInactivityDuration=30000, TightEncodingEnabled=true,
> StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
> 08-31 11:46:02 DEBUG - tcp://mqarms02p/172.16.101.116:61616@47626 before
> negotiation: OpenWireFormat{version=12, cacheEnabled=false,
> stackTraceEnabled=false, tightEncodingEnabled=false,
> sizePrefixDisabled=false, maxFrameSize=9223372036854775807}
> 08-31 11:46:02 DEBUG - tcp://mqarms02p/172.16.101.116:61616@47626 after
> negotiation: OpenWireFormat{version=12, cacheEnabled=true,
> stackTraceEnabled=true, tightEncodingEnabled=true,
> sizePrefixDisabled=false, maxFrameSize=104857600}
> 08-31 11:46:02 DEBUG - conn: ID:tnsags01p.xxxx.com-53927-1504137796960-5:1
> 08-31 11:46:02 DEBUG - session: ID:tnsags01p.xxxx.com-53927-15
> 04137796960-5:1:1441358
> 08-31 11:46:02 DEBUG - restore consumer: ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1441358:1
> in pull mode pending recovery, overriding prefetch: 1000
> 08-31 11:46:02 DEBUG - consumer: ID:tnsags01p.xxxx.com-53927-15
> 04137796960-5:1:1441358:1
> 08-31 11:46:02 DEBUG - session: ID:tnsags01p.xxxx.com-53927-15
> 04137796960-5:1:-1
> 08-31 11:46:02 DEBUG - restore consumer: ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:-1:1
> in pull mode pending recovery, overriding prefetch: 1000
> 08-31 11:46:02 DEBUG - consumer: ID:tnsags01p.xxxx.com-53927-15
> 04137796960-5:1:-1:1
> 08-31 11:46:02 DEBUG - session: ID:tnsags01p.xxxx.com-53927-15
> 04137796960-5:1:1442703
> 08-31 11:46:02 DEBUG - producer: ID:tnsags01p.xxxx.com-53927-15
> 04137796960-5:1:1442703:1
> 08-31 11:46:02 DEBUG - Connection established
> 08-31 11:46:02 INFO - Successfully reconnected to tcp://mqarms02p:61616
> 08-31 11:46:02 TRACE - Running task iteration 0 -
> org.apache.activemq.transport.failover.FailoverTransport$2@112605fd
> 08-31 11:46:02 TRACE - Run task done: org.apache.activemq.transport.
> failover.FailoverTransport$2@112605fd
> 08-31 11:46:02 TRACE - Run task done: org.apache.activemq.transport.
> failover.FailoverTransport$2@112605fd
> 08-31 11:46:02 TRACE - Received ConnectionControl: ConnectionControl
> {commandId = 0, responseRequired = false, suspend = false, resume = false,
> close = false, exit = false, faultTolerant = false, connectedBrokers = ,
> reconnectTo = , token = null, rebalanceConnection = false}
> 08-31 11:46:02 DEBUG - Send oneway attempt: 17752 failed for command:
> ActiveMQObjectMessage {commandId = 7234566, responseRequired = true,
> messageId = ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1442703:1:1,
> originalDestination = null, originalTransactionId = null, producerId =
> ID:tnsags01p.xxxx.com-53927-1504137796960-5:1:1442703:1, destination =
> queue://routing_mia_client, transactionId = null, expiration = 0, timestamp
> = 1504192175689, arrival = 0, brokerInTime = 0, brokerOutTime = 0,
> correlationId = null, replyTo = null, persistent = true, type = null,
> priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null,
> compressed = false, userID = null, content = org.apache.activemq.util.ByteS
> equence@1558c374, marshalledProperties = null, dataStructure = null,
> redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties =
> true, readOnlyBody = true, droppable = false, jmsXGroupFirstForConsumer =
> false}
> 08-31 11:46:02 TRACE - tcp://mqarms02p:61616 handleTransportFailure:
> java.net.SocketException: Broken pipe
> java.net.SocketException: Broken pipe
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> at java.net.SocketOutputStream.socketWrite(SocketOutputStream.
> java:113)
> at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
> at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.wr
> ite(TcpBufferedOutputStream.java:96)
> at java.io.DataOutputStream.write(DataOutputStream.java:107)
> at org.apache.activemq.openwire.v12.BaseDataStreamMarshaller.ti
> ghtMarshalByteSequence2(BaseDataStreamMarshaller.java:431)
> at org.apache.activemq.openwire.v12.MessageMarshaller.tightMars
> hal2(MessageMarshaller.java:182)
> at org.apache.activemq.openwire.v12.ActiveMQMessageMarshaller.t
> ightMarshal2(ActiveMQMessageMarshaller.java:89)
> at org.apache.activemq.openwire.v12.ActiveMQObjectMessageMarsha
> ller.tightMarshal2(ActiveMQObjectMessageMarshaller.java:89)
> at org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWire
> Format.java:235)
> at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTra
> nsport.java:193)
> at org.apache.activemq.transport.AbstractInactivityMonitor.doOn
> ewaySend(AbstractInactivityMonitor.java:335)
> at org.apache.activemq.transport.AbstractInactivityMonitor.onew
> ay(AbstractInactivityMonitor.java:317)
> at org.apache.activemq.transport.TransportFilter.oneway(Transpo
> rtFilter.java:94)
> at org.apache.activemq.transport.WireFormatNegotiator.oneway(Wi
> reFormatNegotiator.java:116)
> at org.apache.activemq.transport.failover.FailoverTransport.one
> way(FailoverTransport.java:668)
>
>