[SDK 1.9]Alexa hang up on "Listenning" state #948
Comments
|
Hi @subjectxbj, Thanks for bringing this into our attention. The error is when reading the attachment containing the audio stream as part of sending the Recognize event: This causes the sent Recognize event to carry invalid data. Thanks, |
|
Hi @bennyAv10 , The "readFailed" may not be the root cause of this issue. From the history on alexa APP, I can see the request and the response, which means Cloud can recognize the "Recognize" event. But alexa client did not receive the "StopCapture" directive. Is it possible to check on the cloud side to see if AVS server send the directive correctly? The "readFailed" also happened in following conversation, but alexa can response correctly. ############################ Listening...############################ 2018-09-06 11:25:52.273 [ f] 5 AudioActivityTracker:provideState Thinking...########################### |
|
Hi @bennyAv10 , Seems this is a very critical issue because it get the device into dead state. We are think of add some workaround to fix this issue so that it does not block certification. I noticed when this issue happens, it will print following log, which means it failed to receive response from the server when sending the "Recognize" event. Can we treat the status "SUCCESS_NO_CONTENT"as an exception and call "resetState()" in "AudioInputProcessor:onSendCompleted", so that alexa can recover to idle state? Thanks |
subjectxbj
changed the title
|
Also I'm thinking of adding a timeout for "Listening" state in the DialogUXStateAggregator. I'm thinking of set the timeout to 15 seconds. But I tried disconnect the WAN connection of the uplink router at state "Listening", then alexa will restore to "idle" after 15 seconds due to this timeout. Do you think it is ok to add this timer? |
|
Hi @subjectxbj, If you add the 15s timeout, if the utterance is more than 15s, would it be a problem? We are still investigating if the SDS error is the cause of the problem. Thanks! |
|
Hi @subjectxbj, sorry for not being more clear, it is not recommended to add a timeout to trigger Listening to Idle state. |
|
Hi @subjectxbj , can you also add -DACSDK_EMIT_SENSITIVE_LOGS to your cmake command so we can also get detailed logs on curl? Note that if you do enable sensitive logs, your logs may include information that you would not want to post publicly (e.g. configuration information used to authorize you client). So, you should be sure to scrub that kind of information before posting any such logs to this forum. |
|
Hi @visayamv , We also got a same case like this one, but we are 1.8.1 SDK. This case is an normal over weekend test and continue to Q&A with AVS (no playing music, just Q&A). |
|
@visayamv , I can use following iptables rule to drop this packet on the router: The rule will drop the "StopCapture" directive sent from AVS server and simulate the packet drop. It does not drop the response from AVS server, so AVS client will not report CURL error. And then AVS client will stay on "LISTENING" state forever. Even I remove this rule after a few seconds, it still can't recover. @zeusshuang, |
|
Hi @subjectxbj @visayamv , I have a clue here, my device ever disconnected from Internet but the Q&A test script is continue running. I think it's not a corner case due to we have users ever saw listening state stuck issue, but due to no log, so we don't know if it's the same case, but I think there should be some potential issue here. |
|
Hi @zeusshuang , ideally, when the network is disconnected, libCurl will notify AudioInputProcessor with an error and this will cause it to reset it's state and go back to IDLE from LISTENING. If I recall correctly, while on the Listening state, if you initiate another query (question), it will not be allowed and that's why you'll see an error: AudioInputProcessor:executeRecognizeFailed:reason=New audio provider can not override In v1.9 we have fixed some issues with network reconnection here. Is the application that produced avs_log.txt running on v1.9? |
|
Hi @visayamv , No, my log is from 1.8.1. Will try to reproduce this case with 1.9 on my device. |
|
Hi @zeusshuang, But "StopCapture" directive is not a response. It is sent from AVS server. curl does not expect this message, and it will not return error. So if network issue drop the response, then AVS will recover by itself; But if network issue drop the "StopCapture" directive, then AVS will stuck at "Listening" for ever. |
|
After checking @subjectxbj 's comments, and review the logs again, I can make sure it's the same case as this original report. |
|
We have been able to verify on the server side that both of the recognize requests in your initial log resulted in StopCapture directives being sent to the client. Where they were lost is still a mystery. Thanks, |
|
Looking at avs_log.txt, and avs_log-2.txt, it appears that SpeechRecognizer.recognize request here: is received and processed correctly. We can see the same in the service logs. However, after that, the next SpeechRecognizer.Recognize request: ...is never seen by the Alexa service. There service receives plenty of other events from the SDK after this, so it does not look like this is a connectivity problem. ACL sends all messages though the same queue, so it seems very likely that something has happened on the client side to prevent that last Recognize event from getting queued. Looking at the AudioInputProcessor code, the obvious culprit is focus management - the Recognize event will not be sent until AudioInputProcessor has acquired focus - and the log does not show AudioInputProcessor acquiring focus - instead, I see in the logs: It seems a little curious that SpeechSynthesizer would try to acquire the channel when it already has focus. We will continue to investigate. Thank you, |
Changes in this update: **Enhancements** * New optional configuration for [EqualizerController](https://github.com/alexa/avs-device-sdk/blob/v1.10.0/Integration/AlexaClientSDKConfig.json#L154). The EqualizerController interface allows you to adjust equalizer settings on your product, such as decibel (dB) levels and modes. * Added reference implementation of the EqualizerController for GStreamer-based (MacOS, Linux, and Raspberry Pi) and OpenSL ES-based (Android) MediaPlayers. Note: In order to use with Android, it must support OpenSL ES. * New optional configuration for the [TemplateRuntime display card value](https://github.com/alexa/avs-device-sdk/blob/v1.10.0/Integration/AlexaClientSDKConfig.json#L144). * A configuration file generator script, `genConfig.sh` is now included with the SDK in the **tools/Install** directory. `genConfig.sh` and it's associated arguments populate `AlexaClientSDKConfig.json` with the data required to authorize with LWA. * Added Bluetooth A2DP source and AVRCP target support for Linux. * Added Amazon for Business (A4B) support, which includes support for handling the new [RevokeAuthorization](https://developer.amazon.com/docs/alexa-voice-service/system.html#revokeauth) directive in the Settings interface. A new CMake option has been added to enable A4B within the SDK, `-DA4B`. * Added locale support for IT and ES. * The Alexa Communication Library (ACL), `CBLAUthDelegate`, and sample app have been enhanced to detect de-authorization using the new `z` command. * Added `ExternalMediaPlayerObserver`, which receives notification of player state, track, and username changes. * `HTTP2ConnectionInterface` was factored out of `HTTP2Transport` to enable unit testing of `HTTP2Transport` and re-use of `HTTP2Connection` logic. **Bug Fixes** * Fixed a bug in which `ExternalMediaPlayer` adapter playback wasn't being recognized by AVS. * [Issue 973](#973) - Fixed issues related to `AudioPlayer` where progress reports were being sent out of order or with incorrect offsets. * An `EXPECTING`, state has been added to `DialogUXState` in order to handle `EXPECT_SPEECH` state for hold-to-talk devices. * [Issue 948](#948) - Fixed a bug in which the sample app was stuck in a listening state. * Fixed a bug where there was a delay between receiving a `DeleteAlert` directive, and deleting the alert. * [Issue 839](#839) - Fixed an issue where speech was being truncated due to the `DialogUXStateAggregator` transitioning between a `THINKING` and `IDLE` state. * Fixed a bug in which the `AudioPlayer` attempted to play when it wasn't in the `FOREGROUND` focus. * `CapabilitiesDelegateTest` now works on Android. * [Issue 950](#950) - Improved Android Media Player audio quality. * [Issue 908](#908) - Fixed compile error on g++ 7.x in which includes were missing.
|
Release 1.10 should help with the case you provided here. We still do not know how the StopCapture is getting lost, but in your case we do see Alexa Service closing the stream, and a recent change to AudioInputProcessor.cpp should cause the SDK to stop listening. Thank you, |
|
Hi @scotthea-amazon , We got this case again with SDK1.9.0 and added AudioInputProcessor.cpp patch. See the log timestamp at 2018-11-12 15:37:11 , it's the last time it can triggered by Alexa voice command, then it had no Speaking state. I think it should be something after last voice triggered. |
|
Hi @scotthea-amazon , It's a new log for this case, it stuck at listening state after 12 hours Q&A test. |
|
Hi AVS Team, |
|
Hi @zeusshuang , is it possible for you to test v1.10? There was some enhancements done also in ACL which has also improved debugging messages. I checked the last recognize event and it seems there are no HTTP response for it or error in the log. |
|
Hi @visayamv , Attached is debug9 log from SDK 1.10. It seems it's more easy to get the fail result ... I continue to play a video file from YouTube. (all my tests are the same, repeat to play this video) Due to it's an video and quality is not really good, so sometimes the Alexa will not be triggered like it did in the video. okay, you can see my log. The timestamp in the AVS log is UTC time. The picture show the last response time is 01:41 (local time), it's 17:41 UTC time. Here are some reviewed comments - So the different is that AVS will return to Idle every hour, but while I tried to trigger it again, it will stuck at listening state again. I don't know the correct way to reproduce it, but it seems I can reproduce this case here. |
|
Hi @zeusshuang , thanks for providing the logs, I have updated our internal ticket with the information you provided. |
|
I will close this out, as we are following tracking the issue under #1143. |
|
@subjectxbj and @zeusshuang , can you confirm if you are still experiencing this issue on newer versions of the SDK? |
|
Not any more. |
SDK: 1.9
When I ask "alexa, what is the time", alexa stay on "Listening state" until I restart alexa. This is not easy to reproduce. But we have encountered this a few times
From the log, seems alexa client has sent the "SpeechRecognize" event to the cloud, And I can find the conversation in the history on Alexa APP. But seems it fails to get the "StopCapture" directive from the cloud, so it hang up on "Listening state". When I wakeup it again, it print the log, but keep on "Listening state"
2018-09-06 10:14:40.834 [ 12] E AudioInputProcessor:executeRecognizeFailed:reason=New audio provider can not override
Why not set a timer at state "Listening"? If alexa client fails to get the directive from cloud, it should reset to "idle".
Here is the full log:
···
########################################
Alexa is currently idle!
########################################
ubus_call ret 0
2018-09-06 10:10:42.018 [ d] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 129901fffee62be2-0000746c-00530fc0-715392a436650b93-f32ea602-5
2018-09-06 10:10:42.020 [ d] 0 HTTP2Transport:handlePingResponse
2018-09-06 10:10:42.022 [ d] 0 HTTP2StreamPool:releaseStream:streamId=367,numAcquiredStreams=1
2018-09-06 10:10:42.023 [ d] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2018-09-06 10:11:00.649 [ 12] 5 UserInactivityMonitor:onUserActive
2018-09-06 10:11:00.651 [ 12] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2018-09-06 10:11:00.653 [ 16] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2018-09-06 10:11:00.653 [ 10] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=36
2018-09-06 10:11:00.653 [ f] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=36
############################
Listening...
############################
2018-09-06 10:11:00.655 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState
2018-09-06 10:11:00.659 [ f] 5 AudioActivityTracker:provideState
2018-09-06 10:11:00.659 [ 10] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=36
2018-09-06 10:11:00.662 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState
2018-09-06 10:11:00.661 [ 11] 5 AudioActivityTracker:executeProvideState
ubus_call ret 0
2018-09-06 10:11:00.656 [ b] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=36
2018-09-06 10:11:00.666 [ 11] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState
2018-09-06 10:11:00.670 [ b] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState
2018-09-06 10:11:00.673 [ f] 5 ContextManager:buildContextSuccessful
2018-09-06 10:11:00.675 [ 12] 0 AudioInputProcessor:executeOnContextAvailable
2018-09-06 10:11:00.677 [ 12] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer
2018-09-06 10:11:00.678 [ 17] 9 AudioInputProcessor:onFocusChanged:newFocus=FOREGROUND
2018-09-06 10:11:00.678 [ 12] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=b4556e26-9027-46c6-95c8-ef78e06deb9b,newValue=0a3bc3e3-01b6-4e27-8f5e-873b8df7e0b4
2018-09-06 10:11:00.680 [ 17] 5 AudioActivityTracker:notifyOfActivityUpdates
2018-09-06 10:11:00.681 [ 12] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=b4556e26-9027-46c6-95c8-ef78e06deb9b
2018-09-06 10:11:00.682 [ 11] 5 AudioActivityTracker:executeNotifyOfActivityUpdates
2018-09-06 10:11:00.685 [ 12] 0 EventBuilder:buildJsonEventString:messageId=8130fd65-1052-457b-aa05-53c52dd64a4b,namespace=SpeechRecognizer,name=Recognize
2018-09-06 10:11:00.694 [ 12] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2018-09-06 10:11:00.696 [ 12] 9 HTTP2Transport:enqueueRequest
2018-09-06 10:11:00.772 [ d] 0 HTTP2Transport:processNextOutgoingMessage
2018-09-06 10:11:00.774 [ d] 0 HTTP2StreamPool:getStream:streamId=369,numAcquiredStreams=2
2018-09-06 10:11:00.776 [ d] 9 HTTP2Transport:insertActiveStream:handle=0x56d03800
2018-09-06 10:11:00.779 [ d] E InProcessAttachmentReader:readFailed:reason=bytes requested smaller than SDS word size
2018-09-06 10:11:00.780 [ d] E InProcessAttachmentReader:readFailed:reason=bytes requested smaller than SDS word size
2018-09-06 10:11:00.782 [ d] E InProcessAttachmentReader:readFailed:reason=bytes requested smaller than SDS word size
2018-09-06 10:11:43.031 [ d] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 129901fffee62be2-0000746c-00530fc0-715392a436650b93-f32ea602-7
2018-09-06 10:13:10.752 [ d] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS_NO_CONTENT
2018-09-06 10:13:10.753 [ d] 0 HTTP2Transport:cleanupFinishedStream:streamId=369,result=204
2018-09-06 10:13:10.754 [ d] 0 HTTP2StreamPool:releaseStream:streamId=369,numAcquiredStreams=1
2018-09-06 10:13:10.756 [ d] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2018-09-06 10:14:13.406 [ 2] 5 InternetConnectionMonitor:testConnection
2018-09-06 10:14:13.879 [ 2] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed
2018-09-06 10:14:13.880 [ 2] 5 InternetConnectionMonitor:updateConnectionStatus:connected=true
2018-09-06 10:14:13.881 [ 2] 9 LibCurlHttpContentFetcher:~LibCurlHttpContentFetcher
2018-09-06 10:14:40.834 [ 12] E AudioInputProcessor:executeRecognizeFailed:reason=New audio provider can not override
2018-09-06 10:14:57.946 [ 12] E AudioInputProcessor:executeRecognizeFailed:reason=New audio provider can not override
read a event
read type-code-value:1-582-1read a event
read type-code-value:0-0-0
2018-09-06 10:16:10.532 [ f] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=37
2018-09-06 10:16:10.532 [ 10] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=37
2018-09-06 10:16:10.534 [ f] 5 AudioActivityTracker:provideState
2018-09-06 10:16:10.534 [ b] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=37
2018-09-06 10:16:10.536 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState
2018-09-06 10:16:10.537 [ 11] 5 AudioActivityTracker:executeProvideState
2018-09-06 10:16:10.540 [ 10] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=37
2018-09-06 10:16:10.540 [ b] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState
2018-09-06 10:16:10.543 [ 11] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState
2018-09-06 10:16:10.545 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState
2018-09-06 10:16:10.547 [ f] 5 ContextManager:buildContextSuccessful
2018-09-06 10:16:10.548 [ 12] 0 AudioInputProcessor:executeOnContextAvailable
2018-09-06 10:16:10.549 [ 12] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=0a3bc3e3-01b6-4e27-8f5e-873b8df7e0b4,newValue=db7efb09-d21f-403a-a281-28dc13d51ff7
2018-09-06 10:16:10.551 [ 12] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=0a3bc3e3-01b6-4e27-8f5e-873b8df7e0b4
2018-09-06 10:16:10.553 [ 12] 0 EventBuilder:buildJsonEventString:messageId=2f4d1b92-6f0c-4864-abbb-5be6903cdf21,namespace=SpeechRecognizer,name=Recognize
2018-09-06 10:16:10.555 [ 12] 9 HTTP2Transport:enqueueRequest
2018-09-06 10:16:10.615 [ d] 0 HTTP2Transport:processNextOutgoingMessage
2018-09-06 10:16:10.617 [ d] 0 HTTP2StreamPool:getStream:streamId=371,numAcquiredStreams=2
2018-09-06 10:16:10.618 [ d] 9 HTTP2Transport:insertActiveStream:handle=0x56cfd800
read a event
read type-code-value:1-582-0read a event
read type-code-value:0-0-0
2018-09-06 10:16:55.886 [ d] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 129901fffee62be2-0000746c-00530fc0-715392a436650b93-f32ea602-9
2018-09-06 10:16:55.909 [ d] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS_NO_CONTENT
2018-09-06 10:16:55.910 [ d] 0 HTTP2Transport:cleanupFinishedStream:streamId=371,result=204
2018-09-06 10:16:55.911 [ d] 0 HTTP2StreamPool:releaseStream:streamId=371,numAcquiredStreams=1
2018-09-06 10:16:55.912 [ d] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2018-09-06 10:19:13.883 [ 2] 5 InternetConnectionMonitor:testConnection
2018-09-06 10:19:14.412 [ 2] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed
2018-09-06 10:19:14.413 [ 2] 5 InternetConnectionMonitor:updateConnectionStatus:connected=true
2018-09-06 10:19:14.415 [ 2] 9 LibCurlHttpContentFetcher:~LibCurlHttpContentFetcher
···
The text was updated successfully, but these errors were encountered: