search

alexa / avs-device-sdk

An SDK for commercial device makers to integrate Alexa directly into connected products.
https://developer.amazon.com/alexa/alexa-voice-service
Apache License 2.0
1.26k stars 601 forks source link

issue about notification #974

Closed bill-lzb closed 5 years ago

bill-lzb commented 5 years ago

IMPORTANT: Before you create an issue, please take a look at our Issue Reporting Guide.

Briefly summarize your issue:

1)I said "Alexa, open QuoteMaker" 2)Alexa asked me "Would you like to set a notification for your self?" 3)I said "Yes" 4)DialogUXState Changed to Speaking, but no sound is output. 5)The notification indicator was set to ON. 6)Then I said "Alexa, why is the sky blue?" 7)DialogUXState changed to "Thinking", then "Speaking", then "Idle", but no sound is output. 8)Then I said "Alexa, what are my notifications?" 9)DialogUXState changed to "Thinking", then "Speaking", then "Idle", the notification indicator changed to OFF, but no sound was output. 10)Then I said "Alexa, why is the sky blue?". 11)I can hear the answer from AVS.

That's to say, if I set a notification via QuoteMaker, sound output will become disabled until the notification is cleared.

What is the expected behavior?

After I set a notification via QuoteMaker, I expect to hear some information about the notification and an audio cue. And after a notification was set, it should not disable the sound output.

What behavior are you observing?

Please refer to step 4) ,7) and 9)

Provide the steps to reproduce the issue, if applicable:

Please refer to the above steps.

Tell us about your environment:

What version of the AVS Device SDK are you using?

  <1.9.0>

Tell us what hardware you're using:

Tell us about your OS (Type & version):

scotthea-amazon commented 5 years ago

Hello bill-lzb,

Would you please provide us DEBUG9 level logs for a reproduction of this problem?

Thank you, -SWH

bill-lzb commented 5 years ago

The problem is not 100% reproduce.

