search

unispeech / asterisk-unimrcp

UniMRCP modules for Asterisk
http://www.unimrcp.org/asterisk
GNU General Public License v2.0
48 stars 36 forks source link

app_unimrcp (v 1.7.0): No timeout and channel freeze if INVITE transaction not completed after MRCP server responds with 100 TRYING #47

Open kremio opened 4 years ago

kremio commented 4 years ago

Hi,

as I am looking into the resilience of the UniMRCP Asterisk module against network errors, I found out that one can completely freeze a PJSIP channel if the MRCP server does not answer after responding 100 TRYING when establishing the SIP session.

MRCP Client                MRCP Server
     |                          |      
     |                          |      
     |---------INVITE --------->|      
     |                          |      
     |<--------TRYING-----------|      
     |                          |      
     |                          |

After waiting over a minute for the timeout, nothing happened so I hanged up the call.

Note that this is a different case than #46 (where the server does not even reply with 100 TRYING).

[2020-08-26 07:27:46] NOTICE[62]: src/mrcp_sofiasip_client_agent.c:357  Local SDP TTS-0 <new>
v=0
o=Asterisk 0 0 IN IP4 xxx.xxx.xxx.xxx
s=-
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechsynth
a=cmid:1
m=audio 10002 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=recvonly
a=ptime:20
a=mid:1

[2020-08-26 07:27:46] DEBUG[62]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-26 07:27:46] NOTICE[65]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_i_state] Status 0 INVITE sent [unimrcp-mrcp2]
[2020-08-26 07:27:46] NOTICE[65]: src/mrcp_sofiasip_client_agent.c:555  SIP Call State TTS-0 [calling]
[2020-08-26 07:28:05] DEBUG[94]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying.
[2020-08-26 07:28:05] DEBUG[7]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 22
[2020-08-26 07:28:14] DEBUG[47]: res_pjsip_registrar.c:1279 check_expiration_thread: Woke up at 1598426894  Interval: 30
[2020-08-26 07:28:14] DEBUG[47]: res_pjsip_registrar.c:1286 check_expiration_thread: Expiring 0 contacts
[2020-08-26 07:28:35] DEBUG[96][C-00000001]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x555e099a6878 and write factory 0x555e099a72b8 both fail to provide 160 samples
[2020-08-26 07:28:40] DEBUG[90]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying.
[2020-08-26 07:28:40] DEBUG[91]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying.
[2020-08-26 07:28:40] DEBUG[93]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying.
[2020-08-26 07:28:40] DEBUG[92]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying.
[2020-08-26 07:28:40] DEBUG[33]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 18
[2020-08-26 07:28:40] DEBUG[33]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 19
[2020-08-26 07:28:40] DEBUG[33]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 21
[2020-08-26 07:28:40] DEBUG[33]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 20
[2020-08-26 07:28:44] DEBUG[47]: res_pjsip_registrar.c:1279 check_expiration_thread: Woke up at 1598426924  Interval: 30
[2020-08-26 07:28:44] DEBUG[47]: res_pjsip_registrar.c:1286 check_expiration_thread: Expiring 0 contacts
[2020-08-26 07:28:45] DEBUG[89]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying.
[2020-08-26 07:28:45] DEBUG[33]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 17
[2020-08-26 07:29:14] DEBUG[47]: res_pjsip_registrar.c:1279 check_expiration_thread: Woke up at 1598426954  Interval: 30
[2020-08-26 07:29:14] DEBUG[47]: res_pjsip_registrar.c:1286 check_expiration_thread: Expiring 0 contacts
<--- Received SIP request (443 bytes) from UDP:xxx.xxx.xxx.xxx:63833 --->
BYE sip:asterisk@xxx.xxx.xxx.xxx:5061 SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:63833;rport;branch=z9hG4bKPjqVqCLfoWnEp53M070eSnnT6LCGmb29em
Max-Forwards: 70
From: <sip:+4911111111111@xxx.xxx.xxx.xxx;ob>;tag=A3OhTO3MsfQ7ejWA0OEmz.EjQ7AcwZvU
To: "Anonymous" <sip:anonymous@anonymous.invalid>;tag=71027622-f20e-45aa-8cfe-c5f7aa9ba1cb
Call-ID: f56c23ee-2cac-4a7f-bbaa-eac9992bf9b8
CSeq: 29426 BYE
User-Agent: Telephone 1.5
Content-Length:  0

