Skip to content
This repository has been archived by the owner on Jan 16, 2024. It is now read-only.

AVS cannot go into Speaking state #1143

Closed
zeusshuang opened this issue Dec 29, 2018 · 21 comments
Closed

AVS cannot go into Speaking state #1143

zeusshuang opened this issue Dec 29, 2018 · 21 comments

Comments

@zeusshuang
Copy link

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

@zeusshuang
Copy link
Author

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

@kjkh
Copy link

kjkh commented Dec 31, 2018

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?

@zeusshuang
Copy link
Author

Hi @kjkh ,

No, this symptom is from SDK 1.11.

@visayamv
Copy link
Contributor

visayamv commented Jan 5, 2019

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?

@jiajchem
Copy link

jiajchem commented Jan 8, 2019

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.

@liunanxuan
Copy link

@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
##############################################################################

@visayamv
Copy link
Contributor

Hi @liunanxuan , I see there is a

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

in your log. Was any speech played ?

@visayamv
Copy link
Contributor

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

@zeusshuang
Copy link
Author

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.

@liunanxuan
Copy link

liunanxuan commented Jan 10, 2019

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()

@liunanxuan
Copy link

@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?

@liunanxuan
Copy link

@visayamv please you see log.
direct_problem2.txt

@visayamv
Copy link
Contributor

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

@liunanxuan
Copy link

@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.

@zeusshuang
Copy link
Author

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.

@liunanxuan
Copy link

@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。.

@zeusshuang
Copy link
Author

zeusshuang commented Jan 12, 2019

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

@zeusshuang
Copy link
Author

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 ?

@zeusshuang
Copy link
Author

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

@dhpp
Copy link
Contributor

dhpp commented Jan 18, 2019

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.

kjkh pushed a commit that referenced this issue Feb 26, 2019
Changes in this update:

**Enhancements**

* Support was added for the `fr_CA` locale.
* The Executor has been optimized to run a single thread when there are active job in the queue, and to remain idle when there are not active jobs.
* An additional parameter of `alertType` has been added to the Alerts capability agent. This will allow observers of alerts to know the type of alert being delivered.
* Support for programmatic unload and load of PulseAudio Bluetooth modules was added. To enable this feature, there is a [new CMake option](https://github.com/alexa/avs-device-sdk/wiki/CMake-parameters#bluetooth): `BLUETOOTH_BLUEZ_PULSEAUDIO_OVERRIDE_ENDPOINTS`. Note that [libpulse-dev is a required dependency](https://github.com/alexa/avs-device-sdk/wiki/Dependencies#bluetooth) of this feature.
* An observer interface was added for when an active Bluetooth device connects and disconnects.
* The `BluetoothDeviceManagerInterface` instantiation was moved from `DefaultClient` to `SampleApp` to allow applications to override it.
* The `MediaPlayerInterface` now supports repeating playback of URL sources.
* The Kitt.AI wake word engine (WWE) is now compatible with GCC5+.
* Stop of ongoing alerts, management of MessageObservers, and management of CallStateObservers have been exposed through DefaultClient.

**Bug Fixes**

* [Issue 953](#953) - The `MediaPlayerInterface` requirement that callbacks not be made upon a callers thread has been removed.
* [Issue 1136](#1136) - Added a missing default virtual destructor.
* [Issue 1140](#1140) - Fixed an issue where DND states were not synchronized to the AVS cloud after device reset.
* [Issue 1143](#1143) - Fixed an issue in which the SpeechSynthesizer couldn't enter a sleeping state.
* [Issue 1183](#1183) - Fixed an issue where alarm is not sounding for certain timezones
* Changing an alert's volume from the Alexa app now works when an alert is playing.
* Added missing shutdown handling for ContentDecrypter to prevent the `Stop` command from triggering a crash when SAMPLE-AES encrypted content was streaming.
* Fixed a bug where if the Notifications database is empty, due to a crash or corruption, the SDK initialization process enters an infinite loop when it retries to get context from the Notifications capability agent.
* Fixed a race condition that caused `AlertsRenderer` observers to miss notification that an alert has been completed.

**Known Issues**

* `PlaylistParser` and `IterativePlaylistParser` generate two HTTP requests (one to fetch the content type, and one to fetch the audio data) for each audio stream played.
* Music playback history isn't being displayed in the Alexa app for certain account and device types.
* On GCC 8+, issues related to `-Wclass-memaccess` will trigger warnings. However, this won't cause the build to fail and these warnings can be ignored.
* Android error ("libDefaultClient.so" not found) can be resolved by upgrading to ADB version 1.0.40
* When network connection is lost, lost connection status is not returned via local TTS.
* `ACL` may encounter issues if audio attachments are received but not consumed.
* `SpeechSynthesizerState` currently uses `GAINING_FOCUS` and `LOSING_FOCUS` as a workaround for handling intermediate state. These states may be removed in a future release.
* The Alexa app doesn't always indicate when a device is successfully connected via Bluetooth.
* Connecting a product to streaming media via Bluetooth will sometimes stop media playback within the source application. Resuming playback through the source application or toggling next/previous will correct playback.
* When a source device is streaming silence via Bluetooth, the Alexa app indicates that audio content is streaming.
* The Bluetooth agent assumes that the Bluetooth adapter is always connected to a power source. Disconnecting from a power source during operation is not yet supported.
* On some products, interrupted Bluetooth playback may not resume if other content is locally streamed.
* `make integration` is currently not available for Android. In order to run integration tests on Android, you'll need to manually upload the test binary file along with any input file. At that point, the adb can be used to run the integration tests.
* On Raspberry Pi running Android Things with HDMI output audio, beginning of speech is truncated when Alexa responds to user text-to-speech (TTS).
* When the sample app is restarted and network connection is lost, Reminder TTS does not play. Instead, the default alarm tone will play twice.
@kclchan
Copy link
Contributor

kclchan commented Mar 5, 2019

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

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants