< Previous by Date	Date Index	Next by Date >
< Previous in Thread	Thread Index

Re: [reSIProcate-users] TCP Connection Resets in long calls

From: Scott Godin <sgodin@xxxxxxxxxxxxxxx>
Date: Mon, 20 Apr 2015 09:16:40 -0400

Seems to me that something between the UA and repro is tearing down / timing out the TCP connection. You UA is getting a 10054 socket error trying to send a keepalive:

10054 is "Connection reset by peer", or "An existing connection was forcibly closed by the remote host".

A wireshark trace of the low level TCP messaging at UA and/or proxy sides might reveal more details. You could also try lowering the keepalive interval to 30 seconds as a test.

Note: The UA could register for ConnectionTerminated events from DUM in order to see when it's TCP connection is lost.

Scott

On Mon, Apr 20, 2015 at 1:27 AM, Julio Cesar Esteves Cabezas <jcabezas@xxxxxxxxxxxxx> wrote:

Hi,

We are going through an acceptance test to check if SIP calls can endure for at least one week in our system.
Unfortunately, after some hours calls are dropped.

The setup is:
    - A repro Proxy V.1.9.8 running on Windows 2008 Server.
    - UserAgents written around reSIProcate V.1.8.14, running on Windows 7 Pro.
    - repro communicates to a Cisco UCM.

  We are using TCP between UAs and repro.

  The pattern of call drop is like this:

  1. A TCP connection is established by repro with the UA.
2. A re-INVITE is sent over the new connection and is acknowledged by the UA, (INVITE, 200, ACK)
     (no session-timers were negotiated, just a refreshing re-INVITE by initiative of the remote UA, each 12 hours)
  3. After that, for some time, each 3 minutes UA and repro follow keep-alive sequence:
          repro   <--- Continuation keep-alive with CRLFCRLF <---   UserAgent
          repro   ---- Continuation keep-alive with CRLF     --->   UserAgent
          repro   <--- TCP ACK with 0 payload length         <---   UserAgent
4. The keepalive sequence above happens 9 times (24 minutes) then UA ‘gives up’ doing keepalives
5. About 11 hours later a refreshing re-INVITE coming from CUCM is forwarded by repro in that same TCP connection to UA and:
          repro   ---> re-INVITE arrived from CUCM           --->   UserAgent
          repro   <--- TCP RESET with wrong (!=0) ACK number <---   UserAgent
6. repro stays quiet
  7. 32 seconds after, CUCM sends BYE
8. repro creates a new TCP connection to UserAgent, sends BYE and that is normally acknowledged. Call was dropped !
9. Note that other TCP connections between repro and the same UA remain alive, what allows for registration refreshes.


  It seems that the UserAgent 'is the culprit'.
  Any insights, suggestions for config and test ?

Could some network box in the middle be cause of such behaviour ?

  Below we see patterns of successful and failed keepalives from the reSIProcate log file of the UserAgent.
Looks as internally reSIProcate keeps trying to do keepalives but fails (we can count 230 failures, one each 3 minutes, almost 12 hours).

Thanks and Best regards.
Julio Cabezas.


Sucessful keepalive: ------------------------------------------------------------------------------------------------

