6
  • ActiveMQ 5.7.0
  • CentOS release 6.3
  • java version "1.6.0_26"
  • Application server: Tomcat

In the activemq.log, I'm seeing this exception every 2 seconds:

2013-11-05 13:00:52,374 | DEBUG | Transport Connection to: tcp://127.0.0.1:37501 failed:
org.apache.activemq.transport.InactivityIOException: 
Cannot send, channel has already failed: tcp://127.0.0.1:37501 | org.apache.activemq.broker.TransportConnection.Transport | Async Exception Handler
org.apache.activemq.transport.InactivityIOException: Cannot send, channel has already failed: tcp://127.0.0.1:37501
        at org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:282)
        at org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:271)
        at org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
        at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
        at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
        at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1312)
        at org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:838)
        at org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:873)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:129)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:47)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)

Due to this keyword InactivityIOException, the first thing comes to my mind is InactivityMonitor, but the strange thing is MaxInactivityDuration=30000:

2013-11-05 13:11:02,672 | DEBUG | Sending: WireFormatInfo { version=9, properties={MaxFrameSize=9223372036854775807, 
CacheSize=1024, 
CacheEnabled=true, 
SizePrefixDisabled=false, 
MaxInactivityDurationInitalDelay=10000, 
TcpNoDelayEnabled=true, 
MaxInactivityDuration=30000, 
TightEncodingEnabled=true, 
StackTraceEnabled=true}, 
magic=[A,c,t,i,v,e,M,Q]} |    org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ BrokerService[localhost] Task-2

Moreover, I also didn't see something like this:

No message received since last read check for ...

or:

Channel was inactive for too (>30000) long

Do a netstat, I see these connections in TIME_WAIT state:

tcp        0      0 127.0.0.1:38545             127.0.0.1:61616             TIME_WAIT   -
tcp        0      0 127.0.0.1:38544             127.0.0.1:61616             TIME_WAIT   -
tcp        0      0 127.0.0.1:38522             127.0.0.1:61616             TIME_WAIT   -

Notice that the "PID/Program name" column only including the dash character.

Here're the output when running tcpdump:

Internet Protocol Version 4, Src: 127.0.0.1 (127.0.0.1), Dst: 127.0.0.1 (127.0.0.1)
    Version: 4
    Header length: 20 bytes
    Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00: Not-ECT (Not ECN-Capable Transport))
        0000 00.. = Differentiated Services Codepoint: Default (0x00)
        .... ..00 = Explicit Congestion Notification: Not-ECT (Not ECN-Capable Transport) (0x00)
    Total Length: 296
    Identification: 0x7b6a (31594)
    Flags: 0x02 (Don't Fragment)
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 64
    Protocol: TCP (6)
    Header checksum: 0xc063 [correct]
        [Good: True]
        [Bad: False]
    Source: 127.0.0.1 (127.0.0.1)
    Destination: 127.0.0.1 (127.0.0.1)

Transmission Control Protocol, Src Port: 61616 (61616), Dst Port: 54669 (54669), Seq: 1, Ack: 2, Len: 244
    Source port: 61616 (61616)
    Destination port: 54669 (54669)
    [Stream index: 11]
    Sequence number: 1    (relative sequence number)
    [Next sequence number: 245    (relative sequence number)]
    Acknowledgement number: 2    (relative ack number)
    Header length: 32 bytes
    Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgement: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 256
    [Calculated window size: 32768]
    [Window size scaling factor: 128]
    Checksum: 0xff1c [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Options: (12 bytes)
        No-Operation (NOP)
        No-Operation (NOP)
        Timestamps: TSval 2304161892, TSecr 2304161891
            Kind: Timestamp (8)
            Length: 10
            Timestamp value: 2304161892
            Timestamp echo reply: 2304161891
    [SEQ/ACK analysis]
        [Bytes in flight: 244]

Constrained Application Protocol, TID: 240, Length: 244
    00.. .... = Version: 0
    ..00 .... = Type: Confirmable (0)
    .... 0000 = Option Count: 0
    Code: Unknown (0)
    Transaction ID: 240
    Payload Content-Type: text/plain (default), Length: 240, offset: 4
        Line-based text data: text/plain
            [truncated] \001ActiveMQ\000\000\000\t\001\000\000\000<DE>\000\000\000\t\000\fMaxFrameSize\006\177<FF><FF><FF><FF>
<FF><FF><FF>\000\tCacheSize\005\000\000\004\000\000\fCacheEnabled\001\001\000\022SizePrefixDisabled\001\000\000 MaxInactivityDurationInitalDelay\006\

It is very likely a tcp port check. This is what I see when trying telnet from another host:

2013-11-05 16:12:41,071 | DEBUG | Transport Connection to: tcp://10.8.20.9:46775 failed: java.io.EOFException | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ Transport: tcp:///10.8.20.9:46775@61616
java.io.EOFException
        at java.io.DataInputStream.readInt(DataInputStream.java:375)
        at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275)
        at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
        at java.lang.Thread.run(Thread.java:662)
2013-11-05 16:12:41,071 | DEBUG | Transport Connection to: tcp://10.8.20.9:46775 failed: org.apache.activemq.transport.InactivityIOException: Cannot send, channel has already failed: tcp://10.8.20.9:46775 | org.apache.activemq.broker.TransportConnection.Transport | Async Exception Handler

org.apache.activemq.transport.InactivityIOException: Cannot send, channel has already failed: tcp://10.8.20.9:46775
        at org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:282)
        at org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:271)
        at org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
        at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
        at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
        at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1312)
        at org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:838)
        at org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:873)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:129)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:47)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
2013-11-05 16:12:41,071 | DEBUG | Unregistering MBean org.apache.activemq:BrokerName=localhost,Type=Connection,ConnectorName=ope
nwire,ViewType=address,Name=tcp_//10.8.20.9_46775 | org.apache.activemq.broker.jmx.ManagementContext | ActiveMQ Transport: tcp:/
//10.8.20.9:46775@61616
2013-11-05 16:12:41,073 | DEBUG | Stopping connection: tcp://10.8.20.9:46775 | org.apache.activemq.broker.TransportConnection | 
ActiveMQ BrokerService[localhost] Task-5
2013-11-05 16:12:41,073 | DEBUG | Stopping transport tcp:///10.8.20.9:46775@61616 | org.apache.activemq.transport.tcp.TcpTranspo
rt | ActiveMQ BrokerService[localhost] Task-5
2013-11-05 16:12:41,073 | DEBUG | Initialized TaskRunnerFactory[ActiveMQ Task] using ExecutorService: java.util.concurrent.Threa
dPoolExecutor@23cc2a28 | org.apache.activemq.thread.TaskRunnerFactory | ActiveMQ BrokerService[localhost] Task-5
2013-11-05 16:12:41,074 | DEBUG | Closed socket Socket[addr=/10.8.20.9,port=46775,localport=61616] | org.apache.activemq.transpo
rt.tcp.TcpTransport | ActiveMQ Task-1
2013-11-05 16:12:41,074 | DEBUG | Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@23cc2a28 | org.apache.activemq.util.ThreadPoolUtils | ActiveMQ BrokerService[localhost] Task-5
2013-11-05 16:12:41,074 | DEBUG | Stopped transport: tcp://10.8.20.9:46775 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-5
2013-11-05 16:12:41,074 | DEBUG | Connection Stopped: tcp://10.8.20.9:46775 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-5
2013-11-05 16:12:41,902 | DEBUG | Sending: WireFormatInfo { version=9, properties={MaxFrameSize=9223372036854775807, CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]} | org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ BrokerService[localhost] Task-5

So the question is: how can I find out the process that is trying to connect to my ActiveMQ (from localhost) every 2 seconds?


UPDATE Thu Nov 7 10:44:09 ICT 2013

My co-worker has talked to me the culprit, it's... keepalived:

vrrp_script chk_SC_ACTIVEMQ {
        script "</dev/tcp/127.0.0.1/61616"
        interval 2                      # check every 2 seconds
        weight 2                        # add 2 points of prio if OK
}

But my question still stands: assuming that I know someone (on localhost) is opening a TCP connection to my ActiveMQ every 2 seconds:

tcp        0      0 127.0.0.1:59408         127.0.0.1:61616         TIME_WAIT   -               
tcp        0      0 127.0.0.1:59398         127.0.0.1:61616         TIME_WAIT   -               
tcp        0      0 127.0.0.1:59399         127.0.0.1:61616         TIME_WAIT   -    

How do I find out the perpetrator? I just thought of a way, it is scan the /etc (or even whole system) to find out all files containing "61616":

# grep -lr 61616 /etc

Is there a better way?

quanta
  • 50,327
  • 19
  • 152
  • 213

0 Answers0