FreeSWITCH -> demo-recog plugin issue

[daniel.s...@ratel.io]

Hello,

i have the issue with demo-recog using:
FreeSWITCH Version 1.6.19 with UniMRCP version 1.4.0 and demo recog plugin.
Both FreeSWITCH and UniMRCP block at some point


FreeSWITCH log:

EXECUTE sofia/external/10...@192.168.22.42 play_and_detect_speech(/usr/local/freeswitch/tts/7215ee9c7d9dc229d2921a40e899ec5f.wav detect:unimrcp:unimrcp-plugin-v2 { start-[181/1858]
rs=false, no-input-timeout=5000, speech-complete-timeout=1100, recognition-timeout=10000 }yes_or_no)
2018-02-17 16:59:23.792712 [INFO] mod_unimrcp.c:3125 asr_handle: name = unimrcp, codec = (null), rate = 8000, grammar = (null), param = unimrcp-plugin-v2
2018-02-17 16:59:23.792712 [INFO] mod_unimrcp.c:3127 codec = L16, rate = 8000, dest = (null)
2018-02-17 16:59:23.792712 [DEBUG] mod_unimrcp.c:683 (ASR-0) audio queue created
2018-02-17 16:59:23.792712 [NOTICE] mrcp_application.c:96 (ASR-0) Create MRCP Handle 0x7fef000ba100 [unimrcp-plugin-v2]
2018-02-17 16:59:23.792712 [INFO] mrcp_client_session.c:133 (ASR-0) Create Channel ASR-0 <new>
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7fef00026b50;4;0]
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7fef00026b50;4;0]
2018-02-17 16:59:23.792712 [INFO] mrcp_client_session.c:387 (ASR-0) Receive App Request ASR-0 <new> [2]
2018-02-17 16:59:23.792712 [INFO] mrcp_client.c:700 (ASR-0) Add MRCP Handle ASR-0 <new>
2018-02-17 16:59:23.792712 [DEBUG] mrcp_client_session.c:1283 (ASR-0) Dispatch App Request ASR-0 <new> [2]
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.792712 [NOTICE] mrcp_client_session.c:719 (ASR-0) Add Control Channel ASR-0 <new@speechrecog>
2018-02-17 16:59:23.792712 [DEBUG] mrcp_client_session.c:745 (ASR-0) Add Media Termination ASR-0 <new@media-tm>
2018-02-17 16:59:23.792712 [DEBUG] mrcp_client_session.c:777 (ASR-0) Add Media Termination ASR-0 <new@rtp-tm>
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7fee8801e820;1;0]
2018-02-17 16:59:23.792712 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.792712 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x1a6ca60;2;0]
2018-02-17 16:59:23.792712 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x1a6ca60;2;0]
2018-02-17 16:59:23.792712 [DEBUG] mrcp_client_session.c:294 (ASR-0) Control Channel Added ASR-0 <new@speechrecog>
2018-02-17 16:59:23.792712 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7fee8801e820;1;0]
2018-02-17 16:59:23.792712 [DEBUG] mpf_context.c:182 () Add Media Context ASR-0
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7feefc000ca0;3;0]
2018-02-17 16:59:23.792712 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7feefc000ca0;3;0]
2018-02-17 16:59:23.792712 [DEBUG] mrcp_client_session.c:944 (ASR-0) Media Termination Added ASR-0 <new@media-tm>
2018-02-17 16:59:23.792712 [DEBUG] mrcp_client_session.c:944 (ASR-0) Media Termination Added ASR-0 <new@rtp-tm>
2018-02-17 16:59:23.792712 [INFO] mrcp_client_session.c:411 (ASR-0) Send Offer ASR-0 <new> [c:1 a:1 v:0] to 192.168.22.42:8060
2018-02-17 16:59:23.792712 [INFO] mrcp_sofiasip_client_agent.c:354 (ASR-0) Local SDP ASR-0 <new>
v=0
o=FreeSWITCH 0 0 IN IP4 192.168.22.42
s=-
c=IN IP4 192.168.22.42
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 12301 RTP/AVP 0 8 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=sendonly
a=mid:1

