Focus manager issue on AVS #138

simplistiq · 2017-09-05T19:24:33Z

In the latest 1.0.2 SDK, we are seeing that on a multiple next/previous scenario when playing Amazon prime music, the FocusManager sometimes loses focus. The Play directive is received however AudioManager never gets the Focus to play out the url. It happens if we do the iterations back-to-back without having to finish out playing the current song. Although this SDK may not support prime per release notes, this lock on Focus Manager may be a generic problem.

Logs are below:
2017-09-01 20:03:10.967 [ 5] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0af853fffed7bf42-00003b0c-00006de2-05e16d7adfd4a2b0-0773c98b-267
2017-09-01 20:03:10.982 [ 6] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"bd2ff320-8440-4cd5-b9f0-521931d6856c",dialogRequestId:"83e62f21-c076-4ac2-af50-ec448e512a0c"}
2017-09-01 20:03:10.982 [ d] I DirectiveRouter:preHandleDirective:messageId=bd2ff320-8440-4cd5-b9f0-521931d6856c,action=calling
2017-09-01 20:03:10.982 [ d] 0 CapabilityAgent:addingMessageIdToMap:messageId=bd2ff320-8440-4cd5-b9f0-521931d6856c
2017-09-01 20:03:10.982 [ d] 9 SpeechSynthesizer:preHandleDirective:messageId=bd2ff320-8440-4cd5-b9f0-521931d6856c
2017-09-01 20:03:10.982 [ 9] 0 SpeechSynthesizer:executePreHandle:messageId=bd2ff320-8440-4cd5-b9f0-521931d6856c
2017-09-01 20:03:10.983 [ e] I DirectiveRouter:handleDirective:messageId=bd2ff320-8440-4cd5-b9f0-521931d6856c,action=calling
2017-09-01 20:03:10.983 [ e] 9 SpeechSynthesizer:handleDirective:messageId=bd2ff320-8440-4cd5-b9f0-521931d6856c
2017-09-01 20:03:10.982 [ b] 0 DialogUXStateAggregator:DialogUXStateAggregator::receive() - THINKING == m_currentState
2017-09-01 20:03:10.984 [ 9] 0 SpeechSynthesizer:executeHandle:messageId=bd2ff320-8440-4cd5-b9f0-521931d6856c
2017-09-01 20:03:10.984 [ 9] 9 SpeechSynthesizer:addToDirectiveQueue:queueSize=1
2017-09-01 20:03:11.184 [ 3b] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut()
2017-09-01 20:03:11.184 [ b] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut - moving to IDLE
2017-09-01 20:03:11.184 [ b] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE
2017-09-01 20:03:11.185 [ a] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
########################################

Alexa is currently idle!

########################################
UIManager::onDialogUXStateChanged state = IDLE
InteractionManager::onDialogUXStateChanged to IDLE
######## QcomSoundTrigger::stopRecording() 1
AudioManager::StopRecorder() 0
2017-09-01 20:03:11.185 [ c] 0 QCMediaPlayer:QCMediaPlayer::restoreVolume - :restore Volume = =1
2017-09-01 20:03:11.186 [ f] 9 AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2017-09-01 20:03:11.186 [ a] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-09-01 20:03:11.186 [ a] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2017-09-01 20:03:11.187 [ c] 0 QCMediaPlayer:QCMediaPlayer::restoreVolume - :restore Volume = =1
2017-09-01 20:03:13.186 [ f] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=executorTimeout

shikha-bansal · 2017-09-05T19:32:11Z

I see the same issue : ( happens when trying to play my playlist from amazon music back to back. )
###########################

Speaking...

###########################
2017-09-05 19:30:57.051 [ 7] I DirectiveRouter:handleDirective:messageId=70892733-6bea-443e-a749-fe8fc867a194,action=calling
2017-09-05 19:30:57.051 [ 7] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=streamFormat
2017-09-05 19:30:57.051 [ 7] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReportIntervalInMilliseconds
2017-09-05 19:30:57.051 [ 7] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-09-05 19:30:57.060 [ 8] I MediaPlayer:Starting Buffering
detection loop heart beat ...
2017-09-05 19:30:59.051 [ a] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=executorTimeout
2017-09-05 19:30:59.060 [ 9] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=notStarted
detection loop heart beat ...

shikha-bansal · 2017-09-07T17:44:15Z

Any comments on this ? Your help is highly appreciated . I don't see this issue with iHeartRadio , wondering what could be different SDK wise.

scotthea-amazon · 2017-09-07T22:06:41Z

Hi simplistiq and shikha-bansal,

Looking at the code that logs

