caleighatamazon
commented
4 years ago Hello @cameled, this is a known issue in the SDK and we are already tracking it internally to fix in a future release. Thanks for reporting it.
If this is affecting certification, please reach out to your business associate at Amazon and we can discuss further.
Briefly summarize your issue:
We are working on the AVS certification self-test right now. When I doing the below test case, sometimes, the "thinking" state in step 5 not stop immediately, it's stoped by the default "timeoutForThinkingToIdle" timer.
What is the expected behavior?
The "thinking" state will always stop immediately in this test case(step 5) .
What behavior are you observing?
Sometimes, it's stopped after 8 seconds.
Provide the steps to reproduce the issue, if applicable:
I think it's caused by race condition for RequestProcessingStarted directive handle time point and RequestProcessingCompleted directive received time point. In other words, the short time (200ms) timer covered by the default 8-second timer. because onRequestProcessingStarted running too late.
I have captured a failed log, it's happened on 2020-08-16 16:04:31.624. In this log, you can find that RequestProcessingCompleted directive received before onRequestProcessingStarted running.
########################################
Alexa is currently idle!
########################################
@@@evecuteOnAVSEvent@@@EVT_AVS_IDLE 2020-08-16 16:03:50.812 [ 19] 5 FocusManager:releaseChannelHelper:channelToRelease=Dialog { MSG[0]: EVT_AVS_IDLE(11) } LightManager onEvent msg:EVT_AVS_IDLE 2020-08-16 16:03:50.812 [ 1b] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE 2020-08-16 16:03:50.812 [ 19] 5 Channel:removeActivityHelperLocked:interface=SpeechRecognizer 2020-08-16 16:03:50.812 [ 19] 0 Channel:addToChannelUpdatesLocked:interface=SpeechRecognizer,focusState=NONE 2020-08-16 16:03:50.812 [ c] 5 DialogUXStateAggregator:tryEnterIdleState 2020-08-16 16:03:50.813 [ 1b] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE 2020-08-16 16:03:50.813 [ 19] 5 Channel:setFocus:name=Dialog,newfocusState=NONE,prevfocusState=FOREGROUND,newMixingBehavior=MUST_STOP,forceUpdate=false 2020-08-16 16:03:50.813 [ 1b] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus 2020-08-16 16:03:50.813 [ 19] W Channel:notifyActivitiesFailed::No Associated Activities Found 2020-08-16 16:03:50.813 [ 1b] 0 AudioInputProcessor:executeResetState 2020-08-16 16:03:50.813 [ 19] 1 FocusManager:notifyActivityTracker:name=Dialog,interfaceName=SpeechRecognizer,focusState=NONE 2020-08-16 16:03:50.813 [ 19] 5 AudioActivityTracker:notifyOfActivityUpdates @@@evecuteOnAVSEvent@@@EVT_AVS_SPEAKER_IDLE { MSG[0]: EVT_AVS_SPEAKER_IDLE(77) } 2020-08-16 16:03:50.813 [ 18] 5 AudioActivityTracker:executeNotifyOfActivityUpdates LightManager onEvent msg:EVT_AVS_SPEAKER_IDLE { MSG[0]: EVT_SYS_STANDBY_ENTER(425) } LightManager onEvent msg:EVT_SYS_STANDBY_ENTER PowerManager enter standby ... 2020-08-16 16:03:51.326 [ 3c] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 9159a536-402a-4801-97ed-ef0d8e727022 2020-08-16 16:03:51.327 [ 3c] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 029767fffe36d1d3-0001bc1d-00c33231-a2651e0c9896ad7c-db2d5d1b-453 serialcomm_process:Receive timout, send cmd DBG_CODE_GET_LIVE_DATA again! 2020-08-16 16:04:21.327 [ 3d] 5 PingHandler:create:context=0x3392c0 2020-08-16 16:04:21.327 [ 3d] 5 ExchangeHandler:ExchangeHandler:context=0x3392c0 2020-08-16 16:04:21.327 [ 3d] 5 PingHandler:PingHandler:context=0x3392c0 2020-08-16 16:04:21.328 [ 3d] 5 PingHandler:getRequestHeaderLines 2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:onReceiveResponseCode:responseCode=204 2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:reportPingAcknowledged 2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:onReceiveHeaderLine:line=HTTP/2 204
2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:onReceiveHeaderLine:line=x-amzn-requestid\: becb2be1-c116-4470-8817-78c0d5197c27
2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:onReceiveHeaderLine:line=access-control-allow-origin\: *
2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:onReceiveHeaderLine:line=
2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:onResponseFinished:status=COMPLETE 2020-08-16 16:04:21.637 [ 3c] 5 PingHandler:reportPingAcknowledged alexa, start 54302560, end 54312320 2020-08-16 16:04:31.622 [ 4e] 5 DefaultClient:notifyOfWakeWord:keyword=alexa,connected=true @@@evecuteOnAVSEvent@@@EVT_FAE_ALEXA_WAKEUP { MSG[0]: EVT_FAE_ALEXA_WAKEUP(424) } LightManager onEvent msg:EVT_FAE_ALEXA_WAKEUP { MSG[0]: EVT_SYS_STANDBY_EXIT(426) } LightManager onEvent msg:EVT_SYS_STANDBY_EXIT PowerManager exit standby ... 2020-08-16 16:04:31.623 [ 1b] 0 AudioInputProcessor:notEncodingAudio 2020-08-16 16:04:31.623 [ 1b] 5 UserInactivityMonitor:onUserActive 2020-08-16 16:04:31.623 [ 1b] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING 2020-08-16 16:04:31.624 [ 1b] 5 ContextManager:getContext 2020-08-16 16:04:31.624 [ c] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING 2020-08-16 16:04:31.624 [ 1b] 0 AudioInputProcessor:executeRecognize:WW_DURATION(ms)=1110 @@@evecuteOnAVSEvent@@@EVT_AVS_SRC_START_LISTENING ############################
Listening...
############################
{ MSG[0]: EVT_AVS_SRC_START_LISTENING(63) } 2020-08-16 16:04:31.624 [ 2b] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=29 LightManager onEvent msg:EVT_AVS_SRC_START_LISTENING 2020-08-16 16:04:31.624 [ 9] 5 CallManager:provideState:stateRequestToken=29 @@@evecuteOnAVSEvent@@@EVT_AVS_LISTENING { MSG[0]: EVT_SRC_START_LISTENING(159) } LightManager onEvent msg:EVT_SRC_START_LISTENING 2020-08-16 16:04:31.624 [ 2b] 5 ExternalMediaPlayer:notifyRenderPlayerInfoCardsObservers { MSG[0]: EVT_AVS_LISTENING[22] } LightManager onEvent msg:EVT_AVS_LISTENING 2020-08-16 16:04:31.624 [ 9] 5 AudioActivityTracker:provideState 2020-08-16 16:04:31.624 [ 2b] 5 ContextManager:setState 2020-08-16 16:04:31.624 [ 27] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=29 2020-08-16 16:04:31.624 [ 18] 5 AudioActivityTracker:executeProvideState 2020-08-16 16:04:31.624 [ 9] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=29 2020-08-16 16:04:31.624 [ 27] 5 SipUserAgent:getSipUserAgentStateContext 2020-08-16 16:04:31.625 [ 18] 5 ContextManager:setState 2020-08-16 16:04:31.625 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.625 INFO ++++++++++:AlexaCommsService:getCurrentCallType 2020-08-16 16:04:31.625 [ 9] 5 ContextManager:sendContextIfReadyLocked:result=stateNotAvailableYet,pendingStates=5 2020-08-16 16:04:31.625 [ 26] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=29 2020-08-16 16:04:31.625 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.625 INFO AlexaCommsService:getCurrentCallType:callType=0 2020-08-16 16:04:31.625 [ 2b] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=29 2020-08-16 16:04:31.625 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.625 INFO ----------:AlexaCommsService:getCurrentCallType 2020-08-16 16:04:31.625 [ 2b] 5 ContextManager:setState 2020-08-16 16:04:31.625 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.625 INFO ++++++++++:AlexaCommsService:getSipUserAgentStateContext 2020-08-16 16:04:31.625 [ 26] 5 ContextManager:setState 2020-08-16 16:04:31.625 [ 9] 5 ContextManager:sendContextIfReadyLocked:result=stateNotAvailableYet,pendingStates=4 2020-08-16 16:04:31.625 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.625 INFO ++++++++++:CallControl:calculateEventJsonString 2020-08-16 16:04:31.626 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.626 INFO CallControl:calculateEventJsonString:sipUserAgentState=UNREGISTERED 2020-08-16 16:04:31.626 [ 9] 5 ContextManager:sendContextIfReadyLocked:result=stateNotAvailableYet,pendingStates=3 2020-08-16 16:04:31.626 [ 9] 5 ContextManager:sendContextIfReadyLocked:result=stateNotAvailableYet,pendingStates=2 2020-08-16 16:04:31.626 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.626 INFO ----------:CallControl:calculateEventJsonString 2020-08-16 16:04:31.626 [ 9] 5 ContextManager:sendContextIfReadyLocked:result=stateNotAvailableYet,pendingStates=1 2020-08-16 16:04:31.626 [ 27] I CallManager:commsMessage::2020-08-16 16:04:31.626 INFO ----------:AlexaCommsService:getSipUserAgentStateContext 2020-08-16 16:04:31.626 [ 27] 5 ContextManager:setState 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked:token=29 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.627 [ 9] 5 ContextManager:sendContextIfReadyLocked 2020-08-16 16:04:31.628 [ 9] 5 AVSContext:toJson 2020-08-16 16:04:31.629 [ 1b] 0 AudioInputProcessor:executeOnContextAvailable 2020-08-16 16:04:31.629 [ 1b] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer 2020-08-16 16:04:31.629 [ 19] 5 FocusManager:acquireChannelHelper:incomingChannel=Dialog,incomingInterface=SpeechRecognizer 2020-08-16 16:04:31.629 [ 1b] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=78d09754-2f5b-4ca7-a2b0-db6eb2f71a3f,newValue=ccc1892d-63d2-4354-8f4e-7ca25d235bd4 2020-08-16 16:04:31.629 [ 19] 5 Channel:setPrimaryActivity:Interface=SpeechRecognizer 2020-08-16 16:04:31.629 [ 1b] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=78d09754-2f5b-4ca7-a2b0-db6eb2f71a3f 2020-08-16 16:04:31.629 [ 19] 5 Channel:setFocus:name=Dialog,newfocusState=FOREGROUND,prevfocusState=NONE,newMixingBehavior=PRIMARY,forceUpdate=false 2020-08-16 16:04:31.629 [ 19] 0 Channel:addToChannelUpdatesLocked:interface=SpeechRecognizer,focusState=FOREGROUND @@@evecuteOnAVSEvent@@@EVT_AVS_SPEAKER_BUSY { MSG[0]: EVT_AVS_SPEAKER_BUSY(78) } 2020-08-16 16:04:31.629 [ 19] 1 FocusManager:notifyActivityTracker:name=Dialog,interfaceName=SpeechRecognizer,focusState=FOREGROUND LightManager onEvent msg:EVT_AVS_SPEAKER_BUSY 2020-08-16 16:04:31.629 [ 19] 5 AudioActivityTracker:notifyOfActivityUpdates { MSG[0]: EVT_SYS_STANDBY_EXIT(426) } LightManager onEvent msg:EVT_SYS_STANDBY_EXIT PowerManager exit standby ... 2020-08-16 16:04:31.630 [ 18] 5 AudioActivityTracker:executeNotifyOfActivityUpdates 2020-08-16 16:04:31.630 [ 1b] 0 EventBuilder:buildJsonEventString:messageId=bc0a78c7-1227-4958-a558-1f3566ec0ce2,namespace=SpeechRecognizer,name=Recognize 2020-08-16 16:04:31.630 [ 1b] 0 EventBuilder:buildJsonEventString:event={"context"\:{"properties"\:[{"namespace"\:"Alerts"\,"name"\:"AlertsState"\,"value"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}\,"timeOfSample"\:"2020-08-16T15\:07\:56.236Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"Alexa.PlaybackStateReporter"\,"name"\:"playbackState"\,"value"\:{"state"\:"IDLE"\,"supportedOperations"\:[]\,"shuffle"\:"NOT_SHUFFLED"\,"repeat"\:"NOT_REPEATED"\,"favorite"\:"NOT_RATED"\,"positionMilliseconds"\:0\,"players"\:[{"playerId"\:"Spotify\:ESDK"\,"state"\:"IDLE"\,"supportedOperations"\:[]\,"positionMilliseconds"\:0\,"shuffle"\:"NOT_SHUFFLED"\,"repeat"\:"NOT_REPEATED"\,"favorite"\:"NOT_RATED"\,"media"\:{"type"\:""\,"value"\:{"playbackSource"\:""\,"playbackSourceId"\:""\,"trackName"\:""\,"trackId"\:""\,"trackNumber"\:""\,"artist"\:""\,"artistId"\:""\,"album"\:""\,"albumId"\:""\,"coverUrls"\:{"tiny"\:""\,"small"\:""\,"medium"\:""\,"large"\:""}\,"coverId"\:""\,"mediaProvider"\:""\,"mediaType"\:"TRACK"\,"durationInMilliseconds"\:0}}}]}\,"timeOfSample"\:"2020-08-16T16\:04\:31.625Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"AudioActivityTracker"\,"name"\:"ActivityState"\,"value"\:{"content"\:{"interface"\:"AudioPlayer"\,"idleTimeInMilliseconds"\:40930}\,"dialog"\:{"interface"\:"SpeechSynthesizer"\,"idleTimeInMilliseconds"\:95800}}\,"timeOfSample"\:"2020-08-16T16\:04\:31.625Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"\,"value"\:{"token"\:"amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#7cef8f31-635f-4eda-a128-572f74ab79b5\:1"\,"offsetInMilliseconds"\:52748\,"playerActivity"\:"STOPPED"}\,"timeOfSample"\:"2020-08-16T16\:03\:50.693Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"Bluetooth"\,"name"\:"BluetoothState"\,"value"\:{"alexaDevice"\:{"friendlyName"\:"Lavazza Voicy-a128"}\,"pairedDevices"\:[]}\,"timeOfSample"\:"2020-08-16T15\:07\:56.395Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"ExternalMediaPlayer"\,"name"\:"ExternalMediaPlayerState"\,"value"\:{"playerInFocus"\:""\,"players"\:[{"playerId"\:"Spotify\:ESDK"\,"endpointId"\:"63e5c52754597c5402c13e1ac2235d892b5a29c7"\,"loggedIn"\:false\,"username"\:""\,"isGuest"\:false\,"launched"\:true\,"active"\:false}]}\,"timeOfSample"\:"2020-08-16T16\:04\:31.626Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"Notifications"\,"name"\:"IndicatorState"\,"value"\:{"isEnabled"\:false\,"isVisualIndicatorPersisted"\:false}\,"timeOfSample"\:"2020-08-16T16\:04\:31.626Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"SipUserAgent"\,"name"\:"SipUserAgentState"\,"value"\:{"sipUserAgentState"\:"UNREGISTERED"\,"deprecated"\:{"state"\:{"callState"\:"INACTIVE"\,"caller"\:{"id"\:""}\,"callee"\:{"id"\:""}\,"callActive"\:{"id"\:""}\,"isDropIn"\:false\,"metrics"\:{"audio"\:{"callRxTotalPackets"\:0\,"callRxTotalBytes"\:0\,"callRxPacketLoss"\:0\,"callRxAvgJitterUsec"\:0\,"callRxAvgLossPeriodUsec"\:0\,"callTxTotalPackets"\:0\,"callTxTotalBytes"\:0\,"callTxPacketLoss"\:0\,"callTxAvgJitterUsec"\:0\,"callTxAvgLossPeriodUsec"\:0\,"callRoundTripDelayUsec"\:0\,"callAvgJitterBuffDepth"\:0}\,"timestamp"\:{"deviceSentAbsoluteTimestamp"\:"1597593871625"\,"deviceSentRelativeTimestamp"\:"3414686"}}}\,"debug"\:{"utteranceInfo"\:{"endOfSpeechAbsoluteTimestampInMillis"\:0\,"endOfSpeechRelativeTimestampInMillis"\:0}}}}\,"timeOfSample"\:"2020-08-16T16\:04\:31.626Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"Speaker"\,"name"\:"VolumeState"\,"value"\:{"volume"\:30\,"muted"\:false}\,"timeOfSample"\:"2020-08-16T15\:07\:56.420Z"\,"uncertaintyInMilliseconds"\:0}\,{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"\,"value"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRendererV4_0a222933-28f9-4636-aac2-85dd57e17e84"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}\,"timeOfSample"\:"2020-08-16T16\:02\:55.622Z"\,"uncertaintyInMilliseconds"\:0}]}\,"event"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"Recognize"\,"messageId"\:"bc0a78c7-1227-4958-a558-1f3566ec0ce2"\,"dialogRequestId"\:"ccc1892d-63d2-4354-8f4e-7ca25d235bd4"}\,"payload"\:{"profile"\:"NEAR_FIELD"\,"format"\:"AUDIO_L16_RATE_16000_CHANNELS_1"\,"initiator"\:{"type"\:"WAKEWORD"\,"payload"\:{"wakeWordIndices"\:{"startIndexInSamples"\:8000\,"endIndexInSamples"\:17760}\,"wakeWord"\:"ALEXA"}}\,"startOfSpeechTimestamp"\:"3414683411835"}}} 2020-08-16 16:04:31.630 [ 1b] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND 2020-08-16 16:04:31.630 [ 1b] 0 AudioInputProcessor:sendRequestNow 2020-08-16 16:04:31.630 [ 3d] 5 ExchangeHandler:ExchangeHandler:context=0x3392c0 2020-08-16 16:04:33.702 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2020-08-16 16:04:33.703 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=payloadVersion 2020-08-16 16:04:33.703 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2020-08-16 16:04:33.703 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=eventCorrelationToken 2020-08-16 16:04:33.703 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2020-08-16 16:04:33.703 [ d] 0 AvsDirective:parseEndpoint::noEndpoint 2020-08-16 16:04:33.703 [ d] I DirectiveSequencer:onDirective:directive=namespace\:SpeechRecognizer\,name\:StopCapture\,messageId\:3d6bca8e-73a9-406b-ae66-f1b7572daff1\,dialogRequestId\:ccc1892d-63d2-4354-8f4e-7ca25d235bd4\,correlationToken\:\,eventCorrelationToken\:\,payloadVersion\:\,instance\: 2020-08-16 16:04:33.703 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:33.703 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:33.704 [ 4f] I DirectiveRouter:preHandleDirective:messageId=3d6bca8e-73a9-406b-ae66-f1b7572daff1,action=calling 2020-08-16 16:04:33.704 [ 4f] 0 CapabilityAgent:addingMessageIdToMap:messageId=3d6bca8e-73a9-406b-ae66-f1b7572daff1 2020-08-16 16:04:33.704 [ 50] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:33.704 [ 50] I DirectiveRouter:handleDirective:messageId=3d6bca8e-73a9-406b-ae66-f1b7572daff1,action=calling 2020-08-16 16:04:33.704 [ 1b] 0 AudioInputProcessor:stopCapture:stopImmediately=true 2020-08-16 16:04:33.704 [ 1b] 5 UserInactivityMonitor:onUserActive 2020-08-16 16:04:33.705 [ 1b] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY 2020-08-16 16:04:33.705 [ 1b] 0 DirectiveProcessor:onHandlingCompeted:messageId=3d6bca8e-73a9-406b-ae66-f1b7572daff1,directiveBeingPreHandled=(nullptr) 2020-08-16 16:04:33.705 [ 1b] 0 CapabilityAgent:removingMessageIdFromMap:messageId=3d6bca8e-73a9-406b-ae66-f1b7572daff1 2020-08-16 16:04:33.713 [ 3c] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: a4e9ad33-a7f5-4cae-9db5-90b1f9fbb6b3 2020-08-16 16:04:33.713 [ 3c] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 029767fffe36d1d3-0001bc1d-00c33231-a2651e0c9896ad7c-db2d5d1b-457 2020-08-16 16:04:33.714 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2020-08-16 16:04:33.714 [ 3c] 0 DefaultAttachmentReader:readFailed:reason=SDS is closed 2020-08-16 16:04:33.714 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=payloadVersion 2020-08-16 16:04:33.714 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2020-08-16 16:04:33.714 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=eventCorrelationToken 2020-08-16 16:04:33.714 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2020-08-16 16:04:33.714 [ d] 0 AvsDirective:parseEndpoint::noEndpoint 2020-08-16 16:04:33.714 [ d] I DirectiveSequencer:onDirective:directive=namespace\:SpeechRecognizer\,name\:SetEndOfSpeechOffset\,messageId\:db5e0487-f3d2-4945-8688-bcb98a2b14c3\,dialogRequestId\:ccc1892d-63d2-4354-8f4e-7ca25d235bd4\,correlationToken\:\,eventCorrelationToken\:\,payloadVersion\:\,instance\: 2020-08-16 16:04:33.715 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:33.715 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:33.715 [ 4f] I DirectiveRouter:preHandleDirective:messageId=db5e0487-f3d2-4945-8688-bcb98a2b14c3,action=calling 2020-08-16 16:04:33.715 [ 4f] 0 CapabilityAgent:addingMessageIdToMap:messageId=db5e0487-f3d2-4945-8688-bcb98a2b14c3 2020-08-16 16:04:33.715 [ 50] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:33.715 [ 50] I DirectiveRouter:handleDirective:messageId=db5e0487-f3d2-4945-8688-bcb98a2b14c3,action=calling 2020-08-16 16:04:33.716 [ 50] 0 AudioInputProcessor:handleSetEndOfSpeechOffsetDirective:startTimeSpeech(ms)=3414683411835,endTimeSpeech(ms)=3414683414245 2020-08-16 16:04:33.716 [ 50] 0 DirectiveProcessor:onHandlingCompeted:messageId=db5e0487-f3d2-4945-8688-bcb98a2b14c3,directiveBeingPreHandled=(nullptr) 2020-08-16 16:04:33.716 [ 50] 0 CapabilityAgent:removingMessageIdFromMap:messageId=db5e0487-f3d2-4945-8688-bcb98a2b14c3 2020-08-16 16:04:34.539 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2020-08-16 16:04:34.539 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=payloadVersion 2020-08-16 16:04:34.539 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2020-08-16 16:04:34.540 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=eventCorrelationToken 2020-08-16 16:04:34.540 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2020-08-16 16:04:34.540 [ d] 0 AvsDirective:parseEndpoint::noEndpoint 2020-08-16 16:04:34.540 [ d] I DirectiveSequencer:onDirective:directive=namespace\:InteractionModel\,name\:RequestProcessingStarted\,messageId\:cead6651-50e1-4051-b8bb-316d6bdeb99a\,dialogRequestId\:ccc1892d-63d2-4354-8f4e-7ca25d235bd4\,correlationToken\:\,eventCorrelationToken\:\,payloadVersion\:\,instance\: 2020-08-16 16:04:34.540 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.540 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.540 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2020-08-16 16:04:34.540 [ 4f] I DirectiveRouter:preHandleDirective:messageId=cead6651-50e1-4051-b8bb-316d6bdeb99a,action=calling 2020-08-16 16:04:34.540 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=payloadVersion 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=eventCorrelationToken 2020-08-16 16:04:34.541 [ 4f] 0 CapabilityAgent:addingMessageIdToMap:messageId=cead6651-50e1-4051-b8bb-316d6bdeb99a 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2020-08-16 16:04:34.541 [ d] 0 AvsDirective:parseEndpoint::noEndpoint 2020-08-16 16:04:34.541 [ 3c] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS 2020-08-16 16:04:34.541 [ 50] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.541 [ 3c] 5 AudioInputProcessor:stopCapture:reason=streamClosed 2020-08-16 16:04:34.541 [ d] I DirectiveSequencer:onDirective:directive=namespace\:AudioPlayer\,name\:Play\,messageId\:1db9d54f-932b-4226-a104-e25c2a9767bd\,dialogRequestId\:ccc1892d-63d2-4354-8f4e-7ca25d235bd4\,correlationToken\:\,eventCorrelationToken\:\,payloadVersion\:\,instance\: 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=payloadVersion 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=eventCorrelationToken 2020-08-16 16:04:34.541 [ d] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2020-08-16 16:04:34.542 [ d] 0 AvsDirective:parseEndpoint::noEndpoint 2020-08-16 16:04:34.542 [ d] I DirectiveSequencer:onDirective:directive=namespace\:InteractionModel\,name\:RequestProcessingCompleted\,messageId\:29d644bb-3c9d-4c0e-9347-6344e721ef66\,dialogRequestId\:ccc1892d-63d2-4354-8f4e-7ca25d235bd4\,correlationToken\:\,eventCorrelationToken\:\,payloadVersion\:\,instance\: 2020-08-16 16:04:34.541 [ 50] I DirectiveRouter:handleDirective:messageId=cead6651-50e1-4051-b8bb-316d6bdeb99a,action=calling 2020-08-16 16:04:34.542 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.542 [ 50] 5 InteractionModel:handleDirective 2020-08-16 16:04:34.542 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.542 [ 50] 5 InteractionModel:handleDirectiveHelper 2020-08-16 16:04:34.542 [ 4f] I DirectiveRouter:preHandleDirective:messageId=1db9d54f-932b-4226-a104-e25c2a9767bd,action=calling 2020-08-16 16:04:34.542 [ 50] 0 DialogUXStateAggregator:onRequestProcessingStarted 2020-08-16 16:04:34.542 [ 50] 0 DirectiveProcessor:onHandlingCompeted:messageId=cead6651-50e1-4051-b8bb-316d6bdeb99a,directiveBeingPreHandled=1db9d54f-932b-4226-a104-e25c2a9767bd 2020-08-16 16:04:34.542 [ 4f] 0 CapabilityAgent:addingMessageIdToMap:messageId=1db9d54f-932b-4226-a104-e25c2a9767bd 2020-08-16 16:04:34.542 [ 50] 0 CapabilityAgent:removingMessageIdFromMap:messageId=cead6651-50e1-4051-b8bb-316d6bdeb99a 2020-08-16 16:04:34.542 [ c] 0 DialogUXStateAggregator:onRequestProcessingStartedLambda:currentState=LISTENING 2020-08-16 16:04:34.542 [ 4f] 5 AudioPlayer:preHandleDirective:name=Play,messageId=1db9d54f-932b-4226-a104-e25c2a9767bd 2020-08-16 16:04:34.542 [ c] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING 2020-08-16 16:04:34.542 [ 4f] 1 AudioPlayer:preHandlePlayDirective 2020-08-16 16:04:34.543 [ 4f] 5 JsonUtils:findNode:reason=missingDirectChild,child=streamFormat @@@evecuteOnAVSEvent@@@EVT_AVS_SRC_STOP_LISTENING 2020-08-16 16:04:34.543 [ 4f] 5 JsonUtils:findNode:reason=missingDirectChild,child=progressReportIntervalInMilliseconds @@@evecuteOnAVSEvent@@@EVT_AVS_THINKING { MSG[0]: EVT_AVS_SRC_STOP_LISTENING(64) } ###########################
Thinking...
###########################
LightManager onEvent msg:EVT_AVS_SRC_STOP_LISTENING { MSG[1]: EVT_AVS_THINKING[22] } LightManager onEvent msg:EVT_AVS_THINKING 2020-08-16 16:04:34.543 [ 4f] 5 JsonUtils:findNode:reason=missingDirectChild,child=expectedPreviousToken { MSG[0]: EVT_SRC_STOP_LISTENING(160) } 2020-08-16 16:04:34.543 [ 4f] 5 AudioPlayer:captionsNotParsed:reason=captionManagerIsNull LightManager onEvent msg:EVT_SRC_STOP_LISTENING 2020-08-16 16:04:34.543 [ 4f] 5 JsonUtils:findNode:reason=missingDirectChild,child=playRequestor 2020-08-16 16:04:34.543 [ 50] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.543 [ 1f] 1 AudioPlayer:executePrePlay:messageId=1db9d54f-932b-4226-a104-e25c2a9767bd,preBufferBehavior=REPLACE_ALL 2020-08-16 16:04:34.544 [ 50] I DirectiveRouter:handleDirective:messageId=1db9d54f-932b-4226-a104-e25c2a9767bd,action=calling 2020-08-16 16:04:34.544 [ 1f] 0 AudioPlayer:executePrePlay::acquiringPlayerSetSource 2020-08-16 16:04:34.544 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.544 [ 50] 5 AudioPlayer:handleDirective:name=Play,messageId=1db9d54f-932b-4226-a104-e25c2a9767bd 2020-08-16 16:04:34.544 [ 4f] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.544 [ 51] 0 MediaPlayer:handleSetSourceForUrlCalled:name=AudioMediaPlayer 2020-08-16 16:04:34.544 [ 50] 1 AudioPlayer:handlePlayDirective 2020-08-16 16:04:34.544 [ 4f] I DirectiveRouter:preHandleDirective:messageId=29d644bb-3c9d-4c0e-9347-6344e721ef66,action=calling 2020-08-16 16:04:34.544 [ 50] 0 DirectiveProcessor:onHandlingCompeted:messageId=1db9d54f-932b-4226-a104-e25c2a9767bd,directiveBeingPreHandled=29d644bb-3c9d-4c0e-9347-6344e721ef66 2020-08-16 16:04:34.544 [ 50] 0 CapabilityAgent:removingMessageIdFromMap:messageId=1db9d54f-932b-4226-a104-e25c2a9767bd 2020-08-16 16:04:34.544 [ 4f] 0 CapabilityAgent:addingMessageIdToMap:messageId=29d644bb-3c9d-4c0e-9347-6344e721ef66 2020-08-16 16:04:34.544 [ 50] 5 DirectiveRouter:getHandlerAndPolicyLocked::configuration found 2020-08-16 16:04:34.544 [ 50] I DirectiveRouter:handleDirective:messageId=29d644bb-3c9d-4c0e-9347-6344e721ef66,action=calling 2020-08-16 16:04:34.544 [ 50] 5 InteractionModel:handleDirective 2020-08-16 16:04:34.544 [ 50] 5 InteractionModel:handleDirectiveHelper 2020-08-16 16:04:34.545 [ 50] 0 DirectiveProcessor:onHandlingCompeted:messageId=29d644bb-3c9d-4c0e-9347-6344e721ef66,directiveBeingPreHandled=(nullptr) 2020-08-16 16:04:34.545 [ 50] 0 CapabilityAgent:removingMessageIdFromMap:messageId=29d644bb-3c9d-4c0e-9347-6344e721ef66 2020-08-16 16:04:34.546 [ 51] 0 MediaPlayer:handleSetAttachmentReaderSourceCalled:name=AudioMediaPlayer 2020-08-16 16:04:34.547 [ 51] 5 MediaPlayer:configureSource:fadeIn=fadeIn{ enabled:0, start:100, end:100, duration(ms):0} 2020-08-16 16:04:34.547 [ 1f] 5 AudioPlayer:configureMediaPlayer:sourceId=28,audioItemId=amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#7cef8f31-635f-4eda-a128-572f74ab79b5\:1 2020-08-16 16:04:34.547 [ 51] 0 MediaPlayer:handleAddObserverCalled:name=AudioMediaPlayer 2020-08-16 16:04:34.548 [ 1f] I AudioPlayer:executePrePlay:enqueuing=amzn1.as-ct.v1.Dee-Domain-Music#ACRI#url#ACRI#7cef8f31-635f-4eda-a128-572f74ab79b5\:1,sourceId=28,messageId=1db9d54f-932b-4226-a104-e25c2a9767bd 2020-08-16 16:04:34.548 [ 1f] 1 AudioPlayer:executePlay 2020-08-16 16:04:34.548 [ 1f] 1 AudioPlayer:executeStop:playNextItem=true,m_currentActivity=STOPPED,sourceId=27 2020-08-16 16:04:34.548 [ 1f] 1 FocusManager:acquireChannel:channelName=Content,interface=AudioPlayer 2020-08-16 16:04:34.548 [ 1f] I AudioPlayer:executePlay:acquiring Channel=Content 2020-08-16 16:04:34.548 [ 19] 5 FocusManager:acquireChannelHelper:incomingChannel=Content,incomingInterface=AudioPlayer 2020-08-16 16:04:34.548 [ 19] 5 Channel:setPrimaryActivity:Interface=AudioPlayer 2020-08-16 16:04:34.548 [ 19] I InterruptModel:getMixingBehavior:lowPriochannel=Content,lowPrioContentType=MIXABLE,highPrioChannel=Dialog,highPrioContentType=MIXABLE 2020-08-16 16:04:34.548 [ 19] 5 Channel:setFocus:name=Content,newfocusState=BACKGROUND,prevfocusState=NONE,newMixingBehavior=MUST_PAUSE,forceUpdate=false 2020-08-16 16:04:34.548 [ 19] 0 Channel:addToChannelUpdatesLocked:interface=AudioPlayer,focusState=BACKGROUND 2020-08-16 16:04:34.548 [ 19] 0 AudioPlayer:onFocusChanged:newFocus=BACKGROUND,MixingBehavior=MUST_PAUSE 2020-08-16 16:04:34.548 [ 1f] 1 AudioPlayer:executeOnFocusChanged:from=NONE,to=BACKGROUND,m_currentActivity=STOPPED @@@evecuteOnAVSEvent@@@EVT_AVS_SPEAKER_BUSY 2020-08-16 16:04:34.549 [ 1f] 1 AudioPlayer:executeOnFocusChanged:action=pauseMediaPlayer { MSG[0]: EVT_AVS_SPEAKER_BUSY(78) } LightManager onEvent msg:EVT_AVS_SPEAKER_BUSY 2020-08-16 16:04:34.549 [ 19] 1 FocusManager:notifyActivityTracker:name=Content,interfaceName=AudioPlayer,focusState=BACKGROUND { MSG[0]: EVT_SYS_STANDBY_EXIT(426) } 2020-08-16 16:04:34.549 [ 19] 5 AudioActivityTracker:notifyOfActivityUpdates 2020-08-16 16:04:34.549 [ 55] 0 MediaPlayer:handlePauseCalled:name=AudioMediaPlayer,idPassed=27,currentId=0 2020-08-16 16:04:34.549 [ 55] E MediaPlayer:validateSourceAndIdFailed:name=AudioMediaPlayer,reason=sourceNotSet 2020-08-16 16:04:34.549 [ 55] E MediaPlayer:handlePauseFailed:name=AudioMediaPlayer LightManager onEvent msg:EVT_SYS_STANDBY_EXIT PowerManager exit standby ... 2020-08-16 16:04:34.549 [ 18] 5 AudioActivityTracker:executeNotifyOfActivityUpdates 2020-08-16 16:04:36.579 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.579 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.579 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.580 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.581 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=STILL_ONGOING 2020-08-16 16:04:36.581 [ 9b] 3 UrlContentToAttachmentConverter:onPlaylistEntryParsed:status=FINISHED 2020-08-16 16:04:42.543 [ c] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut 2020-08-16 16:04:42.543 [ c] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE 2020-08-16 16:04:42.544 [ 1b] 1 FocusManager:releaseChannel:channelName=Dialog ########################################
Alexa is currently idle!
########################################
Tell us about your environment:
What version of the AVS Device SDK are you using?
Tell us what hardware you're using:
Tell us about your OS (Type & version):