The app enter  infinite loops when have trouble to play music

I develop app with AVSSDK verion 1.2.0, when I ask Alexa play beat it,  it enter ininite loops when can not play music, and always say "I have trouble to play music", this is logs:

sundq@ubuntu:~/workspace/tonly_t8c/tonlyAVSApp$
sundq@ubuntu:~/workspace/tonly_t8c/tonlyAVSApp$ ./build/tl_avs_sample ../conf/TonlyConfig.json
./build/tl_avs_sample: /usr/lib/libcurl.so.4: no version information available (required by /home/sundq/workspace/tonly_t8c/AVSSDK/install/usr/lib/libAVSCommon.so)
./build/tl_avs_sample: /usr/lib/libcurl.so.4: no version information available (required by /home/sundq/workspace/tonly_t8c/AVSSDK/install/usr/lib/libACL.so)
Running app with log level: DEBUG9
2017-11-14 01:15:04.873 [  1] I ConfigurationNode:initializeSuccess
2017-11-14 01:15:04.875 [  1] 9 MediaPlayer:createCalled
[2017-11-14 01:15:04.876] [tonly_avs_app] [INFO] [src/DbusMessageWrapper.cpp:270] ************************* message process thread start *************************
2017-11-14 01:15:04.884 [  1] 9 MediaPlayer:createCalled
2017-11-14 01:15:04.885 [  1] 9 MediaPlayer:createCalled
2017-11-14 01:15:04.886 [  1] 9 MediaPlayer:createCalled
#####################################
#       Client not connected!       #
#####################################

2017-11-14 01:15:04.891 [  1] 9 MediaPlayer:setObserverCalled
2017-11-14 01:15:04.891 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-11-14 01:15:04.891 [  1] 9 SpeechSynthesizer:addObserver:observer=0x17b0448
2017-11-14 01:15:04.891 [  1] 9 MediaPlayer:setObserverCalled
2017-11-14 01:15:04.891 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-11-14 01:15:04.891 [  1] 9 MediaPlayer:setObserverCalled
2017-11-14 01:15:04.891 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-11-14 01:15:04.891 [  1] 9 MediaPlayer:setObserverCalled
2017-11-14 01:15:04.891 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-11-14 01:15:04.893 [  1] 9 AlertScheduler:setTimerForNextAlertLocked
2017-11-14 01:15:04.893 [  1] I AlertScheduler:executeScheduleNextAlertForRendering::no work to do.
2017-11-14 01:15:04.893 [  3] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST
2017-11-14 01:15:04.894 [  1] 9 MediaPlayer:getSpeakerTypeCalled
2017-11-14 01:15:04.894 [  1] 9 MediaPlayer:getSpeakerTypeCalled
2017-11-14 01:15:04.894 [  1] 9 MediaPlayer:getSpeakerTypeCalled
2017-11-14 01:15:04.894 [  1] 0 SpeakerManager:mapCreated:numAvsSynced=3,numLocal=0
2017-11-14 01:15:04.894 [  1] 1 AudioPlayer:addObserver
2017-11-14 01:15:04.903 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechSynthesizer,name=Speak,handler=0x17b7900,policy=BLOCKING
2017-11-14 01:15:04.903 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=ClearQueue,handler=0x17b85f0,policy=NON_BLOCKING
2017-11-14 01:15:04.903 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Stop,handler=0x17b85f0,policy=NON_BLOCKING
2017-11-14 01:15:04.903 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Play,handler=0x17b85f0,policy=NON_BLOCKING
2017-11-14 01:15:04.903 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=ExpectSpeech,handler=0x17b6c50,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=StopCapture,handler=0x17b6c50,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=DeleteAlert,handler=0x17ba0e0,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetAlert,handler=0x17ba0e0,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=SetEndpoint,handler=0x17e3100,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=ResetUserInactivity,handler=0x17b68f8,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=SetMute,handler=0x17e2400,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=AdjustVolume,handler=0x17e2400,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=SetVolume,handler=0x17e2400,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] 9 TemplateRuntime:getConfiguration
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=TemplateRuntime,name=RenderPlayerInfo,handler=0x17e2690,policy=NON_BLOCKING
2017-11-14 01:15:04.904 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=TemplateRuntime,name=RenderTemplate,handler=0x17e2690,policy=NON_BLOCKING
[2017-11-14 01:15:04.904] [tonly_avs_app] [INFO] [src/DbusMessageWrapper.cpp:65] add message observer for: tonly.local.audio.play
[2017-11-14 01:15:04.904] [tonly_avs_app] [INFO] [src/AlsaMicrophoneWrapper.cpp:39] m_format=-719441032  m_frames=32 m_channels=1 m_sampleRate=16000 m_alsaDeviceName=噘𹠿
ALSA lib pcm_dsnoop.c:606:(snd_pcm_dsnoop_open) unable to open slave
ALSA lib setup.c:548:(add_elem) Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.center_lfe
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.side
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround21
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround21
ALSA lib setup.c:548:(add_elem) Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround41
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround50
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround51
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround71
ALSA lib setup.c:548:(add_elem) Cannot obtain info for CTL elem (PCM,'IEC958 Playback PCM Stream',0,0,0): No such file or directory
ALSA lib setup.c:548:(add_elem) Cannot obtain info for CTL elem (PCM,'IEC958 Playback PCM Stream',0,0,0): No such file or directory
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.hdmi
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.hdmi
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.modem
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.modem
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.phoneline
ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.phoneline
2017-11-14 01:15:06.176 [  4] 0 HttpPost:doPostSucceeded:code=200
2017-11-14 01:15:06.176 [  4] 0 AuthDelegate:handleLwaResponseSucceeded:expiresInSeconds=3600
2017-11-14 01:15:06.176 [  4] 0 AuthDelegate:onAuthStateChangeCalled:state=1,error=0
2017-11-14 01:15:06.177 [  1] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=PENDING
2017-11-14 01:15:06.177 [  1] 0 HTTP2StreamPool:getStream:streamId=1,numAcquiredStreams=1
2017-11-14 01:15:06.178 [  5] 9 PostConnectSynchronize:Entering postConnectLoop thread
2017-11-14 01:15:06.178 [  3] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST
#############################
#       Connecting...       #
#############################

2017-11-14 01:15:06.178 [  6] 9 SpeakerManager:provideStateCalled
2017-11-14 01:15:06.178 [  7] 9 SpeakerManager:executeProvideStateCalled
2017-11-14 01:15:06.178 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:06.178 [  6] 0 AudioPlayer:provideState:stateRequestToken=1
2017-11-14 01:15:06.178 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"wakeword" \: ""},namespace=SpeechRecognizer,name=RecognizerState
2017-11-14 01:15:06.178 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:06.178 [  6] 9 SpeechSynthesizer:provideState:token=1
2017-11-14 01:15:06.178 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=1
2017-11-14 01:15:06.178 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:06.178 [  9] 0 AudioPlayer:executeProvideState:sendToken=true,stateRequestToken=1
2017-11-14 01:15:06.179 [  9] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"},namespace=AudioPlayer,name=PlaybackState
2017-11-14 01:15:06.179 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:06.179 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:06.179 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:06.179 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:06.179 [  7] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true
2017-11-14 01:15:06.179 [  7] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false
2017-11-14 01:15:06.179 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState
2017-11-14 01:15:06.179 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:100\,"muted"\:false}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}\,{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}]}
2017-11-14 01:15:06.179 [  6] 0 EventBuilder:buildJsonEventString:messageId=c3066982-4e6f-4423-9d3f-9693550bee66,namespace=System,name=SynchronizeState
2017-11-14 01:15:06.179 [  6] 0 PostConnectSynchronize:onContextAvailable : Send PostConnectMessage to transport
2017-11-14 01:15:06.180 [  6] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:07.345 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-1
2017-11-14 01:15:07.345 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:07.345 [  b] 0 HTTP2StreamPool:getStream:streamId=3,numAcquiredStreams=2
2017-11-14 01:15:07.345 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe70118120
2017-11-14 01:15:08.760 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-3
2017-11-14 01:15:08.761 [  b] 0 PostConnectSynchronize:onSendCompleted:status=SUCCESS_NO_CONTENT
2017-11-14 01:15:08.761 [  5] 9 PostConnectSynchronize:Exiting postConnectLoop thread
2017-11-14 01:15:08.761 [  b] 0 PostConnectSynchronize:onConnected()
2017-11-14 01:15:08.761 [  b] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED
2017-11-14 01:15:08.761 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=3,result=204
2017-11-14 01:15:08.761 [  b] 0 HTTP2StreamPool:releaseStream:streamId=3,numAcquiredStreams=1
2017-11-14 01:15:08.761 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
########################################
#       Alexa is currently idle!       #
########################################

