MRCPv2 connection cannot be reused

[njalmeida]

Hi, I'm facing an issue where it seems that sometimes new requests are not able to reuse an existing MRCPv2 connection. Below I have the info from a capture where it is visible that 5 new invites did not exchange any MRCP traffic. During this time an existing connection is established (as it can be seen in the netstat info I put below) but it seems that the client is not able to use it for some reason.

There seems to be an inconsistent behavior on the reuse of existing connections (11:49:10 to 12:00:54) I'm not fully understanding and this keeps happening from time to time.

Could you give me an hint on what can be causing this? Thanks

2020-07-21 11:58:50,811599  <client IP> <server IP> SIP/SDP 892 Request: INVITE sip:<server IP>:8060 | 
2020-07-21 11:58:50,812054  <server IP> <client IP> SIP 351 Status: 100 Trying | 
2020-07-21 11:58:50,817565  <server IP> <client IP> SIP/SDP 967 Status: 200 OK | 
2020-07-21 11:58:50,817710  <client IP> <server IP> SIP 359 Request: ACK sip:<server IP>:8060 | 
2020-07-21 11:58:50,821797  <client IP> <server IP> SIP 502 Request: BYE sip:<server IP>:8060 | 
2020-07-21 11:58:50,822041  <server IP> <client IP> SIP 480 Status: 200 OK | 
2020-07-21 11:59:02,631610  <client IP> <server IP> SIP/SDP 889 Request: INVITE sip:<server IP>:8060 | 
2020-07-21 11:59:02,632066  <server IP> <client IP> SIP 351 Status: 100 Trying | 
2020-07-21 11:59:02,637715  <server IP> <client IP> SIP/SDP 967 Status: 200 OK | 
2020-07-21 11:59:02,637892  <client IP> <server IP> SIP 359 Request: ACK sip:<server IP>:8060 | 
2020-07-21 11:59:02,641741  <client IP> <server IP> SIP 502 Request: BYE sip:<server IP>:8060 | 
2020-07-21 11:59:02,641912  <server IP> <client IP> SIP 480 Status: 200 OK | 
2020-07-21 11:59:16,491657  <client IP> <server IP> SIP/SDP 892 Request: INVITE sip:<server IP>:8060 | 
2020-07-21 11:59:16,492108  <server IP> <client IP> SIP 351 Status: 100 Trying | 
2020-07-21 11:59:16,497681  <server IP> <client IP> SIP/SDP 968 Status: 200 OK | 
2020-07-21 11:59:16,497847  <client IP> <server IP> SIP 359 Request: ACK sip:<server IP>:8060 | 
2020-07-21 11:59:16,501849  <client IP> <server IP> SIP 502 Request: BYE sip:<server IP>:8060 | 
2020-07-21 11:59:16,502056  <server IP> <client IP> SIP 480 Status: 200 OK | 
2020-07-21 11:59:54,241674  <client IP> <server IP> SIP/SDP 891 Request: INVITE sip:<server IP>:8060 | 
2020-07-21 11:59:54,242182  <server IP> <client IP> SIP 351 Status: 100 Trying | 
2020-07-21 11:59:54,247718  <server IP> <client IP> SIP/SDP 968 Status: 200 OK | 
2020-07-21 11:59:54,247901  <client IP> <server IP> SIP 359 Request: ACK sip:<server IP>:8060 | 
2020-07-21 11:59:54,252165  <client IP> <server IP> SIP 502 Request: BYE sip:<server IP>:8060 | 
2020-07-21 11:59:54,252382  <server IP> <client IP> SIP 480 Status: 200 OK | 
2020-07-21 12:00:19,461629  <client IP> <server IP> SIP/SDP 892 Request: INVITE sip:<server IP>:8060 | 
2020-07-21 12:00:19,462164  <server IP> <client IP> SIP 351 Status: 100 Trying | 
2020-07-21 12:00:19,467705  <server IP> <client IP> SIP/SDP 968 Status: 200 OK | 
2020-07-21 12:00:19,467917  <client IP> <server IP> SIP 359 Request: ACK sip:<server IP>:8060 | 
2020-07-21 12:00:19,471911  <client IP> <server IP> SIP 502 Request: BYE sip:<server IP>:8060 | 
2020-07-21 12:00:19,472106  <server IP> <client IP> SIP 480 Status: 200 OK | 

200 OK reply from server:

SIP/2.0 200 OK
Via: SIP/2.0/UDP <client IP>:16090;rport=16090;branch=z9hG4bK3y1tN95tjaDje
From: <sip:<client IP>:16090>;tag=X10jvUNZH2QZK
To: <sip:<server IP>:8060>;tag=NK6UaaBFpvrXp
Call-ID: 004aa539-45e4-1239-df9d-0cc47acd8472
CSeq: 23110773 INVITE
Contact: <sip:<server IP>:8060>
User-Agent: UniMRCP SofiaSIP 1.5.0
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE
Supported: timer, 100rel
Session-Expires: 600;refresher=uac
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 311

v=0
o=UniMRCPServer 8075838404486912199 274076477926422769 IN IP4 <server IP>
s=-
c=IN IP4 <server IP>
t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:existing
a=channel:80ac441a3f254477@speechrecog
a=cmid:1
m=audio 59130 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1

MRCPv2 active connections every 15s: https://pastebin.com/ux0ACRzs

Client: Freeswitch (mod_unimrcp) Server: uniMRCP server 1.5.0 mrcpv2-uas configuration:

  <mrcp-port>1544</mrcp-port>
  <max-connection-count>100</max-connection-count>
  <max-shared-use-count>100</max-shared-use-count>
  <force-new-connection>false</force-new-connection>
  <rx-buffer-size>1024</rx-buffer-size>
  <tx-buffer-size>1024</tx-buffer-size>
  <inactivity-timeout>600</inactivity-timeout>
  <termination-timeout>3</termination-timeout>

[achaloyan]

Hi @njalmeida ,

Sorry, I am not able to follow your post entirely and analyze all the data, but here are some comments regarding the general behavior.

By sending an offer with connection:existing, the client indicates its desire to use an existing connection. The server may or may not accept that based on internal configuration/policies.

Given the configuration attribute max-shared-use-count is set to 100, it is allowed to re-use a connection up to 100 times. Afterwards, the connection will be closed as soon as all the existing sessions are teared down. This is made to prevent unconditional growth of the memory pool associated with the connection.

Other than that, the client should be able to re-use an existing connection, if the server responds accordingly, and such a connection exists.

[njalmeida]

Thank you for your reply @achaloyan

The connection re-use up to max-shared-use-count to prevent the unconditional growth of the memory pool makes perfect sense and it was what caused my first connection to stop being reused, which is fine.

After that I was expecting a new connection and seeing it being re-used which did not happen. This can be explained by your comment "The server may or may not accept that based on internal configuration/policies" as I see indeed that the client sends an offer with connection:existing and the server replies with connection:new.

My only issue is in fact with the requests I shared in my first comment as those 5 requests failed to re-use the established MRCP connection. I see that the client sends the offers with connection:existing and the server replies also with connection:existing and by monitoring the connections on client using netstat I see that an MRCP connection is indeed ESTABLISHED at that point of time. From the server point of view everything seems to be with the expected behavior and you don't see anything that may be causing this issue, right? If so, this should probably be an issue on the client side as it sends the offer to use an existing connection that it then cannot use for some reason.

[achaloyan]

Might be related to #259.

[njalmeida]

I don't have any "Null MRCPv2 Connection" in my case but the issue description does seem to match the behavior I'm having