diameter disconnect peer request (DPR) not working

[Richard Good]

Hi

I am using a Diameter client peer to periodically test that all my Diameter servers are operational.

So every 2 minutes I do CER/CEA, test the diameter application and then do DPR expecting a DPA.

On receipt of the DPR the Diameter servers do not respond with a DPA.  The logs are shown below.  It seems that the DPR is received and the connection is closed and then the DPA cannot be sent because the connection is already closed.

My concern with this is that if the DPR is not correctly processed then the host is maintained in the peer list - and the list will grow until unmanageable.

Any ideas what the problem is?  Is my concern valid?

I am using JSLEE 2.6.0.FINAL with MUX 1.4.0.CR2

Regards
Richard.


2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.controller.PeerImpl] Receive message type [282] to peer [aaa://lte-zone6.dev.za.smilecoms.com:33397]
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] Handling event with type [DPR_EVENT]
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] Not performing validation to message since validator is DISABLED.
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] Placing message into linked blocking queue with remaining capacity: [10000].
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.transport.tcp.TCPTransportClient] Just read [-1] bytes on [Socket[addr=/10.0.1.96,port=33397,localport=3868]]
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] Process event [Event{name:DPR_EVENT, key:null, object:MessageImpl{commandCode=282, flags=128}}]. Peer State is [OKAY]
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.controller.PeerImpl] Connection from aaa://10.0.1.96:33397 is closed
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.controller.PeerImpl] Send DPA message
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] Handling event with type [DISCONNECT_EVENT]
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] Not performing validation to message since validator is DISABLED.
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.controller.PeerImpl] Calling connection to send message [MessageImpl{commandCode=282, flags=0}] to peer [aaa://10.0.1.96:33397] over the network
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] Placing message into linked blocking queue with remaining capacity: [10000].
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.transport.tcp.TCPTransportClient] About to send a byte buffer of size [88] over the TCP nio socket [Socket[addr=/10.0.1.96,port=33397,localport=3868]]
2012-03-12 12:56:15,293 INFO  [org.jdiameter.client.impl.transport.tcp.TCPTransportClient] Read thread is stopped for socket [Socket[addr=/10.0.1.96,port=33397,localport=3868]]
2012-03-12 12:56:15,293 DEBUG [org.jdiameter.client.impl.transport.tcp.TCPTransportClient] Unable to send message
java.nio.channels.ClosedChannelException
        at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java:249)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:440)
        at org.jdiameter.client.impl.transport.tcp.TCPTransportClient.sendMessage(TCPTransportClient.java:228)
        at org.jdiameter.client.impl.transport.tcp.TCPClientConnection.sendMessage(TCPClientConnection.java:171)
        at org.jdiameter.client.impl.controller.PeerImpl$ActionContext.sendMessage(PeerImpl.java:702)
        at org.jdiameter.client.impl.controller.PeerImpl$ActionContext.sendDpaMessage(PeerImpl.java:802)
        at org.jdiameter.server.impl.fsm.PeerFSMImpl$1.processEvent(PeerFSMImpl.java:138)
        at org.jdiameter.client.impl.fsm.PeerFSMImpl$3.run(PeerFSMImpl.java:161)
        at java.lang.Thread.run(Thread.java:722)
2012-03-12 12:56:15,296 DEBUG [org.jdiameter.server.impl.fsm.PeerFSMImpl] Can not send DPA
org.jdiameter.client.api.io.TransportException: Cannot send message:
        at org.jdiameter.client.impl.transport.tcp.TCPClientConnection.sendMessage(TCPClientConnection.java:175)
        at org.jdiameter.client.impl.controller.PeerImpl$ActionContext.sendMessage(PeerImpl.java:702)
        at org.jdiameter.client.impl.controller.PeerImpl$ActionContext.sendDpaMessage(PeerImpl.java:802)
        at org.jdiameter.server.impl.fsm.PeerFSMImpl$1.processEvent(PeerFSMImpl.java:138)
        at org.jdiameter.client.impl.fsm.PeerFSMImpl$3.run(PeerFSMImpl.java:161)
        at java.lang.Thread.run(Thread.java:722)
Caused by: java.io.IOException: Error while sending message: java.nio.channels.ClosedChannelException
        at org.jdiameter.client.impl.transport.tcp.TCPTransportClient.sendMessage(TCPTransportClient.java:232)
        at org.jdiameter.client.impl.transport.tcp.TCPClientConnection.sendMessage(TCPClientConnection.java:171)
        ... 5 more
2012-03-12 12:56:15,296 DEBUG [org.jdiameter.client.impl.transport.tcp.TCPTransportClient] Stopping transport. Socket is [Socket[addr=/10.0.1.96,port=33397,localport=3868]]
2012-03-12 12:56:15,296 DEBUG [org.jdiameter.client.impl.transport.tcp.TCPTransportClient] Transport is stopped. Socket is [Socket[addr=/10.0.1.96,port=33397,localport=3868]]
2012-03-12 12:56:15,296 DEBUG [org.jdiameter.client.impl.controller.PeerImpl] Disconnected from peer aaa://10.0.1.96:33397
2012-03-12 12:56:15,296 DEBUG [org.jdiameter.client.impl.fsm.PeerFSMImpl] SPeer{Uri=aaa://10.0.1.96:33397; State=OKAY; con=org.jdiameter.client.impl.transport.tcp.TCPClientConnection@ff137e; incCon{} } FSM switch state: OKAY -> DOWN

This email is subject to the disclaimer of Smile Communications (PTY) Ltd. at http://www.smilecoms.com/disclaimer

[Tomek]

Hi

It seems the remote peer is closing the connection before the stack is able to send, are you sure that the Mobicents stack is terminating the connection ?

Are you able to get a wireshark trace ?

Regards

Tomasz

http://arevocom.com

[Richard Good]

Hi

Thanks for the quick response.

Attached is a wireshark trace - just showing the CER/CEA and DPR (no DPA) and associated TCP traffic.

I think you are right and it seems my remote peer terminates the TCP connection (with FIN) straight after sending the DPR - when it should probably wait until the DPA is sent. 

Is this a problem?  If the DPR is not correctly processed how long will the host sit in the peers list?  I see from the logs I have many peers with connection valid? [false].  Will these peers eventually be removed?

Regards
Richard.

--

Richard Good

Manager: Applications & Services

Smile Communications (Pty) Ltd

mobile: +27 (0) 72 3898365

email:  richar...@smilecoms.com

Physical address: 12 Culross Road, Bryanston, 2191

Postal address: Postnet suite 605, Private Bag x5, Fourways North, 2086

[Tomek]

The transport connection should be closed on receiving DPA or on timeout receiving DPA. 

In order to answer other questions I need to investigate further, but I think the invalid peer list usually is not a problem, but it may depend on number of clients connecting to a server.

According to RFC3588:

The Disconnect-Peer-Request message is used by a Diameter node to
   inform its peer of its intent to disconnect the transport layer, and
   that the peer shouldn't reconnect unless it has a valid reason to do
   so (e.g., message to be forwarded).  Upon receipt of the message, the
   Disconnect-Peer-Answer is returned, which SHOULD contain an error if
   messages have recently been forwarded, and are likely in flight,
   which would otherwise cause a race condition.
   The receiver of the Disconnect-Peer-Answer initiates the transport
   disconnect.

Regards

Tomasz

http://arevocom.com

email:  richard.good@smilecoms.com

Physical address: 12 Culross Road, Bryanston, 2191

Postal address: Postnet suite 605, Private Bag x5, Fourways North, 2086

[Richard Good]

Hi

All solved.  I fixed the client so that the TCP connection was only closed on DPA and not when sending DPR.  Thanks for the help!

Regards
Richard.

email:  richar...@smilecoms.com

Physical address: 12 Culross Road, Bryanston, 2191

Postal address: Postnet suite 605, Private Bag x5, Fourways North, 2086

[Richard Good]

Hi

I just noticed that even when the Diameter server successfully processes the DPR and sends a DPA the remote host remains in the peers list but with a false connection.  Logs show:

Checking to see if peer name [10.0.1.96] matches peertable value of [aaa://10.0.1.96:44882] or [10.0.1.96]
2012-03-12 16:10:10,333 DEBUG [org.jdiameter.client.impl.controller.PeerTableImpl] Found matching peer value of [aaa://10.0.1.96:44882]. Connection valid? : [false]
2012-03-12 16:10:10,333 DEBUG [org.jdiameter.client.impl.controller.PeerTableImpl] Found matching peer [aaa://10.0.1.96:44882] but its connection is not open. Will ignore it and seek further
2012-03-12 16:10:10,333 DEBUG [org.jdiameter.client.impl.controller.PeerTableImpl] Checking to see if peer name [10.0.1.96] matches peertable value of [aaa://10.0.1.96:49729] or [10.0.1.96]
2012-03-12 16:10:10,333 DEBUG [org.jdiameter.client.impl.controller.PeerTableImpl] Found matching peer value of [aaa://10.0.1.96:49729]. Connection valid? : [false]
2012-03-12 16:10:10,333 DEBUG [org.jdiameter.client.impl.controller.PeerTableImpl] Found matching peer [aaa://10.0.1.96:49729] but its connection is not open. Will ignore it and seek further
2012-03-12 16:10:10,333 DEBUG [org.jdiameter.client.impl.controller.PeerTableImpl] Checking to see if peer name [10.0.1.96] matches peertable value of [aaa://10.0.1.96:56687] or [10.0.1.96]

Is this a problem?  Will these elements eventually be removed from the peers list?

Regards
Richard.

[Alexandre Mendonça]

Hi Richard,

Is it possible to contribute this fix?

Thanks & Best Regards,

--

Alexandre Mendonça // JBoss R&D
http://ammendonca.blogspot.com/

[Alexandre Mendonça]

FYI, the issue about enhancing the peer storage, identifying the peers by FQDN only instead of URI (http://code.google.com/p/mobicents/issues/detail?id=2729) has been committed. 

This should reduce a bit the number of peers showing, but still some measures should be taken to limit/clean the peer table, so i've created an issue for that: http://code.google.com/p/mobicents/issues/detail?id=3167

Regards,

--

Alexandre Mendonça // JBoss R&D
http://ammendonca.blogspot.com/

2012/3/12 Richard Good <richar...@smilecoms.com>

[Richard Good]

Hi

I am using a very basic Diameter client for this (not Mobicents) and this is where I fixed the bug.  There were no fixes for the Mobicents stack on this.

Regards
Richard.

2012/3/29 Alexandre Mendonça <brai...@gmail.com>