Infrequent Disconnection

42 views

Skip to first unread message

Matthias B.

unread,

Jan 30, 2023, 12:40:44 PM1/30/23

to UniMRCP

Hi all,

we have infrequent disconnections during the call of SynthAndRecog() from our asterisk. I have extracted one example from the protocol. The reason for this misbehavior is totally unclear to us. Maybe someone of you had a similar issue and is able to help.

The issue occurs imemediately before the time mark 11.08:18. There seems to be a timeout of 11 seconds, but no error message. After that timeout the connection is terminated.

Here the log:

2023-01-26 11:08:02:949577 [INFO] Create Session 0x7f3678001ae8 <new> [uni2]
2023-01-26 11:08:02:949582 [INFO] Remote SDP 0x7f3678001ae8 <new>
v=0
o=Asterisk 735541253556357878 1087371658113554310 IN IP4 192.0.11.69
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 28000 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

2023-01-26 11:08:02:949648 [NOTICE] Add Session <6818016510c84d68>
2023-01-26 11:08:02:949663 [INFO] Receive Offer 0x7f3678001ae8 <6818016510c84d68> [c:1 a:1 v:0]
2023-01-26 11:08:02:949670 [INFO] Found MRCP Engine [GSR-1] for Resource [speechrecog] 0x7f3678001ae8 <6818016510c84d68>
2023-01-26 11:08:02:949709 [INFO] Add Pending Control Channel <6818016510c84d68@speechrecog> [1]
2023-01-26 11:08:02:959508 [INFO] Enable RTP Session 127.0.0.1:5550
2023-01-26 11:08:02:959525 [INFO] Open RTP Receiver 127.0.0.1:5550 <- 127.0.0.1:28000 playout [50 ms] bounds [0 - 600 ms] adaptive [1] skew detection [1]
2023-01-26 11:08:02:959530 [INFO] Media Path 0x7f3678001ae8 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
2023-01-26 11:08:02:959613 [INFO] Open <6818016510c84d68@gsr>
2023-01-26 11:08:02:959650 [NOTICE] GSR Usage: 1/2/5
2023-01-26 11:08:02:959664 [DEBUG] Update usage /opt/unimrcp/var/status/umsgsr-usage.status
2023-01-26 11:08:02:959802 [DEBUG] Dump channels /opt/unimrcp/var/status/umsgsr-channels.status
2023-01-26 11:08:02:959893 [INFO] Send Answer 0x7f3678001ae8 <6818016510c84d68> [c:1 a:1 v:0] Status OK
2023-01-26 11:08:02:959930 [INFO] Local SDP 0x7f3678001ae8 <6818016510c84d68>
v=0
o=UniMRCPServer 0 0 IN IP4 127.0.0.1
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:6818016510c84d68@speechrecog
a=cmid:1
m=audio 5550 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

2023-01-26 11:08:02:960401 [INFO] Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2023-01-26 11:08:02:960408 [NOTICE] SIP Call State 0x7f3678001ae8 [completed]
2023-01-26 11:08:02:960612 [INFO] Receive SIP Event [nua_i_ack] Status 200 OK [SIP-Agent-1]
2023-01-26 11:08:02:960631 [INFO] Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2023-01-26 11:08:02:960637 [NOTICE] SIP Call State 0x7f3678001ae8 [ready]
2023-01-26 11:08:02:960644 [INFO] Receive SIP Event [nua_i_active] Status 200 Call active [SIP-Agent-1]
2023-01-26 11:08:02:960813 [NOTICE] Accepted TCP/MRCPv2 Connection 127.0.0.1:1544 <-> 127.0.0.1:43908
2023-01-26 11:08:02:969032 [INFO] Receive MRCPv2 Data 127.0.0.1:1544 <-> 127.0.0.1:43908 [448 bytes]
MRCP/2.0 448 RECOGNIZE 1
Channel-Identifier: 6818016510c84d68@speechrecog
Content-Type: text/uri-list
Cancel-If-Queue: false
Start-Input-Timers: false
Dtmf-Term-Char: #
No-Input-Timeout: 15000
Sensitivity-Level: 0.74
Speech-Complete-Timeout: 1000
Recognition-Timeout: 10000
Speech-Language: de-DE
Speech-Incomplete-Timeout: 15000
Content-Length: 84

