[SDK 1.9]Alexa hang up on "Listenning" state
Closed this issue · 26 comments
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
···
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:
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
This causes the sent Recognize event to carry invalid data.
We'll open internal ticket to fix this issue
Thanks,
Benny
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
2018-09-06 11:25:52.273 [ b] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=47
2018-09-06 11:25:52.274 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState
2018-09-06 11:25:52.280 [ 11] 5 AudioActivityTracker:executeProvideState
2018-09-06 11:25:52.283 [ 10] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=47
2018-09-06 11:25:52.283 [ b] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState
ubus_call ret 0
2018-09-06 11:25:52.287 [ 11] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState
2018-09-06 11:25:52.288 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState
2018-09-06 11:25:52.291 [ f] 5 ContextManager:buildContextSuccessful
2018-09-06 11:25:52.293 [ 12] 0 AudioInputProcessor:executeOnContextAvailable
2018-09-06 11:25:52.294 [ 12] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer
2018-09-06 11:25:52.295 [ 17] 9 AudioInputProcessor:onFocusChanged:newFocus=FOREGROUND
2018-09-06 11:25:52.296 [ 12] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=bdcf1562-e98a-4099-9c9b-b8c0ff68a000,newValue=26b289de-d9c9-4fd7-9008-e804c23aab12
2018-09-06 11:25:52.297 [ 17] 5 AudioActivityTracker:notifyOfActivityUpdates
2018-09-06 11:25:52.298 [ 12] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=bdcf1562-e98a-4099-9c9b-b8c0ff68a000
2018-09-06 11:25:52.299 [ 11] 5 AudioActivityTracker:executeNotifyOfActivityUpdates
2018-09-06 11:25:52.301 [ 12] 0 EventBuilder:buildJsonEventString:messageId=f775b9ea-c3d6-44d8-8e9b-611355025943,namespace=SpeechRecognizer,name=Recognize
2018-09-06 11:25:52.304 [ 12] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2018-09-06 11:25:52.305 [ 12] 9 HTTP2Transport:enqueueRequest
2018-09-06 11:25:52.327 [ 38] 0 HTTP2Transport:processNextOutgoingMessage
2018-09-06 11:25:52.328 [ 38] 0 HTTP2StreamPool:getStream:streamId=237,numAcquiredStreams=2
2018-09-06 11:25:52.333 [ 38] 9 HTTP2Transport:insertActiveStream:handle=0x56a47860
2018-09-06 11:25:52.335 [ 38] E InProcessAttachmentReader:readFailed:reason=bytes requested smaller than SDS word size
2018-09-06 11:25:52.336 [ 38] E InProcessAttachmentReader:readFailed:reason=bytes requested smaller than SDS word size
2018-09-06 11:25:52.338 [ 38] E InProcessAttachmentReader:readFailed:reason=bytes requested smaller than SDS word size
2018-09-06 11:25:53.981 [ 18] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechRecognizer",name:"StopCapture",messageId:"e4714f0a-0214-488f-8e22-2bbd63da24ad",dialogRequestId:"26b289de-d9c9-4fd7-9008-e804c23aab12"}
2018-09-06 11:25:54.013 [ 19] I DirectiveRouter:preHandleDirective:messageId=e4714f0a-0214-488f-8e22-2bbd63da24ad,action=calling
2018-09-06 11:25:54.015 [ 19] 0 CapabilityAgent:addingMessageIdToMap:messageId=e4714f0a-0214-488f-8e22-2bbd63da24ad
2018-09-06 11:25:54.016 [ 1a] I DirectiveRouter:handleDirective:messageId=e4714f0a-0214-488f-8e22-2bbd63da24ad,action=calling
2018-09-06 11:25:54.018 [ 12] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2018-09-06 11:25:54.019 [ 12] 5 UserInactivityMonitor:onUserActive
2018-09-06 11:25:54.020 [ 12] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2018-09-06 11:25:54.022 [ 12] 0 DirectiveProcessor:onHandlingCompeted:messageId=e4714f0a-0214-488f-8e22-2bbd63da24ad,directiveBeingPreHandled=(nullptr)
2018-09-06 11:25:54.022 [ 16] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
2018-09-06 11:25:54.023 [ 12] 0 CapabilityAgent:removingMessageIdFromMap:messageId=e4714f0a-0214-488f-8e22-2bbd63da24ad
2018-09-06 11:25:54.024 [ 38] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed
###########################
Thinking...
###########################
ubus_call ret 0
ubus_call ret 0
2018-09-06 11:25:54.787 [ 38] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 021556fffe5fe11a-00006d7e-005399a1-a089cfc97c5a112c-298761cb-27
2018-09-06 11:25:54.791 [ 18] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf",dialogRequestId:"26b289de-d9c9-4fd7-9008-e804c23aab12"}
2018-09-06 11:25:54.791 [ 38] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2018-09-06 11:25:54.793 [ 19] I DirectiveRouter:preHandleDirective:messageId=67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf,action=calling
2018-09-06 11:25:54.795 [ 19] 0 CapabilityAgent:addingMessageIdToMap:messageId=67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf
2018-09-06 11:25:54.796 [ 19] 9 SpeechSynthesizer:preHandleDirective:messageId=67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf
2018-09-06 11:25:54.798 [ 13] 0 SpeechSynthesizer:executePreHandle:messageId=67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf
2018-09-06 11:25:54.798 [ 1a] I DirectiveRouter:handleDirective:messageId=67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf,action=calling
2018-09-06 11:25:54.794 [ 38] 0 HTTP2Transport:cleanupFinishedStream:streamId=237,result=200
2018-09-06 11:25:54.801 [ 1a] 9 SpeechSynthesizer:handleDirective:messageId=67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf
2018-09-06 11:25:54.802 [ 38] 0 HTTP2StreamPool:releaseStream:streamId=237,numAcquiredStreams=1
2018-09-06 11:25:54.803 [ 13] 0 SpeechSynthesizer:executeHandle:messageId=67cf06ed-86cf-47ec-8cde-7ce8a67d9ddf
2018-09-06 11:25:54.835 [ 13] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer
2018-09-06 11:25:54.837 [ 17] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE
2018-09-06 11:25:54.838 [ 12] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2018-09-06 11:25:54.838 [ 17] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2018-09-06 11:25:54.839 [ 12] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2018-09-06 11:25:54.840 [ 17] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS
2018-09-06 11:25:54.842 [ 12] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2018-09-06 11:25:54.843 [ 13] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2018-09-06 11:25:54.845 [ 13] 9 SpeechSynthesizer:startPlaying
2018-09-06 11:25:54.846 [ 13] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2018-09-06 11:25:54.848 [ 3] 0 MediaPlayer:handleSetAttachmentReaderSourceCalled
2018-09-06 11:25:54.849 [ 3] 9 MediaPlayer:tearDownTransientPipelineElements
2018-09-06 11:25:54.850 [ 3] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2018-09-06 11:25:54.852 [ 3] 9 BaseStreamSource:initNoAudioFormat
2018-09-06 11:25:54.854 [ 13] 9 MediaPlayer:playCalled
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.
2018-09-06 10:13:10.752 [ d] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS_NO_CONTENT,
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
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.
Is this issue only in 1.9 or potential issue in previous version?
It's from DEBUG5 log.
we put the log "InProcessAttachmentReader:readFailed:reason=SDS is closed" to DEBUG9 due to sometimes it will flooding ...
but the behavior and other logs are the same as this case.
This case is an normal over weekend test and continue to Q&A with AVS (no playing music, just Q&A).
And finally, it stuck and cannot response anymore.
@visayamv ,
This issue is hard to reproduce. So I may not be able to collect the log in short time. Possiblely it is because the "StopCapture" directive is dropped due to network issue or curl issue. I only reproduce it for just once.
I can use following iptables rule to drop this packet on the router:
iptables -A forwarding_rule -i eth1 -s 54.239.0.0/16 -m length --length 80: -j DROP
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,
This issue seems exist on both 1.6, 1.8.1 and 1.9.
Hi @subjectxbj @visayamv ,
I have a clue here, my device ever disconnected from Internet but the Q&A test script is continue running.
Normally, it will stay at listening state for about 1 minutes and return without issue.
Due to my Q&A case, it will file question every 30-60 seconds, so it may re-enter the listening state while previous listening state is still block due to no response from cloud site.
Again, normally, it will still timeout about 1 minutes but sometimes, it will be stuck forever until restart AVS.
We ever saw the same case while Alert is arrive and immediately Q&A interrupt it (I remember I filed this case before), but it still hard to reproduce, I am searching an easy way to reproduce it..
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,
If AVS client failed to get the response, then curl will return error and AVS client will move to idle. So you will see sometimes it recover by itself.
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.
I attached another log here (same test run but more earlier).
You can see UTC time about 11:56:48 9/16, it's the last time it received StopCapture from remote site.
Then it did not respond anything until restart AVS.
At 12:27:44 , finally AVS also found connecting failed.
I cannot make sure if the Internet is actually disconnected then (actually, it should be working due to another device at the same network and continue play Q&A from Internet), but I can make sure while the tester found AVS no response 1 day later (t's an over weekend test), the Internet is working but AVS still stuck.
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,
-SWH
Looking at avs_log.txt, and avs_log-2.txt, it appears that SpeechRecognizer.recognize request here:
2018-09-16 11:56:44.991 [ 1c] 0 EventBuilder:buildJsonEventString:messageId=1dfcdb85-9e79-4b98-bedb-65faa24f1f48,namespace=SpeechRecognizer,name=Recognize
...
2018-09-16 11:56:48.003 [ 1e] C MessageInterpreter:receive:METRICS::Location=ADSL Enqueue,NAME=StopCapture,MessageID=46e4348f-8ec7-4673-9ca6-2f8e7ca6b0a7,DialogRequestID=a6d8b684-b148-4cbf-9a57-769f3cc2a811
...
2018-09-16 11:56:48.528 [ c9] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ee23bfffe7f7ce8-00007e73-00250acd-f9bb39a63031d26b-a5598061-353
is received and processed correctly. We can see the same in the service logs. However, after that, the next SpeechRecognizer.Recognize request:
2018-09-16 11:56:49.561 [ 1c] C EventBuilder:buildJsonEventString:METRICS::Location=Building Message,NAME=Recognize,MessageID=ad11b9b0-f50c-4825-8e4c-d9f36aa8e856,DialogRequestID=5de0d9e8-0c55-4133-be0c-307be1d8b903
...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:
2018-09-16 11:56:48.761 [ 1d] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
...
2018-09-16 11:56:49.224 [ 1c] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer
...
2018-09-16 11:56:53.764 [ 1d] E SpeechSynthesizer:onFocusChangeFailed:reason=stateChangeTimeout,messageId=e09315e1-5901-47f8-aeeb-4d8ed4467bbf
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,
-SWH
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,
-SWH
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.
Until our morning today, at 2018-11-13 01:26:23 , we trigger trigger it by command (cmd t), it seems working but response is very slowly. after tried 2-3 commands, go to stuck.
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.
You can find the last question at 2018-12-04 12:06:58 , then it go into listening state and never response.
The trigger word callback seems still working, but state machine is no response.
From Alexa APP History, the last log is also the same time 12:06
Hi AVS Team,
As I know, this #948 issue has been fixed in v1.10.0. Could help to provide patches for this issue? I want to patched in v1.8.1 directly. Thanks.
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)
--> https://www.youtube.com/watch?v=BNZGrN8E_EM
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.
And due to AVS response is a little late compared with Echo, so it may cause multiple barge-in happened during the tests. (the previous question is late or missed, and next one is coming ...)
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 -
(1) The last triggered and go into listening state is at 17:41:49.582 (line#733587). Then AVS only can detect trigger word but seems not response. It's what we said, stuck in listening state.
(2) I found , AVS will leave this "listening state" ever hour, I guess it's due to re-authentication. You can search "Listening..." after 17:41:49.
----> It's the only different between SDK 1.10 and previous version from user's point of view. In previous version, it will not return after go into this stuck state.
(3) After it stuck and hours later while I go into my Lab and found it stuck, I tried to stop the Video and trigger it by myself, no working. (about 22:53:03 in the log, line#749182)
(4) After it return to Idle state, I tried to trigger it again but it still stuck at "listening" state. (about 23:27:53, line#750292)
(5) One hour later, it return to Idle. (end of the log file)
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.
I can help you to run any test if you have patch or debug log for advanced checking.
Hi @zeusshuang , thanks for providing the logs, I have updated our internal ticket with the information you provided.
@subjectxbj and @zeusshuang , can you confirm if you are still experiencing this issue on newer versions of the SDK?
Not any more.