search

unispeech / asterisk-unimrcp

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

app_unimrpc (v 1.7.0): request-timeout setting not respected. #46

Closed kremio closed 3 years ago

kremio commented 3 years ago

Hello,

I was testing the resilience of our system against different errors, and in a scenario where for some reason our MRCP server would not respond to an INVITE when establishing the MRCPv2 session, I noticed that whatever value I assign to the parameter request-timeout in mrcp.conf, the request timeout always occurs after about 30 seconds.

Note that In the log trace below I have set request-timeout to 5 but I have tried with other values (10, 10000) and the effect is always the same.

Can someone confirm that the request-timeout setting is being applied as expected on their installation?

In advance, thank you.

Asterisk version: 17.4.0 Asterisk Unimrcp version: 1.7.0

[2020-08-24 16:17:21] DEBUG[1]: ast_unimrcp_framework.c:827 load_mrcp_config: general.request-timeout=5
....
[2020-08-24 16:39:14] NOTICE[3676][C-00000001]: app_synthandrecog.c:1335 app_synthandrecog_exec: SynthAndRecog() prompt: <?xml version='1.0' encoding='UTF-8'?><speak version='1.0' xmlns='http://www.w3.org/2001/10/synthesis' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance' xsi:schemaLocation='http://www.w3.org/2001/10/synthesis http://www.w3.org/TR/speech-synthesis/synthesis.xsd' xml:lang='de-DE'><p>Hallo ich bin ein Test</p></speak>
[2020-08-24 16:39:14] NOTICE[3676][C-00000001]: app_synthandrecog.c:1343 app_synthandrecog_exec: SynthAndRecog() grammar: http://some.server/nuance_package.json?nlptype=config
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_datastore.c:157 app_datastore_get: Create app datastore on PJSIP/+4911111111111-00000000
[2020-08-24 16:39:14] NOTICE[3676][C-00000001]: app_synthandrecog.c:1359 app_synthandrecog_exec: SynthAndRecog() options: p=default&spl=de-DE&sit=1&b=0&t=30000&nit=1000&sct=1000
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1159 synthandrecog_options_parse: Apply option p: default
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1159 synthandrecog_options_parse: Apply option spl: de-DE
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1159 synthandrecog_options_parse: Apply option sit: 1
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1159 synthandrecog_options_parse: Apply option b: 0
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1159 synthandrecog_options_parse: Apply option t: 30000
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1159 synthandrecog_options_parse: Apply option nit: 1000
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1159 synthandrecog_options_parse: Apply option sct: 1000
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_datastore.c:210 app_datastore_session_add: Add entry _default to datastore on PJSIP/+4911111111111-00000000
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: audio_queue.c:253 audio_queue_create: (ASR-0) Audio queue created
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: speech_channel.c:252 speech_channel_create: Created speech channel: Name=ASR-0, Type=RECOGNIZER, Codec=PCMU, Rate=8000 on PJSIP/+4911111111111-00000000
[2020-08-24 16:39:14] NOTICE[3676][C-00000001]: src/mrcp_application.c:117  Create MRCP Handle 0x7fd63c01feb8 [unimrcp-mrcp2]
[2020-08-24 16:39:14] NOTICE[3676][C-00000001]: src/mrcp_client_session.c:131  Create Channel ASR-0 <new>
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd63c001400;4;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd63c001400;4;0]
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:385  Receive App Request ASR-0 <new> [2]
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client.c:697  Add MRCP Handle ASR-0 <new>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:1277  Dispatch App Request ASR-0 <new> [2]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:263  Signal Message to [MRCPv2ConnectionAgent] [0x7fd65c001a40;1;0]
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:717  Add Control Channel ASR-0 <new@speechrecog>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:743  Add Media Termination ASR-0 <new@media-tm>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:772  Add Media Termination ASR-0 <new@rtp-tm>
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:263  Signal Message to [MediaEngine] [0x7fd648006610;1;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_poller_task.c:259  Process Poller Wakeup [MRCPv2ConnectionAgent]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_task.c:335  Process Message [MRCPv2ConnectionAgent] [0x7fd65c001a40;1;0]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd65c001ca0;2;0]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_poller_task.c:249  Wait for Messages [MRCPv2ConnectionAgent]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd65c001ca0;2;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:292  Control Channel Added ASR-0 <new@speechrecog>
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] DEBUG[3663]: src/apt_task.c:335  Process Message [MediaEngine] [0x7fd648006610;1;0]
[2020-08-24 16:39:14] DEBUG[3663]: src/mpf_context.c:180  Add Media Context ASR-0
[2020-08-24 16:39:14] DEBUG[3663]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd64c0018d0;3;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd64c0018d0;3;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:939  Media Termination Added ASR-0 <new@media-tm>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:939  Media Termination Added ASR-0 <new@rtp-tm>
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:409  Send Offer ASR-0 <new> [c:1 a:1 v:0] to 127.0.0.1:8060
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_sofiasip_client_agent.c:357  Local SDP ASR-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:speechrecog
a=cmid:1
m=audio 10000 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=sendonly
a=ptime:20
a=mid:1

[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_i_state] Status 0 INVITE sent [unimrcp-mrcp2]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:555  SIP Call State ASR-0 [calling]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_r_invite] Status 200  [unimrcp-mrcp2]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_i_state] Status 200  [unimrcp-mrcp2]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:555  SIP Call State ASR-0 [ready]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:441  Remote SDP ASR-0 <new>
v=0
o=I4H_Server 1598287154879 1598287154879 IN IP4 127.0.0.1
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 8060 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:9ab35de3-8722-4efa-b2dd-5011006ccde5@speechrecog
a=cmid:1
m=audio 40650 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=ptime:20
a=mid:1

[2020-08-24 16:39:14] DEBUG[3664]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd654006990;1;0]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_i_active] Status 200 Call active [unimrcp-mrcp2]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd654006990;1;0]
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:149  Receive Answer ASR-0 <new> [c:1 a:1 v:0] Status 200
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:1136  Modify Control Channel ASR-0 <9ab35de3-8722-4efa-b2dd-5011006ccde5>
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:263  Signal Message to [MRCPv2ConnectionAgent] [0x7fd6480090b0;1;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:1174  Modify Media Termination ASR-0 <9ab35de3-8722-4efa-b2dd-5011006ccde5@rtp-tm>
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:263  Signal Message to [MediaEngine] [0x7fd64c0018d0;1;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_poller_task.c:259  Process Poller Wakeup [MRCPv2ConnectionAgent]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_task.c:335  Process Message [MRCPv2ConnectionAgent] [0x7fd6480090b0;1;0]
[2020-08-24 16:39:14] NOTICE[3662]: src/mrcp_client_connection.c:346  Established TCP/MRCPv2 Connection 127.0.0.1:37222 <-> 127.0.0.1:8060
[2020-08-24 16:39:14] NOTICE[3662]: src/mrcp_client_connection.c:456  Add Control Channel <9ab35de3-8722-4efa-b2dd-5011006ccde5@speechrecog> 127.0.0.1:37222 <-> 127.0.0.1:8060 [1]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd65c000900;2;1]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_poller_task.c:249  Wait for Messages [MRCPv2ConnectionAgent]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd65c000900;2;1]
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:309  Control Channel Modified ASR-0 <9ab35de3-8722-4efa-b2dd-5011006ccde5@speechrecog>
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] DEBUG[3663]: src/apt_task.c:335  Process Message [MediaEngine] [0x7fd64c0018d0;1;0]
[2020-08-24 16:39:14] NOTICE[3663]: src/mpf_rtp_stream.c:331  Enable RTP Session xxx.xxx.xxx.xxx:10000
[2020-08-24 16:39:14] DEBUG[3663]: src/mpf_bridge.c:153  Create Null Audio Bridge ASR-0
[2020-08-24 16:39:14] NOTICE[3663]: src/mpf_rtp_stream.c:921  Open RTP Transmitter xxx.xxx.xxx.xxx:10000 -> 127.0.0.1:40650
[2020-08-24 16:39:14] NOTICE[3663]: src/mpf_bridge.c:91  Media Path ASR-0 Source->[PCMU/8000/1]->Bridge->[PCMU/8000/1]->Sink
[2020-08-24 16:39:14] DEBUG[3663]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd648006610;3;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd648006610;3;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:980  Media Termination Modified ASR-0 <9ab35de3-8722-4efa-b2dd-5011006ccde5@rtp-tm>
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:453  Raise App Response ASR-0 <9ab35de3-8722-4efa-b2dd-5011006ccde5> [2] SUCCESS [0]
[2020-08-24 16:39:14] DEBUG[3661]: app_synthandrecog.c:232 speech_on_channel_add: (ASR-0) speech_on_channel_add
[2020-08-24 16:39:14] DEBUG[3661]: app_synthandrecog.c:252 speech_on_channel_add: (ASR-0) DTMF generator created
[2020-08-24 16:39:14] NOTICE[3661]: app_synthandrecog.c:271 speech_on_channel_add: (ASR-0) Channel ready codec=PCMU, sample rate=8000
[2020-08-24 16:39:14] DEBUG[3661]: speech_channel.c:109 speech_channel_set_state_unlocked: (ASR-0) CLOSED ==> READY
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: speech_channel.c:501 speech_channel_open: (ASR-0) channel is ready
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1504 app_synthandrecog_exec: (ASR-0) Determine grammar type: http://some.server/nuance_package.json?nlptype=config
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:823 recog_channel_load_grammar: (ASR-0) Loading grammar name=grammar-0, type=text/uri-list, data=http://some.server/nuance_package.json?nlptype=config
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: app_synthandrecog.c:1541 app_synthandrecog_exec: (ASR-0) Add prompt: <?xml version='1.0' encoding='UTF-8'?><speak version='1.0' xmlns='http://www.w3.org/2001/10/synthesis' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance' xsi:schemaLocation='http://www.w3.org/2001/10/synthesis http://www.w3.org/TR/speech-synthesis/synthesis.xsd' xml:lang='de-DE'><p>Hallo ich bin ein Test</p></speak>
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: audio_queue.c:253 audio_queue_create: (TTS-0) Audio queue created
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: speech_channel.c:252 speech_channel_create: Created speech channel: Name=TTS-0, Type=SYNTHESIZER, Codec=PCMU, Rate=8000 on PJSIP/+4911111111111-00000000
[2020-08-24 16:39:14] NOTICE[3676][C-00000001]: src/mrcp_application.c:117  Create MRCP Handle 0x7fd63c02ed68 [unimrcp-mrcp2]
[2020-08-24 16:39:14] NOTICE[3676][C-00000001]: src/mrcp_client_session.c:131  Create Channel TTS-0 <new>
[2020-08-24 16:39:14] DEBUG[3676][C-00000001]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd63c002d20;4;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd63c002d20;4;0]
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:385  Receive App Request TTS-0 <new> [2]
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client.c:697  Add MRCP Handle TTS-0 <new>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:1277  Dispatch App Request TTS-0 <new> [2]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:263  Signal Message to [MRCPv2ConnectionAgent] [0x7fd64800af60;1;0]
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:717  Add Control Channel TTS-0 <new@speechsynth>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:743  Add Media Termination TTS-0 <new@media-tm>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:772  Add Media Termination TTS-0 <new@rtp-tm>
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:263  Signal Message to [MediaEngine] [0x7fd648006610;1;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_poller_task.c:259  Process Poller Wakeup [MRCPv2ConnectionAgent]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_task.c:335  Process Message [MRCPv2ConnectionAgent] [0x7fd64800af60;1;0]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd65c001d80;2;0]
[2020-08-24 16:39:14] DEBUG[3662]: src/apt_poller_task.c:249  Wait for Messages [MRCPv2ConnectionAgent]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd65c001d80;2;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:292  Control Channel Added TTS-0 <new@speechsynth>
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] DEBUG[3663]: src/apt_task.c:335  Process Message [MediaEngine] [0x7fd648006610;1;0]
[2020-08-24 16:39:14] DEBUG[3663]: src/mpf_context.c:180  Add Media Context TTS-0
[2020-08-24 16:39:14] DEBUG[3663]: src/apt_task.c:263  Signal Message to [MRCP Client] [0x7fd64c0018d0;3;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/apt_task.c:335  Process Message [MRCP Client] [0x7fd64c0018d0;3;0]
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:939  Media Termination Added TTS-0 <new@media-tm>
[2020-08-24 16:39:14] DEBUG[3661]: src/mrcp_client_session.c:939  Media Termination Added TTS-0 <new@rtp-tm>
[2020-08-24 16:39:14] NOTICE[3661]: src/mrcp_client_session.c:409  Send Offer TTS-0 <new> [c:1 a:1 v:0] to 127.0.0.1:8060
[2020-08-24 16:39:14] NOTICE[3661]: 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-24 16:39:14] DEBUG[3661]: src/apt_consumer_task.c:135  Wait for Messages [MRCP Client]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_i_state] Status 0 INVITE sent [unimrcp-mrcp2]
[2020-08-24 16:39:14] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:555  SIP Call State TTS-0 [calling]
localhost*CLI> 
localhost*CLI> 
localhost*CLI> 
localhost*CLI> 
localhost*CLI> 
localhost*CLI> 
localhost*CLI> 
localhost*CLI> 
[2020-08-24 16:39:46] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_r_invite] Status 408 Request Timeout [unimrcp-mrcp2]
[2020-08-24 16:39:46] NOTICE[3664]: src/mrcp_sofiasip_client_agent.c:617  Receive SIP Event [nua_i_state] Status 408 Request Timeout [unimrcp-mrcp2]
kremio commented 3 years ago

After reading through the source code, I figured out that request-timeout is not the appropriate setting to control the timeout in this case. The list of MRCPv2 settings that can be set in a profile section in mrcp.conf can be found here app-unimrcp/ast_unimrcp_framework.c:process_mrcpv2_config

For this particular case, you can assign a duration in milliseconds to sip-t1x64 to control how long to wait before timing out the INVITE transaction.

Besides reading the source code, this article was very useful to figure this out.

May I suggest providing a more complete documentation about the supported MRCPv2 settings ? The usage manual makes no mention of them.

Feel free to close the issue if you wish.

achaloyan commented 3 years ago

Given your requirements, the best would be to set sip-t1x64.

If you use TCP as the SIP transport, then the client would return straightaway when the server is not available.