The logs of step1 to step9 are as bellow: Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.175 [ 11] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=2715d5c5-4ff1-4613-8165-070a7f7202e6 Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.175 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.175 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.175 [ 11] 0 EventBuilder:buildJsonEventString:messageId=8c550e16-1c30-42e9-a353-02c7356121dd,namespace=SpeechRecognizer,name=Recognize Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.176 [ 11] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:10 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:49:10 m3ulcb avs-service-app[4718]: # Listening... # Sep 21 02:49:10 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.194 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.195 [ a] 0 HTTP2StreamPool:getStream:streamId=47,numAcquiredStreams=2 Sep 21 02:49:10 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:10.195 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff58039f50 Sep 21 02:49:11 m3ulcb mender[4461]: level=error msg="Failure occured while executing authorization request: &url.Error{Op:\"Post\", URL:\"https://docker.mender.io/api/devices/v1/authentication/auth_requests\", Err:(net.OpError)(0x44203d38b0)}" module="client_auth" Sep 21 02:49:11 m3ulcb mender[4461]: level=error msg="authorization request error: dial tcp 192.168.160.128:443: getsockopt: connection timed out" module="client_auth" Sep 21 02:49:11 m3ulcb mender[4461]: time="2018-09-21T02:49:11Z" level=error msg="Failure occured while executing authorization request: &url.Error{Op:\"Post\", URL:\"https://docker.mender.io/api/devices/v1/authentication/auth_requests\", Err:(net.OpError)(0x44203d38b0)}" module="client_auth" Sep 21 02:49:11 m3ulcb mender[4461]: time="2018-09-21T02:49:11Z" level=error msg="authorization request error: dial tcp 192.168.160.128:443: getsockopt: connection timed out" module="client_auth" Sep 21 02:49:11 m3ulcb mender[4461]: time="2018-09-21T02:49:11Z" level=error msg="authorize failed: transient error: authorization request failed: generic error occured while executing authorization request: Post https://docker.mender.io/api/devices/v1/authentication/auth_requests: dial tcp 192.168.160.128:443: getsockopt: connection timed out" module=state Sep 21 02:49:11 m3ulcb mender[4461]: time="2018-09-21T02:49:11Z" level=info msg="State transition: authorize [Sync] -> authorize-wait [Idle]" module=mender Sep 21 02:49:11 m3ulcb mender[4461]: level=error msg="authorize failed: transient error: authorization request failed: generic error occured while executing authorization request: Post https://docker.mender.io/api/devices/v1/authentication/auth_requests: dial tcp 192.168.160.128:443: getsockopt: connection timed out" module=state Sep 21 02:49:11 m3ulcb mender[4461]: level=info msg="State transition: authorize [Sync] -> authorize-wait [Idle]" module=mender Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.008 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"f55ac987-50d8-4053-9a3b-443be1448e4f"\,dialogRequestId\:"a9276668-4246-491b-aafc-8d28cfcec33d"} Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.009 [ 15] I DirectiveRouter:preHandleDirective:messageId=f55ac987-50d8-4053-9a3b-443be1448e4f,action=calling Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.009 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=f55ac987-50d8-4053-9a3b-443be1448e4f Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.010 [ 17] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.014 [ 1c] I DirectiveRouter:handleDirective:messageId=f55ac987-50d8-4053-9a3b-443be1448e4f,action=calling Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.015 [ 11] 5 UserInactivityMonitor:onUserActive Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.017 [ 11] 0 DirectiveProcessor:onHandlingCompeted:messageId=f55ac987-50d8-4053-9a3b-443be1448e4f,directiveBeingPreHandled=(nullptr) Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.017 [ 11] 0 CapabilityAgent:removingMessageIdFromMap:messageId=f55ac987-50d8-4053-9a3b-443be1448e4f Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.017 [ 7] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING Sep 21 02:49:14 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : THINKING Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.017 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=THINKING Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.018 [ a] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:14 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:14 m3ulcb avs-service-app[4718]: # Thinking... # Sep 21 02:49:14 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:14 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:14.596 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-47 [ 182.892378] retire_capture_urb: 92 callbacks suppressed Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.063 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"8dc9e519-2c57-4b60-a86f-73d07a6291bf"\,dialogRequestId\:"a9276668-4246-491b-aafc-8d28cfcec33d"} Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.063 [ 15] I DirectiveRouter:preHandleDirective:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf,action=calling Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.064 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.064 [ 15] 9 SpeechSynthesizer:preHandleDirective:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.064 [ 1c] I DirectiveRouter:handleDirective:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf,action=calling Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.064 [ 1c] 9 SpeechSynthesizer:handleDirective:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.064 [ 10] 0 SpeechSynthesizer:executePreHandle:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.066 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"ExpectSpeech"\,messageId\:"718afa93-4cdc-40d2-bad0-1c5ed567797b"\,dialogRequestId\:"a9276668-4246-491b-aafc-8d28cfcec33d"} Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.066 [ 15] I DirectiveRouter:preHandleDirective:messageId=718afa93-4cdc-40d2-bad0-1c5ed567797b,action=calling Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.066 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=718afa93-4cdc-40d2-bad0-1c5ed567797b Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.068 [ 10] 0 SpeechSynthesizer:executeHandle:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.068 [ 10] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.069 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=47,result=200 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.069 [ a] 0 HTTP2StreamPool:releaseStream:streamId=47,numAcquiredStreams=1 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.071 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.071 [ 18] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.071 [ 10] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.071 [ 10] 9 SpeechSynthesizer:startPlaying Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.071 [ 1d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.095 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.137 [ 1d] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=22 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.138 [ 10] 0 SpeechSynthesizer:executePlaybackStarted Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.139 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=PLAYING Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.139 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.140 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.141 [ 10] 0 EventBuilder:buildJsonEventString:messageId=6180b5c0-16c6-4d82-bc31-bfe49f1c19a8,namespace=SpeechSynthesizer,name=SpeechStarted Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.141 [ 7] 0 DialogUXStateAggregator:setState:from=THINKING,to=SPEAKING Sep 21 02:49:15 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : SPEAKING Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.145 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=SPEAKING Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.142 [ 18] 9 SpeechSynthesizer:onFocusChangedSuccess Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.142 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:15 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:15 m3ulcb avs-service-app[4718]: # Speaking... # Sep 21 02:49:15 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.158 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.161 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.170 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.171 [ a] 0 HTTP2StreamPool:getStream:streamId=49,numAcquiredStreams=2 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.174 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff58039f50 Sep 21 02:49:15 m3ulcb kernel: retire_capture_urb: 92 callbacks suppressed Sep 21 02:49:15 m3ulcb kernel[3609]: [ 182.892378] retire_capture_urb: 92 callbacks suppressed Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.690 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-49 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.691 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=49,result=204 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.692 [ a] 0 HTTP2StreamPool:releaseStream:streamId=49,numAcquiredStreams=1 Sep 21 02:49:15 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:15.693 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:49:16 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:16.392 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.768 [ 1d] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=22 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.769 [ 10] 0 SpeechSynthesizer:executePlaybackFinished Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.770 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.771 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.771 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.773 [ 10] 0 EventBuilder:buildJsonEventString:messageId=951b8307-637d-4bb0-b69c-652951f7d4c1,namespace=SpeechSynthesizer,name=SpeechFinished Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.774 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.776 [ 10] 9 SpeechSynthesizer:setHandlingCompleted Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.777 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf,directiveBeingPreHandled=(nullptr) Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.778 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=8dc9e519-2c57-4b60-a86f-73d07a6291bf Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.778 [ 1c] I DirectiveRouter:handleDirective:messageId=718afa93-4cdc-40d2-bad0-1c5ed567797b,action=calling Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.780 [ 11] 0 DirectiveProcessor:onHandlingCompeted:messageId=718afa93-4cdc-40d2-bad0-1c5ed567797b,directiveBeingPreHandled=(nullptr) Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.780 [ 11] 0 CapabilityAgent:removingMessageIdFromMap:messageId=718afa93-4cdc-40d2-bad0-1c5ed567797b Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.780 [ 11] 5 UserInactivityMonitor:onUserActive Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.781 [ c] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=8 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.781 [ c] 5 VisualActivityTracker:provideState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.781 [ d] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=8 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.781 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=8 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.782 [ e] 5 VisualActivityTracker:executeProvideState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.782 [ e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.782 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.783 [ c] 5 AudioActivityTracker:provideState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.783 [ d] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=8 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.783 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.784 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.786 [ f] 5 AudioActivityTracker:executeProvideState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.786 [ f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.786 [ c] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.787 [ c] 5 ContextManager:buildContextSuccessful Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.789 [ 11] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.789 [ 11] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=a9276668-4246-491b-aafc-8d28cfcec33d,newValue=8b72091f-15e4-4029-b89d-08aef0e15758 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.789 [ 11] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=a9276668-4246-491b-aafc-8d28cfcec33d Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.790 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.790 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.791 [ 11] 0 EventBuilder:buildJsonEventString:messageId=cfed8ecd-3120-4ec9-8996-ec99afe55d62,namespace=SpeechRecognizer,name=Recognize Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.791 [ 11] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.791 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.799 [ 7] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=LISTENING Sep 21 02:49:18 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : LISTENING Sep 21 02:49:18 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:49:18 m3ulcb avs-service-app[4718]: # Listening... # Sep 21 02:49:18 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.801 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=LISTENING Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.833 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.834 [ a] 0 HTTP2StreamPool:getStream:streamId=51,numAcquiredStreams=2 Sep 21 02:49:18 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:18.835 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff58039f50 Sep 21 02:49:19 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:19.846 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-51 Sep 21 02:49:19 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:19.847 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=51,result=204 Sep 21 02:49:19 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:19.848 [ a] 0 HTTP2StreamPool:releaseStream:streamId=51,numAcquiredStreams=1 Sep 21 02:49:19 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:19.849 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:49:19 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:19.850 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:19 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:19.850 [ a] 0 HTTP2StreamPool:getStream:streamId=53,numAcquiredStreams=2 Sep 21 02:49:19 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:19.851 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff58039f50 [ 189.243507] retire_capture_urb: 243 callbacks suppressed Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.427 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"33603d59-2bea-4ad3-b5d5-9ae60fb4faa7"\,dialogRequestId\:"8b72091f-15e4-4029-b89d-08aef0e15758"} Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.428 [ 15] I DirectiveRouter:preHandleDirective:messageId=33603d59-2bea-4ad3-b5d5-9ae60fb4faa7,action=calling Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.429 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=33603d59-2bea-4ad3-b5d5-9ae60fb4faa7 Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.430 [ 17] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.432 [ 1c] I DirectiveRouter:handleDirective:messageId=33603d59-2bea-4ad3-b5d5-9ae60fb4faa7,action=calling Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.433 [ 11] 5 UserInactivityMonitor:onUserActive Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.435 [ 11] 0 DirectiveProcessor:onHandlingCompeted:messageId=33603d59-2bea-4ad3-b5d5-9ae60fb4faa7,directiveBeingPreHandled=(nullptr) Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.436 [ 11] 0 CapabilityAgent:removingMessageIdFromMap:messageId=33603d59-2bea-4ad3-b5d5-9ae60fb4faa7 Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.436 [ 7] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING Sep 21 02:49:21 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : THINKING Sep 21 02:49:21 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:21 m3ulcb avs-service-app[4718]: # Thinking... # Sep 21 02:49:21 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.442 [ a] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:21 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:21.438 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=THINKING Sep 21 02:49:21 m3ulcb kernel: retire_capture_urb: 243 callbacks suppressed Sep 21 02:49:21 m3ulcb kernel[3609]: [ 189.243507] retire_capture_urb: 243 callbacks suppressed Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.246 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"Notifications"\,name\:"SetIndicator"\,messageId\:"98845b27-a348-49d0-bd97-c2339440da29"\,dialogRequestId\:""} Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.248 [ 15] I DirectiveRouter:handleDirectiveWithPolicyHandleImmediately:messageId=98845b27-a348-49d0-bd97-c2339440da29,action=calling Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.249 [ 15] 0 NotificationsCapabilityAgent:handleDirective:name=SetIndicator,messageId=98845b27-a348-49d0-bd97-c2339440da29 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.250 [ 6] 5 NotificationsCapabilityAgent:executeSetIndicator:currentState=IDLE Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.285 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-53 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.300 [ 6] 5 NotificationsCapabilityAgent:notifyObservers:indicatorState=1 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.302 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=false,stateRequestToken=0 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.305 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ################################################ Sep 21 02:49:22 m3ulcb avs-service-app[4718]: # NOTIFICATION INDICATOR STATE: ON # Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ################################################ Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.308 [ 6] 5 NotificationsCapabilityAgent:executeSetState:previousState=IDLE,newState=PLAYING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.308 [ 6] 5 NotificationsRenderer:renderNotification Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.309 [ 6] 5 NotificationsRenderer:setStateSuccess:state=IDLE,newState=RENDERING_PREFERRED Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.313 [ 16] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.316 [ 16] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.319 [ 6] 5 NotificationsRenderer:renderNotificationPreferredSuccess:sourceId=24 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.321 [ 6] 0 CapabilityAgent:removingMessageIdFromMap:messageId=98845b27-a348-49d0-bd97-c2339440da29 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.322 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=false,stateRequestToken=0 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.324 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.457 [ 7] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.458 [ 7] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.458 [ 11] 1 FocusManager:releaseChannel:channelName=Dialog Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.459 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:22 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : IDLE Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.460 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.461 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:49:22 m3ulcb avs-service-app[4718]: # Alexa is currently idle! # Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.730 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=53,result=200 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.730 [ a] 0 HTTP2StreamPool:releaseStream:streamId=53,numAcquiredStreams=1 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.731 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae"\,dialogRequestId\:"8b72091f-15e4-4029-b89d-08aef0e15758"} Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.731 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"TemplateRuntime"\,name\:"RenderTemplate"\,messageId\:"20ebb9d5-0a41-4384-9bc7-a3fb6597113a"\,dialogRequestId\:"8b72091f-15e4-4029-b89d-08aef0e15758"} Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.732 [ 15] I DirectiveRouter:preHandleDirective:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae,action=calling Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.732 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.732 [ 15] 9 SpeechSynthesizer:preHandleDirective:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.732 [ 15] I DirectiveRouter:handleDirectiveWithPolicyHandleImmediately:messageId=20ebb9d5-0a41-4384-9bc7-a3fb6597113a,action=calling Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.732 [ 15] 5 TemplateRuntime:handleDirectiveImmediately Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.732 [ 15] 5 TemplateRuntime:preHandleDirective Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.732 [ 15] 5 TemplateRuntime:handleRenderTemplateDirective Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.733 [ 10] 0 SpeechSynthesizer:executePreHandle:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.733 [ 1c] I DirectiveRouter:handleDirective:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae,action=calling Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.733 [ 1c] 9 SpeechSynthesizer:handleDirective:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.733 [ 8] 5 TemplateRuntime:handleRenderTemplateDirectiveInExecutor Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.734 [ 8] 1 FocusManager:acquireChannel:channelName=Visual,interface=TemplateRuntime Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.734 [ 8] 3 TemplateRuntime:executeDisplayCardEvent:prevState=IDLE,nextState=ACQUIRING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.734 [ 1e] 5 VisualActivityTracker:notifyOfActivityUpdates Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.734 [ 10] 0 SpeechSynthesizer:executeHandle:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.734 [ 10] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 18] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 8] 5 TemplateRuntime:executeOnFocusChangedEvent:prevFocus=NONE,newFocus=FOREGROUND Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 8] 3 TemplateRuntime:executeStopTimer Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 8] 3 TemplateRuntime:executeRenderTemplateCallbacks:isClear=False Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:22 m3ulcb avs-service-app[4718]: # RenderTemplateCard Sep 21 02:49:22 m3ulcb avs-service-app[4718]: #----------------------------------------------------------------------------- Sep 21 02:49:22 m3ulcb avs-service-app[4718]: # Focus State : FOREGROUND Sep 21 02:49:22 m3ulcb avs-service-app[4718]: # Template Type : BodyTemplate1 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: # Main Title : New message added on Fri, 21 Sep 2018 02:49:21 GMT Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 8] 3 TemplateRuntime:executeOnFocusChangedEvent:prevState=ACQUIRING,nextState=DISPLAYING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 10] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.735 [ 10] 9 SpeechSynthesizer:startPlaying Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.737 [ 1d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.756 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.803 [ 1d] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=25 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.804 [ 10] 0 SpeechSynthesizer:executePlaybackStarted Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.804 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=PLAYING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.804 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.804 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.805 [ 10] 0 EventBuilder:buildJsonEventString:messageId=3db96a5a-65ad-4db2-a22e-ebc72e626f18,namespace=SpeechSynthesizer,name=SpeechStarted Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.805 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.805 [ 7] 0 DialogUXStateAggregator:setState:from=IDLE,to=SPEAKING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : SPEAKING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.805 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=SPEAKING Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.806 [ 18] 9 SpeechSynthesizer:onFocusChangedSuccess Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.806 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:22 m3ulcb avs-service-app[4718]: # Speaking... # Sep 21 02:49:22 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.809 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.836 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.836 [ a] 0 HTTP2StreamPool:getStream:streamId=55,numAcquiredStreams=2 Sep 21 02:49:22 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:22.837 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff58039f50 Sep 21 02:49:23 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:23.300 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-55 Sep 21 02:49:23 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:23.302 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=55,result=204 Sep 21 02:49:23 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:23.303 [ a] 0 HTTP2StreamPool:releaseStream:streamId=55,numAcquiredStreams=1 Sep 21 02:49:23 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:23.303 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:49:23 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:23.596 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.659 [ 1d] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=25 Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.661 [ 10] 0 SpeechSynthesizer:executePlaybackFinished Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.662 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.663 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.663 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.664 [ 10] 0 EventBuilder:buildJsonEventString:messageId=167a4238-8bca-4504-aaf0-ff087c045f6c,namespace=SpeechSynthesizer,name=SpeechFinished Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.667 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.668 [ 10] 9 SpeechSynthesizer:setHandlingCompleted Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.668 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae,directiveBeingPreHandled=(nullptr) Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.670 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=2bfb2c9b-4bb9-43e7-a8cd-1a267aa822ae Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.725 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.726 [ a] 0 HTTP2StreamPool:getStream:streamId=57,numAcquiredStreams=2 Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.730 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff58039f50 Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.876 [ 7] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE Sep 21 02:49:25 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : IDLE Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.879 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE Sep 21 02:49:25 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:49:25 m3ulcb avs-service-app[4718]: # Alexa is currently idle! # Sep 21 02:49:25 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.879 [ 10] 1 FocusManager:releaseChannel:channelName=Dialog Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.886 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.886 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.889 [ 8] 3 TemplateRuntime:executeStartTimer:timeoutInMilliseconds=2000 Sep 21 02:49:25 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:25.891 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:26 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:26.311 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-57 Sep 21 02:49:26 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:26.312 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=57,result=204 Sep 21 02:49:26 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:26.313 [ a] 0 HTTP2StreamPool:releaseStream:streamId=57,numAcquiredStreams=1 Sep 21 02:49:26 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:26.314 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:49:27 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:27.893 [ 8] 3 TemplateRuntime:executeRenderTemplateCallbacks:isClear=True Sep 21 02:49:27 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:27 m3ulcb avs-service-app[4718]: # RenderTemplateCard - Cleared Sep 21 02:49:27 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:27 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:27.896 [ 8] 1 FocusManager:releaseChannel:channelName=Visual Sep 21 02:49:27 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:27.897 [ 8] 3 TemplateRuntime:executeTimerEvent:prevState=DISPLAYING,nextState=RELEASING Sep 21 02:49:27 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:27.897 [ 1e] 5 VisualActivityTracker:notifyOfActivityUpdates Sep 21 02:49:27 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:27.898 [ 8] 5 TemplateRuntime:executeOnFocusChangedEvent:prevFocus=FOREGROUND,newFocus=NONE Sep 21 02:49:27 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:27.899 [ 8] 3 TemplateRuntime:executeOnFocusChangedEvent:prevState=RELEASING,nextState=IDLE Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.286 [ 11] 5 UserInactivityMonitor:onUserActive Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.288 [ 7] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING Sep 21 02:49:42 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : LISTENING Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.290 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=LISTENING Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.289 [ c] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=9 Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.295 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=9 Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.295 [ 17] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.296 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.295 [ c] 5 VisualActivityTracker:provideState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.300 [ c] 5 AudioActivityTracker:provideState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.300 [ f] 5 AudioActivityTracker:executeProvideState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.301 [ f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.302 [ e] 5 VisualActivityTracker:executeProvideState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.303 [ e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.289 [ d] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=9 Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.303 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.303 [ d] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=9 Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.303 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.303 [ c] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.304 [ c] 5 ContextManager:buildContextSuccessful Sep 21 02:49:42 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:49:42 m3ulcb avs-service-app[4718]: # Listening... # Sep 21 02:49:42 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.308 [ 11] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.308 [ 11] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=8b72091f-15e4-4029-b89d-08aef0e15758,newValue=171a8491-2b03-4329-a9d4-86fc912783ab Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.308 [ 11] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=8b72091f-15e4-4029-b89d-08aef0e15758 Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.308 [ 11] 0 EventBuilder:buildJsonEventString:messageId=215c8471-1982-488c-8448-31bc37cae635,namespace=SpeechRecognizer,name=Recognize Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.312 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.313 [ 11] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.313 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.350 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.352 [ a] 0 HTTP2StreamPool:getStream:streamId=59,numAcquiredStreams=2 Sep 21 02:49:42 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:42.354 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff58039f50d Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.167 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"f953dcac-6fa4-41f6-9a9b-e1868f168ec2"\,dialogRequestId\:"171a8491-2b03-4329-a9d4-86fc912783ab"} Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.169 [ 15] I DirectiveRouter:preHandleDirective:messageId=f953dcac-6fa4-41f6-9a9b-e1868f168ec2,action=calling Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.170 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=f953dcac-6fa4-41f6-9a9b-e1868f168ec2 Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.171 [ 17] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.173 [ 1c] I DirectiveRouter:handleDirective:messageId=f953dcac-6fa4-41f6-9a9b-e1868f168ec2,action=calling Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.173 [ 11] 5 UserInactivityMonitor:onUserActive Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.176 [ 7] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING Sep 21 02:49:46 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : THINKING Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.176 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=THINKING Sep 21 02:49:46 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:46 m3ulcb avs-service-app[4718]: # Thinking... # Sep 21 02:49:46 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.176 [ 11] 0 DirectiveProcessor:onHandlingCompeted:messageId=f953dcac-6fa4-41f6-9a9b-e1868f168ec2,directiveBeingPreHandled=(nullptr) Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.177 [ 11] 0 CapabilityAgent:removingMessageIdFromMap:messageId=f953dcac-6fa4-41f6-9a9b-e1868f168ec2 Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.178 [ a] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:46 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:46.857 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-59 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.353 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"5c77cc72-76fc-4de8-aa96-2fa164fbdb59"\,dialogRequestId\:"171a8491-2b03-4329-a9d4-86fc912783ab"} Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.354 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"TemplateRuntime"\,name\:"RenderTemplate"\,messageId\:"66c0032d-8b56-4791-b2b6-ca44c04e76eb"\,dialogRequestId\:"171a8491-2b03-4329-a9d4-86fc912783ab"} Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.355 [ 15] I DirectiveRouter:preHandleDirective:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59,action=calling Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.356 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.356 [ 15] 9 SpeechSynthesizer:preHandleDirective:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.356 [ 15] I DirectiveRouter:handleDirectiveWithPolicyHandleImmediately:messageId=66c0032d-8b56-4791-b2b6-ca44c04e76eb,action=calling Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.356 [ 15] 5 TemplateRuntime:handleDirectiveImmediately Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.356 [ 15] 5 TemplateRuntime:preHandleDirective Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.356 [ 15] 5 TemplateRuntime:handleRenderTemplateDirective Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.357 [ 10] 0 SpeechSynthesizer:executePreHandle:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.357 [ 1c] I DirectiveRouter:handleDirective:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59,action=calling Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.358 [ 1c] 9 SpeechSynthesizer:handleDirective:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.358 [ 10] 0 SpeechSynthesizer:executeHandle:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.358 [ 10] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.358 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.358 [ 18] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.359 [ 10] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.359 [ 10] 9 SpeechSynthesizer:startPlaying Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.359 [ 1d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.363 [ 8] 5 TemplateRuntime:handleRenderTemplateDirectiveInExecutor Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.363 [ 8] 1 FocusManager:acquireChannel:channelName=Visual,interface=TemplateRuntime Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.364 [ 8] 3 TemplateRuntime:executeDisplayCardEvent:prevState=IDLE,nextState=ACQUIRING Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.364 [ 1e] 5 VisualActivityTracker:notifyOfActivityUpdates Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.365 [ 8] 5 TemplateRuntime:executeOnFocusChangedEvent:prevFocus=NONE,newFocus=FOREGROUND Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.365 [ 8] 3 TemplateRuntime:executeStopTimer Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.365 [ 8] 3 TemplateRuntime:executeRenderTemplateCallbacks:isClear=False Sep 21 02:49:47 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:47 m3ulcb avs-service-app[4718]: # RenderTemplateCard Sep 21 02:49:47 m3ulcb avs-service-app[4718]: #----------------------------------------------------------------------------- Sep 21 02:49:47 m3ulcb avs-service-app[4718]: # Focus State : FOREGROUND Sep 21 02:49:47 m3ulcb avs-service-app[4718]: # Template Type : BodyTemplate2 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: # Main Title : Why is the sky blue? Sep 21 02:49:47 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.365 [ 8] 3 TemplateRuntime:executeOnFocusChangedEvent:prevState=ACQUIRING,nextState=DISPLAYING Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.468 [ 1d] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=28 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.474 [ 10] 0 SpeechSynthesizer:executePlaybackStarted Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.475 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=PLAYING Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.476 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.478 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.480 [ 10] 0 EventBuilder:buildJsonEventString:messageId=dc915f57-952b-4843-a163-a425c3cfd531,namespace=SpeechSynthesizer,name=SpeechStarted Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.480 [ 7] 0 DialogUXStateAggregator:setState:from=THINKING,to=SPEAKING Sep 21 02:49:47 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : SPEAKING Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.481 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=SPEAKING Sep 21 02:49:47 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:47 m3ulcb avs-service-app[4718]: # Speaking... # Sep 21 02:49:47 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.481 [ 18] 9 SpeechSynthesizer:onFocusChangedSuccess Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.486 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.487 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.488 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.553 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.557 [ a] 0 HTTP2StreamPool:getStream:streamId=61,numAcquiredStreams=3 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.559 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.698 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=59,result=200 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.699 [ a] 0 HTTP2StreamPool:releaseStream:streamId=59,numAcquiredStreams=2 Sep 21 02:49:47 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:47.745 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:48 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:48.058 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-61 Sep 21 02:49:48 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:48.059 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=61,result=204 Sep 21 02:49:48 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:48.060 [ a] 0 HTTP2StreamPool:releaseStream:streamId=61,numAcquiredStreams=1 Sep 21 02:49:48 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:48.061 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:49:52 m3ulcb kernel[3609]: [ 220.056100] retire_capture_urb: 251 callbacks suppressed Sep 21 02:49:54 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:54.404 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.468 [ 1d] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=28 Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.469 [ 10] 0 SpeechSynthesizer:executePlaybackFinished Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.470 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.471 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.472 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.473 [ 10] 0 EventBuilder:buildJsonEventString:messageId=71bc575a-10fa-4523-8a7f-19d8fd9e0320,namespace=SpeechSynthesizer,name=SpeechFinished Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.475 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.476 [ 10] 9 SpeechSynthesizer:setHandlingCompleted Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.477 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59,directiveBeingPreHandled=(nullptr) Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.478 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=5c77cc72-76fc-4de8-aa96-2fa164fbdb59 Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.510 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.511 [ a] 0 HTTP2StreamPool:getStream:streamId=63,numAcquiredStreams=2 Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.512 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.679 [ 7] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE Sep 21 02:49:56 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : IDLE Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.680 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.682 [ 10] 1 FocusManager:releaseChannel:channelName=Dialog Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.683 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.684 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:49:56 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:49:56 m3ulcb avs-service-app[4718]: # Alexa is currently idle! # Sep 21 02:49:56 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.682 [ 8] 3 TemplateRuntime:executeStartTimer:timeoutInMilliseconds=2000 Sep 21 02:49:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:56.685 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:49:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:57.256 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-63 Sep 21 02:49:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:57.257 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=63,result=204 Sep 21 02:49:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:57.258 [ a] 0 HTTP2StreamPool:releaseStream:streamId=63,numAcquiredStreams=1 Sep 21 02:49:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:57.258 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:49:58 m3ulcb kernel[3609]: [ 225.718786] retire_capture_urb: 206 callbacks suppressed Sep 21 02:49:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:58.702 [ 8] 3 TemplateRuntime:executeRenderTemplateCallbacks:isClear=True Sep 21 02:49:58 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:58 m3ulcb avs-service-app[4718]: # RenderTemplateCard - Cleared Sep 21 02:49:58 m3ulcb avs-service-app[4718]: ############################################################################## Sep 21 02:49:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:58.710 [ 8] 1 FocusManager:releaseChannel:channelName=Visual Sep 21 02:49:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:58.712 [ 8] 3 TemplateRuntime:executeTimerEvent:prevState=DISPLAYING,nextState=RELEASING Sep 21 02:49:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:58.713 [ 1e] 5 VisualActivityTracker:notifyOfActivityUpdates Sep 21 02:49:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:58.713 [ 8] 5 TemplateRuntime:executeOnFocusChangedEvent:prevFocus=FOREGROUND,newFocus=NONE Sep 21 02:49:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:49:58.713 [ 8] 3 TemplateRuntime:executeOnFocusChangedEvent:prevState=RELEASING,nextState=IDLE [ 231.014760] retire_capture_urb: 15 callbacks suppressed Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.134 [ 11] 5 UserInactivityMonitor:onUserActive Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.135 [ 7] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING Sep 21 02:53:49 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : LISTENING Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.135 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=LISTENING Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.138 [ 17] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.145 [ d] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=10 Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.147 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.148 [ c] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=10 Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.150 [ c] 5 VisualActivityTracker:provideState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.150 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=10 Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.152 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.153 [ c] 5 AudioActivityTracker:provideState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.153 [ f] 5 AudioActivityTracker:executeProvideState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.155 [ f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.153 [ e] 5 VisualActivityTracker:executeProvideState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.158 [ e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:53:49 m3ulcb avs-service-app[4718]: # Listening... # Sep 21 02:53:49 m3ulcb avs-service-app[4718]: ############################ Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.154 [ d] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=10 Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.158 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.159 [ c] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.159 [ c] 5 ContextManager:buildContextSuccessful Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.162 [ 11] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.162 [ 11] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=171a8491-2b03-4329-a9d4-86fc912783ab,newValue=eca3b20a-c482-46c4-8cfb-bcf16412710d Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.162 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.162 [ 11] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=171a8491-2b03-4329-a9d4-86fc912783ab Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.163 [ 11] 0 EventBuilder:buildJsonEventString:messageId=7b3e2b25-7978-43a2-9edf-ccd0c8fc561a,namespace=SpeechRecognizer,name=Recognize Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.164 [ 11] 9 HTTP2Transport:enqueueRequest Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.165 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.226 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.227 [ a] 0 HTTP2StreamPool:getStream:streamId=65,numAcquiredStreams=2 Sep 21 02:53:49 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:49.228 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:53:51 m3ulcb wpa_supplicant[4023]: wlan0: WPA: Group rekeying completed with fe:41:5f:0b:e2:c3 [GTK=CCMP] [ 460.898744] retire_capture_urb: 43 callbacks suppressed Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.033 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"3cd6624c-e10a-48ce-a976-dee42160afd0"\,dialogRequestId\:"eca3b20a-c482-46c4-8cfb-bcf16412710d"} Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.035 [ 15] I DirectiveRouter:preHandleDirective:messageId=3cd6624c-e10a-48ce-a976-dee42160afd0,action=calling Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.036 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=3cd6624c-e10a-48ce-a976-dee42160afd0 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.037 [ 17] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.043 [ 1c] I DirectiveRouter:handleDirective:messageId=3cd6624c-e10a-48ce-a976-dee42160afd0,action=calling Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.045 [ 11] 5 UserInactivityMonitor:onUserActive Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.046 [ 11] 0 DirectiveProcessor:onHandlingCompeted:messageId=3cd6624c-e10a-48ce-a976-dee42160afd0,directiveBeingPreHandled=(nullptr) Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.046 [ 11] 0 CapabilityAgent:removingMessageIdFromMap:messageId=3cd6624c-e10a-48ce-a976-dee42160afd0 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.046 [ 7] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : THINKING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.047 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=THINKING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:53 m3ulcb avs-service-app[4718]: # Thinking... # Sep 21 02:53:53 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.054 [ a] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:53:53 m3ulcb kernel: retire_capture_urb: 43 callbacks suppressed Sep 21 02:53:53 m3ulcb kernel[3609]: [ 460.898744] retire_capture_urb: 43 callbacks suppressed Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.569 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-65 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.575 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=65,result=200 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.577 [ a] 0 HTTP2StreamPool:releaseStream:streamId=65,numAcquiredStreams=1 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.575 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"AudioPlayer"\,name\:"Stop"\,messageId\:"f2937cd9-a18b-4576-b26d-06eb540c429a"\,dialogRequestId\:"eca3b20a-c482-46c4-8cfb-bcf16412710d"} Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.582 [ 15] I DirectiveRouter:preHandleDirective:messageId=f2937cd9-a18b-4576-b26d-06eb540c429a,action=calling Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.582 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=f2937cd9-a18b-4576-b26d-06eb540c429a Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.584 [ 1c] I DirectiveRouter:handleDirective:messageId=f2937cd9-a18b-4576-b26d-06eb540c429a,action=calling Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.584 [ 1c] 0 AudioPlayer:handleDirective:name=Stop,messageId=f2937cd9-a18b-4576-b26d-06eb540c429a Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.584 [ 1c] 1 AudioPlayer:handleStopDirective Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.584 [ 1c] 0 DirectiveProcessor:onHandlingCompeted:messageId=f2937cd9-a18b-4576-b26d-06eb540c429a,directiveBeingPreHandled=(nullptr) Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.584 [ 1c] 0 CapabilityAgent:removingMessageIdFromMap:messageId=f2937cd9-a18b-4576-b26d-06eb540c429a Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.587 [ 12] 1 AudioPlayer:executeStop:playNextItem=false,m_currentActivity=IDLE Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.588 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"160f10af-6f27-44f6-8f57-34d4635c7af8"\,dialogRequestId\:"eca3b20a-c482-46c4-8cfb-bcf16412710d"} Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.589 [ 15] I DirectiveRouter:preHandleDirective:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8,action=calling Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.590 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.591 [ 15] 9 SpeechSynthesizer:preHandleDirective:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.596 [ 10] 0 SpeechSynthesizer:executePreHandle:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.597 [ 1c] I DirectiveRouter:handleDirective:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8,action=calling Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.597 [ 1c] 9 SpeechSynthesizer:handleDirective:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.601 [ 10] 0 SpeechSynthesizer:executeHandle:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.602 [ 10] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.602 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.604 [ 18] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.604 [ 10] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.604 [ 10] 9 SpeechSynthesizer:startPlaying Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.605 [ 1d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.628 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.678 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.720 [ 1d] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=31 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.722 [ 10] 0 SpeechSynthesizer:executePlaybackStarted Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.724 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=PLAYING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.727 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.728 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.729 [ 7] 0 DialogUXStateAggregator:setState:from=THINKING,to=SPEAKING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : SPEAKING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.729 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=SPEAKING Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.729 [ 18] 9 SpeechSynthesizer:onFocusChangedSuccess Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.730 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.730 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.729 [ 10] 0 EventBuilder:buildJsonEventString:messageId=d1436510-eb5e-4dd7-b5b4-fcc16fcad027,namespace=SpeechSynthesizer,name=SpeechStarted Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.731 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:53:53 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:53 m3ulcb avs-service-app[4718]: # Speaking... # Sep 21 02:53:53 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.778 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.781 [ a] 0 HTTP2StreamPool:getStream:streamId=67,numAcquiredStreams=2 Sep 21 02:53:53 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:53.782 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:53:54 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:54.261 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-67 Sep 21 02:53:54 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:54.262 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=67,result=204 Sep 21 02:53:54 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:54.264 [ a] 0 HTTP2StreamPool:releaseStream:streamId=67,numAcquiredStreams=1 Sep 21 02:53:54 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:54.264 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.020 [ 1d] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=31 Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.021 [ 10] 0 SpeechSynthesizer:executePlaybackFinished Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.022 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.023 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.026 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.027 [ 10] 0 EventBuilder:buildJsonEventString:messageId=0a483a2f-e362-4016-a11b-8fde847f7794,namespace=SpeechSynthesizer,name=SpeechFinished Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.029 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.029 [ 10] 9 SpeechSynthesizer:setHandlingCompleted Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.030 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8,directiveBeingPreHandled=(nullptr) Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.031 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=160f10af-6f27-44f6-8f57-34d4635c7af8 Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.068 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.069 [ a] 0 HTTP2StreamPool:getStream:streamId=69,numAcquiredStreams=2 Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.069 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.237 [ 7] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE Sep 21 02:53:55 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : IDLE Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.239 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE Sep 21 02:53:55 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:53:55 m3ulcb avs-service-app[4718]: # Alexa is currently idle! # Sep 21 02:53:55 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.239 [ 10] 1 FocusManager:releaseChannel:channelName=Dialog Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.243 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.244 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:53:55 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:55.245 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.007 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-69 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.009 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"0475b1e5-01ed-40b5-8b2e-266955eb0004"\,dialogRequestId\:""} Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.011 [ 15] I DirectiveRouter:preHandleDirective:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004,action=calling Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.012 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.012 [ 15] 9 SpeechSynthesizer:preHandleDirective:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.013 [ 10] 0 SpeechSynthesizer:executePreHandle:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.013 [ 1c] I DirectiveRouter:handleDirective:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004,action=calling Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.014 [ 1c] 9 SpeechSynthesizer:handleDirective:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.015 [ 10] 0 SpeechSynthesizer:executeHandle:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.016 [ 10] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.017 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.018 [ 18] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.018 [ 10] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.019 [ 10] 9 SpeechSynthesizer:startPlaying Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.020 [ 1d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.020 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=69,result=200 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.021 [ a] 0 HTTP2StreamPool:releaseStream:streamId=69,numAcquiredStreams=1 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.037 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.064 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.097 [ 1d] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=32 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.099 [ 10] 0 SpeechSynthesizer:executePlaybackStarted Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.099 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=PLAYING Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.099 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.099 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.099 [ 10] 0 EventBuilder:buildJsonEventString:messageId=15e32333-da1d-41de-805c-c3779929d4ff,namespace=SpeechSynthesizer,name=SpeechStarted Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.100 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.100 [ 7] 0 DialogUXStateAggregator:setState:from=IDLE,to=SPEAKING Sep 21 02:53:56 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : SPEAKING Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.100 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=SPEAKING Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.100 [ 18] 9 SpeechSynthesizer:onFocusChangedSuccess Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.100 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.101 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:53:56 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:56 m3ulcb avs-service-app[4718]: # Speaking... # Sep 21 02:53:56 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.123 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.124 [ a] 0 HTTP2StreamPool:getStream:streamId=71,numAcquiredStreams=2 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.125 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.576 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-71 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.578 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=71,result=204 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.579 [ a] 0 HTTP2StreamPool:releaseStream:streamId=71,numAcquiredStreams=1 Sep 21 02:53:56 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:56.580 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.369 [ 1d] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=32 Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.372 [ 10] 0 SpeechSynthesizer:executePlaybackFinished Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.372 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.372 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.372 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.373 [ 10] 0 EventBuilder:buildJsonEventString:messageId=3b7186e4-8598-4a6e-b8b1-447c032daba6,namespace=SpeechSynthesizer,name=SpeechFinished Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.373 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.373 [ 10] 9 SpeechSynthesizer:setHandlingCompleted Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.373 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004,directiveBeingPreHandled=(nullptr) Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.373 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=0475b1e5-01ed-40b5-8b2e-266955eb0004 Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.383 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.384 [ a] 0 HTTP2StreamPool:getStream:streamId=73,numAcquiredStreams=2 Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.385 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.579 [ 7] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE Sep 21 02:53:57 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : IDLE Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.580 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.580 [ 10] 1 FocusManager:releaseChannel:channelName=Dialog Sep 21 02:53:57 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:53:57 m3ulcb avs-service-app[4718]: # Alexa is currently idle! # Sep 21 02:53:57 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.586 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.588 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:53:57 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:57.589 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates [ 465.915803] retire_capture_urb: 195 callbacks suppressed Sep 21 02:53:58 m3ulcb kernel: retire_capture_urb: 195 callbacks suppressed Sep 21 02:53:58 m3ulcb kernel[3609]: [ 465.915803] retire_capture_urb: 195 callbacks suppressed Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.407 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-73 Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.888 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=73,result=200 Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.889 [ a] 0 HTTP2StreamPool:releaseStream:streamId=73,numAcquiredStreams=1 Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.889 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"4702f582-d57f-45c6-a5f2-b258753cf7fa"\,dialogRequestId\:""} Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.892 [ 15] I DirectiveRouter:preHandleDirective:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa,action=calling Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.892 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.893 [ 15] 9 SpeechSynthesizer:preHandleDirective:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.894 [ 10] 0 SpeechSynthesizer:executePreHandle:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.894 [ 1c] I DirectiveRouter:handleDirective:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa,action=calling Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.894 [ 1c] 9 SpeechSynthesizer:handleDirective:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.895 [ 10] 0 SpeechSynthesizer:executeHandle:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.895 [ 10] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.895 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.895 [ 18] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.895 [ 10] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.896 [ 10] 9 SpeechSynthesizer:startPlaying Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.896 [ 1d] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.920 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.965 [ 1d] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=33 Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.967 [ 10] 0 SpeechSynthesizer:executePlaybackStarted Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.968 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=PLAYING Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.968 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.969 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.970 [ 10] 0 EventBuilder:buildJsonEventString:messageId=90eae7fd-f92f-42c0-ad8f-fb97523f7cd3,namespace=SpeechSynthesizer,name=SpeechStarted Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.971 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.971 [ 18] 9 SpeechSynthesizer:onFocusChangedSuccess Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.973 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.974 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.971 [ 7] 0 DialogUXStateAggregator:setState:from=IDLE,to=SPEAKING Sep 21 02:53:58 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : SPEAKING Sep 21 02:53:58 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:58 m3ulcb avs-service-app[4718]: # Speaking... # Sep 21 02:53:58 m3ulcb avs-service-app[4718]: ########################### Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.976 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=SPEAKING Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.991 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.991 [ a] 0 HTTP2StreamPool:getStream:streamId=75,numAcquiredStreams=2 Sep 21 02:53:58 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:58.991 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:53:59 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:59.688 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-75 Sep 21 02:53:59 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:59.688 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=75,result=204 Sep 21 02:53:59 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:59.688 [ a] 0 HTTP2StreamPool:releaseStream:streamId=75,numAcquiredStreams=1 Sep 21 02:53:59 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:59.688 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:53:59 m3ulcb avs-service-app[4718]: 2018-09-21 02:53:59.733 [ 1d] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.797 [ 1d] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=33 Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.798 [ 10] 0 SpeechSynthesizer:executePlaybackFinished Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.800 [ 10] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.800 [ 10] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0 Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.801 [ 10] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.802 [ 10] 0 EventBuilder:buildJsonEventString:messageId=560b154f-a277-498b-ad19-8378f409c767,namespace=SpeechSynthesizer,name=SpeechFinished Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.804 [ 10] 9 HTTP2Transport:enqueueRequest Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.805 [ 10] 9 SpeechSynthesizer:setHandlingCompleted Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.805 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa,directiveBeingPreHandled=(nullptr) Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.806 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=4702f582-d57f-45c6-a5f2-b258753cf7fa Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.896 [ a] 0 HTTP2Transport:processNextOutgoingMessage Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.896 [ a] 0 HTTP2StreamPool:getStream:streamId=77,numAcquiredStreams=2 Sep 21 02:54:01 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:01.896 [ a] 9 HTTP2Transport:insertActiveStream:handle=0xffff5806c000 Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.012 [ 7] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE Sep 21 02:54:02 m3ulcb avs-service-app[4718]: onDialogUXStateChanged : IDLE Sep 21 02:54:02 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:54:02 m3ulcb avs-service-app[4718]: # Alexa is currently idle! # Sep 21 02:54:02 m3ulcb avs-service-app[4718]: ######################################## Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.014 [ 10] 1 FocusManager:releaseChannel:channelName=Dialog Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.019 [ 18] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.021 [ 18] 5 AudioActivityTracker:notifyOfActivityUpdates Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.022 [ f] 5 AudioActivityTracker:executeNotifyOfActivityUpdates Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.014 [ 7] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.726 [ a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0e489ffffe291426-00001861-0023f35c-1f5abb49a2e53999-00959db0-77 Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.727 [ a] 0 HTTP2Transport:cleanupFinishedStream:streamId=77,result=204 Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.727 [ a] 0 HTTP2StreamPool:releaseStream:streamId=77,numAcquiredStreams=1 Sep 21 02:54:02 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:02.727 [ a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.046 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"Notifications"\,name\:"ClearIndicator"\,messageId\:"22a534c1-3b82-4c88-8d09-6369c8e520f0"\,dialogRequestId\:""} Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.046 [ 15] I DirectiveRouter:handleDirectiveWithPolicyHandleImmediately:messageId=22a534c1-3b82-4c88-8d09-6369c8e520f0,action=calling Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.046 [ 15] 0 NotificationsCapabilityAgent:handleDirective:name=ClearIndicator,messageId=22a534c1-3b82-4c88-8d09-6369c8e520f0 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.046 [ 6] 5 NotificationsCapabilityAgent:executeClearIndicator:currentState=PLAYING Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.046 [ 6] 5 NotificationsCapabilityAgent:executeSetState:previousState=PLAYING,newState=CANCELING_PLAY Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.046 [ 6] 5 NotificationsRenderer:cancelNotificationRendering Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.046 [ 6] 5 NotificationsRenderer:setStateSuccess:state=RENDERING_PREFERRED,newState=CANCELLING Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.048 [ 16] 5 NotificationsRenderer:onPlaybackStarted:sourceId=24 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.048 [ 16] 5 NotificationsRenderer:onPlaybackStopped:sourceId=24 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.048 [ 16] 5 NotificationsRenderer:setStateSuccess:state=CANCELLING,newState=NOTIFYING Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.049 [ 16] 5 NotificationsCapabilityAgent:onNotificationRenderingFinished:currentAssetId=default_notification_sound Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.049 [ 16] 5 NotificationsRenderer:setStateSuccess:state=NOTIFYING,newState=IDLE Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.049 [ 16] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.059 [ 6] 0 CapabilityAgent:removingMessageIdFromMap:messageId=22a534c1-3b82-4c88-8d09-6369c8e520f0 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.086 [ 6] 5 NotificationsCapabilityAgent:notifyObservers:indicatorState=0 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.086 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=false,stateRequestToken=0 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.086 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.086 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=false,stateRequestToken=0 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.086 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.087 [ 6] 5 NotificationsCapabilityAgent:executePlayFinishedZeroQueued:currentState=CANCELING_PLAY Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.087 [ 6] 5 NotificationsCapabilityAgent:executeSetState:previousState=CANCELING_PLAY,newState=IDLE Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.087 [ 6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=false,stateRequestToken=0 Sep 21 02:54:03 m3ulcb avs-service-app[4718]: 2018-09-21 02:54:03.087 [ 6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState Sep 21 02:54:03 m3ulcb avs-service-app[4718]: ################################################# Sep 21 02:54:03 m3ulcb avs-service-app[4718]: # NOTIFICATION INDICATOR STATE: OFF # Sep 21 02:54:03 m3ulcb avs-service-app[4718]: #################################################

scotthea-amazon commented 5 years ago

Hello bill-lzb,

I have tried many times to reproduce the problem, but so far I have had no luck.

Your logs show that the Speak directives you can not hear are resulting in calls to play speech. For example:

2018-09-21 02:49:22.735 [ 10] 9 SpeechSynthesizer:startPlaying

However, where that log is generated, I would have expected a log line from MediaPlayer::play() or an error to be logged. Instead, I am not finding either in your logs.

Is there something special about your configuration that might help us diagnose this problem?

Thank you, -SWH

bill-lzb commented 5 years ago

Hello SWH

There is no special configuration. It's sometimes OK, sometimes NG.

Thank you, -ZongbiaoLiao

kclchan commented 5 years ago

Hi @bill-lzb, #1049 seems to be similar to what you are seeing. As mentioned in that issue, the most common reason for the notifications to not have any contents is because the locale in which the device is registered is different from the locale on the device. Could you check if this is the case for you? Thanks!

visayamv commented 5 years ago

I will be closing this issue due to inactive. Feel free to reopen if you need further assistance on this issue.