AudioPlayer:onFocusChangedFailed:reason=timedout,cause=executorTimeout

It is waiting for AudioPlayer::executeOnFocusChanged(FOREGROUND) to return. The code for that logs "executeOnFocusChanged" upon entry. However, that does not show up in the log provided. So, it seems likely that AudioPlayer::m_executor is blocked handling some previously submitted task. With more complete logs it might be possible to look further back and find out what is holding things up. Would it be possible to get more complete logs?

Also note that It is very possible that playing non iHeartRadio content is simply failing and leaving the AudioPlayer or underlying MediaPlayer in a broken state.

Thank you for bringing this issue to our attention,
-SWH

shikha-bansal · 2017-09-07T22:11:30Z

These are the logs as generated with DEBUG9 option. Is there a MACRO I can enable to get more logs.

scotthea-amazon · 2017-09-07T22:19:55Z

shikha-bansal,

Yes, I can see you have DEBUG9 logging enabled - and that is super helpful! What I was asking for are logs that go further back in time to see if we can identify a previous AudioPlayer operation that is blocking the AudioPlayer::m_executor's thread.

Thank you,
-SWH

shikha-bansal · 2017-09-12T17:40:16Z

Here are more complete logs :
############################

Listening...

############################
2017-09-12 17:31:10.195 [ 5] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=6dc5b67d-e30b-495b-a5d2-aa8559105178
2017-09-12 17:31:14.304 [ 3] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechRecognizer",name:"StopCapture",messageId:"6b158ea0-44a8-473d-8004-56bfd37234ef",dialogRequestId:"6dc5b67d-e30b-495b-a5d2-aa8559105178"}
2017-09-12 17:31:14.306 [ 6] I DirectiveRouter:preHandleDirective:messageId=6b158ea0-44a8-473d-8004-56bfd37234ef,action=calling
2017-09-12 17:31:14.307 [ 7] I DirectiveRouter:handleDirective:messageId=6b158ea0-44a8-473d-8004-56bfd37234ef,action=calling
###########################

Thinking...