builtin:speech/transcribe?alternatives-below-threshold=false;speech-start-timeout=10
2023-01-26 11:08:02:969059 [INFO] Assign Control Channel <6818016510c84d68@speechrecog> to Connection 127.0.0.1:1544 <-> 127.0.0.1:43908 [0] -> [1]
2023-01-26 11:08:02:969075 [INFO] Process RECOGNIZE Request <6818016510c84d68@speechrecog> [1]
2023-01-26 11:08:02:969172 [DEBUG] Add Speech Grammar [transcribe] <6818016510c84d68@gsr>
2023-01-26 11:08:02:969199 [INFO] Init Speech Detector: frame-size=160, max-frame-count=1507, output-frame-count=5, vad-mode=2, noinput-timeout=15000 ms, input-timeout=10000 ms, start-timeout=10 ms, complete-timeout=1000 ms, incomplete-timeout=15000 ms, leading-silence=25 ms, trailing-silence=100 ms, interim-results=1, start-of-input=external <6818016510c84d68>
2023-01-26 11:08:02:969219 [INFO] Create gRPC Channel [eu-speech.googleapis.com] <6818016510c84d68@gsr>
2023-01-26 11:08:02:969307 [DEBUG] Create gRPC Speech Stub [v1] <6818016510c84d68@gsr>
2023-01-26 11:08:02:969326 [DEBUG] Init Streaming Config: encoding=1, sampling-rate=8000, language=de-DE, max-alternatives=1, interim-results=1, single-utterance=1 profanity-filter=0, word-time-offsets=0, word-confidence=0, auto-punctuation=0, spoken-punctuation=0, spoken-emojis=0, use-enhanced=1 <6818016510c84d68@gsr>
2023-01-26 11:08:02:969337 [INFO] Set Model [phone_call] <6818016510c84d68@gsr>
2023-01-26 11:08:02:969341 [INFO] gRPC Streaming Recognize <6818016510c84d68@gsr>
2023-01-26 11:08:02:969689 [INFO] Process RECOGNIZE Response <6818016510c84d68@speechrecog> [1]
2023-01-26 11:08:02:969704 [INFO] State Transition IDLE -> RECOGNIZING <6818016510c84d68@speechrecog>
2023-01-26 11:08:02:969727 [INFO] Send MRCPv2 Data 127.0.0.1:1544 <-> 127.0.0.1:43908 [83 bytes]
MRCP/2.0 83 1 200 IN-PROGRESS
Channel-Identifier: 6818016510c84d68@speechrecog

2023-01-26 11:08:02:979575 [INFO] Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2023-01-26 11:08:02:979591 [INFO] Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2023-01-26 11:08:02:979596 [NOTICE] SIP Call State [received]
2023-01-26 11:08:02:979606 [INFO] Create Session 0x7f3678004618 <new> [uni2]
2023-01-26 11:08:02:979610 [INFO] Remote SDP 0x7f3678004618 <new>
v=0
o=Asterisk 4380076904163393533 7451167744214452901 IN IP4 192.0.11.69
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechsynth
a=cmid:1
m=audio 28002 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

