Issue while performing ASR using Azure SR Plugin

122 views
Skip to first unread message

Vaibhav Sawke

unread,
Feb 23, 2021, 2:39:41 AM2/23/21
to UniMRCP
I am working on a IVR based speech bot. In my setup I have FreeSWITCH and uniMRCP communicating with each other for ASR and TTS.

I am using trial version of Azure SR plugin for ASR, but I am facing issue with same. Though the initial invite is successful, the ASR itself is not working and I see no logs in unimrcp w.r.t. ASR call being sent to Azure. FreeSWITCH and uniMRCP are installed on 2 different servers and I have verified the connectivity between the two servers.

As I am doing this for the first time I need help from the community with the issue I am facing.

2021-02-19 12:02:46:694905 [INFO]   Load Plugin [Azure-SR-1] [/opt/unimrcp/plugin/umsazuresr.so]
2021-02-19 12:02:46:699891 [NOTICE] AZURESR Plugin Version [1.17.0] Date [2021-02-08]
2021-02-19 12:02:46:701070 [INFO]   Register MRCP Engine [Azure-SR-1]
2021-02-19 12:02:46:701089 [INFO]   Register RTP Settings [RTP-Settings-1]
2021-02-19 12:02:46:701099 [NOTICE] Create MRCPv2 Profile [uni2]
2021-02-19 12:02:46:701105 [INFO]   Associate Resource [speechrecog] to Engine [Azure-SR-1] in Profile [uni2]
2021-02-19 12:02:46:701113 [INFO]   Register Profile [uni2]
2021-02-19 12:02:46:701117 [NOTICE] Create MRCPv1 Profile [uni1]
2021-02-19 12:02:46:701122 [INFO]   Associate Resource [speechrecog] to Engine [Azure-SR-1] in Profile [uni1]
2021-02-19 12:02:46:701127 [INFO]   Register Profile [uni1]
2021-02-19 12:02:46:701131 [INFO]   Start Task [MRCP Server]
>2021-02-19 12:02:46:701233 [INFO]   Open Engine [Azure-SR-1]
2021-02-19 12:02:46:701251 [NOTICE] Open Config File [/opt/unimrcp/conf/umsazuresr.xml]
2021-02-19 12:02:46:701639 [NOTICE] Determined License File /opt/unimrcp/data/umsazuresr_bcab1663-0150-4f86-af25-da8734442864.lic
2021-02-19 12:02:46:701763 [INFO]   Start Task [SIP-Agent-1]
2021-02-19 12:02:46:701783 [NOTICE] AzureSR Usage: 0/0/0
2021-02-19 12:02:46:701817 [INFO]   Start Task [RTSP-Agent-1]
2021-02-19 12:02:46:702397 [INFO]   Start Task [MRCPv2-Agent-1]
2021-02-19 12:02:46:702440 [INFO]   Start Task [Media-Engine-1]
2021-02-19 12:02:46:702744 [NOTICE] UniMRCP AzureSR License 

-product name:    umsazuresr
-product version: 1.0.0
-license owner:   -
-license type:    trial
-issue date:      2021-02-17
-exp date:        2021-03-19
-channel count:   2
-feature set:     0