2018-02-17 16:59:23.792712 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.792712 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 0 INVITE sent [unimrcp-plugin-v2]
2018-02-17 16:59:23.792712 [NOTICE] mrcp_sofiasip_client_agent.c:547 (ASR-0) SIP Call State ASR-0 [calling]
2018-02-17 16:59:23.812699 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 200 OK [unimrcp-plugin-v2]
2018-02-17 16:59:23.812699 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 200 OK [unimrcp-plugin-v2]
2018-02-17 16:59:23.812699 [NOTICE] mrcp_sofiasip_client_agent.c:547 (ASR-0) SIP Call State ASR-0 [ready]
2018-02-17 16:59:23.812699 [INFO] mrcp_sofiasip_client_agent.c:433 (ASR-0) Remote SDP ASR-0 <new>
v=0
o=UniMRCPServer 2940468890317763652 9197796835937196364 IN IP4 192.168.22.42
s=-
c=IN IP4 192.168.22.42
t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:e79d86ac140311e8@speechrecog
a=cmid:1
m=audio 5006 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1

2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7feec8010550;1;0]
2018-02-17 16:59:23.812699 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_active] Status 200 Call active [unimrcp-plugin-v2]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7feec8010550;1;0]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:151 (ASR-0) Receive Answer ASR-0 <new> [c:1 a:1 v:0] Status 200
2018-02-17 16:59:23.812699 [DEBUG] mrcp_client_session.c:1141 (ASR-0) Modify Control Channel ASR-0 <e79d86ac140311e8>
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.812699 [DEBUG] mrcp_client_session.c:1180 (ASR-0) Modify Media Termination ASR-0 <e79d86ac140311e8@rtp-tm>
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7fee8801eb30;1;0]
2018-02-17 16:59:23.812699 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.812699 [NOTICE] mrcp_client_connection.c:338 () Established TCP/MRCPv2 Connection 192.168.22.42:56246 <-> 192.168.22.42:1544
2018-02-17 16:59:23.812699 [INFO] mrcp_client_connection.c:435 (ASR-0) Add Control Channel <e79d86ac140311e8@speechrecog> 192.168.22.42:56246 <-> 192.168.22.42:1544 [1]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x1a6ca60;2;1]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x1a6ca60;2;1]
2018-02-17 16:59:23.812699 [DEBUG] mrcp_client_session.c:311 (ASR-0) Control Channel Modified ASR-0 <e79d86ac140311e8@speechrecog>
2018-02-17 16:59:23.812699 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7fee8801eb30;1;0]
2018-02-17 16:59:23.812699 [INFO] mpf_rtp_stream.c:331 () Enable RTP Session 192.168.22.42:12301
2018-02-17 16:59:23.812699 [DEBUG] mpf_bridge.c:129 () Create Linear Audio Bridge ASR-0
2018-02-17 16:59:23.812699 [INFO] mpf_rtp_stream.c:921 () Open RTP Transmitter 192.168.22.42:12301 -> 192.168.22.42:5006
2018-02-17 16:59:23.812699 [INFO] mpf_bridge.c:93 () Media Path ASR-0 Source->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Encoder->[PCMU/8000/1]->Sink
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7feefc001060;3;0]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7feefc001060;3;0]
2018-02-17 16:59:23.812699 [DEBUG] mrcp_client_session.c:985 (ASR-0) Media Termination Modified ASR-0 <e79d86ac140311e8@rtp-tm>
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:455 (ASR-0) Raise App Response ASR-0 <e79d86ac140311e8> [2] SUCCESS [0]
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1893 (ASR-0) RECOGNIZER channel is ready, codec = LPCM, sample rate = 8000
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1577 (ASR-0) CLOSED ==> READY
2018-02-17 16:59:23.812699 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client] [80/1858]
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1055 (ASR-0) channel is ready
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1458 (ASR-0) param = start-input-timers, val = true
2018-02-17 16:59:23.812699 [DEBUG] switch_core_media_bug.c:945 Attaching BUG to sofia/external/10...@192.168.22.42
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1458 (ASR-0) param = start-input-timers, val = false
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1458 (ASR-0) param = no-input-timeout, val = 5000
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1458 (ASR-0) param = speech-complete-timeout, val = 1100
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1458 (ASR-0) param = recognition-timeout, val = 10000
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:3192 (ASR-0) grammar = yes_or_no, name =
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:3217 (ASR-0) Grammar is inside file
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:3279 (ASR-0) grammar is application/srgs
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:2352 (ASR-0) Loading grammar e79ef7e4-1403-11e8-9d15-5393ec5f41d3, data = #ABNF 1.0;
language pl-pl;
mode voice;
root $root;
tag-format <semantics/1.0-literals>;