18/04/2015 12:52:40 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:52525 TCP target domain=unspecified mFlowKey=4312 ](12)
18/04/2015 12:53:12 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](17)
18/04/2015 12:53:18 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](18)
18/04/2015 12:53:18 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](19)
18/04/2015 12:53:18 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:99 | Refreshing keepalive for id=19: [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ], interval=180s, supportsOutbound=false, refCount=1
18/04/2015 12:53:18 [Debug] RESIP:TRANSACTION | 2532 | TimerQueue.cxx:124 | Adding application timer: KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](19) ms=180000
18/04/2015 12:53:18 [Debug] RESIP:TRANSPORT | 4340 | TransportSelector.cxx:1162 | Transmitting to [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ] tlsDomain= via [ V4 10.225.33.70:5060 TCP target domain=unspecified mFlowKey=0 ]
sigcomp id=
18/04/2015 12:53:18 [Debug] RESIP:TRANSPORT | 4340 | TcpBaseTransport.cxx:263 | Processing write for [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ]
18/04/2015 12:53:18 [Debug] RESIP:TRANSPORT | 4340 | ConnectionManager.cxx:59 | Found fd 4288
18/04/2015 12:53:18 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:115 | In State: NewMessage
18/04/2015 12:53:18 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:336 | Received response CRLF (aka pong).
18/04/2015 12:53:18 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:297 | Connection::performReads() read=2
18/04/2015 12:53:18 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:672 | Creating buffer for CONN_BASE: 189DABE0 [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ]
18/04/2015 12:53:18 [Debug] RESIP:DUM | 2532 | DialogUsageManager.cxx:1361 | keepalive pong received from [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ]
18/04/2015 12:53:18 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:153 | Received pong response for keep alive id=19: [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ]
18/04/2015 12:53:41 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ](16)
18/04/2015 12:53:41 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:99 | Refreshing keepalive for id=16: [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ], interval=180s, supportsOutbound=false, refCount=3
18/04/2015 12:53:41 [Debug] RESIP:TRANSACTION | 2532 | TimerQueue.cxx:124 | Adding application timer: KeepAliveTimeout[ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ](16) ms=180000
18/04/2015 12:53:41 [Debug] RESIP:TRANSPORT | 4340 | TransportSelector.cxx:1162 | Transmitting to [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ] tlsDomain= via [ V4 10.225.33.70:5060 TCP target domain=unspecified mFlowKey=0 ]
sigcomp id=
18/04/2015 12:53:41 [Debug] RESIP:TRANSPORT | 4340 | TcpBaseTransport.cxx:263 | Processing write for [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ]
18/04/2015 12:53:41 [Debug] RESIP:TRANSPORT | 4340 | ConnectionManager.cxx:59 | Found fd 4376
18/04/2015 12:53:41 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:115 | In State: NewMessage
18/04/2015 12:53:41 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:336 | Received response CRLF (aka pong).
18/04/2015 12:53:41 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:297 | Connection::performReads() read=2
18/04/2015 12:53:41 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:672 | Creating buffer for CONN_BASE: 18FE07C8 [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ]
18/04/2015 12:53:41 [Debug] RESIP:DUM | 2532 | DialogUsageManager.cxx:1361 | keepalive pong received from [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ]
18/04/2015 12:53:41 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:153 | Received pong response for keep alive id=16: [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ]
18/04/2015 12:56:18 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](19)
18/04/2015 12:56:18 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:99 | Refreshing keepalive for id=19: [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ], interval=180s, supportsOutbound=false, refCount=1
xx:70 | Send to TU: TU: DialogUsageManager size=0

Transition from successful to failed keepalives: -----------------------------------------------------------------------

18/04/2015 13:20:18 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](19)
18/04/2015 13:20:18 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:99 | Refreshing keepalive for id=19: [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ], interval=180s, supportsOutbound=false, refCount=1
18/04/2015 13:20:18 [Debug] RESIP:TRANSACTION | 2532 | TimerQueue.cxx:124 | Adding application timer: KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](19) ms=180000
18/04/2015 13:20:18 [Debug] RESIP:TRANSPORT | 4340 | TransportSelector.cxx:1162 | Transmitting to [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ] tlsDomain= via [ V4 10.225.33.70:5060 TCP target domain=unspecified mFlowKey=0 ]
sigcomp id=
18/04/2015 13:20:18 [Debug] RESIP:TRANSPORT | 4340 | TcpBaseTransport.cxx:263 | Processing write for [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ]
18/04/2015 13:20:18 [Debug] RESIP:TRANSPORT | 4340 | ConnectionManager.cxx:59 | Found fd 4288
18/04/2015 13:20:37 [Error] RESIP:TRANSPORT | 4340 | TcpConnection.cxx:61 | Some other error, code = 10054
18/04/2015 13:20:37 [Info] RESIP:TRANSPORT | 4340 | TcpConnection.cxx:65 | Failed read on 4288 Unknown error
18/04/2015 13:20:37 [Info] RESIP:TRANSPORT | 4340 | Transport.cxx:152 | Connection reset
18/04/2015 13:20:37 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:302 | Closing connection bytesRead=-1
18/04/2015 13:20:37 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:93 | ConnectionBase::~ConnectionBase 189DABE0
18/04/2015 13:20:37 [Info] RESIP:TRANSACTION | 4340 | TuSelector.cxx:102 | Sending ConnectionTerminated [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ] to TUs
18/04/2015 13:20:37 [Debug] RESIP:DUM | 2532 | DialogUsageManager.cxx:1453 | connection terminated message
18/04/2015 13:20:41 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ](16)
18/04/2015 13:20:41 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:99 | Refreshing keepalive for id=16: [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ], interval=180s, supportsOutbound=false, refCount=3
18/04/2015 13:20:41 [Debug] RESIP:TRANSACTION | 2532 | TimerQueue.cxx:124 | Adding application timer: KeepAliveTimeout[ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ](16) ms=180000
18/04/2015 13:20:41 [Debug] RESIP:TRANSPORT | 4340 | TransportSelector.cxx:1162 | Transmitting to [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ] tlsDomain= via [ V4 10.225.33.70:5060 TCP target domain=unspecified mFlowKey=0 ]
sigcomp id=
18/04/2015 13:20:41 [Debug] RESIP:TRANSPORT | 4340 | TcpBaseTransport.cxx:263 | Processing write for [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ]
18/04/2015 13:20:41 [Debug] RESIP:TRANSPORT | 4340 | ConnectionManager.cxx:59 | Found fd 4376
18/04/2015 13:21:00 [Error] RESIP:TRANSPORT | 4340 | TcpConnection.cxx:61 | Some other error, code = 10054
18/04/2015 13:21:00 [Info] RESIP:TRANSPORT | 4340 | TcpConnection.cxx:65 | Failed read on 4376 Unknown error
18/04/2015 13:21:00 [Info] RESIP:TRANSPORT | 4340 | Transport.cxx:152 | Connection reset
18/04/2015 13:21:00 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:302 | Closing connection bytesRead=-1
18/04/2015 13:21:00 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:93 | ConnectionBase::~ConnectionBase 18FE07C8
18/04/2015 13:21:00 [Info] RESIP:TRANSACTION | 4340 | TuSelector.cxx:102 | Sending ConnectionTerminated [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ] to TUs
18/04/2015 13:21:00 [Debug] RESIP:DUM | 2532 | DialogUsageManager.cxx:1453 | connection terminated message

