Termination Timeout Elapsed Possible bug

[Yaron Zehavi]

Hello, 

I suspect a bug in the MRCP server.

When running a load we sometimes see that the MRCP client doesn't send BYE to close the session.

In that case we see the server writes to the log:

1. Termination Timeout Elapsed

2. Initiate Session Termination

However the actual BYE sent from the server actually terminates another MRCP session. The logs below show this issue:

1. First session with nua_handle 0x3618c388 and mrcp_sofia_session 0x17740710 (2019-12-16 13:40:10:323649)

2. Due to resource discover the session destroys nua_handle 0x3618c388 for mrcp_sofia_session 0x17740710 (2019-12-16 13:40:30:117732)

3. A new session binds to nua_handle 0x3618c388 and mrcp_sofia_session 0x6d92f010 (2019-12-16 13:41:08:825272)

4. The first call detects a timeout and tries to initiate a timeout for mrcp_sofia_session 0x17740710 (2019-12-16 13:41:14:098023)

5. Termination is handled on the second session nua_handle  0x3618c388 mrcp_sofia_session 0x6d92f010 instead of the first one (2019-12-16 13:41:14:123041)

How can it be fixed?

2019-12-16 13:40:10:323649 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:253 06664 [NOTICE] mrcp_sofia_session_create: nua_handle_bind nh 0x3618c388 mrcp_sofia_session_t 0x17740710

2019-12-16 13:40:10:335657 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x17740618 [completed] 1882 mrcp_session_t 0x17740618 mrcp_sofia_session_t 0x17740710

2019-12-16 13:40:10:358673 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x17740618 [ready] 1882 mrcp_session_t 0x17740618 mrcp_sofia_session_t 0x17740710

2019-12-16 13:40:10:358673 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x17740618 [received] 1882 mrcp_session_t 0x17740618 mrcp_sofia_session_t 0x17740710

2019-12-16 13:40:10:362676 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x17740618 [completed] 1882 mrcp_session_t 0x17740618 mrcp_sofia_session_t 0x17740710

2019-12-16 13:40:10:383691 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x17740618 [ready] 1882 mrcp_session_t 0x17740618 mrcp_sofia_session_t 0x17740710

2019-12-16 13:40:30:117732 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:504 06664 [NOTICE] mrcp_sofia_on_resource_discover: nua_handle_bind nh 0x3618c388 mrcp_sofia_session_t 0x17740710

2019-12-16 13:41:08:825272 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:253 06664 [NOTICE] mrcp_sofia_session_create: nua_handle_bind nh 0x3618c388 mrcp_sofia_session_t 0x6d92f010

2019-12-16 13:41:08:834279 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x6d92ef18 [completed] 1907 mrcp_session_t 0x6d92ef18 mrcp_sofia_session_t 0x6d92f010

2019-12-16 13:41:08:857295 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x6d92ef18 [ready] 1907 mrcp_session_t 0x6d92ef18 mrcp_sofia_session_t 0x6d92f010

2019-12-16 13:41:08:857295 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x6d92ef18 [received] 1907 mrcp_session_t 0x6d92ef18 mrcp_sofia_session_t 0x6d92f010

2019-12-16 13:41:08:862298 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x6d92ef18 [completed] 1907 mrcp_session_t 0x6d92ef18 mrcp_sofia_session_t 0x6d92f010

2019-12-16 13:41:08:883314 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x6d92ef18 [ready] 1907 mrcp_session_t 0x6d92ef18 mrcp_sofia_session_t 0x6d92f010

2019-12-16 13:41:14:098023 c:\dev\vocanom\mrcp\libs\mrcpv2-transport\src\mrcp_server_connection.c:638 06688     [WARN]   Termination Timeout Elapsed 10.31.5.247:1544 <-> 10.31.5.247:56969

2019-12-16 13:41:14:098023 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:350 05332 [NOTICE] Initiate Session Termination <1882> 0x17740618 mrcp_session_t 0x17740618 mrcp_sofia_session_t 0x17740710 nh 0x3618c388

2019-12-16 13:41:14:119038 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:522 06664 [INFO]   Receive SIP Event [nua_r_bye] Status 200 OK

2019-12-16 13:41:14:119038 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:522 06664 [INFO]   Receive SIP Event [nua_i_state] Status 200 to BYE

2019-12-16 13:41:14:119038 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:453 06664 [NOTICE] SIP Call State 0x6d92ef18 [terminated] 1907 mrcp_session_t 0x6d92ef18 mrcp_sofia_session_t 0x6d92f010

2019-12-16 13:41:14:123041 c:\dev\vocanom\mrcp\modules\mrcp-sofiasip\src\mrcp_sofiasip_server_agent.c:326 05332 [NOTICE] mrcp_sofia_on_session_terminate: nua_handle_bind nh 0x3618c388 mrcp_sofia_session_t 0x6d92f010

Thanks,

Yaron

[Arsen Chaloyan]

Hello Yaron,

If I read your description correctly, the same SIP dialog is used for both resource discovery and MRCPv2 session. Although this scenario does not violate the specs, it is not very common either. If my assumption is true, can you separate the use of resource discovery in your MRCP client application.

Since I may not have the time to take a closer look at this problem in the nearest future, please open a new issue by referring to this post for further analysis.

https://github.com/unispeech/unimrcp/issues

--
You received this message because you are subscribed to the Google Groups "UniMRCP" group.
To unsubscribe from this group and stop receiving emails from it, send an email to unimrcp+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/unimrcp/26a4609f-e215-4176-bc83-892202ea8244%40googlegroups.com.

--

Arsen Chaloyan
Author of UniMRCP
http://www.unimrcp.org