$root=
tak |
owszem |
nie;

2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1577 (ASR-0) READY ==> PROCESSING
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7fef0000ec70;4;0]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7fef0000ec70;4;0]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:392 (ASR-0) Receive App MRCP Request ASR-0 <e79d86ac140311e8>
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:622 (ASR-0) Send MRCP Request ASR-0 <e79d86ac140311e8@speechrecog> [1]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.812699 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_connection.c:530 (ASR-0) Send MRCPv2 Data 192.168.22.42:56246 <-> 192.168.22.42:1544 [305 bytes]
MRCP/2.0 305 DEFINE-GRAMMAR 1
Channel-Identifier: e79d86ac140311e8@speechrecog
Content-Type: application/srgs
Content-Id: e79ef7e4-1403-11e8-9d15-5393ec5f41d3
Content-Length: 119

#ABNF 1.0;
language pl-pl;
mode voice;
root $root;
tag-format <semantics/1.0-literals>;

$root=
tak |
owszem |
nie;

2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 192.168.22.42:56246 <-> 192.168.22.42:1544 [112 bytes]
MRCP/2.0 112 1 200 COMPLETE
Channel-Identifier: e79d86ac140311e8@speechrecog
Completion-Cause: 000 success


2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x1a6ca60;2;3]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x1a6ca60;2;3]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:500 (ASR-0) Raise App MRCP Response ASR-0 <e79d86ac140311e8>
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:3647 (ASR-0) grammar loaded
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1577 (ASR-0) PROCESSING ==> READY
2018-02-17 16:59:23.812699 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:2517 (ASR-0) Disabling all grammars
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:2476 (ASR-0) Enabling grammar e79ef7e4-1403-11e8-9d15-5393ec5f41d3
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:2839 (ASR-0) "recognition-timeout": "10000"
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:2839 (ASR-0) "start-input-timers": "false"
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:2839 (ASR-0) "no-input-timeout": "5000"
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:2839 (ASR-0) "speech-complete-timeout": "1100"
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7fef0007c660;4;0]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7fef0007c660;4;0]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:392 (ASR-0) Receive App MRCP Request ASR-0 <e79d86ac140311e8>
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:622 (ASR-0) Send MRCP Request ASR-0 <e79d86ac140311e8@speechrecog> [2]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.812699 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7fee8801e4b0;1;0]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_connection.c:530 (ASR-0) Send MRCPv2 Data 192.168.22.42:56246 <-> 192.168.22.42:1544 [305 bytes]
MRCP/2.0 305 RECOGNIZE 2
Channel-Identifier: e79d86ac140311e8@speechrecog
Content-Type: text/uri-list
Cancel-If-Queue: false
Recognition-Timeout: 10000
Start-Input-Timers: false
No-Input-Timeout: 5000
Speech-Complete-Timeout: 1100
Content-Length: 44

session:e79ef7e4-1403-11e8-9d15-5393ec5f41d3
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 192.168.22.42:56246 <-> 192.168.22.42:1544 [83 bytes]
MRCP/2.0 83 2 200 IN-PROGRESS
Channel-Identifier: e79d86ac140311e8@speechrecog


2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x1a6ca60;2;3]
2018-02-17 16:59:23.812699 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2018-02-17 16:59:23.812699 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x1a6ca60;2;3]
2018-02-17 16:59:23.812699 [INFO] mrcp_client_session.c:500 (ASR-0) Raise App MRCP Response ASR-0 <e79d86ac140311e8>
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:3599 (ASR-0) RECOGNIZE IN PROGRESS
2018-02-17 16:59:23.812699 [DEBUG] mod_unimrcp.c:1577 (ASR-0) READY ==> PROCESSING
2018-02-17 16:59:23.812699 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:23.812699 [DEBUG] switch_core_file.c:342 File /usr/local/freeswitch/tts/7215ee9c7d9dc229d2921a40e899ec5f.wav sample rate 44100 doesn't match requested rate 8000
2018-02-17 16:59:23.812699 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2018-02-17 16:59:25.172698 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2018-02-17 16:59:25.172698 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2018-02-17 16:59:30.012709 [DEBUG] apt_poller_task.c:269 () Process Signalled Descriptor [MRCPv2ConnectionAgent]
2018-02-17 16:59:30.012709 [INFO] mrcp_client_connection.c:635 () Receive MRCPv2 Data 192.168.22.42:56246 <-> 192.168.22.42:1544 [94 bytes]
MRCP/2.0 94 START-OF-INPUT 2 IN-PROGRESS
Channel-Identifier: e79d86ac140311e8@speechrecog