2017-11-14 01:15:08.761 [  3] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=CONNECTED,reason=ACL_CLIENT_REQUEST
[2017-11-14 01:15:08.761] [tonly_avs_app] [INFO] [src/DbusMessageWrapper.cpp:150] msg interface is: org.freedesktop.DBus
[2017-11-14 01:15:08.761] [tonly_avs_app] [WARNING] [src/DbusMessageWrapper.cpp:200] there is no observer for message: org.freedesktop.DBus
[2017-11-14 01:15:08.761] [tonly_avs_app] [INFO] [src/DbusMessageWrapper.cpp:150] msg interface is: org.freedesktop.DBus
[2017-11-14 01:15:08.761] [tonly_avs_app] [WARNING] [src/DbusMessageWrapper.cpp:200] there is no observer for message: org.freedesktop.DBus
[2017-11-14 01:15:08.761] [tonly_avs_app] [INFO] [src/DbusMessageWrapper.cpp:150] msg interface is: tonly.local.audio.play
2017-11-14 01:15:08.761 [  c] 1 FocusManager:acquireChannel:channelName=LocalAudioChannel,activityId=LocalTonlyAlertAudioPlayer.Play
2017-11-14 01:15:08.762 [  d] I TonlyAudioPlayer:onFocusChanged:newFocus=FOREGROUND
[2017-11-14 01:15:08.762] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:129] executeOnFocusChanged from NONE to FOREGROUND
[2017-11-14 01:15:08.762] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:145] executeOnFocusChanged: action=playNextItem
2017-11-14 01:15:08.762 [  c] 9 MediaPlayer:setSourceCalled:sourceType=istream
2017-11-14 01:15:08.762 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-14 01:15:08.762 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:08.764 [  c] 9 MediaPlayer:playCalled
2017-11-14 01:15:08.764 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2017-11-14 01:15:08.764 [  2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-11-14 01:15:08.766 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  e] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.767 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:08.767 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:08.767 [  2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=15
2017-11-14 01:15:08.767 [  2] 9 IStreamSource:read:size=4096,pos=4096,eof=false
2017-11-14 01:15:08.767 [  2] 9 IStreamSource:read:size=4096,pos=8192,eof=false
2017-11-14 01:15:08.767 [  2] 9 IStreamSource:read:size=1454,pos=-1,eof=true
2017-11-14 01:15:08.767 [  2] 9 IStreamSource:read:size=0,pos=-1,eof=true
2017-11-14 01:15:08.767 [  2] 9 BaseStreamSource:signalEndOfDataCalled
2017-11-14 01:15:08.767 [  2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=15
[2017-11-14 01:15:08.769] [tonly_avs_app] [INFO] [src/DbusMessageWrapper.cpp:65] add message observer for: tonly.key.message
#######                                      #    #     #  #####
   #      ####   #    #  #      #   #       # #   #     # #     #
   #     #    #  ##   #  #       # #       #   #  #     # #
   #     #    #  # #  #  #        #       #     # #     #  #####
   #     #    #  #  # #  #        #       #######  #   #        #
   #     #    #  #   ##  #        #       #     #   # #   #     #
   #      ####   #    #  ######   #       #     #    #     #####

2017-11-14 01:15:08.771 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.771 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.773 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.773 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.778 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.778 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.779 [  e] 9 MediaPlayer:onPadAddedCalled
2017-11-14 01:15:08.779 [  2] 9 MediaPlayer:handlePadAddedSignalCalled
2017-11-14 01:15:08.779 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.779 [  2] 9 MediaPlayer:messageReceived:messageType=stream-start
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:messageReceived:messageType=latency
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:08.799 [  2] 0 MediaPlayer:callingOnTags
[2017-11-14 01:15:08.799] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:281] onTags: id=1
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:08.799 [  2] 0 MediaPlayer:callingOnTags
[2017-11-14 01:15:08.799] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:281] onTags: id=1
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:State Change:oldState=READY,newState=PAUSED,pendingState=PLAYING
2017-11-14 01:15:08.799 [  2] 9 MediaPlayer:messageReceived:messageType=async-done
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=new-clock
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:State Change:oldState=PAUSED,newState=PLAYING,pendingState=VOID_PENDING
2017-11-14 01:15:08.800 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
[2017-11-14 01:15:08.800] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:233] onPlaybackStarted: id=1
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:08.800 [  2] 0 MediaPlayer:callingOnTags
[2017-11-14 01:15:08.800] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:281] onTags: id=1
2017-11-14 01:15:08.800 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:08.800 [  2] 0 MediaPlayer:callingOnTags
[2017-11-14 01:15:08.801] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:281] onTags: id=1
2017-11-14 01:15:10.383 [  e] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:10.383 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:10.582 [  2] 9 MediaPlayer:messageReceived:messageType=eos
2017-11-14 01:15:10.582 [  2] 9 BaseStreamSource:~BaseStreamSource
2017-11-14 01:15:10.582 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=1
[2017-11-14 01:15:10.583] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:245] onPlaybackFinished: id=1
2017-11-14 01:15:10.583 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:10.583 [  c] 1 FocusManager:releaseChannel:channelName=LocalAudioChannel
2017-11-14 01:15:10.583 [  d] I TonlyAudioPlayer:onFocusChanged:newFocus=NONE
[2017-11-14 01:15:10.583] [tonly_avs_app] [INFO] [src/TonlyAudioPlayer.cpp:129] executeOnFocusChanged from FOREGROUND to NONE
t
2017-11-14 01:15:18.006 [  8] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2017-11-14 01:15:18.006 [  f] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
############################
#       Listening...       #
############################

[2017-11-14 01:15:18.006] [tonly_avs_app] [ERR] [src/AlsaMicrophoneWrapper.cpp:293] Failed to start PortAudio stream
2017-11-14 01:15:18.006 [  6] 9 SpeakerManager:provideStateCalled
2017-11-14 01:15:18.007 [  7] 9 SpeakerManager:executeProvideStateCalled
2017-11-14 01:15:18.007 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:18.007 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:18.007 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:18.007 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:18.007 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:18.007 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:18.007 [  7] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true
2017-11-14 01:15:18.007 [  7] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false
2017-11-14 01:15:18.007 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState
2017-11-14 01:15:18.008 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:100\,"muted"\:false}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}\,{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}]}
2017-11-14 01:15:18.008 [  8] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context"\:[{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:100\,"muted"\:false}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}\,{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}]}
2017-11-14 01:15:18.008 [  8] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechRecognizer.Recognize
2017-11-14 01:15:18.008 [  8] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=435b2b1f-a793-4110-915a-67a14e9cda03
2017-11-14 01:15:18.008 [  8] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId
2017-11-14 01:15:18.008 [  8] 0 EventBuilder:buildJsonEventString:messageId=9afa26fa-c8b4-41bd-a1e8-ede8ebfffdc9,namespace=SpeechRecognizer,name=Recognize
2017-11-14 01:15:18.008 [  8] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:18.008 [  8] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:18.087 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:18.087 [  b] 0 HTTP2StreamPool:getStream:streamId=5,numAcquiredStreams=2
2017-11-14 01:15:18.087 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe70118120
2017-11-14 01:15:20.893 [ 10] 0 MessageInterpreter:receive:messageId=e0fcc693-9b2c-46ab-8d89-f4b07485b8e9:No dialogRequestId attached to message.
2017-11-14 01:15:20.893 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"e0fcc693-9b2c-46ab-8d89-f4b07485b8e9"\,dialogRequestId\:""}
2017-11-14 01:15:20.893 [ 11] I DirectiveRouter:preHandleDirective:messageId=e0fcc693-9b2c-46ab-8d89-f4b07485b8e9,action=calling
2017-11-14 01:15:20.893 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=e0fcc693-9b2c-46ab-8d89-f4b07485b8e9
2017-11-14 01:15:20.894 [ 12] I DirectiveRouter:handleDirective:messageId=e0fcc693-9b2c-46ab-8d89-f4b07485b8e9,action=calling
2017-11-14 01:15:20.894 [  8] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2017-11-14 01:15:20.894 [  8] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-11-14 01:15:20.894 [  f] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
###########################
#       Thinking...       #
###########################