[2020-08-26 07:29:19] DEBUG[35]: res_pjsip/pjsip_distributor.c:503 distributor: Searching for serializer associated with dialog dlg0x7f1a34009378 for Request msg BYE/cseq=29426 (rdata0x7f1a38002eb8)
[2020-08-26 07:29:19] DEBUG[35]: res_pjsip/pjsip_distributor.c:511 distributor: Found serializer pjsip/outsess/+4911111111111-00000058 associated with dialog dlg0x7f1a34009378
[2020-08-26 07:29:19] DEBUG[33]: threadpool.c:536 grow: Increasing threadpool pjsip/pool's size by 5
[2020-08-26 07:29:19] DEBUG[97]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'xxx.xxx.xxx.xxx' into...
[2020-08-26 07:29:19] DEBUG[97]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'xxx.xxx.xxx.xxx' and port ''.
<--- Transmitting SIP response (427 bytes) to UDP:xxx.xxx.xxx.xxx:63833 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:63833;rport=63833;received=94.223.85.136;branch=z9hG4bKPjqVqCLfoWnEp53M070eSnnT6LCGmb29em
Call-ID: f56c23ee-2cac-4a7f-bbaa-eac9992bf9b8
From: <sip:+4911111111111@xxx.xxx.xxx.xxx;ob>;tag=A3OhTO3MsfQ7ejWA0OEmz.EjQ7AcwZvU
To: "Anonymous" <sip:anonymous@anonymous.invalid>;tag=71027622-f20e-45aa-8cfe-c5f7aa9ba1cb
CSeq: 29426 BYE
Server: Asterisk PBX 17.4.0
Content-Length:  0

[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3507 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3521 __print_debug_details: The state change pertains to the endpoint '+4911111111111(PJSIP/+4911111111111-00000000)'
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3529 __print_debug_details: The inv session does NOT have an invite_tsx
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3532 __print_debug_details: The UAS BYE transaction involved in this state change is 0x7f1a5c037cc8
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3536 __print_debug_details: The current transaction state is Completed
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3538 __print_debug_details: The transaction state change event is TX_MSG
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3543 __print_debug_details: The current inv state is CONFIRMED
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3507 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3521 __print_debug_details: The state change pertains to the endpoint '+4911111111111(PJSIP/+4911111111111-00000000)'
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3529 __print_debug_details: The inv session does NOT have an invite_tsx
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3541 __print_debug_details: There is no transaction involved in this state change
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3543 __print_debug_details: The current inv state is DISCONNCTD
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3787 session_inv_on_state_changed: Source of transaction state change is RX_MSG
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3620 handle_incoming: Received request
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3553 handle_incoming_request: Method is BYE
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3507 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3521 __print_debug_details: The state change pertains to the endpoint '+4911111111111(PJSIP/+4911111111111-00000000)'
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3529 __print_debug_details: The inv session does NOT have an invite_tsx
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3532 __print_debug_details: The UAS BYE transaction involved in this state change is 0x7f1a5c037cc8
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3536 __print_debug_details: The current transaction state is Completed
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3538 __print_debug_details: The transaction state change event is RX_MSG
[2020-08-26 07:29:19] DEBUG[97]: res_pjsip_session.c:3543 __print_debug_details: The current inv state is DISCONNCTD
[2020-08-26 07:29:19] DEBUG[31]: manager.c:6123 match_filter: Examining AMI event:
Event: HangupRequest
Privilege: call,all
Channel: PJSIP/+4911111111111-00000000
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: <unknown>
CallerIDName: ??????????
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode: 
Context: from-internal
Exten: 1
Priority: 5
Uniqueid: 1598426860.0
Linkedid: 1598426860.0
Cause: 16

[2020-08-26 07:29:19] DEBUG[88]: manager.c:6123 match_filter: Examining AMI event:
Event: HangupRequest
Privilege: call,all
Channel: PJSIP/+4911111111111-00000000
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: <unknown>
CallerIDName: ??????????
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode: 
Context: from-internal
Exten: 1
Priority: 5
Uniqueid: 1598426860.0
Linkedid: 1598426860.0
Cause: 16

[2020-08-26 07:29:25] DEBUG[96][C-00000001]: audiohook.c:275 audiohook_read_frame_both: Read factory 0x555e099a6878 and write factory 0x555e099a72b8 both fail to provide 160 samples

After hanging up the call, the PJSIP channel is left active waiting on the SynthAndRecog application to finish. As far as I know, the only way to close it is to restart Asterisk, channel request hangup does not work.

localhost*CLI> channel request hangup PJSIP/+4911111111111-00000000
localhost*CLI> pjsip show channels

  Channel:  <ChannelId........................................>  <State.....>  <Time.....>
      Exten: <DialedExten.............>  CLCID: <ConnectedLineCID.......>
==========================================================================================

  Channel: PJSIP/+4911111111111-00000000/SynthAndRecog           Up            00:01:52   
      Exten: 1                           CLCID: "" <>

Objects found: 1
achaloyan commented 4 years ago

I'll try to take a look at this issue, but it is unlikely I will be able to find some spare time any soon. Patches are welcome in the meantime.