2018-02-17 16:59:30.012709 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x1aa6cf0;2;3]
2018-02-17 16:59:30.012709 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2018-02-17 16:59:30.012709 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x1aa6cf0;2;3]
2018-02-17 16:59:30.012709 [INFO] mrcp_client_session.c:516 (ASR-0) Raise App MRCP Event ASR-0 <e79d86ac140311e8>
2018-02-17 16:59:30.012709 [DEBUG] mod_unimrcp.c:3689 (ASR-0) START OF INPUT
2018-02-17 16:59:30.012709 [DEBUG] mod_unimrcp.c:2591 (ASR-0) start of input
2018-02-17 16:59:30.012709 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2018-02-17 16:59:30.012709 [DEBUG] mod_unimrcp.c:2538 (ASR-0) SUCCESS, start of input
2018-02-17 16:59:30.012709 [DEBUG] mod_unimrcp.c:2538 (ASR-0) SUCCESS, start of input
2018-02-17 16:59:30.012709 [DEBUG] mod_unimrcp.c:2781 (ASR-0) start of input
2018-02-17 16:59:30.032698 [INFO] switch_ivr_async.c:4219 (sofia/external/10...@192.168.22.42) START OF SPEECH
2018-02-17 16:59:30.032698 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/tts/7215ee9c7d9dc229d2921a40e899ec5f.wav
2018-02-17 16:59:30.032698 [INFO] switch_ivr_async.c:4308 (sofia/external/10...@192.168.22.42) WAITING FOR RESULT
freeswitch@moria>



and UniMRCP with:



2018-02-17 16:59:23.811466 recv 830 bytes from tcp/[192.168.22.42]:42799
------------------------------------------------------------------------
INVITE sip:192.168.22.42:8060 SIP/2.0
Via: SIP/2.0/TCP 192.168.22.42:7097;branch=z9hG4bKXBgcyS604NrNe
Max-Forwards: 70
From: <sip:192.168.22.42:7097>;tag=XDFNHte4KK22m
To: <sip:192.168.22.42:8060>
Call-ID: befbac6c-8ea6-1236-7299-14dda95189c4
CSeq: 119107317 INVITE
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE
Supported: timer, 100rel
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 331

v=0
o=FreeSWITCH 4954423539581416289 4595996862740413737 IN IP4 192.168.22.42
s=-
c=IN IP4 192.168.22.42
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 12301 RTP/AVP 0 8 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=sendonly
a=mid:1
------------------------------------------------------------------------
2018-02-17 16:59:23.811661 send 305 bytes to tcp/[192.168.22.42]:42799
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.168.22.42:7097;branch=z9hG4bKXBgcyS604NrNe;rport=42799
From: <sip:192.168.22.42:7097>;tag=XDFNHte4KK22m
To: <sip:192.168.22.42:8060>
Call-ID: befbac6c-8ea6-1236-7299-14dda95189c4
CSeq: 119107317 INVITE
User-Agent: UniMRCP SofiaSIP 1.4.0
Content-Length: 0

------------------------------------------------------------------------
2018-02-17 16:59:23:811747 [INFO] Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2018-02-17 16:59:23:811755 [INFO] Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2018-02-17 16:59:23:811759 [NOTICE] SIP Call State [received]
2018-02-17 16:59:23:811768 [INFO] Create Session 0x7f43a0001a38 <new> [uni2]
2018-02-17 16:59:23:811771 [INFO] Remote SDP 0x7f43a0001a38 <new>
v=0
o=FreeSWITCH 4954423539581416289 4595996862740413737 IN IP4 192.168.22.42
s=-
c=IN IP4 192.168.22.42
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 12301 RTP/AVP 0 8 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=sendonly
a=mid:1

