t
2019-04-02 17:12:18.967 [ 12] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2019-04-02 17:12:18.967 [  7] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2019-04-02 17:12:18.967 [  7] 5 TemplateRuntime:onDialogUXStateChanged:state=LISTENING
############################
#       Listening...       #
############################

2019-04-02 17:12:18.967 [  c] 5 VisualActivityTracker:provideState
2019-04-02 17:12:18.967 [  c] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=2
2019-04-02 17:12:18.967 [  c] 5 AudioActivityTracker:provideState
2019-04-02 17:12:18.967 [  6] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=2
2019-04-02 17:12:18.967 [  d] 5 VisualActivityTracker:executeProvideState
2019-04-02 17:12:18.967 [  d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState
2019-04-02 17:12:18.967 [  f] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=2
2019-04-02 17:12:18.967 [  f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState
2019-04-02 17:12:18.967 [  f] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=2
2019-04-02 17:12:18.967 [  6] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState
2019-04-02 17:12:18.967 [ 11] 5 AudioActivityTracker:executeProvideState
2019-04-02 17:12:18.967 [ 11] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState
2019-04-02 17:12:18.967 [  f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState
2019-04-02 17:12:18.967 [  c] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState
2019-04-02 17:12:18.967 [  c] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState
2019-04-02 17:12:18.968 [  c] 5 ContextManager:buildContextSuccessful
2019-04-02 17:12:18.968 [ 12] 0 AudioInputProcessor:executeOnContextAvailable
2019-04-02 17:12:18.968 [ 12] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer
2019-04-02 17:12:18.968 [ 12] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=060b3cf4-123f-47c1-9fe3-c9b87e48b090
2019-04-02 17:12:18.968 [ 12] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId
2019-04-02 17:12:18.968 [ 13] 9 AudioInputProcessor:onFocusChanged:newFocus=FOREGROUND
2019-04-02 17:12:18.968 [ 12] 0 EventBuilder:buildJsonEventString:messageId=72264e63-5314-4e16-8589-41988cd0bf86,namespace=SpeechRecognizer,name=Recognize
2019-04-02 17:12:18.968 [ 13] 5 AudioActivityTracker:notifyOfActivityUpdates
2019-04-02 17:12:18.968 [ 11] 5 AudioActivityTracker:executeNotifyOfActivityUpdates
2019-04-02 17:12:18.968 [ 12] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2019-04-02 17:12:18.968 [ 12] 9 HTTP2Transport:enqueueRequest
2019-04-02 17:12:19.050 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2019-04-02 17:12:19.050 [  a] 0 HTTP2StreamPool:getStream:streamId=5,numAcquiredStreams=2
2019-04-02 17:12:19.050 [  a] 9 HTTP2Transport:insertActiveStream:handle=0xb59f9148
2019-04-02 17:12:21.385 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"dcf634fe-9529-41ec-a46e-a42fbeed9720"\,dialogRequestId\:"060b3cf4-123f-47c1-9fe3-c9b87e48b090"}
2019-04-02 17:12:21.385 [ 15] I DirectiveRouter:preHandleDirective:messageId=dcf634fe-9529-41ec-a46e-a42fbeed9720,action=calling
2019-04-02 17:12:21.385 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=dcf634fe-9529-41ec-a46e-a42fbeed9720
2019-04-02 17:12:21.385 [ 16] I DirectiveRouter:handleDirective:messageId=dcf634fe-9529-41ec-a46e-a42fbeed9720,action=calling
2019-04-02 17:12:21.385 [ 12] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2019-04-02 17:12:21.385 [ 12] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2019-04-02 17:12:21.385 [ 12] 0 DirectiveProcessor:onHandlingCompeted:messageId=dcf634fe-9529-41ec-a46e-a42fbeed9720,directiveBeingPreHandled=(nullptr)
2019-04-02 17:12:21.385 [ 12] 0 CapabilityAgent:removingMessageIdFromMap:messageId=dcf634fe-9529-41ec-a46e-a42fbeed9720
2019-04-02 17:12:21.385 [  7] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
2019-04-02 17:12:21.385 [  7] 5 TemplateRuntime:onDialogUXStateChanged:state=THINKING
###########################
#       Thinking...       #
###########################

2019-04-02 17:12:21.394 [  a] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2019-04-02 17:12:21.809 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0abb93fffe824ff6-00000588-00073c80-51e52b4acb79f73e-8b7aa4be-5
2019-04-02 17:12:21.814 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd"\,dialogRequestId\:"060b3cf4-123f-47c1-9fe3-c9b87e48b090"}
2019-04-02 17:12:21.815 [ 15] I DirectiveRouter:preHandleDirective:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd,action=calling
2019-04-02 17:12:21.815 [ 15] 0 CapabilityAgent:addingMessageIdToMap:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:21.815 [ 15] 9 SpeechSynthesizer:preHandleDirective:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:21.815 [ 16] I DirectiveRouter:handleDirective:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd,action=calling
2019-04-02 17:12:21.815 [ 16] 9 SpeechSynthesizer:handleDirective:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:21.815 [  e] 0 SpeechSynthesizer:executePreHandle:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:21.816 [  e] 0 SpeechSynthesizer:executeHandle:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:21.816 [  e] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechSynthesizer
2019-04-02 17:12:21.816 [ 13] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE
2019-04-02 17:12:21.816 [ 12] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2019-04-02 17:12:21.816 [ 13] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2019-04-02 17:12:21.816 [ 12] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2019-04-02 17:12:21.816 [ 13] 9 SpeechSynthesizer:setCurrentStateLocked:state=GAINING_FOCUS
2019-04-02 17:12:21.816 [ 12] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2019-04-02 17:12:21.816 [  e] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2019-04-02 17:12:21.816 [  e] 9 SpeechSynthesizer:startPlaying
2019-04-02 17:12:21.816 [  e] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2019-04-02 17:12:21.817 [  4] 0 MediaPlayer:handleSetSourceCalled
2019-04-02 17:12:21.817 [  4] 9 MediaPlayer:tearDownTransientPipelineElements
2019-04-02 17:12:21.817 [  4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2019-04-02 17:12:21.818 [  4] 9 BaseStreamSource:initNoAudioFormat
2019-04-02 17:12:21.824 [  e] 9 MediaPlayer:playCalled
2019-04-02 17:12:21.825 [  4] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2019-04-02 17:12:21.831 [ 14] I DirectiveSequencer:onDirective:directive={"namespace\:"TemplateRuntime"\,name\:"RenderTemplate"\,messageId\:"ec69b145-d6c0-4617-8dd9-21626936980c"\,dialogRequestId\:"060b3cf4-123f-47c1-9fe3-c9b87e48b090"}
2019-04-02 17:12:21.831 [ 15] I DirectiveRouter:handleDirectiveWithPolicyHandleImmediately:messageId=ec69b145-d6c0-4617-8dd9-21626936980c,action=calling
2019-04-02 17:12:21.831 [ 15] 5 TemplateRuntime:handleDirectiveImmediately
2019-04-02 17:12:21.831 [ 15] 5 TemplateRuntime:preHandleDirective
2019-04-02 17:12:21.831 [ 15] 5 TemplateRuntime:handleRenderTemplateDirective
2019-04-02 17:12:21.831 [  9] 5 TemplateRuntime:handleRenderTemplateDirectiveInExecutor
2019-04-02 17:12:21.831 [  9] 1 FocusManager:acquireChannel:channelName=Visual,interface=TemplateRuntime
2019-04-02 17:12:21.831 [  9] 3 TemplateRuntime:executeDisplayCardEvent:prevState=IDLE,nextState=ACQUIRING
2019-04-02 17:12:21.841 [  9] 5 TemplateRuntime:executeOnFocusChangedEvent:prevFocus=NONE,newFocus=FOREGROUND
2019-04-02 17:12:21.841 [ 17] 5 VisualActivityTracker:notifyOfActivityUpdates
2019-04-02 17:12:21.841 [  9] 3 TemplateRuntime:executeStopTimer
2019-04-02 17:12:21.841 [  9] 3 TemplateRuntime:executeRenderTemplateCallbacks:isClear=False
##############################################################################
#     RenderTemplateCard
#-----------------------------------------------------------------------------
# Focus State         : FOREGROUND
# Template Type       : WeatherTemplate
# Main Title          : Philadelphia, PA
##############################################################################

2019-04-02 17:12:21.842 [  9] 3 TemplateRuntime:executeOnFocusChangedEvent:prevState=ACQUIRING,nextState=DISPLAYING
2019-04-02 17:12:21.897 [  a] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2019-04-02 17:12:21.897 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=5,result=200
2019-04-02 17:12:21.897 [  a] 0 HTTP2StreamPool:releaseStream:streamId=5,numAcquiredStreams=1
2019-04-02 17:12:21.954 [  4] 9 AttachmentReaderSource:handleSeekData:offset=0
2019-04-02 17:12:21.955 [  4] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=audio_sink
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=volume
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=converter
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=typefind
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=decoder
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=src
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=audio-pipeline
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=audio_sink-actual-sink-brcmpcm
2019-04-02 17:12:21.955 [ 18] 9 BaseStreamSource:onNeedDataCalled:size=4096
2019-04-02 17:12:21.955 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=audio_sink
2019-04-02 17:12:22.031 [  7] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut
2019-04-02 17:12:22.287 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=volume
2019-04-02 17:12:22.287 [  7] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE
2019-04-02 17:12:22.287 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=converter
2019-04-02 17:12:22.287 [  7] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE
########################################
#       Alexa is currently idle!       #
########################################

2019-04-02 17:12:22.288 [  9] 3 TemplateRuntime:executeStartTimer:timeoutInMilliseconds=2000
2019-04-02 17:12:22.288 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=typefind
2019-04-02 17:12:22.288 [  4] 9 MediaPlayer:messageReceived:type=stream-status,source=src
2019-04-02 17:12:22.288 [  4] 9 MediaPlayer:messageReceived:type=state-changed,source=src
2019-04-02 17:12:22.288 [  4] 9 MediaPlayer:messageReceived:type=stream-status,source=src
2019-04-02 17:12:22.288 [  4] 9 BaseStreamSource:handleNeedDataCalled
2019-04-02 17:12:22.288 [  4] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=17
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.288 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.289 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.289 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.289 [  4] 9 AttachmentReaderSource:read:size=4096,status=0
2019-04-02 17:12:22.289 [  4] 9 AttachmentReaderSource:read:size=1469,status=0
2019-04-02 17:12:22.289 [  4] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2019-04-02 17:12:22.289 [  4] 9 AttachmentReaderSource:read:size=0,status=3
2019-04-02 17:12:22.289 [  4] 9 AttachmentReaderSource:handleReadData:info=signalingEndOfData
2019-04-02 17:12:22.289 [  4] 9 BaseStreamSource:signalEndOfDataCalled
2019-04-02 17:12:22.289 [  4] 9 BaseStreamSource:gstAppSrcEndOfStreamSuccess
2019-04-02 17:12:22.289 [  4] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=17
2019-04-02 17:12:22.297 [  4] 9 MediaPlayer:messageReceived:type=element,source=decoder
2019-04-02 17:12:22.297 [  4] 9 MediaPlayer:messageReceived:type=error,source=decoder
2019-04-02 17:12:22.297 [  4] E MediaPlayer:handleBusMessageError:source=decoder,error=Your GStreamer installation is missing a plug-in.,debug=../../../gst-plugins-base-1.10.4/gst/playback/gstdecodebin2.c(4593)\: gst_decode_bin_expose ()\: /GstPipeline\:audio-pipeline/GstDecodeBin\:decoder\:
no suitable plugins found\:
Missing decoder\: ID3 tag (application/x-id3)

2019-04-02 17:12:22.297 [  4] 0 MediaPlayer:callingOnPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=Your GStreamer installation is missing a plug-in.,currentId=1
2019-04-02 17:12:22.297 [  4] 9 SpeechSynthesizer:onPlaybackError:callbackSourceId=1
2019-04-02 17:12:22.629 [  4] 9 MediaPlayer:tearDownTransientPipelineElements
2019-04-02 17:12:22.629 [  e] 0 SpeechSynthesizer:executePlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=Your GStreamer installation is missing a plug-in.
2019-04-02 17:12:22.629 [  e] 9 SpeechSynthesizer:setCurrentStateLocked:state=FINISHED
2019-04-02 17:12:22.630 [  e] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2019-04-02 17:12:22.630 [  4] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
2019-04-02 17:12:22.630 [  e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SpeechSynthesizer,name=SpeechState
2019-04-02 17:12:22.630 [  e] 9 SpeechSynthesizer:releaseForegroundFocus
2019-04-02 17:12:22.630 [  e] 1 FocusManager:releaseChannel:channelName=Dialog
0:00:30.822532644 13114    0xe2120 INFO             brcmpcmsink gst_pcm_sink.c:250:cancel_eos_timer: cancel_eos_timer=0x0
2019-04-02 17:12:22.630 [  e] 0 CapabilityAgent:removingMessageIdFromMap:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:22.630 [  e] 0 EventBuilder:buildJsonEventString:messageId=abdc256f-41b3-4a23-b3b3-fc97bb1d2277,namespace=System,name=ExceptionEncountered
2019-04-02 17:12:22.630 [  e] 9 HTTP2Transport:enqueueRequest
2019-04-02 17:12:22.630 [  e] 0 DirectiveProcessor:onHandlingFailed:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd,directiveBeingPreHandled=(nullptr),description=Your GStreamer installation is missing a plug-in.
2019-04-02 17:12:22.630 [  e] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=060b3cf4-123f-47c1-9fe3-c9b87e48b090
2019-04-02 17:12:22.630 [  e] 0 CapabilityAgent:removingMessageIdFromMap:messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:22.699 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2019-04-02 17:12:22.699 [  a] 0 HTTP2StreamPool:getStream:streamId=7,numAcquiredStreams=2
2019-04-02 17:12:22.699 [  a] 9 HTTP2Transport:insertActiveStream:handle=0xb59f9148
2019-04-02 17:12:22.739 [  4] 9 BaseStreamSource:~BaseStreamSource
2019-04-02 17:12:22.760 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0abb93fffe824ff6-00000588-00073c80-51e52b4acb79f73e-8b7aa4be-7
2019-04-02 17:12:22.760 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=7,result=204
2019-04-02 17:12:22.760 [  a] 0 HTTP2StreamPool:releaseStream:streamId=7,numAcquiredStreams=1
2019-04-02 17:12:22.760 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2019-04-02 17:12:24.288 [  9] 3 TemplateRuntime:executeRenderTemplateCallbacks:isClear=True
##############################################################################
#     RenderTemplateCard - Cleared
##############################################################################

2019-04-02 17:12:24.288 [  9] 1 FocusManager:releaseChannel:channelName=Visual
2019-04-02 17:12:24.288 [  9] 3 TemplateRuntime:executeTimerEvent:prevState=DISPLAYING,nextState=RELEASING
2019-04-02 17:12:24.288 [  9] 5 TemplateRuntime:executeOnFocusChangedEvent:prevFocus=FOREGROUND,newFocus=NONE
2019-04-02 17:12:24.288 [ 17] 5 VisualActivityTracker:notifyOfActivityUpdates
2019-04-02 17:12:24.288 [  9] 3 TemplateRuntime:executeOnFocusChangedEvent:prevState=RELEASING,nextState=IDLE
2019-04-02 17:12:26.816 [ 13] E SpeechSynthesizer:onFocusChangeFailed:reason=stateChangeTimeout,messageId=0a388b78-7c9f-4ae6-a6a1-b0ba6c0344bd
2019-04-02 17:12:26.817 [ 13] 5 AudioActivityTracker:notifyOfActivityUpdates
2019-04-02 17:12:26.817 [ 13] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2019-04-02 17:12:26.817 [ 13] 5 AudioActivityTracker:notifyOfActivityUpdates
2019-04-02 17:12:26.817 [ 11] 5 AudioActivityTracker:executeNotifyOfActivityUpdates
2019-04-02 17:12:26.817 [ 11] 5 AudioActivityTracker:executeNotifyOfActivityUpdates