Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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 this issue Aug 26, 2020 · 1 comment
Open

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

kremio opened this issue Aug 26, 2020 · 1 comment
Assignees
@achaloyan

Comments

@kremio
Copy link

kremio commented Aug 26, 2020 •
edited
Loading

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:[email protected]:5061 SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:63833;rport;branch=z9hG4bKPjqVqCLfoWnEp53M070eSnnT6LCGmb29em
Max-Forwards: 70
From: <sip:[email protected];ob>;tag=A3OhTO3MsfQ7ejWA0OEmz.EjQ7AcwZvU
To: "Anonymous" <sip:[email protected]>;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:[email protected];ob>;tag=A3OhTO3MsfQ7ejWA0OEmz.EjQ7AcwZvU
To: "Anonymous" <sip:[email protected]>;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
@kremio kremio changed the title app_unimrcp (v 1.7.0): No timeout and channel freeze if SIP session not established after MRCP server respond with 100 TRYING app_unimrcp (v 1.7.0): No timeout and channel freeze if INVITE transaction not completed after MRCP server respond with 100 TRYING Aug 26, 2020
@kremio kremio changed the title app_unimrcp (v 1.7.0): No timeout and channel freeze if INVITE transaction not completed after MRCP server respond with 100 TRYING app_unimrcp (v 1.7.0): No timeout and channel freeze if INVITE transaction not completed after MRCP server responds with 100 TRYING Aug 26, 2020
@achaloyan achaloyan self-assigned this Aug 29, 2020
@achaloyan
Copy link
Contributor

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@achaloyan achaloyan

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@kremio @achaloyan