Recognition is suspended 15 seconds after the start of work
rybushkindmitry opened this issue · 18 comments
Recognition is suspended 15 seconds after the start of work.
same => n,SpeechBackground(Speech,10)
The timeout option does not affect performance.
I've tried setting to 5, 10, 40 and no value.
After the end of the conversation on the phone, the channel on the asterisk remains in a frozen state.
localhost*CLI> core show channels verbose
Channel Context Extension Prio State Application Data CallerID Duration Accountcode PeerAccount BridgeID
PJSIP/102-00000000 internal 1 10 Up SpeechBackgr Speech-2 102 00:12:58
PJSIP/102-00000001 internal 1 10 Up SpeechBackgr Speech-2,10 102 00:10:37
PJSIP/102-00000002 internal 1 10 Up SpeechBackgr Speech-2,10 102 00:04:41
3 active channels
3 active calls
3 calls processed
Most likely you don't have latest asterisk patches with ping/pong handling
I have updated the asterisk to the latest version. I checked that this patch is in the source code. The problem was not solved.
Hi, it is true, I have the same problem. After 15 seconds sometimes is like 30 seconds, rtp stops flowing, and the channel get stuck in asterisk ( you can validate it with core show channels verbose).
Something I verify is that when I hang the channel in the softphone I'm using, the sip messages flow normally, asterisk receive the BYE and send the ACK, but the channel is up and stuck.
I'm using pjsip by the way...Can someone solve this issue...
btw. If using speechbackground during the first 15 seconds the app works very well.
I tried 16.13.0 and 17.7.0. With both versions the result is the same....
Ok, what is dumped on console log when channel hangs?
Well, actually nothing special. Using the default app, it just suddenly stops showing some info. It starts like this:
Executing [123@profile-6:1] NoOp("PJSIP/user1-00000003", "") in new stack
-- Executing [123@profile-6:2] Answer("PJSIP/user1-00000003", "") in new stack
-- Executing [123@profile-6:3] SpeechCreate("PJSIP/user1-00000003", "") in new stack
[Oct 13 08:48:44] NOTICE[28196][C-00000004]: res_speech_vosk.c:83 vosk_recog_create: (vosk) Create speech resource ws://127.0.0.1:2700
[Oct 13 08:48:44] NOTICE[28196][C-00000004]: res_speech_vosk.c:91 vosk_recog_create: (vosk) Created speech resource result 0
-- Executing [123@profile-6:4] TryExec("PJSIP/user1-00000003", "SpeechBackground(demo-congrats)") in new stack
[Oct 13 08:48:44] NOTICE[28196][C-00000004]: res_speech_vosk.c:201 vosk_recog_start: (vosk) Start recognition
[Oct 13 08:48:44] NOTICE[28196][C-00000004]: res_speech_vosk.c:166 vosk_recog_write: (vosk) Got result: '{
"partial" : ""
}'
[Oct 13 08:48:44] NOTICE[28196][C-00000004]: res_speech_vosk.c:166 vosk_recog_write: (vosk) Got result: '{
"partial" : ""
}'
[Oct 13 08:48:44] NOTICE[28196][C-00000004]: res_speech_vosk.c:166 vosk_recog_write: (vosk) Got result: '{
"partial" : ""
}'
[Oct 13 08:48:45] NOTICE[28196][C-00000004]: res_speech_vosk.c:166 vosk_recog_write: (vosk) Got result: '{
"partial" : ""
}'
[Oct 13 08:48:45] NOTICE[28196][C-00000004]: res_speech_vosk.c:166 vosk_recog_write: (vosk) Got result: '{
"partial" : ""
}'
And after many lines of the same notice, it simply stops showing no more info, nor a different notice or warning or error, it justs stops, and in the phone the call continue, when I hang up the phone in asterisk the channel stay:
asterisk*CLI> core show channels verbose
Channel Context Extension Prio State Application Data CallerID Duration Accountcode PeerAccount BridgeID
PJSIP/user1-00000001 profile-6 123 4 Up SpeechBackgr demo-congrats 1000 16:31:01
PJSIP/user1-00000002 profile-6 123 4 Up SpeechBackgr demo-congrats 1000 16:19:48
PJSIP/user1-00000003 profile-6 123 4 Up SpeechBackgr demo-congrats 1000 00:02:26
3 active channels
3 active call
Sometimes the channel hangs automatically with the message of no RTP activity... but some channels just stays in ther, like the ones you see, until I restart asterisk.
Enabling the DEBUG, the last message it show the console is:
[Oct 13 08:55:53] DEBUG[28569][C-00000006]: res_http_websocket.c:382 __ast_websocket_write: Writing websocket binary frame, length 3200
[Oct 13 08:55:53] NOTICE[28569][C-00000006]: res_speech_vosk.c:166 vosk_recog_write: (vosk) Got result: '{
"partial" : ""
}'
[Oct 13 08:55:53] DEBUG[28569][C-00000006]: res_http_websocket.c:382 __ast_websocket_write: Writing websocket binary frame, length 3200
[Oct 13 08:55:53] NOTICE[28569][C-00000006]: res_speech_vosk.c:166 vosk_recog_write: (vosk) Got result: '{
"partial" : ""
}'
[Oct 13 08:55:53] DEBUG[28569][C-00000006]: res_http_websocket.c:382 __ast_websocket_write: Writing websocket pong frame, length 4
Always the last message is the "Writing websocket pong frame, length 4" and then it stops. Although It show like 4 or 5 pong messages before.
Ok, this is helpful. You can probably run the asr server from terminal too and get the log there. To enable logging you can uncomment this part in asr_server.py:
# Enable loging if needed
#
# logger = logging.getLogger('websockets')
# logger.setLevel(logging.INFO)
# logger.addHandler(logging.StreamHandler())
Hi I try enabling loging en asr_server.py (within docker), but besides this:
LOG (VoskAPI:ReadDataFiles():vosk/model.cc:192) Decoding params beam=13 max-active=7000 lattice-beam=6
LOG (VoskAPI:ReadDataFiles():vosk/model.cc:195) Silence phones 1:2:3:4:5:6:7:8:9:10
LOG (VoskAPI:RemoveOrphanNodes():nnet-nnet.cc:948) Removed 1 orphan nodes.
LOG (VoskAPI:RemoveOrphanComponents():nnet-nnet.cc:847) Removing 2 orphan components.
LOG (VoskAPI:Collapse():nnet-utils.cc:1472) Added 1 components, removed 2
LOG (VoskAPI:CompileLooped():nnet-compile-looped.cc:345) Spent 0.07177 seconds in looped compilation.
LOG (VoskAPI:ReadDataFiles():vosk/model.cc:219) Loading i-vector extractor from /opt/vosk-model-es/model/ivector/final.ie
LOG (VoskAPI:ComputeDerivedVars():ivector-extractor.cc:183) Computing derived variables for iVector extractor
LOG (VoskAPI:ComputeDerivedVars():ivector-extractor.cc:204) Done.
LOG (VoskAPI:ReadDataFiles():vosk/model.cc:240) Loading HCL and G from /opt/vosk-model-es/model/HCLr.fst /opt/vosk-model-es/model/Gr.fst
LOG (VoskAPI:ReadDataFiles():vosk/model.cc:262) Loading winfo /opt/vosk-model-es/model/word_boundary.int_
After initializing the asr_server, no message is shown when asterisk channel connects or freezes....or maybe I'm doing something wrong?
Hi.
I want to share something else I realize. When I execute the SpeechCreate app, and vosk server isn't available, the channel get stuck, like 2 minutes, untill some "Connection timed out" occur in module tcptls.c. But the case is that when the SpeechCreate is executing, no sip event affect the channel, I mean, I hangup but the channel keeps searching for vosk server.
I think maybe this is for other issue or even for an asterisk bug report, but the behavior is the same when no audio to recognize is sent to SpeechBackground app.
I will keep looking more because this is the best way to integrate asterisk with the amazing Vosk project for an IVR application. I hope @nshmyrev could find more.
@laar789 thank you, this is useful information. I wish I can have a time to look on this issue closer, I'll try.
Any news on this subject ? i have the same probleme !
Hi. It seems like there is no solution right now. I use a workaround, that has work for me. Basically I split the long audio into 2 or more short audios (like 10 seconds) and then repeat the SpeechBackground as many times as audios I have, something like this:
exten => 1,1,Answer
same => n,Wait(1)
same => n,SpeechCreate
same => n,SpeechBackground(hello_1)
same => n,Verbose(0,Result was ${SPEECH_TEXT(0)})
same => n,SpeechDestroy()
same => n,SpeechCreate
same => n,SpeechBackground(hello_2)
same => n,Verbose(0,Result was ${SPEECH_TEXT(0)})
same => n,SpeechDestroy()
same => n,SpeechCreate
same => n,SpeechBackground(hello_2)
same => n,Verbose(0,Result was ${SPEECH_TEXT(0)})
same => n,SpeechDestroy()
With this works, but it has its down side, because when something is about to be recognized just in between the destroy, and the next create, it just get lost. But it mostly works.
So, a complete fix is still desirable and needed, because it sometimes will fail, and split a minute audio into 6 can make the dialplan very long and that's not desirable.
The software is really good and I like it very much. I will try to find a fix, and learn more C to try to collaborate with the project, but right now I am in other projects and C is not my strong
Also running into this issue.
Just curious @nshmyrev what version of Asterisk did you test on that didn't have this issue?
Thanks
UPDATE : I tested on asterisk 16 and git master as of today. Same issue on both.
Hi, I can confirm that this is still the issue. My system is composed of:
- OS Ubuntu 20.04.6
- Asterisk 18.17.1 compiled from sources.
- Docker image alphacep/kaldi-es:latest MODEL_VERSION=0.42
an excerpt from my dialplan:
After 10 secs Vosk stops recognizing words and simply freezes. If I hang the call up, a message begins to appear in the asterisk console:
In order to get things back to normal I usually have to restart the docker container.
If the calling party talks less than 10 seconds, then the recognizing works fine and the dialplan executes without a problem.
I believe there is a SIP session timeout, but not sure where to fix it yet. Needs closer investigation.
Also, SpeechAPI is more designed for short inputs. If you want continuous recognition, you'd better use vosk through ARI. https://github.com/alphacep/vosk-server/tree/master/client-samples/asterisk-ari
@nshmyrev Thanks! I will try with ARI, but right now I resolved using UniMRCP which in fact uses the speechAPI and I have no problem going over the 10 secs.
Would appreciated feedback on latest patch from users who can test with "core show locks" on the Asterisk CLI and seeing if this is similar problem (before applying the patch to resolve it :)
*CLI> core show locks
=======================================================================
=== 20.8.1 === Currently Held Locks at Time: 477141:27:52.060579 =================
======================================================================= ===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> === <locked at>, <failed at>, <held for> (attempts, times locked)
=== === Thread ID: 0x7f41923af6c0 LWP:39610 (pbx_thread started at [ 4727] pbx.c ast_pbx_start())
=== ---> Lock #0 (app_speech_utils.c): MUTEX 834 speech_background &speech->lock 0x7f41d0076340 === 477141:06:52.026943, 477141:06:32.018003, 00:21:00.033665 (1, 1)
asterisk __ast_pthread_mutex_lock() [0x7f41d64edc0e] app_speech_utils.so app_speech_utils.c:835 speech_background()
asterisk pbx_exec() asterisk <unknown>()
asterisk ast_spawn_extension()
asterisk <unknown>()
asterisk <unknown>()
asterisk <unknown>()
[0x7f41da257134] libc.so.6 pthread_create.c:442 start_thread()
[0x7f41da2d77dc] libc.so.6 clone3.S:83 clone3()
=== ---> Lock #1 (res_http_websocket.c): MUTEX 548 ws_safe_read session 0x7f41d007ad10
=== 477141:27:33.125698, 477141:06:52.026907, 00:00:19.085175 (1, 1)
asterisk __ast_pthread_mutex_lock()
asterisk __ao2_lock()
[0x7f41d9c35530] res_http_websocket.so res_http_websocket.c:549 ws_safe_read()
[0x7f41d9c358e0] res_http_websocket.so res_http_websocket.c:613 __ast_websocket_read()
[0x7f41d9c38647] res_http_websocket.so res_http_websocket.c:1480 __ast_websocket_read_string()
[0x7f41d9c2a906] res_speech_vosk.so res_speech_vosk.c:168 vosk_recog_write()
[0x7f41db2c66c0] res_speech.so res_speech.c:151 ast_speech_write()
[0x7f41d64eddae] app_speech_utils.so app_speech_utils.c:861 speech_background()
asterisk pbx_exec()
asterisk <unknown>()
asterisk ast_spawn_extension()
asterisk <unknown>()
asterisk <unknown>()
asterisk <unknown>()
[0x7f41da257134] libc.so.6 pthread_create.c:442 start_thread()
[0x7f41da2d77dc] libc.so.6 clone3.S:83 clone3()
=== -------------------------------------------------------------------
===
=======================================================================