Failed keepalive: -----------------------------------------------------------------------------------------------------

18/04/2015 13:26:18 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](19)
18/04/2015 13:26:18 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:99 | Refreshing keepalive for id=19: [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ], interval=180s, supportsOutbound=false, refCount=1
18/04/2015 13:26:18 [Debug] RESIP:TRANSACTION | 2532 | TimerQueue.cxx:124 | Adding application timer: KeepAliveTimeout[ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ](19) ms=180000
18/04/2015 13:26:18 [Debug] RESIP:TRANSPORT | 4340 | TransportSelector.cxx:1162 | Transmitting to [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ] tlsDomain= via [ V4 10.225.33.70:5060 TCP target domain=unspecified mFlowKey=0 ]
sigcomp id=
18/04/2015 13:26:18 [Debug] RESIP:TRANSPORT | 4340 | TcpBaseTransport.cxx:263 | Processing write for [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ]
18/04/2015 13:26:18 [Debug] RESIP:TRANSPORT | 4340 | ConnectionManager.cxx:71 | fd 4288 does not exist.
18/04/2015 13:26:18 [Debug] RESIP:TRANSPORT | 4340 | TcpBaseTransport.cxx:290 | Failed to create/get connection: [ V4 10.225.33.6:52549 TCP target domain=unspecified mFlowKey=4288 ]
18/04/2015 13:26:41 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4376 ](16)
18/04/2015 13:26:41 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0
KeepAliveTimeout[ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ](20)
18/04/2015 13:26:41 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:99 | Refreshing keepalive for id=20: [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ], interval=180s, supportsOutbound=false, refCount=3
18/04/2015 13:26:41 [Debug] RESIP:TRANSACTION | 2532 | TimerQueue.cxx:124 | Adding application timer: KeepAliveTimeout[ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ](20) ms=180000
18/04/2015 13:26:41 [Debug] RESIP:TRANSPORT | 4340 | TransportSelector.cxx:1162 | Transmitting to [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ] tlsDomain= via [ V4 10.225.33.70:5060 TCP target domain=unspecified mFlowKey=0 ]
sigcomp id=
18/04/2015 13:26:41 [Debug] RESIP:TRANSPORT | 4340 | TcpBaseTransport.cxx:263 | Processing write for [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ]
18/04/2015 13:26:41 [Debug] RESIP:TRANSPORT | 4340 | ConnectionManager.cxx:59 | Found fd 4468
18/04/2015 13:26:41 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:115 | In State: NewMessage
18/04/2015 13:26:41 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:336 | Received response CRLF (aka pong).
18/04/2015 13:26:41 [Debug] RESIP:TRANSPORT | 4340 | Connection.cxx:297 | Connection::performReads() read=2
18/04/2015 13:26:41 [Debug] RESIP:TRANSPORT | 4340 | ConnectionBase.cxx:672 | Creating buffer for CONN_BASE: 0E2945F8 [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ]
18/04/2015 13:26:41 [Debug] RESIP:DUM | 2532 | DialogUsageManager.cxx:1361 | keepalive pong received from [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ]
18/04/2015 13:26:41 [Debug] RESIP:DUM | 2532 | KeepAliveManager.cxx:153 | Received pong response for keep alive id=20: [ V4 10.225.33.6:5060 TCP target domain=10.225.33.6 mFlowKey=4468 ]
18/04/2015 13:29:18 [Debug] RESIP:TRANSACTION | 4340 | TuSelector.cxx:70 | Send to TU: TU: DialogUsageManager size=0

-----------------------------------------------------------------------------------------------------------------------








_______________________________________________
resiprocate-users mailing list
resiprocate-users@xxxxxxxxxxxxxxx
List Archive: http://list.resiprocate.org/archive/resiprocate-users/

References:
- [reSIProcate-users] TCP Connection Resets in long calls
  - From: Julio Cesar Esteves Cabezas

Prev by Date: [reSIProcate-users] TCP Connection Resets in long calls
Next by Date: Re: [reSIProcate-users] Cryptic logs on SSL_read
Previous by thread: [reSIProcate-users] TCP Connection Resets in long calls
Next by thread: [reSIProcate-users] reSIPro configuration - compensation offered
Index(es):
- Date
- Thread