ContextManager:updateStatesLoopFailed

[subjectxbj]

SDK: 1.10
OS: Linux
Platform: ARMv7

Hi AVS team,

Our device has upgraded to 1.10, but yesterday one of the customer reported the same issue that I mentioned in following ticket:

#911

The problem is I can see the log of "AudioPlayer:provideState", but can't find the log of "AudioPlayer:executeProvideState", which means the "m_executor" is still executing the previous task. Not able to execute the "AudioPlayer:executeProvideState" task.

Alexa can't recover from this state, which cause subsequence voice request can't get response. And a restart is required to recover.

[subjectxbj]

Here are the logs:

2019-05-19 04:20:28.579 [ 16] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2019-05-19 04:20:28.581 [  c] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=292
2019-05-19 04:20:28.581 [ 17] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2019-05-19 04:20:28.581 [  d] 0 AudioPlayer:provideState:stateRequestToken=292
2019-05-19 04:20:28.583 [  c] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=292
############################
#       Listening...       #
############################

2019-05-19 04:20:28.586 [  f] 0 AudioPlayer:executeProvideState:sendToken=true,stateRequestToken=292
2019-05-19 04:20:28.590 [  3] 0 MediaPlayer:handleGetOffsetCalled:idPassed=38,currentId=38
2019-05-19 04:20:28.594 [ 16] 0 AudioInputProcessor:executeOnContextAvailable
2019-05-19 04:20:28.596 [ 16] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer
2019-05-19 04:20:28.598 [ 1f] 0 AudioPlayer:onFocusChanged:newFocus=BACKGROUND
2019-05-19 04:20:28.598 [ 16] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=6a32f72f-ec61-4564-824a-dcf7b3265efa,newValue=5708c51d-c3d6-481e-8c39-3c34fd1aa5b6
ubus_call ret 0
2019-05-19 04:20:28.600 [  f] 1 AudioPlayer:executeOnFocusChanged:from=FOREGROUND,to=BACKGROUND,m_currentActivity=PLAYING
2019-05-19 04:20:28.601 [ 16] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=6a32f72f-ec61-4564-824a-dcf7b3265efa
2019-05-19 04:20:28.603 [  f] 1 AudioPlayer:executeOnFocusChanged:action=pauseMediaPlayer
2019-05-19 04:20:28.605 [ 16] 0 EventBuilder:buildJsonEventString:messageId=cdcf17ac-ce4d-4e36-876f-08b0f8605407,namespace=SpeechRecognizer,name=Recognize
2019-05-19 04:20:28.606 [  3] 0 MediaPlayer:handlePauseCalled:idPassed=38,currentId=38
2019-05-19 04:20:30.600 [ 1f] E AudioPlayer:onFocusChangedTimedOut:newFocus=BACKGROUND,m_currentActivity=PLAYING
2019-05-19 04:20:30.602 [ 16] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2019-05-19 04:20:30.678 [145] E InProcessAttachmentReader:readFailed:reason=bytes requested smaller than SDS word size
2019-05-19 04:20:32.156 [ 18] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"f144348e-39a1-4983-bad2-98bd8533aaec"\,dialogRequestId\:"5708c51d-c3d6-481e-8c39-3c34fd1aa5b6"}
2019-05-19 04:20:32.158 [ 19] I DirectiveRouter:preHandleDirective:messageId=f144348e-39a1-4983-bad2-98bd8533aaec,action=calling
2019-05-19 04:20:32.159 [ 19] 0 CapabilityAgent:addingMessageIdToMap:messageId=f144348e-39a1-4983-bad2-98bd8533aaec
2019-05-19 04:20:32.160 [ 1a] I DirectiveRouter:handleDirective:messageId=f144348e-39a1-4983-bad2-98bd8533aaec,action=calling
2019-05-19 04:20:32.161 [ 16] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2019-05-19 04:20:32.163 [ 16] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2019-05-19 04:20:32.165 [ 16] 0 DirectiveProcessor:onHandlingCompeted:messageId=f144348e-39a1-4983-bad2-98bd8533aaec,directiveBeingPreHandled=(nullptr)
2019-05-19 04:20:32.165 [ 17] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
2019-05-19 04:20:32.166 [ 16] 0 CapabilityAgent:removingMessageIdFromMap:messageId=f144348e-39a1-4983-bad2-98bd8533aaec
###########################
#       Thinking...       #
###########################