2023-01-26 11:08:02:979672 [NOTICE] Add Session <a0986af520064013>
2023-01-26 11:08:02:979685 [INFO] Receive Offer 0x7f3678004618 <a0986af520064013> [c:1 a:1 v:0]
2023-01-26 11:08:02:979691 [INFO] Found MRCP Engine [GSS-1] for Resource [speechsynth] 0x7f3678004618 <a0986af520064013>
2023-01-26 11:08:02:979767 [INFO] Add Pending Control Channel <a0986af520064013@speechsynth> [1]
2023-01-26 11:08:02:989533 [INFO] Enable RTP Session 127.0.0.1:5552
2023-01-26 11:08:02:989548 [INFO] Open RTP Transmitter 127.0.0.1:5552 -> 127.0.0.1:28002
2023-01-26 11:08:02:989552 [INFO] Media Path 0x7f3678004618 Source->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Encoder->[PCMU/8000/1]->Sink
2023-01-26 11:08:02:989583 [INFO] Open <a0986af520064013@gss>
2023-01-26 11:08:02:989597 [NOTICE] GSS Usage: 1/3/5
2023-01-26 11:08:02:989772 [INFO] Send Answer 0x7f3678004618 <a0986af520064013> [c:1 a:1 v:0] Status OK
2023-01-26 11:08:02:989808 [INFO] Local SDP 0x7f3678004618 <a0986af520064013>
v=0
o=UniMRCPServer 0 0 IN IP4 127.0.0.1
s=-
c=IN IP4 127.0.0.1
t=0 0
m=application 1544 TCP/MRCPv2 1
a=setup:passive
a=connection:new
a=channel:a0986af520064013@speechsynth
a=cmid:1
m=audio 5552 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2023-01-26 11:08:02:990217 [INFO] Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2023-01-26 11:08:02:990234 [NOTICE] SIP Call State 0x7f3678004618 [completed]
2023-01-26 11:08:02:990415 [INFO] Receive SIP Event [nua_i_ack] Status 200 OK [SIP-Agent-1]
2023-01-26 11:08:02:990427 [INFO] Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
2023-01-26 11:08:02:990432 [NOTICE] SIP Call State 0x7f3678004618 [ready]
2023-01-26 11:08:02:990436 [INFO] Receive SIP Event [nua_i_active] Status 200 Call active [SIP-Agent-1]
2023-01-26 11:08:02:990628 [NOTICE] Accepted TCP/MRCPv2 Connection 127.0.0.1:1544 <-> 127.0.0.1:43910
2023-01-26 11:08:02:999168 [INFO] Receive MRCPv2 Data 127.0.0.1:1544 <-> 127.0.0.1:43910 [265 bytes]
MRCP/2.0 265 SPEAK 1
Channel-Identifier: a0986af520064013@speechsynth
Content-Type: application/ssml+xml
Voice-Name: de-DE-Wavenet-B
Speech-Language: de-DE
Content-Length: 82

<speak>Möchten sie ihr Taxi zu Provianthofstraße 3 für Villa bestellen?</speak>
2023-01-26 11:08:02:999227 [INFO] Assign Control Channel <a0986af520064013@speechsynth> to Connection 127.0.0.1:1544 <-> 127.0.0.1:43910 [0] -> [1]
2023-01-26 11:08:02:999256 [INFO] Process SPEAK Request <a0986af520064013@speechsynth> [1]
2023-01-26 11:08:02:999293 [INFO] Create gRPC Channel [texttospeech.googleapis.com:443] <a0986af520064013@gss>
2023-01-26 11:08:02:999366 [INFO] Set Voice Name [de-DE-Wavenet-B] <a0986af520064013@gss>
2023-01-26 11:08:02:999492 [INFO] Start Async Synth: encoding=1, sampling-rate=8000, language=de-DE <a0986af520064013@gss>
{"input":{"ssml":"\u003cspeak\u003eMöchten sie ihr Taxi zu Provianthofstraße 3 für Villa bestellen?\u003c/speak\u003e"},"voice":{"languageCode":"de-DE","name":"de-DE-Wavenet-B"},"audioConfig":{"audioEncoding":"LINEAR16","sampleRateHertz":8000}}
2023-01-26 11:08:03:140660 [DEBUG] Process gRPC Event: name [create stream] status [1] <6818016510c84d68@gsr>
2023-01-26 11:08:18:345215 [INFO] Process SPEAK Response <a0986af520064013@speechsynth> [1]
2023-01-26 11:08:18:345235 [NOTICE] State Transition IDLE -> SPEAKING <a0986af520064013@speechsynth>
2023-01-26 11:08:18:345325 [INFO] Send MRCPv2 Data 127.0.0.1:1544 <-> 127.0.0.1:43910 [83 bytes]
MRCP/2.0 83 1 200 IN-PROGRESS
Channel-Identifier: a0986af520064013@speechsynth

2023-01-26 11:08:18:345938 [INFO] TCP/MRCPv2 Peer Disconnected 127.0.0.1:1544 <-> 127.0.0.1:43910
2023-01-26 11:08:18:346422 [INFO] Receive SIP Event [nua_i_bye] Status 200 Session Terminated [SIP-Agent-1]
2023-01-26 11:08:18:346440 [INFO] Receive SIP Event [nua_i_state] Status 200 Session Terminated [SIP-Agent-1]
2023-01-26 11:08:18:346456 [NOTICE] SIP Call State 0x7f3678004618 [terminated]
2023-01-26 11:08:18:346466 [INFO] Receive SIP Event [nua_i_terminated] Status 200 Session Terminated [SIP-Agent-1]
2023-01-26 11:08:18:346471 [INFO] Deactivate Session 0x7f3678004618 <a0986af520064013>
2023-01-26 11:08:18:346486 [INFO] Create and Process STOP Request <a0986af520064013@speechsynth> [2]
2023-01-26 11:08:18:349257 [INFO] TCP/MRCPv2 Peer Disconnected 127.0.0.1:1544 <-> 127.0.0.1:43908
2023-01-26 11:08:18:349478 [INFO] Receive SIP Event [nua_i_bye] Status 200 Session Terminated [SIP-Agent-1]
2023-01-26 11:08:18:349494 [INFO] Receive SIP Event [nua_i_state] Status 200 Session Terminated [SIP-Agent-1]
2023-01-26 11:08:18:349500 [NOTICE] SIP Call State 0x7f3678001ae8 [terminated]
2023-01-26 11:08:18:349509 [INFO] Receive SIP Event [nua_i_terminated] Status 200 Session Terminated [SIP-Agent-1]
2023-01-26 11:08:18:349515 [INFO] Deactivate Session 0x7f3678001ae8 <6818016510c84d68>
2023-01-26 11:08:18:349508 [NOTICE] Stop Complete <a0986af520064013@gss>
2023-01-26 11:08:18:349535 [INFO] Create and Process STOP Request <6818016510c84d68@speechrecog> [2]
2023-01-26 11:08:18:349607 [INFO] Process DEACTIVATE Response <a0986af520064013@speechsynth> [2]
2023-01-26 11:08:18:349613 [NOTICE] State Transition SPEAKING -> IDLE <a0986af520064013@speechsynth>
2023-01-26 11:08:18:349616 [INFO] Terminate Session 0x7f3678004618 <a0986af520064013>
2023-01-26 11:08:18:349620 [DEBUG] Stop Input <6818016510c84d68@gsr>
2023-01-26 11:08:18:349634 [INFO] Remove Control Channel <a0986af520064013@speechsynth> [0]
2023-01-26 11:08:18:349633 [INFO] Close <a0986af520064013@gss>
2023-01-26 11:08:18:349668 [NOTICE] GSS Usage: 0/3/5
2023-01-26 11:08:18:359528 [INFO] Close RTP Transmitter 127.0.0.1:5552 -> 127.0.0.1:28002 [s:0 o:0]
2023-01-26 11:08:18:359543 [INFO] Remove RTP Session 127.0.0.1:5552
2023-01-26 11:08:18:359568 [NOTICE] Destroy TCP/MRCPv2 Connection 127.0.0.1:1544 <-> 127.0.0.1:43910
2023-01-26 11:08:18:359629 [INFO] Input Complete [stopped] size=0 bytes, dur=0 ms <6818016510c84d68@gsr>
2023-01-26 11:08:18:360765 [NOTICE] Remove Session <a0986af520064013>
2023-01-26 11:08:18:360777 [INFO] Session Terminated 0x7f3678004618 <a0986af520064013>
2023-01-26 11:08:18:360792 [NOTICE] Destroy Session <a0986af520064013>
2023-01-26 11:08:18:360802 [INFO] Process DEACTIVATE Response <6818016510c84d68@speechrecog> [2]
2023-01-26 11:08:18:360807 [INFO] State Transition RECOGNIZING -> IDLE <6818016510c84d68@speechrecog>
2023-01-26 11:08:18:360810 [INFO] Terminate Session 0x7f3678001ae8 <6818016510c84d68>
2023-01-26 11:08:18:360832 [INFO] Remove Control Channel <6818016510c84d68@speechrecog> [0]
2023-01-26 11:08:18:360878 [INFO] Close <6818016510c84d68@gsr>
2023-01-26 11:08:18:360901 [DEBUG] Send Close Response <6818016510c84d68@gsr>
2023-01-26 11:08:18:360907 [NOTICE] GSR Usage: 0/2/5
2023-01-26 11:08:18:360918 [DEBUG] Update usage /opt/unimrcp/var/status/umsgsr-usage.status
2023-01-26 11:08:18:361040 [DEBUG] Dump channels /opt/unimrcp/var/status/umsgsr-channels.status
2023-01-26 11:08:18:369531 [INFO] Close RTP Receiver 127.0.0.1:5550 <- 127.0.0.1:28000 [r:0 l:0 j:0 p:50 d:0 i:0]
2023-01-26 11:08:18:369548 [INFO] Remove RTP Session 127.0.0.1:5550
2023-01-26 11:08:18:369572 [NOTICE] Destroy TCP/MRCPv2 Connection 127.0.0.1:1544 <-> 127.0.0.1:43908
2023-01-26 11:08:18:370730 [NOTICE] Remove Session <6818016510c84d68>
2023-01-26 11:08:18:370740 [INFO] Session Terminated 0x7f3678001ae8 <6818016510c84d68>
2023-01-26 11:08:18:370754 [NOTICE] Destroy Session <6818016510c84d68>

