AVS cannot go into Speaking state

Question

AVS cannot go into Speaking state

Closed this issue 6 years ago · 21 comments

Hi AVS team,

SDK 1.11
ARM based embedded linux
RaspberryPi3

No sure if it's related to case #948
But I actually test it for case#948 , but the symptom is a little bit as case#948.
--> continue to play this youtube video: https://www.youtube.com/watch?v=BNZGrN8E_EM

After hours, AVS will not go into Speaking state. Sometimes, it only stop at Listening state, or Thinking state.
Will not return normal after stopped test for hours.
While this symptom happens, it still can see History from APP, so it seems it will still send audio to the cloud site.

attached log is from Pi3, the log is huge under DEBUG9, you can find last Speaking at line 2018915

1228_pi - Copy.zip

Answer 1 · 2018-12-29T00:15:02.000Z

This log is from our own DUT. Almost the same symptom, but not sure if it's the same root cause.
You can find last speaking at lint 712029
It's run about 6 hours (the log is huge, so I removed the previous lines)

no-speaking-DUT.zip

Answer 2 · 2018-12-31T20:40:31.000Z

Hi @zeusshuang,

The Speak directive is being received, but the error starts at

712838 2018-12-28 17:34:16.882 [ 3] E CapabilityAgent:handleDirectiveFailed:reason=messageIdNotFound,messageId=77b259c3-b09c-4ab8-bfee-70d4155a0216

This causes the Speak to be canceled. It looks to be related to the TemplateRuntime directive which comes in shortly after the Speak. Did you see these errors in previous versions of the SDK?

Answer 3 · 2019-01-02T00:54:58.000Z

Hi @kjkh ,

No, this symptom is from SDK 1.11.

Answer 4 · 2019-01-05T02:22:09.000Z

Hi @zeusshuang , checking no-speaking-DUT log looks like the Speak directive is being canceled by the next listening request.
`

Listening...

Thinking...

2018-12-28 22:45:58.329 [ 23] I DirectiveSequencer:onDirective:avs_current_directive_namespace=SpeechSynthesizer
2018-12-28 22:45:58.330 [ 23] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"48f3a40e-fb47-4740-b4d7-ecbad8404729",dialogRequestId:"d24703cb-808f-4764-9e22-f9ff799a5c5d"}
2018-12-28 22:45:58.335 [ 24] 9 SpeechSynthesizer:preHandleDirective:messageId=48f3a40e-fb47-4740-b4d7-ecbad8404729
2018-12-28 22:45:58.336 [ 15] 0 SpeechSynthesizer:executePreHandle:messageId=48f3a40e-fb47-4740-b4d7-ecbad8404729
2018-12-28 22:45:58.341 [ 3] 9 SpeechSynthesizer:handleDirective:messageId=48f3a40e-fb47-4740-b4d7-ecbad8404729
2018-12-28 22:45:58.342 [ 3] C SpeechSynthesizer:handleDirective:METRICS::Location=SpeechSynthesizer Receive,NAME=Speak,MessageID=48f3a40e-fb47-4740-b4d7-ecbad8404729,DialogRequestID=d24703cb-808f-4764-9e22-f9ff799a5c5d
2018-12-28 22:45:58.343 [ 15] 0 SpeechSynthesizer:executeHandle:messageId=48f3a40e-fb47-4740-b4d7-ecbad8404729
2018-12-28 22:45:58.343 [ 15] 9 SpeechSynthesizer:addToDirectiveQueue:queueSize=1
2018-12-28 22:46:02.375 [ 10] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut
2018-12-28 22:46:02.409 [ 10] I DialogUXStateAggregator:avsAnalytic:avs_current_directive_namespace=SpeechSynthesizer

Listening...

2018-12-28 22:46:23.240 [ 3] I DirectiveRouter:cancelDirective:messageId=48f3a40e-fb47-4740-b4d7-ecbad8404729,action=calling
2018-12-28 22:46:23.240 [ 3] 9 SpeechSynthesizer:cancelDirective:messageId=48f3a40e-fb47-4740-b4d7-ecbad8404729
2018-12-28 22:46:23.241 [ 15] 0 SpeechSynthesizer:executeCancel:messageId=48f3a40e-fb47-4740-b4d7-ecbad8404729
`

From what I am seeing there is an utterance, so it goes to Listening state.
AVS sends down a Speak directive and SpeechSynthesizer puts it in the queue.
But 1-2 seconds later, there is another utterance, and another Speak directive is sent down.
This cancels the previous speak directive in the queue.
The SpeechSynthesizer loops on the Speak directive in the queue to play the speech.

Can you increase your test utterance interval to >10 seconds and see if this still happens?

Answer 5 · 2019-01-08T09:23:15.000Z

Is the issue fixed by increase the interval? we also have this issue here with sdk 1.11. 1.09 doesn't have such problem. It seems not interval problem.

Answer 6 · 2019-01-10T00:36:01.000Z

@kjkh @visayamv I also had the same problem with SDK version 1.11.
Previous versions did not have this problem.
log:
1959:2032:0109/090402:166645817:INFO:CONSOLE(1)] "==========Alexa Event2=============="DialogUXThinking"", source: file:///mtd_apexe/board/com.nvt.skyweb/home/static/js/app.f0f9310646fe09c75a1f.js (1)
2019-01-09 07:04:02.398 [ e] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechRecognizer",name:"SetEndOfSpeechOffset",messageId:"60c87d5d-5a5f-4a49-b4a2-4e62dcb2099a",dialogRequestId:"69b85c19-bd67-4f9a-bf5b-3cb8032bc819"}
2019-01-09 07:04:02.398 [ f] I DirectiveRouter:preHandleDirective:messageId=60c87d5d-5a5f-4a49-b4a2-4e62dcb2099a,action=calling
2019-01-09 07:04:02.398 [ 10] I DirectiveRouter:handleDirective:messageId=60c87d5d-5a5f-4a49-b4a2-4e62dcb2099a,action=calling
2019-01-09 07:04:02.399 [ e] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"e8ffe60c-e549-46da-aee4-d2fc93a8bb22",dialogRequestId:"69b85c19-bd67-4f9a-bf5b-3cb8032bc819"}
2019-01-09 07:04:02.399 [ f] I DirectiveRouter:preHandleDirective:messageId=e8ffe60c-e549-46da-aee4-d2fc93a8bb22,action=calling
2019-01-09 07:04:02.402 [ 10] I DirectiveRouter:handleDirective:messageId=e8ffe60c-e549-46da-aee4-d2fc93a8bb22,action=calling
2019-01-09 07:04:02.403 [ c] I AudioInputProcessor:executeResetState
[AlexaSpeaker] Trace: [enqueueRequest:85] start
[AlexaSpeaker] Trace: [enqueueRequest:99] end
###########################
Speaking...
###########################

2019-01-09 07:04:02.600 [ e] I DirectiveSequencer:onDirective:directive={"namespace:"TemplateRuntime",name:"RenderTemplate",messageId:"e2699ef1-7a74-40de-a7eb-7cd95da99038",dialogRequestId:"69b85c19-bd67-4f9a-bf5b-3cb8032bc819"}
2019-01-09 07:04:02.600 [ f] I DirectiveRouter:preHandleDirective:messageId=e2699ef1-7a74-40de-a7eb-7cd95da99038,action=calling
2019-01-09 07:04:02.601 [ 10] I DirectiveRouter:handleDirective:messageId=e2699ef1-7a74-40de-a7eb-7cd95da99038,action=calling
2019-01-09 07:04:02.601 [ 10] E CapabilityAgent:handleDirectiveFailed:reason=messageIdNotFound,messageId=e2699ef1-7a74-40de-a7eb-7cd95da99038
2019-01-09 07:04:02.601 [ 10] W DirectiveRouter:messageIdNotRecognized:handler=0x4f885008,messageId=e2699ef1-7a74-40de-a7eb-7cd95da99038,reason=handleDirectiveReturnedFalse
2019-01-09 07:04:02.601 [ 10] E DirectiveProcessor:handleDirectiveFailed:message id=e2699ef1-7a74-40de-a7eb-7cd95da99038
2019-01-09 07:04:02.601 [ 10] I DirectiveRouter:cancelDirective:messageId=e8ffe60c-e549-46da-aee4-d2fc93a8bb22,action=calling
##############################################################################
RenderTemplateCard
#-----------------------------------------------------------------------------
Focus State : FOREGROUND
Template Type : WeatherTemplate
Main Title : Hong Kong
##############################################################################

2019-01-09 07:04:02.603 [ 13] I NtkMediaPlayer:stopCalled
[AlexaSpeaker] Trace: [stop:889] start
[AlexaSpeaker] Trace: [stopAll:868] start
[stop][m_isSpeaking:1]
[AlexaSpeaker] Debug: get stop interrupt!
[AlexaSpeaker] Trace: [soundOut:686] end
[MGR Get Mute]enType = 1,*pbMute = 0
0xb34f5841
[AlexaSpeaker] Trace: [_stop_Alexa_file:739] end
[AlexaSpeaker] Trace: [_deinit_AlexaPlayer:417] start
[AlexaSpeaker] Trace: [_deinit_AlexaPlayer:420] end
[AlexaSpeaker] Trace: [dataDecode:708] end
[AlexaSpeaker] Trace: [doPlayFile:800] end
[1959:2032:0109/090402:167224620:INFO:CONSOLE(1)] "==========Alexa Event2=============="DialogUXSpeaking"", source: file:///mtd_apexe/board/com.nvt.skyweb/home/static/js/app.f0f9310646fe09c75a1f.js (1)
[AlexaSpeaker] Trace: [stopAll:885] end
[AlexaSpeaker] Trace: [stop:893] end
[1959:2032:0109/090402:167353677:INFO:CONSOLE(1)] "==========Alexa Event2=============="RenderTemplate"", source: file:///mtd_apexe/board/com.nvt.skyweb/home/static/js/app.f0f9310646fe09c75a1f.js (1)
[1959:2032:0109/090402:167354839:INFO:CONSOLE(1)] "Joy|||||| Idle2", source: file:///mtd_apexe/board/com.nvt.skyweb/home/static/js/app.f0f9310646fe09c75a1f.js (1)
[1959:2032:0109/090402:167422933:INFO:CONSOLE(1)] "mounted", source: file:///mtd_apexe/board/com.nvt.skyweb/home/static/js/app.f0f9310646fe09c75a1f.js (1)
[1959:2032:0109/090402:167442395:INFO:CONSOLE(1)] "updated", source: file:///mtd_apexe/board/com.nvt.skyweb/home/static/js/app.f0f9310646fe09c75a1f.js (1)
[PLAT_AOUT_SetSpeakerMainGain]PLAT_AOUT_SetSpeakerMainGain Vender Audio init
Vender_Audio_NL_CB@657 enter
Vender_Audio_NL_CB@662 Receive GetOPUGain from kernel
Vender_Audio_NL_CB@671 Cell=0, MainGain=0x0, MixGain=0xd00
Vender_Audio_Ctrl@252 Mutex Lock
Vender_Audio_Ctrl@256 Cell=0, MainGain=0x0, MixGain=0xd00
PLAT_AOUT_SetSpeakerMainGain spkid[0] current main[0x0] mix[0xd00]
PLAT_AOUT_SetSpeakerMainGain Set in main gain spkid[0] main[0x8000] mix[0xd00]
Vender_Audio_NL_CB@657 enter
Vender_Audio_NL_CB@662 Receive GetOPUGain from kernel
Vender_Audio_NL_CB@671 Cell=0, MainGain=0x8000, MixGain=0xd00
Vender_Audio_Ctrl@252 Mutex Lock
Vender_Audio_Ctrl@256 Cell=0, MainGain=0x8000, MixGain=0xd00
PLAT_AOUT_SetSpeakerMainGain success[0x8000]
[PLAT_AOUT_SetSpeakerMainGain]PLAT_AOUT_SetSpeakerMainGain Vender Audio init
Vender_Audio_NL_CB@657 enter
Vender_Audio_NL_CB@662 Receive GetOPUGain from kernel
Vender_Audio_NL_CB@671 Cell=4, MainGain=0x0, MixGain=0x8000
Vender_Audio_Ctrl@252 Mutex Lock
Vender_Audio_Ctrl@256 Cell=4, MainGain=0x0, MixGain=0x8000
PLAT_AOUT_SetSpeakerMainGain spkid[1] current main[0x0] mix[0x8000]
PLAT_AOUT_SetSpeakerMainGain Set in main gain spkid[1] main[0x8000] mix[0x8000]
Vender_Audio_NL_CB@657 enter
Vender_Audio_NL_CB@662 Receive GetOPUGain from kernel
Vender_Audio_NL_CB@671 Cell=4, MainGain=0x8000, MixGain=0x8000
Vender_Audio_Ctrl@252 Mutex Lock
Vender_Audio_Ctrl@256 Cell=4, MainGain=0x8000, MixGain=0x8000
PLAT_AOUT_SetSpeakerMainGain success[0x8000]
########################################
Alexa is currently idle!
########################################
##############################################################################
RenderTemplateCard - Cleared
##############################################################################

Answer 7 · 2019-01-10T06:23:38.000Z

Hi @liunanxuan , I see there is a

###########################
Speaking...
###########################

in your log. Was any speech played ?

Answer 8 · 2019-01-10T06:38:22.000Z

I have filed an internal ticket to investigate further. In the meantime, @liunanxuan , can you provide an answer to the question above?

Answer 9 · 2019-01-10T07:53:12.000Z

Hi @visayamv ,

From what I am seeing there is an utterance, so it goes to Listening state.
AVS sends down a Speak directive and SpeechSynthesizer puts it in the queue.
But 1-2 seconds later, there is another utterance, and another Speak directive is sent down.
This cancels the previous speak directive in the queue.
The SpeechSynthesizer loops on the Speak directive in the queue to play the speech.

Can you increase your test utterance interval to >10 seconds and see if this still happens?

For this question, it looks okay while the interval is > 10 seconds by normal test.
But I am not sure if it's related to #948, due to I was testing this case then.
I will create another test run and see if I will see this problem again.

Answer 10 · 2019-01-10T09:00:11.000Z

I have filed an internal ticket to investigate further

It does enter the speak state. However, when the instruction is processed, the instruction of the speak is cancelled. Causes the speak to call stopplaying.

================
（1）
DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"e8ffe60c-e549-46da-aee4-d2fc93a8bb22",dialogRequestId:"69b85c19-bd67-4f9a-bf5b-3cb8032bc819"}
2019-01-09 07:04:02.399 [ f] I DirectiveRouter:preHandleDirective:messageId=e8ffe60c-e549-46da-aee4-d2fc93a8bb22,action=calling
2019-01-09 07:04:02.402 [ 10] I DirectiveRouter:handleDirective:messageId=e8ffe60c-e549-46da-aee4-d2fc93a8bb22,action=calling
（2）
DirectiveRouter:cancelDirective:messageId=e8ffe60c-e549-46da-aee4-d2fc93a8bb22,action=calling
（3）
SpeechSynthesizer::stopPlaying()