2021-02-19 12:02:46:702863 [INFO]   Create Utterance Manager
2021-02-19 12:02:46:702906 [NOTICE] Populate files from /opt/unimrcp/var/ pattern [umsazuresr-*.wav] max-count [100] max-age [60 min] purge-existing [0]
2021-02-19 12:02:46:702915 [INFO]   Create RDR Manager
2021-02-19 12:02:46:702955 [NOTICE] Populate files from /opt/unimrcp/var/ pattern [umsazuresr-*.json] max-count [100] max-age [60 min] purge-existing [0]
2021-02-19 12:02:46:702956 [NOTICE] AzureSR Usage: 0/0/2
2021-02-19 12:02:46:703222 [INFO]   Start HTTP client event loop
2021-02-19 12:02:46:703241 [INFO]   Initiate HTTP auth <AzureSR> [https://centralindia.api.cognitive.microsoft.com/sts/v1.0/issueToken]
2021-02-19 12:02:46:703249 [NOTICE] MRCP Server Started
2021-02-19 12:02:46:771193 [INFO]   Set HTTP request timer 30 sec for <AzureSR>
2021-02-19 12:02:46:871447 [INFO]   Received HTTP response [200 OK] in 168 msec for <AzureSR> [https://centralindia.api.cognitive.microsoft.com/sts/v1.0/issueToken]
2021-02-19 12:02:46:871480 [INFO]   Access token retrieved [776 bytes] <AzureSR>
2021-02-19 12:02:46:871484 [INFO]   Clear HTTP timer <AzureSR>
2021-02-19 12:02:46:871488 [INFO]   Close HTTP connection <AzureSR>
2021-02-19 12:02:46:871493 [INFO]   Set revalidation timer [480 sec] for <AzureSR>
2021-02-19 12:03:28:666293 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2021-02-19 12:03:28:666330 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2021-02-19 12:03:28:666341 [NOTICE] SIP Call State  [received]
2021-02-19 12:03:28:666369 [INFO]   Create Session 0x7f9660001cb8 <new> [uni2]
2021-02-19 12:03:28:666384 [INFO]   Remote SDP 0x7f9660001cb8 <new>
v=0
o=FreeSWITCH 6909019815214770101 1963679284402576501 IN IP4 35.154.97.204
s=-
c=IN IP4 35.154.97.204
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4000 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=mid:1

2021-02-19 12:03:28:666539 [NOTICE] Add Session <bcb7e8ce86be428e>
2021-02-19 12:03:28:666562 [INFO]   Receive Offer 0x7f9660001cb8 <bcb7e8ce86be428e> [c:1 a:1 v:0]
2021-02-19 12:03:28:666574 [INFO]   Found MRCP Engine [Azure-SR-1] for Resource [speechrecog] 0x7f9660001cb8 <bcb7e8ce86be428e>
2021-02-19 12:03:28:666640 [INFO]   Add Pending Control Channel <bcb7e8ce86be428e@speechrecog> [1]
2021-02-19 12:03:28:672682 [INFO]   Enable RTP Session 10.2.2.7:5000
2021-02-19 12:03:28:672707 [INFO]   Open RTP Receiver 10.2.2.7:5000 <- 35.154.97.204:4000 playout [50 ms] bounds [0 - 600 ms] adaptive [1] skew detection [1]
2021-02-19 12:03:28:672713 [INFO]   Media Path 0x7f9660001cb8 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2021-02-19 12:03:28:672847 [INFO]   Open <bcb7e8ce86be428e@azuresr>
2021-02-19 12:03:28:672874 [NOTICE] AzureSR Usage: 1/1/2
2021-02-19 12:03:28:672900 [INFO]   Send Answer 0x7f9660001cb8 <bcb7e8ce86be428e> [c:1 a:1 v:0] Status OK
2021-02-19 12:03:28:672930 [INFO]   Local SDP 0x7f9660001cb8 <bcb7e8ce86be428e>
v=0
o=UniMRCPServer 0 0 IN IP4 10.2.2.7
s=-
c=IN IP4 10.2.2.7
t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:bcb7e8ce86be428e@speechrecog
a=cmid:1
m=audio 5000 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=recvonly
a=mid:1

2021-02-19 12:03:28:673328 [INFO]   Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2021-02-19 12:03:28:673350 [NOTICE] SIP Call State 0x7f9660001cb8 [completed]
2021-02-19 12:04:00:672952 [INFO]   Receive SIP Event [nua_i_error] Status 408 ACK Timeout [SIP-Agent-1]
2021-02-19 12:04:00:672993 [INFO]   Receive SIP Event [nua_i_state] Status 0 ACK Timeout [SIP-Agent-1]
2021-02-19 12:04:00:673001 [NOTICE] SIP Call State 0x7f9660001cb8 [terminating]
2021-02-19 12:04:00:677503 [INFO]   Receive SIP Event [nua_r_bye] Status 200 OK [SIP-Agent-1]
2021-02-19 12:04:00:677529 [INFO]   Receive SIP Event [nua_i_state] Status 200 to BYE [SIP-Agent-1]
2021-02-19 12:04:00:677535 [NOTICE] SIP Call State 0x7f9660001cb8 [terminated]
2021-02-19 12:04:00:677551 [INFO]   Receive SIP Event [nua_i_terminated] Status 200 to BYE [SIP-Agent-1]
2021-02-19 12:04:00:677576 [INFO]   Deactivate Session 0x7f9660001cb8 <bcb7e8ce86be428e>
2021-02-19 12:04:00:677592 [INFO]   Terminate Session 0x7f9660001cb8 <bcb7e8ce86be428e>
2021-02-19 12:04:00:677755 [INFO]   Close <bcb7e8ce86be428e@azuresr>
2021-02-19 12:04:00:677789 [NOTICE] AzureSR Usage: 0/1/2
2021-02-19 12:04:00:677759 [INFO]   Remove Pending Control Channel <bcb7e8ce86be428e@speechrecog> [0]
2021-02-19 12:04:00:682585 [INFO]   Close RTP Receiver 10.2.2.7:5000 <- 35.154.97.204:4000 [r:0 l:0 j:0 p:50 d:0 i:0]
2021-02-19 12:04:00:682606 [INFO]   Remove RTP Session 10.2.2.7:5000
2021-02-19 12:04:00:682659 [NOTICE] Remove Session <bcb7e8ce86be428e>
2021-02-19 12:04:00:682672 [INFO]   Session Terminated 0x7f9660001cb8 <bcb7e8ce86be428e>
2021-02-19 12:04:00:682697 [NOTICE] Destroy Session <bcb7e8ce86be428e>
2021-02-19 12:10:46:901377 [INFO]   Revalidate access token for HTTP auth <AzureSR>


Thanks and Regards
Vaibhav

Arsen Chaloyan

unread,
Feb 24, 2021, 5:23:22 PM2/24/21
to UniMRCP
While we have discussed this issue with Vaibhav offline, I'd rather add a comment here for other users possibly experiencing the same problem.

> 2021-02-19 12:04:00:672952 [INFO]   Receive SIP Event [nua_i_error] Status 408 ACK Timeout [SIP-Agent-1]

The statement above indicates that no SIP ACK was received in a timely manner, which obviously happened because the client and the server reside in different networks. As a result, the IP address advertised by the server in the SDP answer is not reachable by the client.

While it is possible to configure the network and the client/server to be used in such a deployment, I'd recommend to get started from a much simpler setup where both the client and the server reside on the same LAN.

--
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/95120276-4c9d-4040-a89b-2fffacb274b8n%40googlegroups.com.


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

yanyi

unread,
Apr 10, 2024, 8:43:55 AMApr 10
to UniMRCP
I encountered the same problem
> 2021-02-19 12:04:00:672952 [INFO]   Receive SIP Event [nua_i_error] Status 408 ACK Timeout [SIP-Agent-1]
The unimrcp service is deployed in a container and the client is on another server. How can we solve the communication problem? Looking forward to your reply. Thank you

version: '2.2'

services:
  robot_unimrcp:
    image: unimrcp
    command: ./unimrcpserver -o 2
    stdin_open: true
    tty: true
    container_name: robot_unimrcp
    ports:
      - "8060:8060"
      - "1554:1554"
      - "1544:1544"
      - "8060:8060/udp"
      - "5050-5060:5050-5060/udp"


_______________________________________________________________________________________________

2024-04-10 18:26:03:032847 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2024-04-10 18:26:03:032900 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2024-04-10 18:26:03:032912 [NOTICE] SIP Call State  [received]
2024-04-10 18:26:03:032939 [INFO]   Create Session 0x7f7a88001cd8 <new> [uni2]
2024-04-10 18:26:03:032950 [INFO]   Remote SDP 0x7f7a88001cd8 <new>
v=0
o=UniMRCPClient 5843505662903709283 6820315391071798549 IN IP4 10.0.1.210
s=-
c=IN IP4 10.0.1.210

t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4000 RTP/AVP 0 8 9 96 101

a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/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

2024-04-10 18:26:03:033087 [NOTICE] Add Session <bb6b7bb0f72411ee>
2024-04-10 18:26:03:033116 [INFO]   Receive Offer 0x7f7a88001cd8 <bb6b7bb0f72411ee> [c:1 a:1 v:0]
2024-04-10 18:26:03:033130 [INFO]   Found MRCP Engine [Hbgj-Recog-1] for Resource [speechrecog] 0x7f7a88001cd8 <bb6b7bb0f72411ee>
2024-04-10 18:26:03:033222 [INFO]   Add Pending Control Channel <bb6b7bb0f72411ee@speechrecog> [1]
2024-04-10 18:26:03:036543 [INFO]   Enable RTP Session 172.22.0.2:5050
2024-04-10 18:26:03:036575 [INFO]   Open RTP Receiver 172.22.0.2:5050 <- 10.0.1.210:4000 playout [50 ms] bounds [0 - 600 ms] adaptive [1] skew detection [1]
2024-04-10 18:26:03:036583 [INFO]   Media Path 0x7f7a88001cd8 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2024-04-10 18:26:03:036702 [INFO]   Send Answer 0x7f7a88001cd8 <bb6b7bb0f72411ee> [c:1 a:1 v:0] Status OK
2024-04-10 18:26:03:036731 [INFO]   Local SDP 0x7f7a88001cd8 <bb6b7bb0f72411ee>
v=0
o=UniMRCPServer 0 0 IN IP4 172.22.0.2
s=-
c=IN IP4 172.22.0.2

t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:bb6b7bb0f72411ee@speechrecog
a=cmid:1
m=audio 5050 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=recvonly
a=ptime:20
a=mid:1

2024-04-10 18:26:03:037094 [INFO]   Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2024-04-10 18:26:03:037105 [NOTICE] SIP Call State 0x7f7a88001cd8 [completed]
2024-04-10 18:26:35:037101 [INFO]   Receive SIP Event [nua_i_error] Status 408 ACK Timeout [SIP-Agent-1]
2024-04-10 18:26:35:037286 [INFO]   Receive SIP Event [nua_i_state] Status 0 ACK Timeout [SIP-Agent-1]
2024-04-10 18:26:35:037296 [NOTICE] SIP Call State 0x7f7a88001cd8 [terminating]
2024-04-10 18:26:35:037664 [INFO]   Receive SIP Event [nua_r_bye] Status 200 OK [SIP-Agent-1]
2024-04-10 18:26:35:037673 [INFO]   Receive SIP Event [nua_i_state] Status 200 to BYE [SIP-Agent-1]
2024-04-10 18:26:35:037678 [NOTICE] SIP Call State 0x7f7a88001cd8 [terminated]
2024-04-10 18:26:35:037698 [INFO]   Receive SIP Event [nua_i_terminated] Status 200 to BYE [SIP-Agent-1]
2024-04-10 18:26:35:037715 [INFO]   Deactivate Session 0x7f7a88001cd8 <bb6b7bb0f72411ee>
2024-04-10 18:26:35:037744 [INFO]   Terminate Session 0x7f7a88001cd8 <bb6b7bb0f72411ee>
2024-04-10 18:26:35:037792 [INFO]   Remove Pending Control Channel <bb6b7bb0f72411ee@speechrecog> [0]
2024-04-10 18:26:35:046424 [INFO]   Close RTP Receiver 172.22.0.2:5050 <- 10.0.1.210:4000 [r:0 l:0 j:0 p:50 d:0 i:0]
2024-04-10 18:26:35:046452 [INFO]   Remove RTP Session 172.22.0.2:5050
2024-04-10 18:26:35:046521 [NOTICE] Remove Session <bb6b7bb0f72411ee>
2024-04-10 18:26:35:046535 [INFO]   Session Terminated 0x7f7a88001cd8 <bb6b7bb0f72411ee>
2024-04-10 18:26:35:046564 [NOTICE] Destroy Session <bb6b7bb0f72411ee>

_______________________________________________________________________________________________

>2024-04-10 18:26:03:598630 [NOTICE] Run Demo Application Scenario [recog]
2024-04-10 18:26:03:598696 [NOTICE] Create MRCP Handle 0x7f9950000a88 [uni2]
2024-04-10 18:26:03:598720 [INFO]   Create Channel 0x7f9950000a88 <new>
2024-04-10 18:26:03:598751 [INFO]   Receive App Request 0x7f9950000a88 <new> [2]
2024-04-10 18:26:03:598809 [INFO]   Add MRCP Handle 0x7f9950000a88 <new>
2024-04-10 18:26:03:598847 [NOTICE] Add Control Channel 0x7f9950000a88 <new@speechrecog>
2024-04-10 18:26:03:599473 [INFO]   Send Offer 0x7f9950000a88 <new> [c:1 a:1 v:0] to 10.0.1.99:8060
2024-04-10 18:26:03:599499 [INFO]   Local SDP 0x7f9950000a88 <new>
v=0
o=UniMRCPClient 0 0 IN IP4 10.0.1.210
s=-
c=IN IP4 10.0.1.210

t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4000 RTP/AVP 0 8 9 96 101

a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/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

2024-04-10 18:26:03:600136 [INFO]   Receive SIP Event [nua_i_state] Status 0 INVITE sent [SIP-Agent-1]
2024-04-10 18:26:03:600153 [NOTICE] SIP Call State 0x7f9950000a88 [calling]
2024-04-10 18:26:03:605224 [INFO]   Receive SIP Event [nua_r_invite] Status 200 OK [SIP-Agent-1]
2024-04-10 18:26:03:605311 [INFO]   Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2024-04-10 18:26:03:605324 [NOTICE] SIP Call State 0x7f9950000a88 [ready]
2024-04-10 18:26:03:605330 [INFO]   Remote SDP 0x7f9950000a88 <new>
v=0
o=UniMRCPServer 3863867942467067635 1892147632185709027 IN IP4 172.22.0.2
s=-
c=IN IP4 172.22.0.2

t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:bb6b7bb0f72411ee@speechrecog
a=cmid:1
m=audio 5050 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=recvonly
a=ptime:20
a=mid:1

2024-04-10 18:26:03:605391 [INFO]   Receive SIP Event [nua_i_active] Status 200 Call active [SIP-Agent-1]
2024-04-10 18:26:03:605400 [INFO]   Receive Answer 0x7f9950000a88 <new> [c:1 a:1 v:0] Status 200
2024-04-10 18:26:03:609470 [INFO]   Enable RTP Session 10.0.1.210:4000
2024-04-10 18:26:03:609493 [INFO]   Open RTP Transmitter 10.0.1.210:4000 -> 172.22.0.2:5050
2024-04-10 18:26:03:609499 [INFO]   Media Path 0x7f9950000a88 Source->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Encoder->[PCMU/8000/1]->Sink
2024-04-10 18:26:35:606609 [INFO]   Receive SIP Event [nua_i_bye] Status 200 Session Terminated [SIP-Agent-1]
2024-04-10 18:26:35:606632 [INFO]   Receive SIP Event [nua_i_state] Status 200 Session Terminated [SIP-Agent-1]
2024-04-10 18:26:35:606640 [NOTICE] SIP Call State 0x7f9950000a88 [terminated]
2024-04-10 18:27:06:605040 [WARN]   Failed to Establish TCP/MRCPv2 Connection
2024-04-10 18:27:06:605090 [INFO]   Raise App Response 0x7f9950000a88 <bb6b7bb0f72411ee> [2] FAILURE [2]
2024-04-10 18:27:06:605151 [INFO]   Receive App Request 0x7f9950000a88 <bb6b7bb0f72411ee> [1]
2024-04-10 18:27:06:605159 [INFO]   Terminate Session 0x7f9950000a88 <bb6b7bb0f72411ee>
2024-04-10 18:27:06:605187 [INFO]   Session Terminated 0x7f9950000a88 <bb6b7bb0f72411ee>
2024-04-10 18:27:06:609363 [INFO]   Close RTP Transmitter 10.0.1.210:4000 -> 172.22.0.2:5050 [s:0 o:0]
2024-04-10 18:27:06:609380 [INFO]   Remove RTP Session 10.0.1.210:4000
2024-04-10 18:27:06:609417 [INFO]   Remove MRCP Handle 0x7f9950000a88 <bb6b7bb0f72411ee>
2024-04-10 18:27:06:609427 [INFO]   Raise App Response 0x7f9950000a88 <bb6b7bb0f72411ee> [1] FAILURE [2]
2024-04-10 18:27:06:609453 [NOTICE] Destroy MRCP Handle 0x7f9950000a88
Reply all
Reply to author
Forward
0 new messages