2017-11-14 01:15:20.894 [  8] 0 DirectiveProcessor:onHandlingCompeted:messageId=e0fcc693-9b2c-46ab-8d89-f4b07485b8e9,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:20.894 [  8] 0 CapabilityAgent:removingMessageIdFromMap:messageId=e0fcc693-9b2c-46ab-8d89-f4b07485b8e9
2017-11-14 01:15:20.903 [  b] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-14 01:15:21.718 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-5
2017-11-14 01:15:21.966 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"1432e1d4-4694-47fd-8671-7a607510f629"\,dialogRequestId\:"435b2b1f-a793-4110-915a-67a14e9cda03"}
2017-11-14 01:15:21.966 [ 11] I DirectiveRouter:preHandleDirective:messageId=1432e1d4-4694-47fd-8671-7a607510f629,action=calling
2017-11-14 01:15:21.966 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=1432e1d4-4694-47fd-8671-7a607510f629
2017-11-14 01:15:21.966 [ 11] 9 SpeechSynthesizer:preHandleDirective:messageId=1432e1d4-4694-47fd-8671-7a607510f629
2017-11-14 01:15:21.966 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"AudioPlayer"\,name\:"Play"\,messageId\:"54c7afad-2b2c-47e5-9ae4-5d718ad034d7"\,dialogRequestId\:"435b2b1f-a793-4110-915a-67a14e9cda03"}
2017-11-14 01:15:21.966 [ 11] I DirectiveRouter:preHandleDirective:messageId=54c7afad-2b2c-47e5-9ae4-5d718ad034d7,action=calling
2017-11-14 01:15:21.966 [  a] 0 SpeechSynthesizer:executePreHandle:messageId=1432e1d4-4694-47fd-8671-7a607510f629
2017-11-14 01:15:21.966 [ 12] I DirectiveRouter:handleDirective:messageId=1432e1d4-4694-47fd-8671-7a607510f629,action=calling
2017-11-14 01:15:21.966 [ 12] 9 SpeechSynthesizer:handleDirective:messageId=1432e1d4-4694-47fd-8671-7a607510f629
2017-11-14 01:15:21.966 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=54c7afad-2b2c-47e5-9ae4-5d718ad034d7
2017-11-14 01:15:21.966 [  b] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2017-11-14 01:15:21.966 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=5,result=200
2017-11-14 01:15:21.966 [  b] 0 HTTP2StreamPool:releaseStream:streamId=5,numAcquiredStreams=1
2017-11-14 01:15:21.966 [  a] 0 SpeechSynthesizer:executeHandle:messageId=1432e1d4-4694-47fd-8671-7a607510f629
2017-11-14 01:15:21.966 [  a] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-11-14 01:15:21.966 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:21.966 [  8] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-11-14 01:15:21.966 [  8] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
2017-11-14 01:15:21.966 [  8] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-11-14 01:15:21.966 [  a] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-11-14 01:15:21.966 [  a] 9 SpeechSynthesizer:startPlaying
2017-11-14 01:15:21.966 [  f] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE
2017-11-14 01:15:21.967 [  a] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
########################################
#       Alexa is currently idle!       #
########################################