2019-05-19 04:20:32.167 [145] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed
2019-05-19 04:20:32.666 [145] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 0e8b5afffe10217c-00005bab-00204682-4ab528148de3587a-172b11eb-85
2019-05-19 04:20:32.669 [145] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2019-05-19 04:20:32.669 [ 18] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"SetEndOfSpeechOffset"\,messageId\:"0813d1a0-f866-40e7-bf37-e407f4e3de3a"\,dialogRequestId\:"5708c51d-c3d6-481e-8c39-3c34fd1aa5b6"}
2019-05-19 04:20:32.670 [145] 0 LibcurlHTTP2Connection:streamFinished:streamId=AVSEvent-4045,result=No error,CURLcode=0
2019-05-19 04:20:32.673 [145] E SdsReader:seekFailed:reason=seekBeyondCloseIndex,position=7328026880,readerCloseIndex=7328026624
2019-05-19 04:20:32.672 [ 18] I DirectiveSequencer:onDirective:directive={"namespace\:"Speaker"\,name\:"SetVolume"\,messageId\:"20472fd2-de9e-4b14-92a0-f268d8b3fdff"\,dialogRequestId\:"5708c51d-c3d6-481e-8c39-3c34fd1aa5b6"}
2019-05-19 04:20:32.672 [ 19] I DirectiveRouter:preHandleDirective:messageId=0813d1a0-f866-40e7-bf37-e407f4e3de3a,action=calling
2019-05-19 04:20:32.677 [ 19] 0 CapabilityAgent:addingMessageIdToMap:messageId=0813d1a0-f866-40e7-bf37-e407f4e3de3a
2019-05-19 04:20:32.678 [ 1a] I DirectiveRouter:handleDirective:messageId=0813d1a0-f866-40e7-bf37-e407f4e3de3a,action=calling
2019-05-19 04:20:32.679 [ 19] I DirectiveRouter:preHandleDirective:messageId=20472fd2-de9e-4b14-92a0-f268d8b3fdff,action=calling
2019-05-19 04:20:32.679 [ 1a] E JsonUtils:convertToInt64ValueFailed:reason=invalidValue,expectedValue=Int64
2019-05-19 04:20:32.680 [ 19] 0 CapabilityAgent:addingMessageIdToMap:messageId=20472fd2-de9e-4b14-92a0-f268d8b3fdff
2019-05-19 04:20:32.682 [ 1a] 0 AudioInputProcessor:handleSetEndOfSpeechOffsetDirective:startTimeSpeech(ms)=missing,endTimeSpeech(ms)=3100
2019-05-19 04:20:32.684 [ 1a] 0 DirectiveProcessor:onHandlingCompeted:messageId=0813d1a0-f866-40e7-bf37-e407f4e3de3a,directiveBeingPreHandled=(nullptr)
2019-05-19 04:20:32.685 [ 1a] I DirectiveRouter:handleDirective:messageId=20472fd2-de9e-4b14-92a0-f268d8b3fdff,action=calling
2019-05-19 04:20:32.876 [ 17] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut
2019-05-19 04:20:32.878 [ 17] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE
2019-05-19 04:20:32.879 [ 16] 1 FocusManager:releaseChannel:channelName=Dialog
2019-05-19 04:20:32.880 [ 16] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2019-05-19 04:20:32.880 [ 1f] 0 AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2019-05-19 04:20:32.882 [ 16] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2019-05-19 04:20:32.884 [ 16] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
########################################
#       Alexa is currently idle!       #
########################################

2019-05-19 04:20:41.539 [ 16] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2019-05-19 04:20:41.541 [ 17] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2019-05-19 04:20:41.541 [  d] 0 AudioPlayer:provideState:stateRequestToken=293
2019-05-19 04:20:41.541 [  c] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=293
############################
#       Listening...       #
############################

2019-05-19 04:20:41.545 [  c] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=293
2019-05-19 04:20:43.544 [  d] E ContextManager:updateStatesLoopFailed:reason=stateProviderTimedOut
2019-05-19 04:20:43.545 [ 16] E AudioInputProcessor:executeOnContextFailure:error=STATE_PROVIDER_TIMEDOUT
2019-05-19 04:20:43.547 [ 16] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=IDLE
2019-05-19 04:20:43.749 [ 17] 0 DialogUXStateAggregator:setState:from=LISTENING,to=IDLE
########################################
#       Alexa is currently idle!       #
########################################

[dhpp]

Hi @subjectxbj, in our experience this is caused by a deadlock occurring in some thread within the SDK. What happens is the ContextManager is requesting state from various components, and one blocks. This can be tricky to pin down since it looks like the component trying to gather Context to send an Event is what's blocked, but it's really some other component which the ContextManager is talking to.

Could you please update trace to DEBUG9 and post what you see? Also note that the 3rd column is the thread id, so you should be able to work backward from where the deadlock occurs, and should quickly find the issue.

[kclchan]

I am closing this issue due to inactivity. Please feel free to re-open it if it has been closed in error.