Answer 11 · 2019-01-10T09:30:55.000Z

@visayamv
There is a very strange point from my log, the speak command is blocked. Why does the call to handleDirective when the RenderTemplate command comes over?

Answer 12 · 2019-01-10T09:47:22.000Z

@visayamv please you see log.
direct_problem2.txt

Answer 13 · 2019-01-10T22:04:35.000Z

Hi @liunanxuan , i think you're analysis is right. We'll dig deeper into this.

Answer 14 · 2019-01-11T02:25:46.000Z

@visayamv Thanks for the support. I hope that you can solve it as soon as possible. This problem is very serious. All direcives that were previously enqueued will be cancelled.

Answer 15 · 2019-01-11T02:36:30.000Z

Hi @liunanxuan ,
a question here, in your case, will it return to normal from next command?
By my case, it will not return to normal and locked forever until restart SampleAPP.

Answer 16 · 2019-01-11T02:46:00.000Z

@zeusshuang This problem is probabilistic. There is no need to restart sampleAPP. My situation here has the opportunity to return to normal under the next command。.

Answer 17 · 2019-01-12T00:42:37.000Z

Hi @visayamv ,

I have a new log for this case, it run about 34 hours, and 135-140 trigger events per hour (all are Q&A case, no play music), finally it seems try to go into speaking state (?) but never return forever.
AVS is still alive, and it still detect WWE trigger event, but stuck at Listening state.

you can see the last speaking is at line#475416 (UTC 2019-01-11 20:39:00), and it seems it's working. (due to it's auto-test, I was not nearby the DUT).
Then, next WWE at line#475524, and it seems try to go into speak state but I am not sure if it's working.
After this state, all following WWE trigger will only go into Listening state.

From Alexa APP History, the last command is: Alexa, launch daily word (The time is 20:39, same as log.)
Then no more history log in the APP.

It's SDK 1.11

8-case#1143.zip

Answer 18 · 2019-01-12T01:34:19.000Z

Hi @visayamv ,
following by my last failed log, I have a question here.
I saw it failed at "starteChangeTimeout" in SpeechSynthesizer::onFocusChanged
During in my 34 hours tests, I never got this log before this stuck case.
If it's a exception case and cannot be recovered, can I just restart AVS if it go into this state ?

Answer 19 · 2019-01-12T02:31:14.000Z

following my fail log hours ago, I left this DUT static there (still under stuck state), and it seemes it will un-lack every hour, but it still cannot recovery and will failed a listening state.

8-case#1143-unlock_each_hours.log

Answer 20 · 2019-01-18T20:24:01.000Z

Hi @zeusshuang, I have taken a look into this, and it appears to me that the SpeechSynthesizer is related to this problem. I do think this is the same issue as reported in #948.

In many of the logfiles you've uploaded, I have noticed the following error trace (which occurs only once):
SpeechSynthesizer:onFocusChangeFailed

followed by repeated error trace:
AudioInputProcessor:executeRecognizeFailed:reason=New audio provider can not override

I believe that this indicates that the SpeechSynthesizer (SS) fails to release the dialog channel, which AIP (recognizer) needs to begin listening. SS and AIP share the Dialog channel, and so must gracefully release it when they are done.

My take right now is that this is caused by a missing state transition with the SS MediaPlayer, resulting in the SS being locked up. I will need to dig deeper into the code, alongside your logs, to verify. I wanted to share these thoughts however today in case they help you to move forward independently.

I will close out #948, as we will track the issue here. Thank you again for your patience in raising this issue to us.

Answer 21 · 2019-03-05T02:21:25.000Z

Thanks for opening this issue. It has been fixed in our v1.12 release. Thanks!