Best regards

Matthias Bremer

Arsen Chaloyan

unread,

Feb 21, 2023, 8:12:33 PM2/21/23

to uni...@googlegroups.com

Hi Mattias,

I see two different issues here. The main problem is the response to the following speech synthesis request arrived very late.

2023-01-26 11:08:02:999492 [INFO] Start Async Synth: encoding=1, sampling-rate=8000, language=de-DE <a0986af520064013@gss>
{"input":{"ssml":"\u003cspeak\u003eMöchten sie ihr Taxi zu Provianthofstraße 3 für Villa bestellen?\u003c/speak\u003e"},"voice":{"languageCode":"de-DE","name":"de-DE-Wavenet-B"},"audioConfig":{"audioEncoding":"LINEAR16","sampleRateHertz":8000}}

2023-01-26 11:08:18:345215 [INFO] Process SPEAK Response <a0986af520064013@speechsynth> [1]

You would need to enable the gRPC library logs to identify the cause. Sporadic delays like that one could be caused by the DNS server used in your network. Alternatively, you may also check your Google account console for any unusual response times or errors happening about that time.

The question is why the Asterisk (MRCP client) disconnected after the late response was received. It could be an implementation-specific timeout. If you have the Asterisk logs and or application used on Asterisk, that may help understand why the connection is closed. Anyway, this is just a side effect. You should focus on finding out the root cause of the delay in responses to TTS requests placed to Google.

--
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/d05e7d74-0d04-4ea4-ae25-73e7233ebf2bn%40googlegroups.com.