2018-02-17 16:59:23:811789 [DEBUG] Signal Message to [MRCP Server] [0x7f43a0004170;1;0]
2018-02-17 16:59:23:811799 [DEBUG] Process Message [MRCP Server] [0x7f43a0004170;1;0]
2018-02-17 16:59:23:811805 [DEBUG] Dispatch Signaling Message [0]
2018-02-17 16:59:23:811808 [NOTICE] Add Session <e79d86ac140311e8>
2018-02-17 16:59:23:811811 [INFO] Receive Offer 0x7f43a0001a38 <e79d86ac140311e8> [c:1 a:1 v:0]
2018-02-17 16:59:23:811818 [DEBUG] Add Control Channel 0x7f43a0001a38 <e79d86ac140311e8@speechrecog> [0]
2018-02-17 16:59:23:811820 [DEBUG] Signal Message to [MRCPv2-Agent-1] [0x7f43b000d180;1;0]
2018-02-17 16:59:23:811827 [DEBUG] Add Media Termination 0x7f43a0001a38 <e79d86ac140311e8@rtp-tm> [0]
2018-02-17 16:59:23:811829 [DEBUG] Signal Message to [Media-Engine-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:23:811831 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23:811838 [DEBUG] Process Poller Wakeup [MRCPv2-Agent-1]
2018-02-17 16:59:23:811842 [DEBUG] Process Message [MRCPv2-Agent-1] [0x7f43b000d180;1;0]
2018-02-17 16:59:23:811845 [INFO] Add Pending Control Channel <e79d86ac140311e8@speechrecog> [1]
2018-02-17 16:59:23:811847 [DEBUG] Signal Message to [MRCP Server] [0x7f43a80008c0;2;0]
2018-02-17 16:59:23:811850 [DEBUG] Wait for Messages [MRCPv2-Agent-1]
2018-02-17 16:59:23:811853 [DEBUG] Process Message [MRCP Server] [0x7f43a80008c0;2;0]
2018-02-17 16:59:23:811854 [DEBUG] Control Channel Modified 0x7f43a0001a38 <e79d86ac140311e8@speechrecog>
2018-02-17 16:59:23:811856 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23:816921 [DEBUG] Process Message [Media-Engine-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:23:816975 [INFO] Enable RTP Session 192.168.22.42:5006
2018-02-17 16:59:23:816991 [INFO] Open RTP Receiver 192.168.22.42:5006 <- 192.168.22.42:12301 playout [50 ms] bounds [0 - 600 ms] adaptive [1] skew detection [1]
2018-02-17 16:59:23:817003 [INFO] Media Path 0x7f43a0001a38 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2018-02-17 16:59:23:817005 [DEBUG] Signal Message to [MRCP Server] [0x7f43980008c0;4;0]
2018-02-17 16:59:23:817016 [DEBUG] Process Message [MRCP Server] [0x7f43980008c0;4;0]
2018-02-17 16:59:23:817022 [DEBUG] Media Termination Modified 0x7f43a0001a38 <e79d86ac140311e8@media-tm>
2018-02-17 16:59:23:817024 [DEBUG] Media Termination Modified 0x7f43a0001a38 <e79d86ac140311e8@rtp-tm>
2018-02-17 16:59:23:817027 [DEBUG] Signal Message to [Demo Recog Engine] [0x7f43b0004b60;1;0]
2018-02-17 16:59:23:817033 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23:817041 [DEBUG] Process Message [Demo Recog Engine] [0x7f43b0004b60;1;0]
2018-02-17 16:59:23:817046 [DEBUG] Signal Message to [MRCP Server] [0x7f439c0008c0;3;2]
2018-02-17 16:59:23:817051 [DEBUG] Wait for Messages [Demo Recog Engine]
2018-02-17 16:59:23:817056 [DEBUG] Process Message [MRCP Server] [0x7f439c0008c0;3;2]
2018-02-17 16:59:23:817058 [DEBUG] Engine Channel Opened 0x7f43a0001a38 <e79d86ac140311e8@speechrecog> [OK]
2018-02-17 16:59:23:817059 [INFO] Send Answer 0x7f43a0001a38 <e79d86ac140311e8> [c:1 a:1 v:0] Status OK
2018-02-17 16:59:23:817067 [INFO] Local SDP 0x7f43a0001a38 <e79d86ac140311e8>
v=0
o=UniMRCPServer 0 0 IN IP4 192.168.22.42
s=-
c=IN IP4 192.168.22.42
t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:e79d86ac140311e8@speechrecog
a=cmid:1
m=audio 5006 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1

2018-02-17 16:59:23:817081 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23.817308 send 864 bytes to tcp/[192.168.22.42]:42799
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.22.42:7097;branch=z9hG4bKXBgcyS604NrNe;rport=42799
From: <sip:192.168.22.42:7097>;tag=XDFNHte4KK22m
To: <sip:192.168.22.42:8060>;tag=8356eSBete1rS
Call-ID: befbac6c-8ea6-1236-7299-14dda95189c4
CSeq: 119107317 INVITE
Contact: <sip:192.168.22.42:8060>
User-Agent: UniMRCP SofiaSIP 1.4.0
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE
Supported: timer, 100rel
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 304

v=0
o=UniMRCPServer 2940468890317763652 9197796835937196364 IN IP4 192.168.22.42
s=-
c=IN IP4 192.168.22.42
t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:e79d86ac140311e8@speechrecog
a=cmid:1
m=audio 5006 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=recvonly
a=mid:1
------------------------------------------------------------------------
2018-02-17 16:59:23:817446 [INFO] Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2018-02-17 16:59:23:817452 [NOTICE] SIP Call State 0x7f43a0001a38 [completed]
2018-02-17 16:59:23.817587 recv 306 bytes from tcp/[192.168.22.42]:42799
------------------------------------------------------------------------
ACK sip:192.168.22.42:8060 SIP/2.0
Via: SIP/2.0/TCP 192.168.22.42:7097;branch=z9hG4bKym94ZmQ41ye8S
Max-Forwards: 70
From: <sip:192.168.22.42:7097>;tag=XDFNHte4KK22m
To: <sip:192.168.22.42:8060>;tag=8356eSBete1rS
Call-ID: befbac6c-8ea6-1236-7299-14dda95189c4
CSeq: 119107317 ACK
Content-Length: 0

------------------------------------------------------------------------
2018-02-17 16:59:23:817644 [INFO] Receive SIP Event [nua_i_ack] Status 200 OK [SIP-Agent-1]
2018-02-17 16:59:23:817648 [INFO] Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2018-02-17 16:59:23:817650 [NOTICE] SIP Call State 0x7f43a0001a38 [ready]
2018-02-17 16:59:23:817652 [INFO] Receive SIP Event [nua_i_active] Status 200 Call active [SIP-Agent-1]
2018-02-17 16:59:23:817724 [DEBUG] Process Signalled Descriptor [MRCPv2-Agent-1]
2018-02-17 16:59:23:817741 [NOTICE] Accepted TCP/MRCPv2 Connection 192.168.22.42:1544 <-> 192.168.22.42:56246
2018-02-17 16:59:23:817744 [DEBUG] Wait for Messages [MRCPv2-Agent-1]
2018-02-17 16:59:23:821346 [DEBUG] Process Signalled Descriptor [MRCPv2-Agent-1]
2018-02-17 16:59:23:821353 [INFO] Receive MRCPv2 Data 192.168.22.42:1544 <-> 192.168.22.42:56246 [305 bytes]
MRCP/2.0 305 DEFINE-GRAMMAR 1
Channel-Identifier: e79d86ac140311e8@speechrecog
Content-Type: application/srgs
Content-Id: e79ef7e4-1403-11e8-9d15-5393ec5f41d3
Content-Length: 119

#ABNF 1.0;
language pl-pl;
mode voice;
root $root;
tag-format <semantics/1.0-literals>;

$root=
tak |
owszem |
nie;

2018-02-17 16:59:23:821373 [INFO] Assign Control Channel <e79d86ac140311e8@speechrecog> to Connection 192.168.22.42:1544 <-> 192.168.22.42:56246 [0] -> [1]
2018-02-17 16:59:23:821376 [DEBUG] Signal Message to [MRCP Server] [0x7f43a80008c0;2;3]
2018-02-17 16:59:23:821381 [DEBUG] Wait for Messages [MRCPv2-Agent-1]
2018-02-17 16:59:23:821385 [DEBUG] Process Message [MRCP Server] [0x7f43a80008c0;2;3]
2018-02-17 16:59:23:821389 [DEBUG] Dispatch Signaling Message [1]
2018-02-17 16:59:23:821391 [INFO] Process DEFINE-GRAMMAR Request <e79d86ac140311e8@speechrecog> [1]
2018-02-17 16:59:23:821394 [DEBUG] Signal Message to [Demo Recog Engine] [0x7f43b00029f0;1;0]
2018-02-17 16:59:23:821399 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23:821404 [DEBUG] Process Message [Demo Recog Engine] [0x7f43b00029f0;1;0]
2018-02-17 16:59:23:821407 [DEBUG] Signal Message to [MRCP Server] [0x7f439c0008c0;3;4]
2018-02-17 16:59:23:821410 [DEBUG] Wait for Messages [Demo Recog Engine]
2018-02-17 16:59:23:821413 [DEBUG] Process Message [MRCP Server] [0x7f439c0008c0;3;4]
2018-02-17 16:59:23:821419 [INFO] Process DEFINE-GRAMMAR Response <e79d86ac140311e8@speechrecog> [1]
2018-02-17 16:59:23:821425 [DEBUG] Signal Message to [MRCPv2-Agent-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:23:821431 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23:821437 [DEBUG] Process Poller Wakeup [MRCPv2-Agent-1]
2018-02-17 16:59:23:821440 [DEBUG] Process Message [MRCPv2-Agent-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:23:821444 [INFO] Send MRCPv2 Data 192.168.22.42:1544 <-> 192.168.22.42:56246 [112 bytes]
MRCP/2.0 112 1 200 COMPLETE
Channel-Identifier: e79d86ac140311e8@speechrecog
Completion-Cause: 000 success


2018-02-17 16:59:23:821464 [DEBUG] Wait for Messages [MRCPv2-Agent-1]
2018-02-17 16:59:23:821555 [DEBUG] Process Signalled Descriptor [MRCPv2-Agent-1]
2018-02-17 16:59:23:821560 [INFO] Receive MRCPv2 Data 192.168.22.42:1544 <-> 192.168.22.42:56246 [305 bytes]
MRCP/2.0 305 RECOGNIZE 2
Channel-Identifier: e79d86ac140311e8@speechrecog
Content-Type: text/uri-list
Cancel-If-Queue: false
Recognition-Timeout: 10000
Start-Input-Timers: false
No-Input-Timeout: 5000
Speech-Complete-Timeout: 1100
Content-Length: 44

session:e79ef7e4-1403-11e8-9d15-5393ec5f41d3
2018-02-17 16:59:23:821574 [DEBUG] Signal Message to [MRCP Server] [0x7f43a80008c0;2;3]
2018-02-17 16:59:23:821582 [DEBUG] Wait for Messages [MRCPv2-Agent-1]
2018-02-17 16:59:23:821587 [DEBUG] Process Message [MRCP Server] [0x7f43a80008c0;2;3]
2018-02-17 16:59:23:821590 [DEBUG] Dispatch Signaling Message [1]
2018-02-17 16:59:23:821592 [INFO] Process RECOGNIZE Request <e79d86ac140311e8@speechrecog> [2]
2018-02-17 16:59:23:821595 [DEBUG] Signal Message to [Demo Recog Engine] [0x7f43b00029f0;1;0]
2018-02-17 16:59:23:821599 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23:821603 [DEBUG] Process Message [Demo Recog Engine] [0x7f43b00029f0;1;0]
2018-02-17 16:59:23:821607 [INFO] Open Utterance Output File [/opt/unimrcp/var/utter-8kHz-e79d86ac140311e8.pcm] for Writing
2018-02-17 16:59:23:821620 [WARN] Failed to Open Utterance Output File [/opt/unimrcp/var/utter-8kHz-e79d86ac140311e8.pcm] for Writing
2018-02-17 16:59:23:821622 [DEBUG] Signal Message to [MRCP Server] [0x7f439c0008c0;3;4]
2018-02-17 16:59:23:821625 [DEBUG] Wait for Messages [Demo Recog Engine]
2018-02-17 16:59:23:821628 [DEBUG] Process Message [MRCP Server] [0x7f439c0008c0;3;4]
2018-02-17 16:59:23:821631 [INFO] Process RECOGNIZE Response <e79d86ac140311e8@speechrecog> [2]
2018-02-17 16:59:23:821633 [INFO] State Transition IDLE -> RECOGNIZING <e79d86ac140311e8@speechrecog>
2018-02-17 16:59:23:821636 [DEBUG] Signal Message to [MRCPv2-Agent-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:23:821640 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:23:821645 [DEBUG] Process Poller Wakeup [MRCPv2-Agent-1]
2018-02-17 16:59:23:821647 [DEBUG] Process Message [MRCPv2-Agent-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:23:821651 [INFO] Send MRCPv2 Data 192.168.22.42:1544 <-> 192.168.22.42:56246 [83 bytes]
MRCP/2.0 83 2 200 IN-PROGRESS
Channel-Identifier: e79d86ac140311e8@speechrecog


2018-02-17 16:59:23:821665 [DEBUG] Wait for Messages [MRCPv2-Agent-1]
2018-02-17 16:59:30:016944 [INFO] Detected Voice Activity <e79d86ac140311e8@speechrecog>
2018-02-17 16:59:30:016968 [DEBUG] Signal Message to [MRCP Server] [0x7f43980008c0;3;4]
2018-02-17 16:59:30:016998 [DEBUG] Process Message [MRCP Server] [0x7f43980008c0;3;4]
2018-02-17 16:59:30:017006 [INFO] Process START-OF-INPUT Event <e79d86ac140311e8@speechrecog> [2]
2018-02-17 16:59:30:017019 [DEBUG] Signal Message to [MRCPv2-Agent-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:30:017027 [DEBUG] Wait for Messages [MRCP Server]
2018-02-17 16:59:30:017048 [DEBUG] Process Poller Wakeup [MRCPv2-Agent-1]
2018-02-17 16:59:30:017052 [DEBUG] Process Message [MRCPv2-Agent-1] [0x7f43b000d060;1;0]
2018-02-17 16:59:30:017061 [INFO] Send MRCPv2 Data 192.168.22.42:1544 <-> 192.168.22.42:56246 [94 bytes]
MRCP/2.0 94 START-OF-INPUT 2 IN-PROGRESS
Channel-Identifier: e79d86ac140311e8@speechrecog


2018-02-17 16:59:30:017114 [DEBUG] Wait for Messages [MRCPv2-Agent-1]


both waiting infinitely.



Did anyone experienced the same problem, or could you give some tips?
Thanks in advance!

[Ray Keating]

What does the  log of your MRCP ASR server show?  You can't diagnose a problem

that occurs across a network protocol interface without looking at what's occurring

on both sides of the interface.

Ray Keating, Pontimax Technologies LLC

Pontimax’s mrcpSP11-STT- the lowest cost, by far, highest recognition accuracy MRCP server available

[daniel.s...@ratel.io]

Hi Ray,

thanks for the response. Actually i posted both logs fromd freeswitch and unimrcp server, but didn't split them in a more elegant way, now sending both files as attachments.

As you can see, at some point both freeswitch and unimrcp server wait for each other..

FS:

2018-02-17 16:59:30.032698 [INFO] switch_ivr_async.c:4308 (sofia/external/10...@192.168.22.42) WAITING FOR RESULT

UniMRCP:

2018-02-17 16:59:30:017114 [DEBUG]  Wait for Messages [MRCPv2-Agent-1]

i am using play_and_detect_speech() function in FS.

[Ray Keating]

One thing that stands out is that you set Start-Input-Timers header field to FALSE but then you never send START-INPUT-TIMERS

request from the client (i.e. FS) to the server.  Looking at the FS side, you don't play a prompt file, right?  If so, you should

be setting Start-Input-Timers to TRUE.  The server never issues the RECOGNITION-COMPLETE to the client with any

recognition results or any recognition error condition report, despite having issued the START-OF-INPUT after internally

reporting "Detected Voice Activity". Be aware that, without the START-INPUT-TIMERS being issued by the client, the server

may just sit there waiting for (more) input.   Speaking of input, are you sure that you're sending validly generated and

formatted speech data?

Easiest approach is to just set the Start-Input-Timers header field to True in the play-and-detect-speech FS call and

see if that fixes the condition.  I also suggest that you locate a copy of RFC 6787, "MRCPv2" and review the

section on use of the Start-Input-Timers header field values.

Ray Keating, Pontimax Technologies LLC (www.pontimax.com)

Pontimax’s mrcpSP11-STT- the lowest cost, by far, highest recognition accuracy MRCP server available

[daniel.s...@ratel.io]

Hi Ray, thanks a lot, that helped!