2017-11-14 01:15:21.967 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-14 01:15:21.967 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:21.967 [  a] 9 MediaPlayer:playCalled
2017-11-14 01:15:21.967 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2017-11-14 01:15:21.967 [  2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-11-14 01:15:21.969 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-14 01:15:21.969 [ 13] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.969 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.970 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.970 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:21.970 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.970 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:21.970 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:21.970 [  2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=24
2017-11-14 01:15:21.970 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:21.970 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:21.970 [  2] 9 AttachmentReaderSource:read:size=1933,status=0
2017-11-14 01:15:21.970 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-14 01:15:21.970 [  2] 9 AttachmentReaderSource:read:size=0,status=3
2017-11-14 01:15:21.970 [  2] 9 BaseStreamSource:signalEndOfDataCalled
2017-11-14 01:15:21.970 [  2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=24
2017-11-14 01:15:21.971 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.971 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.971 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.971 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.971 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.971 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.971 [ 13] 9 MediaPlayer:onPadAddedCalled
2017-11-14 01:15:21.971 [  2] 9 MediaPlayer:handlePadAddedSignalCalled
2017-11-14 01:15:21.972 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.972 [  2] 9 MediaPlayer:messageReceived:messageType=stream-start
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=latency
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:21.989 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:21.989 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:State Change:oldState=READY,newState=PAUSED,pendingState=PLAYING
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=async-done
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=new-clock
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.989 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.990 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.990 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.990 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.990 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.990 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:21.990 [  2] 9 MediaPlayer:State Change:oldState=PAUSED,newState=PLAYING,pendingState=VOID_PENDING
2017-11-14 01:15:21.990 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=2
2017-11-14 01:15:21.990 [  2] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=2
2017-11-14 01:15:21.990 [  a] 0 SpeechSynthesizer:executePlaybackStarted
2017-11-14 01:15:21.990 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:21.990 [  a] 9 MediaPlayer:getOffsetCalled
2017-11-14 01:15:21.990 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=2,currentId=2
2017-11-14 01:15:21.993 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRendererV4_593f21bc-91dd-4500-a052-a23b595f7f02"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"PLAYING"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:21.993 [  d] 9 SpeechSynthesizer:onFocusChangedSuccess
2017-11-14 01:15:21.993 [  a] 0 EventBuilder:buildJsonEventString:messageId=4cb2fef5-7c5e-4175-87d9-4843b755e55e,namespace=SpeechSynthesizer,name=SpeechStarted
2017-11-14 01:15:21.993 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:21.993 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:21.993 [  f] 0 DialogUXStateAggregator:setState:from=IDLE,to=SPEAKING
2017-11-14 01:15:21.993 [  2] 0 MediaPlayer:callingOnTags
###########################
#       Speaking...       #
###########################

2017-11-14 01:15:22.067 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:22.067 [  b] 0 HTTP2StreamPool:getStream:streamId=7,numAcquiredStreams=2
2017-11-14 01:15:22.067 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe70118120
2017-11-14 01:15:22.433 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-7
2017-11-14 01:15:22.433 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=7,result=204
2017-11-14 01:15:22.433 [  b] 0 HTTP2StreamPool:releaseStream:streamId=7,numAcquiredStreams=1
2017-11-14 01:15:22.433 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:22.916 [ 13] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:22.916 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:23.500 [  2] 9 MediaPlayer:messageReceived:messageType=eos
2017-11-14 01:15:23.500 [  2] 9 BaseStreamSource:~BaseStreamSource
2017-11-14 01:15:23.500 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=2
2017-11-14 01:15:23.500 [  2] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=2
2017-11-14 01:15:23.500 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:23.500 [  a] 0 SpeechSynthesizer:executePlaybackFinished
2017-11-14 01:15:23.500 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:23.500 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRendererV4_593f21bc-91dd-4500-a052-a23b595f7f02"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:23.500 [  a] 9 SpeechSynthesizer:releaseForegroundFocus
2017-11-14 01:15:23.500 [  a] 1 FocusManager:releaseChannel:channelName=Dialog
2017-11-14 01:15:23.501 [  a] 0 EventBuilder:buildJsonEventString:messageId=6e6e9e43-9498-4220-b1eb-87dba6bc8cee,namespace=SpeechSynthesizer,name=SpeechFinished
2017-11-14 01:15:23.501 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:23.501 [  a] 9 SpeechSynthesizer:setHandlingCompleted
2017-11-14 01:15:23.501 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-11-14 01:15:23.501 [  a] 0 DirectiveProcessor:onHandlingCompeted:messageId=1432e1d4-4694-47fd-8671-7a607510f629,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:23.501 [  a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=1432e1d4-4694-47fd-8671-7a607510f629
2017-11-14 01:15:23.501 [ 12] I DirectiveRouter:handleDirective:messageId=54c7afad-2b2c-47e5-9ae4-5d718ad034d7,action=calling
2017-11-14 01:15:23.501 [ 12] 0 AudioPlayer:handleDirective:name=Play,messageId=54c7afad-2b2c-47e5-9ae4-5d718ad034d7
2017-11-14 01:15:23.501 [ 12] 1 AudioPlayer:handlePlayDirective
2017-11-14 01:15:23.501 [ 12] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=streamFormat
2017-11-14 01:15:23.502 [ 12] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReportIntervalInMilliseconds
2017-11-14 01:15:23.502 [ 12] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-11-14 01:15:23.502 [ 12] 0 DirectiveProcessor:onHandlingCompeted:messageId=54c7afad-2b2c-47e5-9ae4-5d718ad034d7,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:23.502 [ 12] 0 CapabilityAgent:removingMessageIdFromMap:messageId=54c7afad-2b2c-47e5-9ae4-5d718ad034d7
2017-11-14 01:15:23.503 [  9] 1 AudioPlayer:executePlay:playBehavior=REPLACE_ALL
2017-11-14 01:15:23.503 [  9] 1 AudioPlayer:executeStop:playNextItem=true,m_currentActivity=IDLE
2017-11-14 01:15:23.503 [  9] 1 FocusManager:acquireChannel:channelName=Content,activityId=AudioPlayer.Play
2017-11-14 01:15:23.503 [  d] 0 AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:23.503 [  9] 1 AudioPlayer:executeOnFocusChanged:from=NONE,to=FOREGROUND,m_currentActivity=IDLE
2017-11-14 01:15:23.503 [  9] 1 AudioPlayer:executeOnFocusChanged:action=playNextItem
2017-11-14 01:15:23.503 [  9] 1 AudioPlayer:playNextItem:m_audioItems.size=1
2017-11-14 01:15:23.503 [  9] 9 MediaPlayer:setSourceForUrlCalled
2017-11-14 01:15:23.520 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:23.520 [ 14] 0 MediaPlayer:handleSetSourceForUrlCalled
2017-11-14 01:15:23.520 [ 14] 9 UrlSource:UrlSourceCreate
2017-11-14 01:15:23.520 [ 14] 0 UrlSource:initCalledForUrlSource
2017-11-14 01:15:23.521 [  9] 1 AudioPlayer:playNextItem:item.stream.offset=0
2017-11-14 01:15:23.521 [  9] 9 MediaPlayer:playCalled
2017-11-14 01:15:23.537 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:23.537 [  b] 0 HTTP2StreamPool:getStream:streamId=9,numAcquiredStreams=2
2017-11-14 01:15:23.537 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe70118120
2017-11-14 01:15:23.703 [  f] 0 DialogUXStateAggregator:setState:from=FINISHED,to=IDLE
########################################
#       Alexa is currently idle!       #
########################################

2017-11-14 01:15:23.977 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-9
2017-11-14 01:15:23.977 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=9,result=204
2017-11-14 01:15:23.977 [  b] 0 HTTP2StreamPool:releaseStream:streamId=9,numAcquiredStreams=1
2017-11-14 01:15:23.977 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:24.621 [ 15] 9 LibCurlHttpContentFetcher:getContent:responseCode=200
2017-11-14 01:15:24.621 [ 15] 9 LibCurlHttpContentFetcher:getContent:contentType=application/vnd.apple.mpegurl
2017-11-14 01:15:24.621 [ 16] 9 PlaylistParser:PlaylistParser:contentType=application/vnd.apple.mpegurl
2017-11-14 01:15:25.626 [ 16] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-14 01:15:25.627 [ 16] 9 PlaylistParser:isM3U8Playlist
2017-11-14 01:15:25.627 [ 16] 9 UrlSource:urlParsedSuccessfully
2017-11-14 01:15:25.628 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=3,currentId=3
2017-11-14 01:15:25.628 [  2] 0 MediaPlayer:handlePlay:attemptBuffering=1
2017-11-14 01:15:25.630 [  2] 0 MediaPlayer:handlePlay:startingState=PAUSED,stateReturn=FAILURE
2017-11-14 01:15:25.630 [  2] E MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure
2017-11-14 01:15:25.630 [  2] 0 MediaPlayer:callingOnPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer\:handlePlayFailed\:reason\=gstElementSetStateFailure,currentId=3
2017-11-14 01:15:25.630 [  2] 0 AudioPlayer:onPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer\:handlePlayFailed\:reason\=gstElementSetStateFailure,id=3
2017-11-14 01:15:25.630 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:25.630 [  2] 9 UrlSource:shutdownCalled
2017-11-14 01:15:25.631 [  9] E AudioPlayer:executeOnPlaybackError:id=3,type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer\:handlePlayFailed\:reason\=gstElementSetStateFailure
2017-11-14 01:15:25.631 [  9] 0 EventBuilder:buildJsonEventString:messageId=124b7407-4c9e-4a19-928c-faef3ed721fd,namespace=AudioPlayer,name=PlaybackFailed
2017-11-14 01:15:25.631 [  9] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:25.631 [  9] 1 AudioPlayer:executeStop:playNextItem=false,m_currentActivity=IDLE
2017-11-14 01:15:25.681 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:25.681 [  b] 0 HTTP2StreamPool:getStream:streamId=11,numAcquiredStreams=2
2017-11-14 01:15:25.681 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe70118120
2017-11-14 01:15:26.575 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-11
2017-11-14 01:15:26.630 [  9] 1 AudioPlayer:sendEventWithTokenAndOffset:eventName=ProgressReportDelayElapsed
2017-11-14 01:15:26.630 [  9] 0 EventBuilder:buildJsonEventString:messageId=e2978212-9c50-464f-978c-06ea8c530933,namespace=AudioPlayer,name=ProgressReportDelayElapsed
2017-11-14 01:15:26.631 [  9] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:26.677 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:26.677 [  b] 0 HTTP2StreamPool:getStream:streamId=13,numAcquiredStreams=3
2017-11-14 01:15:26.677 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe70133540
2017-11-14 01:15:26.814 [ 10] 0 MessageInterpreter:receive:messageId=39fe4460-67dc-4878-b270-838796bb1726:No dialogRequestId attached to message.
2017-11-14 01:15:26.814 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"Speaker"\,name\:"SetMute"\,messageId\:"39fe4460-67dc-4878-b270-838796bb1726"\,dialogRequestId\:""}
2017-11-14 01:15:26.815 [ 11] I DirectiveRouter:preHandleDirective:messageId=39fe4460-67dc-4878-b270-838796bb1726,action=calling
2017-11-14 01:15:26.815 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=39fe4460-67dc-4878-b270-838796bb1726
2017-11-14 01:15:26.815 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=11,result=200
2017-11-14 01:15:26.815 [  b] 0 HTTP2StreamPool:releaseStream:streamId=11,numAcquiredStreams=2
2017-11-14 01:15:26.815 [ 10] 0 MessageInterpreter:receive:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c:No dialogRequestId attached to message.
2017-11-14 01:15:26.815 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"f40142f3-f981-4915-b2c1-361b400d9d1c"\,dialogRequestId\:""}
2017-11-14 01:15:26.815 [ 12] I DirectiveRouter:handleDirective:messageId=39fe4460-67dc-4878-b270-838796bb1726,action=calling
2017-11-14 01:15:26.815 [ 11] I DirectiveRouter:preHandleDirective:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c,action=calling
2017-11-14 01:15:26.815 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c
2017-11-14 01:15:26.815 [ 11] 9 SpeechSynthesizer:preHandleDirective:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c
2017-11-14 01:15:26.815 [  7] 9 SpeakerManager:executeSetMuteCalled:mute=false
2017-11-14 01:15:26.815 [ 12] I DirectiveRouter:handleDirective:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c,action=calling
2017-11-14 01:15:26.815 [ 12] 9 SpeechSynthesizer:handleDirective:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c
2017-11-14 01:15:26.815 [  a] 0 SpeechSynthesizer:executePreHandle:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c
2017-11-14 01:15:26.815 [  a] 0 SpeechSynthesizer:executeHandle:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c
2017-11-14 01:15:26.815 [  a] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-11-14 01:15:26.815 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:26.815 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:26.815 [  d] 0 AudioPlayer:onFocusChanged:newFocus=BACKGROUND
2017-11-14 01:15:26.815 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:26.815 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:26.815 [  9] 1 AudioPlayer:executeOnFocusChanged:from=FOREGROUND,to=BACKGROUND,m_currentActivity=IDLE
2017-11-14 01:15:26.815 [  9] 1 AudioPlayer:executeOnFocusChanged:action=pauseMediaPlayer
2017-11-14 01:15:26.815 [  9] 9 MediaPlayer:pausedCalled
2017-11-14 01:15:26.815 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:26.815 [  2] 0 MediaPlayer:handlePauseCalled:idPassed=3,currentId=0
2017-11-14 01:15:26.815 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-14 01:15:26.815 [  2] E MediaPlayer:handlePauseFailed
2017-11-14 01:15:26.816 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:26.816 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:26.816 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:26.816 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:26.816 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:26.816 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:26.816 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:26.816 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:26.816 [  7] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true
2017-11-14 01:15:26.816 [  7] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false
2017-11-14 01:15:26.816 [  7] 9 SpeakerManager:executeNotifyObserverCalled
2017-11-14 01:15:26.816 [  7] 9 SpeakerManager:executeSendSpeakerSettingsChangedEvent
2017-11-14 01:15:26.816 [  7] 0 EventBuilder:buildJsonEventString:messageId=ddb55ff3-1983-404b-a6fd-607fcc53149c,namespace=Speaker,name=MuteChanged
2017-11-14 01:15:26.816 [  7] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:26.816 [  7] 0 DirectiveProcessor:onHandlingCompeted:messageId=39fe4460-67dc-4878-b270-838796bb1726,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:26.816 [  7] 0 CapabilityAgent:removingMessageIdFromMap:messageId=39fe4460-67dc-4878-b270-838796bb1726
2017-11-14 01:15:26.817 [  a] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-11-14 01:15:26.817 [  a] 9 SpeechSynthesizer:startPlaying
2017-11-14 01:15:26.817 [  a] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-11-14 01:15:26.817 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-14 01:15:26.817 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:26.817 [  a] 9 MediaPlayer:playCalled
2017-11-14 01:15:26.817 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=4,currentId=4
2017-11-14 01:15:26.817 [  2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-11-14 01:15:26.818 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [ 17] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.818 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:26.818 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:26.818 [  2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=40
2017-11-14 01:15:26.818 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:26.818 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:26.818 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:26.818 [  2] 9 AttachmentReaderSource:read:size=3309,status=0
2017-11-14 01:15:26.818 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-14 01:15:26.818 [  2] 9 AttachmentReaderSource:read:size=0,status=3
2017-11-14 01:15:26.818 [  2] 9 BaseStreamSource:signalEndOfDataCalled
2017-11-14 01:15:26.818 [  2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=40
2017-11-14 01:15:26.819 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.819 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.819 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.819 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.819 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.819 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.819 [ 17] 9 MediaPlayer:onPadAddedCalled
2017-11-14 01:15:26.819 [  2] 9 MediaPlayer:handlePadAddedSignalCalled
2017-11-14 01:15:26.820 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.820 [  2] 9 MediaPlayer:messageReceived:messageType=stream-start
2017-11-14 01:15:26.821 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:26.821 [  2] 9 MediaPlayer:messageReceived:messageType=latency
2017-11-14 01:15:26.821 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:26.821 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:26.821 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:26.821 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:State Change:oldState=READY,newState=PAUSED,pendingState=PLAYING
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=async-done
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=new-clock
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:State Change:oldState=PAUSED,newState=PLAYING,pendingState=VOID_PENDING
2017-11-14 01:15:26.822 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=4
2017-11-14 01:15:26.822 [  2] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=4
2017-11-14 01:15:26.822 [  a] 0 SpeechSynthesizer:executePlaybackStarted
2017-11-14 01:15:26.822 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:26.822 [  a] 9 MediaPlayer:getOffsetCalled
2017-11-14 01:15:26.822 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:26.822 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:26.822 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
2017-11-14 01:15:26.823 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRenderer_736b05fe-6069-4dda-a55f-4ce852deb49b"\,"offsetInMilliseconds"\:170\,"playerActivity"\:"PLAYING"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:26.823 [  a] 0 EventBuilder:buildJsonEventString:messageId=02186105-ab86-461c-b564-d7ffd5e2166d,namespace=SpeechSynthesizer,name=SpeechStarted
2017-11-14 01:15:26.823 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:26.823 [  d] 9 SpeechSynthesizer:onFocusChangedSuccess
2017-11-14 01:15:26.823 [  f] 0 DialogUXStateAggregator:setState:from=IDLE,to=SPEAKING
###########################
#       Speaking...       #
###########################

2017-11-14 01:15:27.252 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-13
2017-11-14 01:15:27.252 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=13,result=204
2017-11-14 01:15:27.252 [  b] 0 HTTP2StreamPool:releaseStream:streamId=13,numAcquiredStreams=1
2017-11-14 01:15:27.253 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:27.253 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:27.253 [  b] 0 HTTP2StreamPool:getStream:streamId=15,numAcquiredStreams=2
2017-11-14 01:15:27.253 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:27.802 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-15
2017-11-14 01:15:27.802 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=15,result=204
2017-11-14 01:15:27.802 [  b] 0 HTTP2StreamPool:releaseStream:streamId=15,numAcquiredStreams=1
2017-11-14 01:15:27.802 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:27.802 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:27.802 [  b] 0 HTTP2StreamPool:getStream:streamId=17,numAcquiredStreams=2
2017-11-14 01:15:27.802 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:28.405 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-17
2017-11-14 01:15:28.405 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=17,result=204
2017-11-14 01:15:28.405 [  b] 0 HTTP2StreamPool:releaseStream:streamId=17,numAcquiredStreams=1
2017-11-14 01:15:28.405 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:28.719 [ 17] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:28.719 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:29.180 [  2] 9 MediaPlayer:messageReceived:messageType=eos
2017-11-14 01:15:29.180 [  2] 9 BaseStreamSource:~BaseStreamSource
2017-11-14 01:15:29.180 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=4
2017-11-14 01:15:29.180 [  2] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=4
2017-11-14 01:15:29.180 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:29.180 [  a] 0 SpeechSynthesizer:executePlaybackFinished
2017-11-14 01:15:29.180 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:29.180 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRenderer_736b05fe-6069-4dda-a55f-4ce852deb49b"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:29.181 [  a] 9 SpeechSynthesizer:releaseForegroundFocus
2017-11-14 01:15:29.181 [  a] 1 FocusManager:releaseChannel:channelName=Dialog
2017-11-14 01:15:29.181 [  a] 0 EventBuilder:buildJsonEventString:messageId=423592e1-6b91-48e2-b60c-8da80bd7aa33,namespace=SpeechSynthesizer,name=SpeechFinished
2017-11-14 01:15:29.181 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-11-14 01:15:29.181 [  d] 0 AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:29.181 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:29.181 [  a] 9 SpeechSynthesizer:setHandlingCompleted
2017-11-14 01:15:29.181 [  a] 0 DirectiveProcessor:onHandlingCompeted:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:29.181 [  a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=f40142f3-f981-4915-b2c1-361b400d9d1c
2017-11-14 01:15:29.181 [  9] 1 AudioPlayer:executeOnFocusChanged:from=BACKGROUND,to=FOREGROUND,m_currentActivity=IDLE
2017-11-14 01:15:29.181 [  9] 1 AudioPlayer:executeOnFocusChanged:action=playNextItem
2017-11-14 01:15:29.181 [  9] 1 AudioPlayer:playNextItem:m_audioItems.size=0
2017-11-14 01:15:29.181 [  9] 0 EventBuilder:buildJsonEventString:messageId=2f48ad79-dca1-46d0-9817-ad06fc9ea967,namespace=AudioPlayer,name=PlaybackFailed
2017-11-14 01:15:29.181 [  9] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:29.181 [  9] E AudioPlayer:playNextItemFailed:reason=emptyQueue
2017-11-14 01:15:29.181 [  9] 1 AudioPlayer:executeStop:playNextItem=false,m_currentActivity=IDLE
2017-11-14 01:15:29.207 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:29.207 [  b] 0 HTTP2StreamPool:getStream:streamId=19,numAcquiredStreams=2
2017-11-14 01:15:29.207 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:29.382 [  f] 0 DialogUXStateAggregator:setState:from=FINISHED,to=IDLE
########################################
#       Alexa is currently idle!       #
########################################

2017-11-14 01:15:29.688 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-19
2017-11-14 01:15:29.688 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=19,result=204
2017-11-14 01:15:29.688 [  b] 0 HTTP2StreamPool:releaseStream:streamId=19,numAcquiredStreams=1
2017-11-14 01:15:29.688 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:29.688 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:29.688 [  b] 0 HTTP2StreamPool:getStream:streamId=21,numAcquiredStreams=2
2017-11-14 01:15:29.689 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:30.451 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-21
2017-11-14 01:15:30.698 [ 10] 0 MessageInterpreter:receive:messageId=0cdb24dd-d875-416b-ab9e-e7d1b8dede15:No dialogRequestId attached to message.
2017-11-14 01:15:30.698 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=21,result=200
2017-11-14 01:15:30.698 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"Speaker"\,name\:"SetMute"\,messageId\:"0cdb24dd-d875-416b-ab9e-e7d1b8dede15"\,dialogRequestId\:""}
2017-11-14 01:15:30.698 [  b] 0 HTTP2StreamPool:releaseStream:streamId=21,numAcquiredStreams=1
2017-11-14 01:15:30.698 [ 11] I DirectiveRouter:preHandleDirective:messageId=0cdb24dd-d875-416b-ab9e-e7d1b8dede15,action=calling
2017-11-14 01:15:30.698 [ 10] 0 MessageInterpreter:receive:messageId=66d64477-d444-489a-9b31-6eab5a4e7609:No dialogRequestId attached to message.
2017-11-14 01:15:30.698 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"66d64477-d444-489a-9b31-6eab5a4e7609"\,dialogRequestId\:""}
2017-11-14 01:15:30.698 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=0cdb24dd-d875-416b-ab9e-e7d1b8dede15
2017-11-14 01:15:30.699 [ 11] I DirectiveRouter:preHandleDirective:messageId=66d64477-d444-489a-9b31-6eab5a4e7609,action=calling
2017-11-14 01:15:30.699 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=66d64477-d444-489a-9b31-6eab5a4e7609
2017-11-14 01:15:30.699 [ 11] 9 SpeechSynthesizer:preHandleDirective:messageId=66d64477-d444-489a-9b31-6eab5a4e7609
2017-11-14 01:15:30.699 [ 12] I DirectiveRouter:handleDirective:messageId=0cdb24dd-d875-416b-ab9e-e7d1b8dede15,action=calling
2017-11-14 01:15:30.699 [ 12] I DirectiveRouter:handleDirective:messageId=66d64477-d444-489a-9b31-6eab5a4e7609,action=calling
2017-11-14 01:15:30.699 [ 12] 9 SpeechSynthesizer:handleDirective:messageId=66d64477-d444-489a-9b31-6eab5a4e7609
2017-11-14 01:15:30.699 [  7] 9 SpeakerManager:executeSetMuteCalled:mute=false
2017-11-14 01:15:30.699 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:30.699 [  a] 0 SpeechSynthesizer:executePreHandle:messageId=66d64477-d444-489a-9b31-6eab5a4e7609
2017-11-14 01:15:30.699 [  a] 0 SpeechSynthesizer:executeHandle:messageId=66d64477-d444-489a-9b31-6eab5a4e7609
2017-11-14 01:15:30.699 [  a] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-11-14 01:15:30.699 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:30.699 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:30.699 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:30.699 [  d] 0 AudioPlayer:onFocusChanged:newFocus=BACKGROUND
2017-11-14 01:15:30.699 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:30.700 [  9] 1 AudioPlayer:executeOnFocusChanged:from=FOREGROUND,to=BACKGROUND,m_currentActivity=IDLE
2017-11-14 01:15:30.700 [  9] 1 AudioPlayer:executeOnFocusChanged:action=pauseMediaPlayer
2017-11-14 01:15:30.700 [  9] 9 MediaPlayer:pausedCalled
2017-11-14 01:15:30.699 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:30.700 [  2] 0 MediaPlayer:handlePauseCalled:idPassed=3,currentId=0
2017-11-14 01:15:30.700 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-14 01:15:30.700 [  2] E MediaPlayer:handlePauseFailed
2017-11-14 01:15:30.700 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:30.700 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:30.700 [  a] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-11-14 01:15:30.700 [  a] 9 SpeechSynthesizer:startPlaying
2017-11-14 01:15:30.700 [  a] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-11-14 01:15:30.700 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:30.700 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-14 01:15:30.700 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:30.700 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:30.700 [  a] 9 MediaPlayer:playCalled
2017-11-14 01:15:30.700 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:30.700 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=5
2017-11-14 01:15:30.700 [  2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-11-14 01:15:30.701 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:30.702 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [ 18] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:30.702 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:30.702 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:30.702 [  2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=54
2017-11-14 01:15:30.702 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:30.702 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:30.702 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:30.702 [  2] 9 AttachmentReaderSource:read:size=3309,status=0
2017-11-14 01:15:30.702 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-14 01:15:30.702 [  2] 9 AttachmentReaderSource:read:size=0,status=3
2017-11-14 01:15:30.702 [  2] 9 BaseStreamSource:signalEndOfDataCalled
2017-11-14 01:15:30.702 [  2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=54
2017-11-14 01:15:30.702 [  7] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true
2017-11-14 01:15:30.702 [  7] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false
2017-11-14 01:15:30.702 [  7] 9 SpeakerManager:executeNotifyObserverCalled
2017-11-14 01:15:30.702 [  7] 9 SpeakerManager:executeSendSpeakerSettingsChangedEvent
2017-11-14 01:15:30.702 [  7] 0 EventBuilder:buildJsonEventString:messageId=226f33c8-d9b7-4cff-bc89-8989cf444aa1,namespace=Speaker,name=MuteChanged
2017-11-14 01:15:30.702 [  7] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:30.702 [  7] 0 DirectiveProcessor:onHandlingCompeted:messageId=0cdb24dd-d875-416b-ab9e-e7d1b8dede15,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:30.702 [  7] 0 CapabilityAgent:removingMessageIdFromMap:messageId=0cdb24dd-d875-416b-ab9e-e7d1b8dede15
2017-11-14 01:15:30.703 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.703 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.703 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.703 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.704 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.704 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.704 [ 18] 9 MediaPlayer:onPadAddedCalled
2017-11-14 01:15:30.704 [  2] 9 MediaPlayer:handlePadAddedSignalCalled
2017-11-14 01:15:30.705 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.705 [  2] 9 MediaPlayer:messageReceived:messageType=stream-start
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:messageReceived:messageType=latency
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:30.706 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:30.706 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.706 [  2] 9 MediaPlayer:State Change:oldState=READY,newState=PAUSED,pendingState=PLAYING
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=async-done
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=new-clock
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:State Change:oldState=PAUSED,newState=PLAYING,pendingState=VOID_PENDING
2017-11-14 01:15:30.707 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=5
2017-11-14 01:15:30.707 [  2] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=5
2017-11-14 01:15:30.707 [  a] 0 SpeechSynthesizer:executePlaybackStarted
2017-11-14 01:15:30.707 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:30.707 [  a] 9 MediaPlayer:getOffsetCalled
2017-11-14 01:15:30.707 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:30.707 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:30.707 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=5,currentId=5
2017-11-14 01:15:30.710 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRenderer_e9784392-979d-4d18-9385-a18d16577b1a"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"PLAYING"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:30.710 [  a] 0 EventBuilder:buildJsonEventString:messageId=c64f9b9a-50c5-4e23-850e-fd709510c275,namespace=SpeechSynthesizer,name=SpeechStarted
2017-11-14 01:15:30.710 [  d] 9 SpeechSynthesizer:onFocusChangedSuccess
2017-11-14 01:15:30.710 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:30.710 [  f] 0 DialogUXStateAggregator:setState:from=IDLE,to=SPEAKING
###########################
#       Speaking...       #
###########################

2017-11-14 01:15:30.799 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:30.799 [  b] 0 HTTP2StreamPool:getStream:streamId=23,numAcquiredStreams=2
2017-11-14 01:15:30.799 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:31.212 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-23
2017-11-14 01:15:31.212 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=23,result=204
2017-11-14 01:15:31.212 [  b] 0 HTTP2StreamPool:releaseStream:streamId=23,numAcquiredStreams=1
2017-11-14 01:15:31.212 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:31.212 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:31.212 [  b] 0 HTTP2StreamPool:getStream:streamId=25,numAcquiredStreams=2
2017-11-14 01:15:31.212 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:35.325 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-25
2017-11-14 01:15:35.325 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=25,result=204
2017-11-14 01:15:35.325 [  b] 0 HTTP2StreamPool:releaseStream:streamId=25,numAcquiredStreams=1
2017-11-14 01:15:35.325 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:36.171 [ 18] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:36.171 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:36.639 [  2] 9 MediaPlayer:messageReceived:messageType=eos
2017-11-14 01:15:36.639 [  2] 9 BaseStreamSource:~BaseStreamSource
2017-11-14 01:15:36.639 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=5
2017-11-14 01:15:36.639 [  2] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=5
2017-11-14 01:15:36.639 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:36.639 [  a] 0 SpeechSynthesizer:executePlaybackFinished
2017-11-14 01:15:36.639 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:36.639 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRenderer_e9784392-979d-4d18-9385-a18d16577b1a"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:36.639 [  a] 9 SpeechSynthesizer:releaseForegroundFocus
2017-11-14 01:15:36.639 [  a] 1 FocusManager:releaseChannel:channelName=Dialog
2017-11-14 01:15:36.639 [  a] 0 EventBuilder:buildJsonEventString:messageId=26973d60-6342-4316-9b19-0ab0b3619f42,namespace=SpeechSynthesizer,name=SpeechFinished
2017-11-14 01:15:36.639 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-11-14 01:15:36.639 [  d] 0 AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:36.639 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:36.639 [  a] 9 SpeechSynthesizer:setHandlingCompleted
2017-11-14 01:15:36.639 [  a] 0 DirectiveProcessor:onHandlingCompeted:messageId=66d64477-d444-489a-9b31-6eab5a4e7609,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:36.639 [  a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=66d64477-d444-489a-9b31-6eab5a4e7609
2017-11-14 01:15:36.640 [  9] 1 AudioPlayer:executeOnFocusChanged:from=BACKGROUND,to=FOREGROUND,m_currentActivity=IDLE
2017-11-14 01:15:36.640 [  9] 1 AudioPlayer:executeOnFocusChanged:action=playNextItem
2017-11-14 01:15:36.640 [  9] 1 AudioPlayer:playNextItem:m_audioItems.size=0
2017-11-14 01:15:36.640 [  9] 0 EventBuilder:buildJsonEventString:messageId=dd5e2d4a-8b0b-4bdb-8450-053471c46740,namespace=AudioPlayer,name=PlaybackFailed
2017-11-14 01:15:36.640 [  9] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:36.640 [  9] E AudioPlayer:playNextItemFailed:reason=emptyQueue
2017-11-14 01:15:36.640 [  9] 1 AudioPlayer:executeStop:playNextItem=false,m_currentActivity=IDLE
2017-11-14 01:15:36.730 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:36.730 [  b] 0 HTTP2StreamPool:getStream:streamId=27,numAcquiredStreams=2
2017-11-14 01:15:36.730 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:36.840 [  f] 0 DialogUXStateAggregator:setState:from=FINISHED,to=IDLE
########################################
#       Alexa is currently idle!       #
########################################

2017-11-14 01:15:37.208 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-27
2017-11-14 01:15:37.208 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=27,result=204
2017-11-14 01:15:37.208 [  b] 0 HTTP2StreamPool:releaseStream:streamId=27,numAcquiredStreams=1
2017-11-14 01:15:37.208 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:37.208 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:37.208 [  b] 0 HTTP2StreamPool:getStream:streamId=29,numAcquiredStreams=2
2017-11-14 01:15:37.208 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:38.292 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-29
2017-11-14 01:15:38.540 [ 10] 0 MessageInterpreter:receive:messageId=515df2a9-91ae-4467-ab80-dce1c11f8834:No dialogRequestId attached to message.
2017-11-14 01:15:38.540 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=29,result=200
2017-11-14 01:15:38.540 [  b] 0 HTTP2StreamPool:releaseStream:streamId=29,numAcquiredStreams=1
2017-11-14 01:15:38.540 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"Speaker"\,name\:"SetMute"\,messageId\:"515df2a9-91ae-4467-ab80-dce1c11f8834"\,dialogRequestId\:""}
2017-11-14 01:15:38.540 [ 11] I DirectiveRouter:preHandleDirective:messageId=515df2a9-91ae-4467-ab80-dce1c11f8834,action=calling
2017-11-14 01:15:38.540 [ 10] 0 MessageInterpreter:receive:messageId=d3c2631d-8857-4858-805f-d272674d704f:No dialogRequestId attached to message.
2017-11-14 01:15:38.540 [ 10] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechSynthesizer"\,name\:"Speak"\,messageId\:"d3c2631d-8857-4858-805f-d272674d704f"\,dialogRequestId\:""}
2017-11-14 01:15:38.540 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=515df2a9-91ae-4467-ab80-dce1c11f8834
2017-11-14 01:15:38.540 [ 11] I DirectiveRouter:preHandleDirective:messageId=d3c2631d-8857-4858-805f-d272674d704f,action=calling
2017-11-14 01:15:38.540 [ 11] 0 CapabilityAgent:addingMessageIdToMap:messageId=d3c2631d-8857-4858-805f-d272674d704f
2017-11-14 01:15:38.540 [ 11] 9 SpeechSynthesizer:preHandleDirective:messageId=d3c2631d-8857-4858-805f-d272674d704f
2017-11-14 01:15:38.540 [ 12] I DirectiveRouter:handleDirective:messageId=515df2a9-91ae-4467-ab80-dce1c11f8834,action=calling
2017-11-14 01:15:38.540 [  a] 0 SpeechSynthesizer:executePreHandle:messageId=d3c2631d-8857-4858-805f-d272674d704f
2017-11-14 01:15:38.541 [ 12] I DirectiveRouter:handleDirective:messageId=d3c2631d-8857-4858-805f-d272674d704f,action=calling
2017-11-14 01:15:38.541 [ 12] 9 SpeechSynthesizer:handleDirective:messageId=d3c2631d-8857-4858-805f-d272674d704f
2017-11-14 01:15:38.541 [  a] 0 SpeechSynthesizer:executeHandle:messageId=d3c2631d-8857-4858-805f-d272674d704f
2017-11-14 01:15:38.541 [  a] 1 FocusManager:acquireChannel:channelName=Dialog,activityId=SpeechSynthesizer.Speak
2017-11-14 01:15:38.541 [  7] 9 SpeakerManager:executeSetMuteCalled:mute=false
2017-11-14 01:15:38.541 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:38.541 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:38.541 [  d] 0 AudioPlayer:onFocusChanged:newFocus=BACKGROUND
2017-11-14 01:15:38.541 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:38.541 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:38.541 [  9] 1 AudioPlayer:executeOnFocusChanged:from=FOREGROUND,to=BACKGROUND,m_currentActivity=IDLE
2017-11-14 01:15:38.541 [  9] 1 AudioPlayer:executeOnFocusChanged:action=pauseMediaPlayer
2017-11-14 01:15:38.541 [  9] 9 MediaPlayer:pausedCalled
2017-11-14 01:15:38.541 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:38.541 [  2] 0 MediaPlayer:handlePauseCalled:idPassed=3,currentId=0
2017-11-14 01:15:38.541 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-14 01:15:38.541 [  2] E MediaPlayer:handlePauseFailed
2017-11-14 01:15:38.541 [  7] 9 MediaPlayer:setMuteCalled
2017-11-14 01:15:38.541 [  2] 9 MediaPlayer:handleSetMuteCalled
2017-11-14 01:15:38.541 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:38.541 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:38.541 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:38.541 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:38.541 [  7] 9 MediaPlayer:getSpeakerSettingsCalled
2017-11-14 01:15:38.541 [  2] 9 MediaPlayer:handleGetSpeakerSettingsCalled
2017-11-14 01:15:38.541 [  7] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true
2017-11-14 01:15:38.541 [  7] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false
2017-11-14 01:15:38.541 [  7] 9 SpeakerManager:executeNotifyObserverCalled
2017-11-14 01:15:38.541 [  7] 9 SpeakerManager:executeSendSpeakerSettingsChangedEvent
2017-11-14 01:15:38.541 [  7] 0 EventBuilder:buildJsonEventString:messageId=d7d5084c-d3f5-4b23-8319-fe0d0985b69b,namespace=Speaker,name=MuteChanged
2017-11-14 01:15:38.541 [  7] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:38.541 [  7] 0 DirectiveProcessor:onHandlingCompeted:messageId=515df2a9-91ae-4467-ab80-dce1c11f8834,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:38.541 [  7] 0 CapabilityAgent:removingMessageIdFromMap:messageId=515df2a9-91ae-4467-ab80-dce1c11f8834
2017-11-14 01:15:38.541 [  a] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-11-14 01:15:38.541 [  a] 9 SpeechSynthesizer:startPlaying
2017-11-14 01:15:38.541 [  a] 9 MediaPlayer:setSourceCalled:sourceType=AttachmentReader
2017-11-14 01:15:38.541 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-14 01:15:38.541 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:38.541 [  a] 9 MediaPlayer:playCalled
2017-11-14 01:15:38.541 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=6,currentId=6
2017-11-14 01:15:38.541 [  2] 0 MediaPlayer:handlePlay:attemptBuffering=0
2017-11-14 01:15:38.557 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [ 19] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:State Change:oldState=NULL,newState=READY,pendingState=PLAYING
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.557 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:38.557 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:38.557 [  2] 9 BaseStreamSource:installOnReadDataHandler:action=newSourceId,sourceId=68
2017-11-14 01:15:38.557 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:38.557 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:38.557 [  2] 9 AttachmentReaderSource:read:size=4096,status=0
2017-11-14 01:15:38.557 [  2] 9 AttachmentReaderSource:read:size=3309,status=0
2017-11-14 01:15:38.557 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-14 01:15:38.557 [  2] 9 AttachmentReaderSource:read:size=0,status=3
2017-11-14 01:15:38.557 [  2] 9 BaseStreamSource:signalEndOfDataCalled
2017-11-14 01:15:38.557 [  2] 9 BaseStreamSource:clearOnReadDataHandlerCalled:sourceId=68
2017-11-14 01:15:38.558 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.558 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.558 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.558 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.559 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.559 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.559 [ 19] 9 MediaPlayer:onPadAddedCalled
2017-11-14 01:15:38.559 [  2] 9 MediaPlayer:handlePadAddedSignalCalled
2017-11-14 01:15:38.560 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.560 [  2] 9 MediaPlayer:messageReceived:messageType=stream-start
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=latency
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=stream-status
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:38.561 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:38.561 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:State Change:oldState=READY,newState=PAUSED,pendingState=PLAYING
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=async-done
2017-11-14 01:15:38.561 [  2] 9 MediaPlayer:messageReceived:messageType=new-clock
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=tag
2017-11-14 01:15:38.562 [  2] 0 MediaPlayer:callingOnTags
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:messageReceived:messageType=state-changed
2017-11-14 01:15:38.562 [  2] 9 MediaPlayer:State Change:oldState=PAUSED,newState=PLAYING,pendingState=VOID_PENDING
2017-11-14 01:15:38.562 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=6
2017-11-14 01:15:38.562 [  2] 9 SpeechSynthesizer:onPlaybackStarted:callbackSourceId=6
2017-11-14 01:15:38.562 [  a] 0 SpeechSynthesizer:executePlaybackStarted
2017-11-14 01:15:38.562 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:38.562 [  a] 9 MediaPlayer:getOffsetCalled
2017-11-14 01:15:38.562 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=6,currentId=6
2017-11-14 01:15:38.565 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRenderer_7a2490fa-a747-40fd-800c-9032d03b6244"\,"offsetInMilliseconds"\:8\,"playerActivity"\:"PLAYING"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:38.565 [  a] 0 EventBuilder:buildJsonEventString:messageId=db008e6d-94c1-46a1-b50e-a4c43fd6b08e,namespace=SpeechSynthesizer,name=SpeechStarted
2017-11-14 01:15:38.566 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:38.566 [  d] 9 SpeechSynthesizer:onFocusChangedSuccess
2017-11-14 01:15:38.566 [  f] 0 DialogUXStateAggregator:setState:from=IDLE,to=SPEAKING
###########################
#       Speaking...       #
###########################

2017-11-14 01:15:38.640 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:38.640 [  b] 0 HTTP2StreamPool:getStream:streamId=31,numAcquiredStreams=2
2017-11-14 01:15:38.641 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:39.063 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-31
2017-11-14 01:15:39.063 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=31,result=204
2017-11-14 01:15:39.063 [  b] 0 HTTP2StreamPool:releaseStream:streamId=31,numAcquiredStreams=1
2017-11-14 01:15:39.063 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:39.063 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:39.063 [  b] 0 HTTP2StreamPool:getStream:streamId=33,numAcquiredStreams=2
2017-11-14 01:15:39.063 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:39.428 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-33
2017-11-14 01:15:39.428 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=33,result=204
2017-11-14 01:15:39.428 [  b] 0 HTTP2StreamPool:releaseStream:streamId=33,numAcquiredStreams=1
2017-11-14 01:15:39.428 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-14 01:15:40.447 [ 19] 9 BaseStreamSource:onNeedDataCalled:size=4096
2017-11-14 01:15:40.447 [  2] 9 BaseStreamSource:handleNeedDataCalled
2017-11-14 01:15:40.915 [  2] 9 MediaPlayer:messageReceived:messageType=eos
2017-11-14 01:15:40.915 [  2] 9 BaseStreamSource:~BaseStreamSource
2017-11-14 01:15:40.915 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=6
2017-11-14 01:15:40.915 [  2] 9 SpeechSynthesizer:onPlaybackFinished:callbackSourceId=6
2017-11-14 01:15:40.915 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:40.915 [  a] 0 SpeechSynthesizer:executePlaybackFinished
2017-11-14 01:15:40.915 [  a] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-14 01:15:40.915 [  a] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Music#ACRI#DeviceTTSRenderer_7a2490fa-a747-40fd-800c-9032d03b6244"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-14 01:15:40.915 [  a] 9 SpeechSynthesizer:releaseForegroundFocus
2017-11-14 01:15:40.915 [  a] 1 FocusManager:releaseChannel:channelName=Dialog
2017-11-14 01:15:40.915 [  d] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-11-14 01:15:40.915 [  d] 0 AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2017-11-14 01:15:40.915 [  9] 1 AudioPlayer:executeOnFocusChanged:from=BACKGROUND,to=FOREGROUND,m_currentActivity=IDLE
2017-11-14 01:15:40.915 [  9] 1 AudioPlayer:executeOnFocusChanged:action=playNextItem
2017-11-14 01:15:40.915 [  9] 1 AudioPlayer:playNextItem:m_audioItems.size=0
2017-11-14 01:15:40.915 [  9] 0 EventBuilder:buildJsonEventString:messageId=38e4f668-645a-43c5-9f9c-a8db082ed75f,namespace=AudioPlayer,name=PlaybackFailed
2017-11-14 01:15:40.915 [  9] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:40.915 [  9] E AudioPlayer:playNextItemFailed:reason=emptyQueue
2017-11-14 01:15:40.915 [  9] 1 AudioPlayer:executeStop:playNextItem=false,m_currentActivity=IDLE
2017-11-14 01:15:40.915 [  a] 0 EventBuilder:buildJsonEventString:messageId=0aa2cea1-b48a-43a4-aa25-9f165f8dc7d8,namespace=SpeechSynthesizer,name=SpeechFinished
2017-11-14 01:15:40.915 [  a] 9 HTTP2Transport:enqueueRequest
2017-11-14 01:15:40.915 [  a] 9 SpeechSynthesizer:setHandlingCompleted
2017-11-14 01:15:40.915 [  a] 0 DirectiveProcessor:onHandlingCompeted:messageId=d3c2631d-8857-4858-805f-d272674d704f,directiveBeingPreHandled=(nullptr)
2017-11-14 01:15:40.916 [  a] 0 CapabilityAgent:removingMessageIdFromMap:messageId=d3c2631d-8857-4858-805f-d272674d704f
2017-11-14 01:15:40.933 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:40.934 [  b] 0 HTTP2StreamPool:getStream:streamId=35,numAcquiredStreams=2
2017-11-14 01:15:40.934 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe7012b6b0
2017-11-14 01:15:41.116 [  f] 0 DialogUXStateAggregator:setState:from=FINISHED,to=IDLE
########################################
#       Alexa is currently idle!       #
########################################

2017-11-14 01:15:41.789 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 06504afffece393c-00004731-000020b2-fae3b4e89175aee7-40410845-35
2017-11-14 01:15:41.789 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-14 01:15:41.789 [  b] 0 HTTP2StreamPool:getStream:streamId=37,numAcquiredStreams=3
2017-11-14 01:15:41.789 [  b] 9 HTTP2Transport:insertActiveStream:handle=0x7fbe70118120
^C
sundq@ubuntu:~/workspace/tonly_t8c/tonlyAVSApp$

Hi @sundq,
I can confirm that during my tests with TuneIn playback I reproduced the situation where the application reports "XXXX station is currently unavailable" and starting from that will continue in an endless loop reporting this vocal feedback.
There is no way to stop the endless loop (the "Alexa stop" and "Alexa shut-up" does not produce any result) unless asking Alexa for another TuneIn station (and, hopefully, an available station) and wait for the playback to start. After that the "Alexa stop" command is properly recognized and it is possible to continue with voice prompts.
It goes without saying that this is only a possible way to recover from that condition (it cannot considered either as a proper way to recover from it), but the reproducibility of this issue is 100%. On previous versions (v.1.0.2) it was working as expected.
Regards

Hi Tony,
I tried the steps that you have detailed but could not reproduce the issue. When I ask "Beat it" it plays the right song.  On what platform are you running the SDKv1.2.0 and which gstreamer version are you using.
I see a couple of interesting errors
[2017-11-14 01:15:18.006] [tonly_avs_app] [ERR] [src/AlsaMicrophoneWrapper.cpp:293] Failed to start PortAudio stream.
2017-11-14 01:15:25.630 [  2] E MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure
2017-11-14 01:15:25.630 [  2] 0 MediaPlayer:callingOnPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure,currentId=3
2017-11-14 01:15:25.630 [  2] 0 AudioPlayer:onPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=MediaPlayer:handlePlayFailed:reason=gstElementSetStateFailure,id=3
2017-11-14 01:15:25.630 [  2] 9 MediaPlayer:tearDownTransientPipelineElements
2017-11-14 01:15:25.630 [  2] 9 UrlSource:shutdownCalled
For some reason
I see file name TonlyAudioPlayer.cpp in the log. Are you using the C++ SDK as is or have you changed it. If you have changed how extensively has it been changed.
Thanks
Priya

Hi @priyagsenthil
I  notice that @Longynus83 have reproduced the issue. This issue can reproduce when alexa can not play music, such as the gstreamer can not support https URL, because glib-networking and gnutls not installed, this is why the MEDIA_ERROR_INTERNAL_DEVICE_ERROR error log emited. The  TonlyAudioPlayer.cpp file is myself audio player refer to audoplay.cpp to  play local audio file, so it would not affect the SDK.

@Longynus83  would you have plan to fix this bug?

Hi @priyagsenthil
I met this problem when I tried to play C89.5 on tunein yesterday but I can play C89.5 on tunein today, So, I think this maybe related with account or network condition?
Thank you : )

Hi,
Regarding the Amazon music problem I see in another thread a similar error https://github.com/alexa/avs-device-sdk/issues/293 and this was because of missing plugins.
Can you check if you have base/good/bad plugins of gstreamer 1.10.4 and also libav.
Thanks
Priya

Hi All,
We do have all of the plugins installed in our setup, and the libav is properly configured. As I said in my post, the issue can be repro-ed and it seems like it is not related to account/network condition.
Additionally, please consider that the issue is not related to being able/not being able to play a radio (as sometimes still happens not being able to playa a radio and then try again few minutes later and it works without any reason): the reported issue is related to the endless speech loop triggered when an error is reported by Alexa about a requested radio.
Regards

I got the same issues with 1.2.0 SDK (I tried to playback TuneIn and the application reported "XXXX station is currently unavailable" and starting from that will continue in an endless loop reporting this vocal feedback and only restarting the recovered it). I do not think this is related to glib-networking,gnutls as the same build played the same channel after some time. I will collect the logs if I am able to reproduce the issue.
Thanks,
gl

Hi, lajeeraj!
It seems that this issue has been fixed in 1.2.1 release. Can you upgrade to that version?

Hi @sundq
I am doing a user study on the AVS-device-SDK and would love to talk to you about your experiences as a developer. To participate, please fill out this Contact Form and I will get in touch with you.
Thanks

Hi @sundq,
Closing issue due to inactivity. Feel free to re-open if you run into issues around this again or there are further comments.
Regards,
-SWH

@scotthea-amazon There are serveral users or developer  reproduced this issue, do you reproduced it ? , if you do,  I think you should write  a version's Changelog when this isssue is fixed。due to inactivity is a good reason?

@anu-mathur Sorry ,I can not open your link

Hello sundq,
I closed the issue because mavamazon indicated that the problem appeared to be fixed in 1.2.1, after a few weeks there was no further activity on this issue.  It sounds like you are concerned that this may still be a live issue in the current code, so I am re-opening it.  Would you please confirm if you are still seeing the problem in the latest version (currently 1.3)?
Thank you,
-SWH

Hi,
The issue as described was listed as a Known Issue in V1.2:
Music playback failures may result in an error Text to Speech being rendered repeatedly
As @scotthea-amazon and @mavamazon mentions, this was fixed in V1.2.1. It was not explicitly mentioned as a Bug Fix, but was removed from the list of Known Issues. If this issue is still being seen, please feel free to re-open.