###########################
2017-09-12 17:31:14.312 [ 4] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-09-12 17:31:15.962 [ 3] I DirectiveSequencer:onDirective:directive={"namespace:"Speaker",name:"SetMute",messageId:"7d54f7c8-c173-4c5c-8bee-7f895fa3a2ba",dialogRequestId:"6dc5b67d-e30b-495b-a5d2-aa8559105178"}
2017-09-12 17:31:15.962 [ 6] W DirectiveRouter:preHandleDirectiveFailed:messageId=7d54f7c8-c173-4c5c-8bee-7f895fa3a2ba,reason=noHandlerRegistered
2017-09-12 17:31:15.962 [ 6] I DirectiveSequencer:sendingExceptionEncountered:messageId=7d54f7c8-c173-4c5c-8bee-7f895fa3a2ba
2017-09-12 17:31:15.962 [ 3] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"136f28d3-a489-4d71-94ee-d8addb103a4e",dialogRequestId:"6dc5b67d-e30b-495b-a5d2-aa8559105178"}
2017-09-12 17:31:15.964 [ 3] I DirectiveSequencer:onDirective:directive={"namespace:"Speaker",name:"SetMute",messageId:"0324b4e9-8cdb-49e6-a6cb-e28abd60cc51",dialogRequestId:"6dc5b67d-e30b-495b-a5d2-aa8559105178"}
2017-09-12 17:31:15.964 [ 3] I DirectiveSequencer:onDirective:directive={"namespace:"AudioPlayer",name:"Play",messageId:"e59defad-4da0-46a6-a26e-881575f1b24f",dialogRequestId:"6dc5b67d-e30b-495b-a5d2-aa8559105178"}
2017-09-12 17:31:15.965 [ 6] I DirectiveRouter:preHandleDirective:messageId=136f28d3-a489-4d71-94ee-d8addb103a4e,action=calling
2017-09-12 17:31:15.965 [ 6] W DirectiveRouter:preHandleDirectiveFailed:messageId=0324b4e9-8cdb-49e6-a6cb-e28abd60cc51,reason=noHandlerRegistered
2017-09-12 17:31:15.965 [ 6] I DirectiveSequencer:sendingExceptionEncountered:messageId=0324b4e9-8cdb-49e6-a6cb-e28abd60cc51
2017-09-12 17:31:15.965 [ 6] I DirectiveRouter:preHandleDirective:messageId=e59defad-4da0-46a6-a26e-881575f1b24f,action=calling
2017-09-12 17:31:15.967 [ 7] I DirectiveRouter:handleDirective:messageId=136f28d3-a489-4d71-94ee-d8addb103a4e,action=calling
#######

Alexa is currently idle!

########################################
2017-09-12 17:31:16.313 [ 8] I InProcessAttachmentReader:readFailed:reason=SDS is closed
###########################

Speaking...

###########################
2017-09-12 17:31:18.350 [ 7] I DirectiveRouter:handleDirective:messageId=e59defad-4da0-46a6-a26e-881575f1b24f,action=calling
2017-09-12 17:31:18.352 [ 7] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=streamFormat
2017-09-12 17:31:18.353 [ 7] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReportIntervalInMilliseconds
2017-09-12 17:31:18.353 [ 7] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
onFocusChanged 0 newFocus
########################################

Alexa is currently idle!

########################################
2017-09-12 17:31:18.798 [ 8] I MediaPlayer:Starting Buffering
onPlaybackStarted
onPlaybackFinished
onFocusChanged 2 newFocus
2017-09-12 17:32:14.887 [ 9] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=executorTimeout
2017-09-12 17:32:14.888 [ a] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=notFinished

simplistiq · 2017-09-12T19:35:46Z

We see lock issues in AudioPlayer. We are testing the AudioPlayer by issuing next/previous/thumbs up/thumbs down commands by interrupting the system.

AudioPlayer blocks acquiring lock in the following line
std::unique_lockstd::mutex lock(m_playbackMutex);

void AudioPlayer::onPlaybackFinished() {
ACSDK_DEBUG9(LX("onPlaybackFinished"));
m_executor.submit([this] { executeOnPlaybackFinished(); });
ACSDK_DEBUG9(LX("onPlaybackFinished try acquire lock"));
std::unique_lockstd::mutex lock(m_playbackMutex);
ACSDK_DEBUG9(LX("onPlaybackFinished successfully acquired lock"));
m_playbackFinished = true;
ACSDK_DEBUG9(LX("onPlaybackFinished notify_all"));
m_playbackConditionVariable.notify_all();
ACSDK_DEBUG9(LX("onPlaybackFinished notify_all done"));
}

2017-09-06 09:48:22.548 [ 39] 9 AudioPlayer:onPlaybackFinished try acquire lock
[LWP 4233 exited]
2017-09-06 09:48:23.188 [ 5] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0634f9fffe479e06-00001337-00014386-8a0880b19ccd6406-f45195d7-225
2017-09-06 09:48:23.188 [ 5] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-09-06 09:48:24.518 [ e] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=executorTimeout

shikha-bansal · 2017-09-12T19:41:08Z

Thanks for the analysis , when can I expect to get a fix for this.
Or can you suggest a workaround I can use , this issue is a blocker for us.

shikha-bansal · 2017-09-12T21:17:55Z

I get the same issue when trying to read a book from Audible. I get the response "starting your book " , but then Audioplayer is stuck.

2017-09-12 21:16:35.421 [ a] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
call from executeRecognize
AIP executeProvideState m_wakeword ALEXA
2017-09-12 21:16:35.421 [ b] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2017-09-12 21:16:35.422 [ a] 0 ContextManager:updateStateLocked:action=updatedState,state={"wakeword" : "ALEXA"},namespace=SpeechRecognizer,name=RecognizerState
############################

Listening...

############################
line 246
buildState {"token":"","offsetInMilliseconds":0,"playerActivity":"IDLE"}
buildState {"token":"","offsetInMilliseconds":0,"playerActivity":"FINISHED"}
buildState {"allAlerts":[],"activeAlerts":[]}
buildState {"wakeword" : "ALEXA"}
2017-09-12 21:16:35.423 [ 7] E ContextManager:buildContextSuccessful:context={"context":[{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"IDLE"}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"ALEXA"}}]}
ContextManager sendContextAndClearQueue
updateStatesLoop
2017-09-12 21:16:35.424 [ a] E AudioInputProcessor:executeOnContextAvailable:jsonContext={"context":[{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"IDLE"}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"ALEXA"}}]}
2017-09-12 21:16:35.425 [ a] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=f41f0b81-ec34-41bc-9aaf-61d30cf53c57
2017-09-12 21:16:35.426 [ a] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId
2017-09-12 21:16:35.426 [ a] 0 EventBuilder:buildJsonEventString:messageId=07605629-73b7-4eaa-a61e-3617b321937b,namespace=SpeechRecognizer,name=Recognize
2017-09-12 21:16:35.428 [ a] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
detection loop heart beat ...
detection loop heart beat ...
2017-09-12 21:16:38.569 [ 6] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechRecognizer",name:"StopCapture",messageId:"42260943-df98-49da-87d1-81f395809e9d",dialogRequestId:"f41f0b81-ec34-41bc-9aaf-61d30cf53c57"}
2017-09-12 21:16:38.571 [ c] I DirectiveRouter:preHandleDirective:messageId=42260943-df98-49da-87d1-81f395809e9d,action=calling
2017-09-12 21:16:38.572 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=42260943-df98-49da-87d1-81f395809e9d
2017-09-12 21:16:38.577 [ d] I DirectiveRouter:handleDirective:messageId=42260943-df98-49da-87d1-81f395809e9d,action=calling
2017-09-12 21:16:38.578 [ a] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2017-09-12 21:16:38.578 [ a] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-09-12 21:16:38.578 [ b] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
2017-09-12 21:16:38.579 [ a] 0 DirectiveProcessor:onHandlingCompeted:messageId=42260943-df98-49da-87d1-81f395809e9d,directiveBeingPreHandled=(nullptr)
2017-09-12 21:16:38.579 [ a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=42260943-df98-49da-87d1-81f395809e9d
###########################

Thinking...

###########################
2017-09-12 21:16:38.589 [ 5] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-09-12 21:16:39.335 [ 5] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0e9837fffefbacf8-000060d6-00017614-961b5d8372fefa62-da279ef9-5
2017-09-12 21:16:39.343 [ 6] I DirectiveSequencer:onDirective:directive={"namespace:"Speaker",name:"SetMute",messageId:"08792d31-f3a3-4827-8400-d3fce2c75971",dialogRequestId:"f41f0b81-ec34-41bc-9aaf-61d30cf53c57"}
2017-09-12 21:16:39.344 [ c] W DirectiveRouter:preHandleDirectiveFailed:messageId=08792d31-f3a3-4827-8400-d3fce2c75971,reason=noHandlerRegistered
2017-09-12 21:16:39.344 [ c] I DirectiveSequencer:sendingExceptionEncountered:messageId=08792d31-f3a3-4827-8400-d3fce2c75971
2017-09-12 21:16:39.344 [ 6] I DirectiveSequencer:onDirective:directive={"namespace:"SpeechSynthesizer",name:"Speak",messageId:"0a2ab5d0-14b1-4273-b1c5-41b3620b051a",dialogRequestId:"f41f0b81-ec34-41bc-9aaf-61d30cf53c57"}
2017-09-12 21:16:39.345 [ 6] I DirectiveSequencer:onDirective:directive={"namespace:"Speaker",name:"SetMute",messageId:"866bf90e-1452-47ac-88df-cca356982894",dialogRequestId:"f41f0b81-ec34-41bc-9aaf-61d30cf53c57"}
2017-09-12 21:16:39.345 [ c] 0 EventBuilder:buildJsonEventString:messageId=47ac372e-8607-4a44-8e9b-5ce05b4faf09,namespace=System,name=ExceptionEncountered
2017-09-12 21:16:39.345 [ 6] I DirectiveSequencer:onDirective:directive={"namespace:"AudioPlayer",name:"Play",messageId:"d4898f26-7041-4843-bd5b-32d6e7044e95",dialogRequestId:"f41f0b81-ec34-41bc-9aaf-61d30cf53c57"}
2017-09-12 21:16:39.346 [ c] I DirectiveRouter:preHandleDirective:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a,action=calling
2017-09-12 21:16:39.346 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a
2017-09-12 21:16:39.346 [ c] E SpeechSynthesizer:preHandleDirective:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a
2017-09-12 21:16:39.346 [ c] W DirectiveRouter:preHandleDirectiveFailed:messageId=866bf90e-1452-47ac-88df-cca356982894,reason=noHandlerRegistered
2017-09-12 21:16:39.346 [ c] I DirectiveSequencer:sendingExceptionEncountered:messageId=866bf90e-1452-47ac-88df-cca356982894
2017-09-12 21:16:39.347 [ c] 0 EventBuilder:buildJsonEventString:messageId=3eae2701-9da1-4fab-a7bc-2fcdfd0037b7,namespace=System,name=ExceptionEncountered
2017-09-12 21:16:39.347 [ c] I DirectiveRouter:preHandleDirective:messageId=d4898f26-7041-4843-bd5b-32d6e7044e95,action=calling
2017-09-12 21:16:39.348 [ c] 0 CapabilityAgent:addingMessageIdToMap:messageId=d4898f26-7041-4843-bd5b-32d6e7044e95
2017-09-12 21:16:39.348 [ 9] 0 SpeechSynthesizer:executePreHandle:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a
2017-09-12 21:16:39.348 [ d] I DirectiveRouter:handleDirective:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a,action=calling
2017-09-12 21:16:39.350 [ d] E SpeechSynthesizer:handleDirective:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a
2017-09-12 21:16:39.356 [ 9] 0 SpeechSynthesizer:executeHandle:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a
2017-09-12 21:16:39.357 [ e] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-09-12 21:16:39.357 [ 9] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-09-12 21:16:39.357 [ a] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-09-12 21:16:39.358 [ 9] E SpeechSynthesizer:startPlaying
2017-09-12 21:16:39.358 [ a] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2017-09-12 21:16:39.358 [ a] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-09-12 21:16:39.358 [ 9] E MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-09-12 21:16:39.358 [ 2] 0 MediaPlayer:handleSetSourceCalled
2017-09-12 21:16:39.358 [ 2] E MediaPlayer:tearDownPipeline
2017-09-12 21:16:39.440 [ 9] E MediaPlayer:playCalled
2017-09-12 21:16:39.443 [ 2] 0 MediaPlayer:handlePlayCalled
2017-09-12 21:16:39.443 [ 2] 0 MediaPlayer:doStopSuccess:reason=alreadyStopped
2017-09-12 21:16:39.443 [ 2] E MediaPlayer:doStopSuccess
2017-09-12 21:16:39.443 [ 2] 0 MediaPlayer:handlePlay:supportsBuffering=0
2017-09-12 21:16:39.448 [ 2] 0 MediaPlayer:handlePlay:stateReturn=ASYNC
2017-09-12 21:16:39.450 [ f] E BaseStreamSource:onNeedDataCalled:size=4096
2017-09-12 21:16:39.451 [ 5] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0e9837fffefbacf8-000060d6-00017614-961b5d8372fefa62-da279ef9-7
2017-09-12 21:16:39.451 [ 5] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-09-12 21:16:39.453 [ 2] E BaseStreamSource:handleNeedDataCalled
2017-09-12 21:16:39.453 [ 2] E BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=9
2017-09-12 21:16:39.454 [ 2] E AttachmentReaderSource:read:size=4096,status=0
2017-09-12 21:16:39.454 [ 2] E AttachmentReaderSource:read:size=3581,status=0
2017-09-12 21:16:39.454 [ 2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-09-12 21:16:39.455 [ 2] E AttachmentReaderSource:read:size=0,status=3
2017-09-12 21:16:39.455 [ 2] E BaseStreamSource:signalEndOfDataCalled
2017-09-12 21:16:39.456 [ 2] E BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=9
2017-09-12 21:16:39.486 [ f] E BaseStreamSource:onNeedDataCalled:size=4096
2017-09-12 21:16:39.486 [ 2] E BaseStreamSource:handleNeedDataCalled
2017-09-12 21:16:39.519 [ f] E MediaPlayer:onPadAddedCalled
2017-09-12 21:16:39.520 [ 2] E MediaPlayer:handlePadAddedSignalCalled
2017-09-12 21:16:39.543 [ 2] 0 MediaPlayer:callingOnPlaybackStarted
2017-09-12 21:16:39.543 [ 2] E SpeechSynthesizer:onPlaybackStarted
2017-09-12 21:16:39.543 [ 9] 0 SpeechSynthesizer:executePlaybackStarted
2017-09-12 21:16:39.543 [ 9] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-09-12 21:16:39.544 [ 9] E MediaPlayer:getOffsetInMillisecondsCalled
2017-09-12 21:16:39.544 [ 2] 0 MediaPlayer:handleGetOffsetInMillisecondsCalled
2017-09-12 21:16:39.545 [ 9] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.AudibleClientId#ACRI#DeviceTTSRendererV4_5105815d-aae6-497b-abac-484adf395834","offsetInMilliseconds":0,"playerActivity":"PLAYING"},namespace=SpeechSynthesizer,name=SpeechState
2017-09-12 21:16:39.546 [ 9] 0 EventBuilder:buildJsonEventString:messageId=79c39fb5-ba73-4696-be5b-86682a4f11da,namespace=SpeechSynthesizer,name=SpeechStarted
2017-09-12 21:16:39.547 [ e] E SpeechSynthesizer:onFocusChangedSuccess
2017-09-12 21:16:39.547 [ b] 0 DialogUXStateAggregator:setState:from=THINKING,to=SPEAKING
###########################

Speaking...

###########################
2017-09-12 21:16:39.560 [ 5] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0e9837fffefbacf8-000060d6-00017614-961b5d8372fefa62-da279ef9-9
2017-09-12 21:16:39.561 [ 5] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-09-12 21:16:40.113 [ 5] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0e9837fffefbacf8-000060d6-00017614-961b5d8372fefa62-da279ef9-11
2017-09-12 21:16:40.113 [ 5] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
detection loop heart beat ...
2017-09-12 21:16:40.841 [ 2] E BaseStreamSource:BaseStreamSource
2017-09-12 21:16:40.842 [ 2] 0 MediaPlayer:callingOnPlaybackFinished
2017-09-12 21:16:40.842 [ 2] E SpeechSynthesizer:onPlaybackFinished
2017-09-12 21:16:40.842 [ 9] 0 SpeechSynthesizer:executePlaybackFinished
2017-09-12 21:16:40.842 [ 9] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-09-12 21:16:40.842 [ 9] 0 ContextManager:updateStateLocked:action=updatedState,state={"token":"amzn1.as-ct.v1.AudibleClientId#ACRI#DeviceTTSRendererV4_5105815d-aae6-497b-abac-484adf395834","offsetInMilliseconds":0,"playerActivity":"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-09-12 21:16:40.842 [ 9] E SpeechSynthesizer:releaseForegroundFocus
2017-09-12 21:16:40.843 [ 9] 0 EventBuilder:buildJsonEventString:messageId=8c39c70c-b02d-4884-a3d1-38a0d00e3df6,namespace=SpeechSynthesizer,name=SpeechFinished
2017-09-12 21:16:40.843 [ e] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-09-12 21:16:40.843 [ 9] E SpeechSynthesizer:setHandlingCompleted
2017-09-12 21:16:40.843 [ 9] 0 DirectiveProcessor:onHandlingCompeted:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a,directiveBeingPreHandled=(nullptr)
2017-09-12 21:16:40.843 [ d] I DirectiveRouter:handleDirective:messageId=d4898f26-7041-4843-bd5b-32d6e7044e95,action=calling
2017-09-12 21:16:40.844 [ d] E AudioPlayer:handlePlayDirective
2017-09-12 21:16:40.844 [ 9] 0 CapabilityAgent:removingMessageIdFromMap:messageId=0a2ab5d0-14b1-4273-b1c5-41b3620b051a
2017-09-12 21:16:40.845 [ d] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=streamFormat
2017-09-12 21:16:40.846 [ d] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-09-12 21:16:40.849 [ 8] E AudioPlayer:executePlay:playBehavior=REPLACE_ALL
2017-09-12 21:16:40.850 [ 8] E AudioPlayer:executestop:m_currentActivity=IDLE
2017-09-12 21:16:40.851 [ 8] 0 DirectiveProcessor:onHandlingCompeted:messageId=d4898f26-7041-4843-bd5b-32d6e7044e95,directiveBeingPreHandled=(nullptr)
2017-09-12 21:16:40.851 [ e] E AudioPlayer:onFocusChanged:newFocus=FOREGROUND
onFocusChanged 0 newFocus
2017-09-12 21:16:40.851 [ 8] 0 CapabilityAgent:removingMessageIdFromMap:messageId=d4898f26-7041-4843-bd5b-32d6e7044e95
2017-09-12 21:16:40.852 [ 8] E AudioPlayer:executeOnFocusChanged:from=NONE,to=FOREGROUND
2017-09-12 21:16:40.852 [ 8] E AudioPlayer:executeOnFocusChanged:action=playNextItem
2017-09-12 21:16:40.852 [ 8] E MediaPlayer:setSourceForUrlCalled
2017-09-12 21:16:40.853 [ 10] 0 MediaPlayer:handleSetSourceForUrlCalled
2017-09-12 21:16:40.853 [ 10] E MediaPlayer:tearDownPipeline
2017-09-12 21:16:40.857 [ 10] E PlaylistParser:createCalled
2017-09-12 21:16:40.863 [ 10] 0 UrlSource:initCalledForUrlSource
2017-09-12 21:16:40.863 [ 10] E PlaylistParser:parsePlaylist:url=https://audiblecdn-vh.akamaihd.net/i/296060/audiblewords/content/bk/sans/007958/V$387218$V/aax/bk_sans_007958_22_32.mp4/master.m3u8?start=0&end=2&hdnea=st=1505250998exp=1505251058~acl=/i/296060/audiblewords/content/bk/sans/007958/V$387218$V/aax/bk_sans_007958_22_32.mp4/*~~data=0,2~~hmac=7278e4de4345ce5dccedc0c60bcde35fbe60f9881df54142a128b8493b315f0f
2017-09-12 21:16:40.863 [ 10] E PlaylistParser:createPlaylistInfo
2017-09-12 21:16:40.867 [ 11] E PlaylistParser:handleParsingLocked
2017-09-12 21:16:40.868 [ 8] E MediaPlayer:playCalled
2017-09-12 21:16:40.899 [ 2] E PlaylistParser:onParseComplete
2017-09-12 21:16:40.899 [ 2] E PlaylistParser:handleOnParseComplete
2017-09-12 21:16:40.900 [ 2] E PlaylistParser:playlistCouldNotBeHandled
2017-09-12 21:16:40.900 [ 2] 0 UrlSource:onPlaylistParsed:parseResult=PARSE_RESULT_UNHANDLED,numUrlsParsed=0
2017-09-12 21:16:40.901 [ 8] E PlaylistParser:destructorCalled
2017-09-12 21:16:40.904 [ 2] 0 MediaPlayer:handlePlayCalled
2017-09-12 21:16:40.904 [ 2] 0 MediaPlayer:doStopSuccess:reason=alreadyStopped
2017-09-12 21:16:40.904 [ 2] E MediaPlayer:doStopSuccess
2017-09-12 21:16:40.904 [ 2] 0 MediaPlayer:handlePlay:supportsBuffering=1
2017-09-12 21:16:41.049 [ b] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE
########################################

Alexa is currently idle!

########################################
2017-09-12 21:16:41.083 [ 5] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid: 0e9837fffefbacf8-000060d6-00017614-961b5d8372fefa62-da279ef9-13
2017-09-12 21:16:41.083 [ 5] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-09-12 21:16:41.233 [ 2] I MediaPlayer:Starting Buffering
2017-09-12 21:16:42.235 [ 12] E MediaPlayer:onPadAddedCalled
2017-09-12 21:16:42.236 [ 2] E MediaPlayer:handlePadAddedSignalCalled
2017-09-12 21:16:42.852 [ e] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=executorTimeout
2017-09-12 21:16:43.235 [ 8] E AudioPlayer:onFocusChangedFailed:reason=timedout,cause=notStarted

sanjayrd · 2017-09-12T22:24:14Z

Thank you all for the useful logs. I've been able to reproduce focus management issues in AudioPlayer. We will be digging into this as soon as possible to provide a potential fix.

shikha-bansal · 2017-09-15T18:08:29Z

any updates on this one ?

shikha-bansal · 2017-09-20T20:49:52Z

is this issue supposed to be fixed with 1.0.3 ?

frozenberg · 2017-09-20T22:02:15Z

Hi shikha-bansal,

The issue is not fixed in 1.0.3. I was able to reproduce your issue and I think I may have found a fix. The problem lies in the AudioPlayer making a call to releaseChannel and then never calling acquireChannel before playback starts.

You can try adding a check for if the FocusState is None in executeOnPlaybackStarted() and if it checks out making a call to acquireChannel

julianobRibeiro · 2017-09-21T01:52:39Z

Hi,

We are also still experiencing that issue on SDK V1.0.3.
From our analisys looks like the the problem is at AiduoPlayer.cpp on executePlay().
If focus is different form FOREGROUND AudioPlayer is requesting acquireChannel() for FocusManager.
AcquireChannel() will call setObserver() on Channel which will bring channel focus to NONE stopping PLAY directive that has just started to be proccesed on AudioPlayer.

if (FocusState::FOREGROUND == m_focus) { playNextItem(); } else if (!m_focusManager->acquireChannel(CHANNEL_NAME, shared_from_this(), ACTIVITY_ID)) { ACSDK_ERROR(LX("executePlayFailed") .d("reason", "CouldNotAcquireChannel")); sendPlaybackFailedEvent( m_token, ErrorType::MEDIA_ERROR_INTERNAL_DEVICE_ERROR, std::string("Could not acquire ") + CHANNEL_NAME + " for " + ACTIVITY_ID); return; }

Can you please evaluate the fix below where we are changing code above to request to acquire Channel only if Focus state is equal to NONE. That will avoid ask for require a channel while in BACKGROUND and
consecutively stop current PLAYBACK which was about to start.

if (FocusState::FOREGROUND == m_focus) { playNextItem(); } else if (m_focus == FocusState::NONE) { ACSDK_DEBUG9(LX("m_focus == avsCommon::avs::FocusState::NONE - acquireChannel() ")); if (!m_focusManager->acquireChannel(CHANNEL_NAME, shared_from_this(), ACTIVITY_ID)) { ACSDK_ERROR(LX("executePlayFailed") .d("reason", "CouldNotAcquireChannel")); sendPlaybackFailedEvent(m_token, ErrorType::MEDIA_ERROR_INTERNAL_DEVICE_ERROR, std::string("Could not acquire ") + CHANNEL_NAME + " for " + ACTIVITY_ID); return; } }

Thank you in advanced
Juliano

frozenberg · 2017-09-21T22:30:12Z

Hi julianobRibeiro,

After some introspection, the fix I originally suggested turned out to be a bit misguided. We don't want to make an additional call to acquireChannel at all, because the releaseChannel call that is screwing everything up should never have been made.

As a temporary fix, try saving the m_currentActivity to a temporary variable before the switch statement in executePlay, and then adding an || PlayerActivity::PAUSED == previousActivity to if (m_starting || PlayerActivity::PLAYING == previousActivity).

- Changes in this update: - Better GStreamer error reporting. MediaPlayer used to only report `MEDIA_ERROR_UNKNOWN`, now reports more specific errors as defined in `ErrorType.h`. - Codebase has been formatted for easier reading. - `DirectiveRouter::removeDirectiveHandler()` signature changed and now returns a bool indicating if given handler should be successfully removed or not. - Cleanup of raw and shared pointers in the creation of `Transport` objects. - `HTTP2Stream`s now have IDs assigned as they are acquired as opposed to created, making associated logs easier to interpret. - `AlertsCapabilityAgent` has been refactored. - Alert management has been factored out into an `AlertScheduler` class. - Creation of Reminder (implements Alert) class. - Added new capability agent for `PlaybackController` with unit tests. - Added Settings interface with unit tests. - Return type of `getOffsetInMilliseconds()` changed from `int64_t` to `std::chronology::milliseconds`. - Added `AudioPlayer` unit tests. - Added teardown for all Integration tests except Alerts. - Implemented PlaylistParser. - Bug fixes: - AIP getting stuck in `LISTENING` or `THINKING` and refusing user input on network outage. - SampleApp crashing if running for 5 minutes after network disconnect. - Issue where on repeated user barge-ins, `AudioPlayer` would not pause. Specifically, the third attempt to “Play iHeartRadio” would not result in currently-playing music pausing. - Utterances being ignored after particularly long TTS. - GStreamer errors cropping up on SampleApp exit as a result of accessing the pipeline before it’s been setup. - Crashing when playing one URL after another. - Buffer overrun in Alerts Renderer. - [SampleApp crashing when issuing "Alexa skip" command with iHeartRadio.](#153) - [`HTTP2Transport` network thread triggering a join on itself.](#127) - [`HTTP2Stream` request handling truncating exception messages.](#67) - [`AudioPlayer` was attempting an incorrect state transition from `STOPPED` to `PLAYING` through a `playbackResumed`.](#138)

kclchan · 2017-10-03T17:34:08Z

This issue is fixed in release v1.1.0. Thanks!

kclchan closed this as completed Oct 3, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Focus manager issue on AVS #138

Focus manager issue on AVS #138

simplistiq commented Sep 5, 2017

shikha-bansal commented Sep 5, 2017

shikha-bansal commented Sep 7, 2017

scotthea-amazon commented Sep 7, 2017

shikha-bansal commented Sep 7, 2017

scotthea-amazon commented Sep 7, 2017

shikha-bansal commented Sep 12, 2017

simplistiq commented Sep 12, 2017 •

edited

Loading

shikha-bansal commented Sep 12, 2017

shikha-bansal commented Sep 12, 2017

sanjayrd commented Sep 12, 2017

shikha-bansal commented Sep 15, 2017

shikha-bansal commented Sep 20, 2017

frozenberg commented Sep 20, 2017

julianobRibeiro commented Sep 21, 2017 •

edited

Loading

frozenberg commented Sep 21, 2017

kclchan commented Oct 3, 2017

Focus manager issue on AVS #138

Focus manager issue on AVS #138

Comments

simplistiq commented Sep 5, 2017

shikha-bansal commented Sep 5, 2017

Speaking...

shikha-bansal commented Sep 7, 2017

scotthea-amazon commented Sep 7, 2017

shikha-bansal commented Sep 7, 2017

scotthea-amazon commented Sep 7, 2017

shikha-bansal commented Sep 12, 2017

Listening...

Thinking...

Alexa is currently idle!

Speaking...

Alexa is currently idle!

simplistiq commented Sep 12, 2017 • edited Loading

shikha-bansal commented Sep 12, 2017

shikha-bansal commented Sep 12, 2017

Listening...

Thinking...

Speaking...

Alexa is currently idle!

sanjayrd commented Sep 12, 2017

shikha-bansal commented Sep 15, 2017

shikha-bansal commented Sep 20, 2017

frozenberg commented Sep 20, 2017

julianobRibeiro commented Sep 21, 2017 • edited Loading

frozenberg commented Sep 21, 2017

kclchan commented Oct 3, 2017

simplistiq commented Sep 12, 2017 •

edited

Loading

julianobRibeiro commented Sep 21, 2017 •

edited

Loading