cannot hear the response audio when barge-in during my sports update on V1.2.0 SDK

error_log_20171115.txt

		**********  AVS_SDK	Start test AVS  ********** --> 2017-11-15 18:58:11:993
[==========] Muticast address is: 224.0.0.251
Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from QCSVA_AlexaAudioTestbinded success!!!
	Nut2AVS: findMe:: waiting for new command...

[ RUN      ] QCSVA_AlexaAudioTest.avsFunctionTest
2017-11-15 10:58:12.001 [  3] I ConfigurationNode:initializeSuccess
2017-11-15 10:58:12.082 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=SetEndpoint,handler=0xa7a30244,policy=NON_BLOCKING
2017-11-15 10:58:12.084 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=ResetUserInactivity,handler=0xa7a30244,policy=NON_BLOCKING
2017-11-15 10:58:12.087 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=ExpectSpeech,handler=0xa7a30488,policy=NON_BLOCKING
2017-11-15 10:58:12.087 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=StopCapture,handler=0xa7a30488,policy=NON_BLOCKING
2017-11-15 10:58:12.091 [  3] I SensoryKeywordDetector:License expires on 01 Feb 2018 00:00:00 GMT
2017-11-15 10:58:12.091 [  3] I SensoryKeywordDetector:Sensory library license does not expire for at least 60 more days.
2017-11-15 10:58:12.138 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-11-15 10:58:12.139 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechSynthesizer,name=Speak,handler=0xa7a4a5a0,policy=BLOCKING
2017-11-15 10:58:12.144 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-11-15 10:58:12.144 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=ClearQueue,handler=0xa7a4da00,policy=NON_BLOCKING
2017-11-15 10:58:12.145 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Stop,handler=0xa7a4da00,policy=NON_BLOCKING
2017-11-15 10:58:12.145 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Play,handler=0xa7a4da00,policy=NON_BLOCKING
2017-11-15 10:58:12.147 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-11-15 10:58:12.168 [  3] I AlertScheduler:executeScheduleNextAlertForRendering::no work to do.
2017-11-15 10:58:12.170 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=DeleteAlert,handler=0xa7a6ecd8,policy=NON_BLOCKING
2017-11-15 10:58:12.171 [  3] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetAlert,handler=0xa7a6ecd8,policy=NON_BLOCKING
2017-11-15 10:58:13.167 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:58:13.593 [  5] 0 HttpPost:doPostSucceeded:code=200
2017-11-15 10:58:13.598 [  5] 0 AuthDelegate:handleLwaResponseSucceeded:expiresInSeconds=3600
2017-11-15 10:58:13.602 [  5] 0 AuthDelegate:onAuthStateChangeCalled:state=1,error=0
2017-11-15 10:58:13.604 [  3] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=PENDING
2017-11-15 10:58:13.634 [  3] 0 HTTP2StreamPool:getStream:streamId=1,numAcquiredStreams=1
2017-11-15 10:58:13.641 [  6] E AudioPlayer:provideState:stateRequestToken=1
King AVSConnectionManager::onConnectionStatusChanged: status = 1, reason=0
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:58:13.642 [  7] E AudioPlayer:executeProvideState:sendToken=true,stateRequestToken=1
2017-11-15 10:58:13.647 [  8] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=1
--> King:: AudioPlayer executeProvideState update payload to: {"token":"","offsetInMilliseconds":0,"playerActivity":"IDLE"}
2017-11-15 10:58:13.650 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:58:13.651 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-15 10:58:13.652 [  9] 0 ContextManager:updateStateLocked:action=updatedState,state={"wakeword" \: ""},namespace=SpeechRecognizer,name=RecognizerState
8
		current mediaPlayer voluem value: 8 --> 2017-11-15 18:58:13:697
2017-11-15 10:58:13.697 [  6] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:80\,"muted"\:0},namespace=Speaker,name=VolumeState
2017-11-15 10:58:13.699 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}\,{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:80\,"muted"\:0}}]}
2017-11-15 10:58:13.701 [  6] 0 EventBuilder:buildJsonEventString:messageId=297f6ad5-f4da-48f9-9746-da23ebd17b51,namespace=System,name=SynchronizeState
2017-11-15 10:58:13.704 [  6] 0 PostConnectSynchronize:onContextAvailable : Send PostConnectMessage to transport
2017-11-15 10:58:14.171 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:58:15.173 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:58:15.439 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-1
2017-11-15 10:58:15.447 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:58:15.451 [  a] 0 HTTP2StreamPool:getStream:streamId=3,numAcquiredStreams=2
2017-11-15 10:58:16.174 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:58:17.044 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-3
2017-11-15 10:58:17.051 [  a] 0 PostConnectSynchronize:onSendCompleted:status=SUCCESS_NO_CONTENT
2017-11-15 10:58:17.063 [  a] 0 PostConnectSynchronize:onConnected()
2017-11-15 10:58:17.069 [  a] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED
King AVSConnectionManager::onConnectionStatusChanged: status = 2, reason=0
	DB20_demo_tool: volUpKeyDetectError = 0
file name: /data/nut2_avs/refreshtoken.json
start AVS test
		


>>>>>>>>>  AVS: AVS is ready......


 --> 2017-11-15 18:58:17:78
LOCAL_AUDIO_FILE_PATH=/usr/nut2_avs/iamready.mp3
2017-11-15 10:58:17.080 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=3,result=204
2017-11-15 10:58:17.080 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-15 10:58:17.081 [  a] 0 HTTP2StreamPool:releaseStream:streamId=3,numAcquiredStreams=1
2017-11-15 10:58:17.082 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:58:17.175 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
LocalMediaPlayer setSource success
 TEST_F setMediaPlayerSource
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 10:58:17.281 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2017-11-15 10:58:17.285 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 10:58:17.645 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:58:17.657 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11130, sample rate = 48000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 456
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 14, Topology Id 112fa
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 14 path = 0
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
2017-11-15 10:58:18.123 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:58:18.178 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:58:19.180 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:58:19.245 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=1
2017-11-15 10:58:19.664 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:58:19.665 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:58:19.668 [  2] E MediaPlayer:handleStopFailed
		Start execute handleOneSpeechBySensory() --> 2017-11-15 18:58:19:670
___________________________________AIP isExpectDirectStatus: 0
**********  start hal_rec_test recording *********
-----> For Vick: qahw_load_module...

 start first record thread 
		qahw_open_input_stream...... --> 2017-11-15 18:58:19:676
 input opened, buffer  0xaa407240, size 640, handle(2457)
 Please speak into the microphone for 15.000000 seconds, handle(2457)
		Start Recording!!!!!!!   Start Recording!!!!!!!   Start Recording!!!!!!! --> 2017-11-15 18:58:19:683
ACDB -> send_audio_cal, acdb_id = 4, path = 1, app id = 0x11132, sample rate = 16000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE Returned = -19
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB audproc returned = -19
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AudProc vol returned = -19
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
2017-11-15 10:58:19.696 [  b] I SensoryKeywordDetector:License expires on 01 Feb 2018 00:00:00 GMT
2017-11-15 10:58:19.699 [  b] I SensoryKeywordDetector:Sensory library license does not expire for at least 60 more days.
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 16
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 4, Topology Id 112fb
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AFE returned = -19
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 4 path = 1
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
2017-11-15 10:58:20.181 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:20.233 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
handleOneSpeechBySensory::waitForWakeword------
2017-11-15 10:59:21.234 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
 *** testKeyWordObserverDebug:: onKeyWordDetected
openFMDuringTest : isFMOpened = 0
stopMediaPlayer 11111
stopLocalMediaPlayer 222
2017-11-15 10:59:21.626 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:21.626 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:21.626 [  2] E MediaPlayer:handleStopFailed
stopSpeakMediaPlayer 33333
2017-11-15 10:59:21.626 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:21.626 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:21.627 [  2] E MediaPlayer:handleStopFailed
stopMediaPlayer m_rendererMediaPlayer
2017-11-15 10:59:21.627 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:21.627 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:21.627 [  2] E MediaPlayer:handleStopFailed
stopMediaPlayer 44444
Nut2AVS  King:: testKeyWordObserverDebug::onKeyWordDetected.....beginIndex = 979920, endIndex = 988080,
		Start to open < Listening > LED --> 2017-11-15 18:59:21:642
___________________________________AIP isExpectDirectStatus: 0
--> handleOneSpeechBySensory::readOffset = 370976
--> RingBufferConsumer m_read_offset = 370976
exitAVS = 0, m_wisStatusChanged->isStopCaptureFlag = 0, isRecordingFinish = 0
consumer is done
		Start to play med_ui_voice_start_listening.wav --> 2017-11-15 18:59:21:740
SKU detect: CX/SB
Current SKU is: CX
SKU is CX:  To play  preRecording  sound cue
Playing sample: 2 ch, 48000 hz, 16 bit
2017-11-15 10:59:22.629 [  c] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
		End play med_ui_voice_start_listening.wav --> 2017-11-15 18:59:22:741



##### Start recording!


Nut2AVS  King:: wakeWordTrigger::onKeyWordDetected.....beginIndex = 12000, endIndex = 21360,
Nut2AVS King:: wakeWordTrigger::Sensory recognize.....beginIndex = 12000, endIndex = 21360
*** AudioInputProcessor::executeRecognize initiatorPayloadJson="wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":17360}
2017-11-15 10:59:22.816 [  9] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2017-11-15 10:59:22.817 [  9] 0 ContextManager:updateStateLocked:action=updatedState,state={"wakeword" \: "alexa"},namespace=SpeechRecognizer,name=RecognizerState
m_expectingSpeechTimer.stop...
2017-11-15 10:59:22.817 [  d] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
8
		current mediaPlayer voluem value: 8 --> 2017-11-15 18:59:22:870
2017-11-15 10:59:22.871 [  6] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:80\,"muted"\:0},namespace=Speaker,name=VolumeState
2017-11-15 10:59:22.871 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:"alexa"}}\,{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:80\,"muted"\:0}}]}
2017-11-15 10:59:22.872 [  9] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context"\:[{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:"alexa"}}\,{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:80\,"muted"\:0}}]}
2017-11-15 10:59:22.873 [  9] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=4d26da04-abac-4195-b6e5-d30481f30981
2017-11-15 10:59:22.873 [  9] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId
2017-11-15 10:59:22.874 [  9] 0 EventBuilder:buildJsonEventString:messageId=e27a5c85-6ea2-4565-a9e1-3444ce13c4b0,namespace=SpeechRecognizer,name=Recognize
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-11-15 10:59:22.875 [  9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
AVSConnectionManager::sendMessage {"context":[{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"IDLE"}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}},{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":80,"muted":0}}],"event":{"header":{"namespace":"SpeechRecognizer","name":"Recognize","messageId":"e27a5c85-6ea2-4565-a9e1-3444ce13c4b0","dialogRequestId":"4d26da04-abac-4195-b6e5-d30481f30981"},"payload":{"profile":"NEAR_FIELD","format":"AUDIO_L16_RATE_16000_CHANNELS_1","initiator":{"type":"WAKEWORD","payload":{"wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":17360}}}}}}
2017-11-15 10:59:22.926 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:22.928 [  a] 0 HTTP2StreamPool:getStream:streamId=5,numAcquiredStreams=2
2017-11-15 10:59:25.583 [  e] 0 MessageInterpreter:receive:messageId=f8c6737e-f40e-4e79-91ad-5364d804c517:No dialogRequestId attached to message.
2017-11-15 10:59:25.585 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"StopCapture"\,"messageId"\:"f8c6737e-f40e-4e79-91ad-5364d804c517"}\,"payload"\:{}}}
...onDirectiveArrived...
onDirectiveArrived: To stop recording...
2017-11-15 10:59:25.587 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"StopCapture"\,"messageId"\:"f8c6737e-f40e-4e79-91ad-5364d804c517"}\,"payload"\:{}}}
2017-11-15 10:59:25.589 [  f] I DirectiveRouter:preHandleDirective:messageId=f8c6737e-f40e-4e79-91ad-5364d804c517,action=calling
2017-11-15 10:59:25.590 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=f8c6737e-f40e-4e79-91ad-5364d804c517
2017-11-15 10:59:25.593 [ 10] I DirectiveRouter:handleDirective:messageId=f8c6737e-f40e-4e79-91ad-5364d804c517,action=calling
AudioInputProcessor::handleDirective --------StopCapture
2017-11-15 10:59:25.594 [  9] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2017-11-15 10:59:25.594 [  9] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-11-15 10:59:25.595 [  d] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
2017-11-15 10:59:25.595 [  9] 0 DirectiveProcessor:onHandlingCompeted:messageId=f8c6737e-f40e-4e79-91ad-5364d804c517,directiveBeingPreHandled=(nullptr)
2017-11-15 10:59:25.596 [  9] 0 CapabilityAgent:removingMessageIdFromMap:messageId=f8c6737e-f40e-4e79-91ad-5364d804c517
2017-11-15 10:59:25.598 [  a] I InProcessAttachmentReader:readFailed:reason=SDS is closed
		End Recording!!!!!!! --> 2017-11-15 18:59:25:600
 closing input, handle(2457)
closing input
		---> Get Directive start! --> 2017-11-15 18:59:25:634


 The audio recording has been saved to /data/nut2_avs/hal_rec_test_rec_original.wav. Please use adb pull to get the file and play it using audacity. The audio data has the following characteristics:
 Sample rate: 16000
 Format: 1
 Num channels: 1, handle(2457)


 Done with hal record test 
producer is done
		Start to open < Thinking > LED --> 2017-11-15 18:59:25:661
		Start to play med_ui_voice_stop_listening.wav --> 2017-11-15 18:59:25:755
SKU detect: CX/SB
Current SKU is: CX
SKU is CX:  To play  postRecording  sound cue
Playing sample: 2 ch, 48000 hz, 16 bit
2017-11-15 10:59:26.556 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
		End play med_ui_voice_stop_listening.wav --> 2017-11-15 18:59:26:846



##### End recording!


2017-11-15 10:59:27.391 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-5
2017-11-15 10:59:27.559 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:27.692 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"ea7a92ac-5336-41c6-987a-000de1d8dd6d"\,"dialogRequestId"\:"4d26da04-abac-4195-b6e5-d30481f30981"}\,"payload"\:{"url"\:"cid\:PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0_1336116353"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"}}}
...onDirectiveArrived...
----------------- default directive
2017-11-15 10:59:27.698 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"ea7a92ac-5336-41c6-987a-000de1d8dd6d"\,"dialogRequestId"\:"4d26da04-abac-4195-b6e5-d30481f30981"}\,"payload"\:{"url"\:"cid\:PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0_1336116353"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"}}}
2017-11-15 10:59:27.698 [  f] I DirectiveRouter:preHandleDirective:messageId=ea7a92ac-5336-41c6-987a-000de1d8dd6d,action=calling
2017-11-15 10:59:27.699 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=ea7a92ac-5336-41c6-987a-000de1d8dd6d
2017-11-15 10:59:27.700 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"a9b95a03-ff13-4e3b-932e-532000dae63c"\,"dialogRequestId"\:"4d26da04-abac-4195-b6e5-d30481f30981"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"\,"stream"\:{"streamFormat"\:"AUDIO_MPEG"\,"offsetInMilliseconds"\:0\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"}}\,"playBehavior"\:"REPLACE_ALL"}}}
...onDirectiveArrived...
----------------- default directive2017-11-15 10:59:27.701 [ 10] I DirectiveRouter:handleDirective:messageId=ea7a92ac-5336-41c6-987a-000de1d8dd6d,action=calling

2017-11-15 10:59:27.701 [  8] 0 SpeechSynthesizer:executePreHandle:messageId=ea7a92ac-5336-41c6-987a-000de1d8dd6d
2017-11-15 10:59:27.706 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"a9b95a03-ff13-4e3b-932e-532000dae63c"\,"dialogRequestId"\:"4d26da04-abac-4195-b6e5-d30481f30981"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"\,"stream"\:{"streamFormat"\:"AUDIO_MPEG"\,"offsetInMilliseconds"\:0\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"}}\,"playBehavior"\:"REPLACE_ALL"}}}
2017-11-15 10:59:27.707 [  f] I DirectiveRouter:preHandleDirective:messageId=a9b95a03-ff13-4e3b-932e-532000dae63c,action=calling
2017-11-15 10:59:27.708 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=a9b95a03-ff13-4e3b-932e-532000dae63c
2017-11-15 10:59:27.734 [  8] 0 SpeechSynthesizer:executeHandle:messageId=ea7a92ac-5336-41c6-987a-000de1d8dd6d
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-11-15 10:59:27.736 [ 11] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-11-15 10:59:27.736 [  9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-11-15 10:59:27.737 [  9] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
executeResetState  m_expectingSpeechTimer.stop...
2017-11-15 10:59:27.737 [  9] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-11-15 10:59:27.737 [  8] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-11-15 10:59:27.739 [  d] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE
2017-11-15 10:59:27.739 [  2] 0 MediaPlayer:handleSetSourceCalled
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 10:59:27.743 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=2,currentId=2
2017-11-15 10:59:27.744 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 10:59:27.745 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
		---> Get Directive end! --> 2017-11-15 18:59:27:747
--> To handle the 0 directive: SpeechSynthesizer - Speak
		Wait for get response audio!!!!!!! --> 2017-11-15 18:59:27:747
2017-11-15 10:59:27.786 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:27.786 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:27.787 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=2
2017-11-15 10:59:27.794 [  8] 0 SpeechSynthesizer:executePlaybackStarted
2017-11-15 10:59:27.795 [  8] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-15 10:59:27.796 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=2,currentId=2
2017-11-15 10:59:27.797 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"\,"offsetInMilliseconds"\:9\,"playerActivity"\:"PLAYING"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-15 10:59:27.798 [  8] 0 EventBuilder:buildJsonEventString:messageId=c053ac23-4685-4e6b-87e8-4fb42e9e83ee,namespace=SpeechSynthesizer,name=SpeechStarted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"SpeechSynthesizer","name":"SpeechStarted","messageId":"c053ac23-4685-4e6b-87e8-4fb42e9e83ee"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"}}}
TestSpeechSynthesizerObserver::onStateChanged  currentSpeechSynthesizerState: 1, newState = 0
*** onSpeechSynthesizerObserverStateChanged:: Start to open < Speaking > LED
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11130, sample rate = 48000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 456
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 14, Topology Id 112fa
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 14 path = 0
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
2017-11-15 10:59:27.840 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:27.841 [  a] 0 HTTP2StreamPool:getStream:streamId=7,numAcquiredStreams=3
TestSpeechSynthesizerObserver::waitForNext------finished
		Playing AVS response audio via gstreamer..... --> 2017-11-15 18:59:27:884
		Start to open < Speaking > LED --> 2017-11-15 18:59:27:884


Waiting for Mediaplayer finish1.................... currentSpeechSynthesizerState: 0
Media Player has finished....................
^_^^^_^^^^_^^^^^^_^^^^^^_^^^^^^^^_^^^^ testCycleIndex: 1
executeResetState  m_expectingSpeechTimer.stop...
2017-11-15 10:59:28.076 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:28.534 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-7
2017-11-15 10:59:28.537 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=7,result=204
2017-11-15 10:59:28.540 [  a] 0 HTTP2StreamPool:releaseStream:streamId=7,numAcquiredStreams=2
2017-11-15 10:59:28.541 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:28.545 [  a] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2017-11-15 10:59:28.548 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=5,result=200
2017-11-15 10:59:28.549 [  a] 0 HTTP2StreamPool:releaseStream:streamId=5,numAcquiredStreams=1
2017-11-15 10:59:28.561 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:29.564 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:29.637 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=2
2017-11-15 10:59:29.639 [  8] 0 SpeechSynthesizer:executePlaybackFinished
2017-11-15 10:59:29.639 [  8] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-15 10:59:29.641 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-15 10:59:29.643 [  8] 0 EventBuilder:buildJsonEventString:messageId=f8be9930-524b-4e69-9741-7d9ec3781b75,namespace=SpeechSynthesizer,name=SpeechFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"SpeechSynthesizer","name":"SpeechFinished","messageId":"f8be9930-524b-4e69-9741-7d9ec3781b75"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"}}}
2017-11-15 10:59:29.645 [ 11] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-11-15 10:59:29.646 [  8] 0 DirectiveProcessor:onHandlingCompeted:messageId=ea7a92ac-5336-41c6-987a-000de1d8dd6d,directiveBeingPreHandled=(nullptr)
2017-11-15 10:59:29.647 [ 10] I DirectiveRouter:handleDirective:messageId=a9b95a03-ff13-4e3b-932e-532000dae63c,action=calling
2017-11-15 10:59:29.648 [  8] 0 CapabilityAgent:removingMessageIdFromMap:messageId=ea7a92ac-5336-41c6-987a-000de1d8dd6d
2017-11-15 10:59:29.649 [ 10] E AudioPlayer:handleDirective:name=Play,messageId=a9b95a03-ff13-4e3b-932e-532000dae63c
AudioPlayer::handleDirective getName = Play
2017-11-15 10:59:29.650 [ 10] E AudioPlayer:handlePlayDirective
TestSpeechSynthesizerObserver::onStateChanged  currentSpeechSynthesizerState: 0, newState = 1
*** onSpeechSynthesizerObserverStateChanged::  isRecordingFinish = 1
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onSpeechSynthesizerObserverStateChanged:: Start to open < Default > LED
2017-11-15 10:59:29.676 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:29.678 [  a] 0 HTTP2StreamPool:getStream:streamId=9,numAcquiredStreams=2
2017-11-15 10:59:29.679 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expiryTime
2017-11-15 10:59:29.679 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReport
2017-11-15 10:59:29.680 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-11-15 10:59:29.680 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=a9b95a03-ff13-4e3b-932e-532000dae63c,directiveBeingPreHandled=(nullptr)
2017-11-15 10:59:29.681 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=a9b95a03-ff13-4e3b-932e-532000dae63c
2017-11-15 10:59:29.684 [  7] E AudioPlayer:executePlay:playBehavior=REPLACE_ALL
2017-11-15 10:59:29.685 [  7] E AudioPlayer:executeStop:playNextItem=true,m_currentActivity=IDLE
2017-11-15 10:59:29.686 [ 11] E AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2017-11-15 10:59:29.688 [  7] E AudioPlayer:executeOnFocusChanged:from=NONE,to=FOREGROUND,m_currentActivity=IDLE
2017-11-15 10:59:29.689 [  7] E AudioPlayer:executeOnFocusChanged:action=playNextItem
2017-11-15 10:59:29.690 [  7] E AudioPlayer:playNextItem:m_audioItems.size=1
		Start execute handleOneSpeechBySensory() --> 2017-11-15 18:59:29:985
___________________________________AIP isExpectDirectStatus: 0
**********  start hal_rec_test recording *********
-----> For Vick: qahw_load_module...

 start first record thread 
		qahw_open_input_stream...... --> 2017-11-15 18:59:29:990
 input opened, buffer  0xa78668b0, size 640, handle(2457)
 Please speak into the microphone for 15.000000 seconds, handle(2457)
		Start Recording!!!!!!!   Start Recording!!!!!!!   Start Recording!!!!!!! --> 2017-11-15 18:59:29:994
ACDB -> send_audio_cal, acdb_id = 4, path = 1, app id = 0x11132, sample rate = 16000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
2017-11-15 10:59:30.003 [ 12] I SensoryKeywordDetector:License expires on 01 Feb 2018 00:00:00 GMT
Failed to fetch the lookup information of the device 00000004 
2017-11-15 10:59:30.005 [ 12] I SensoryKeywordDetector:Sensory library license does not expire for at least 60 more days.
Error: ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE Returned = -19
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB audproc returned = -19
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AudProc vol returned = -19
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
2017-11-15 10:59:30.009 [  2] 0 MediaPlayer:handleSetSourceCalled
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 16
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 4, Topology Id 112fb
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AFE returned = -19
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 4 path = 1
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
2017-11-15 10:59:30.014 [  7] E AudioPlayer:playNextItem:item.stream.offset=0
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 10:59:30.014 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:30.014 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:30.014 [  2] E MediaPlayer:handleStopFailed
2017-11-15 10:59:30.015 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=3,currentId=3
2017-11-15 10:59:30.017 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 10:59:30.020 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-15 10:59:30.042 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:30.042 [  2] E AudioPlayer:onTags:id=3
2017-11-15 10:59:30.043 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:30.043 [  7] E AudioPlayer:executeOnTags:id=3
2017-11-15 10:59:30.043 [  2] E AudioPlayer:onTags:id=3
2017-11-15 10:59:30.051 [  7] 0 EventBuilder:buildJsonEventString:messageId=d48b5025-686d-46e6-a60a-b50dea30343a,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"d48b5025-686d-46e6-a60a-b50dea30343a"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag"}}}}
2017-11-15 10:59:30.051 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=3
2017-11-15 10:59:30.052 [  2] E AudioPlayer:onPlaybackStarted:id=3
2017-11-15 10:59:30.052 [  7] E AudioPlayer:executeOnTags:id=3
2017-11-15 10:59:30.053 [  7] 0 EventBuilder:buildJsonEventString:messageId=98abd8e1-b761-415a-a3a4-f3b32c41f21d,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"98abd8e1-b761-415a-a3a4-f3b32c41f21d"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000"}}}}
2017-11-15 10:59:30.054 [  7] E AudioPlayer:executeOnPlaybackStarted:id=3
--> King:: AudioPlayer changeActivity  from  IDLE to PLAYING...
2017-11-15 10:59:30.054 [  7] E AudioPlayer:changeActivity:from=IDLE,to=PLAYING
	King:: onAudioPlayerPlayStatusChanged to 1
*** onAudioPlayerPlayStatusChanged:: Start to open < Speaking > LED
2017-11-15 10:59:30.080 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-9
2017-11-15 10:59:30.080 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=9,result=204
2017-11-15 10:59:30.080 [  a] 0 HTTP2StreamPool:releaseStream:streamId=9,numAcquiredStreams=1
2017-11-15 10:59:30.080 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:30.081 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:30.081 [  a] 0 HTTP2StreamPool:getStream:streamId=11,numAcquiredStreams=2
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11130, sample rate = 48000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 456
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 14, Topology Id 112fa
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 14 path = 0
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
socketfd = 58
send content is: play_music:status=1

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:30.152 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
2017-11-15 10:59:30.153 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","offsetInMilliseconds":24,"playerActivity":"PLAYING"}
2017-11-15 10:59:30.154 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"PLAYING"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:30.154 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
2017-11-15 10:59:30.155 [  7] E AudioPlayer:notifyObserver:playerActivity=PLAYING
2017-11-15 10:59:30.155 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackStarted
2017-11-15 10:59:30.155 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
2017-11-15 10:59:30.156 [  7] 0 EventBuilder:buildJsonEventString:messageId=32494c81-52c3-4c20-a9f3-5b01466b2eda,namespace=AudioPlayer,name=PlaybackStarted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackStarted","messageId":"32494c81-52c3-4c20-a9f3-5b01466b2eda"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:30.156 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackNearlyFinished
2017-11-15 10:59:30.157 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=3,currentId=3
2017-11-15 10:59:30.158 [  7] 0 EventBuilder:buildJsonEventString:messageId=d6e9f27e-e84d-4539-9b4c-1dd4c7b69922,namespace=AudioPlayer,name=PlaybackNearlyFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackNearlyFinished","messageId":"d6e9f27e-e84d-4539-9b4c-1dd4c7b69922"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:30.325 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:30.325 [  2] E AudioPlayer:onTags:id=3
2017-11-15 10:59:30.325 [  7] E AudioPlayer:executeOnTags:id=3
2017-11-15 10:59:30.326 [  7] 0 EventBuilder:buildJsonEventString:messageId=c123eb38-fa33-4289-8170-f2659e8f3072,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"c123eb38-fa33-4289-8170-f2659e8f3072"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000","minimum-bitrate":"48000","maximum-bitrate":"48000","bitrate":"48000"}}}}
2017-11-15 10:59:30.565 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:30.573 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-11
2017-11-15 10:59:30.573 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=11,result=204
2017-11-15 10:59:30.573 [  a] 0 HTTP2StreamPool:releaseStream:streamId=11,numAcquiredStreams=1
2017-11-15 10:59:30.573 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:30.574 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:30.574 [  a] 0 HTTP2StreamPool:getStream:streamId=13,numAcquiredStreams=2
2017-11-15 10:59:31.085 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-13
2017-11-15 10:59:31.086 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=13,result=204
2017-11-15 10:59:31.086 [  a] 0 HTTP2StreamPool:releaseStream:streamId=13,numAcquiredStreams=1
2017-11-15 10:59:31.087 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:31.088 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:31.089 [  a] 0 HTTP2StreamPool:getStream:streamId=15,numAcquiredStreams=2
2017-11-15 10:59:31.565 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:31.583 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-15
2017-11-15 10:59:31.583 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=15,result=204
2017-11-15 10:59:31.583 [  a] 0 HTTP2StreamPool:releaseStream:streamId=15,numAcquiredStreams=1
2017-11-15 10:59:31.583 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:31.584 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:31.584 [  a] 0 HTTP2StreamPool:getStream:streamId=17,numAcquiredStreams=2
2017-11-15 10:59:32.192 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-17
2017-11-15 10:59:32.193 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:32.194 [  a] 0 HTTP2StreamPool:getStream:streamId=19,numAcquiredStreams=3
2017-11-15 10:59:32.491 [  e] 0 MessageInterpreter:receive:messageId=a3d5634d-140f-4cc1-a2c9-16abfff3d70a:No dialogRequestId attached to message.
2017-11-15 10:59:32.492 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"a3d5634d-140f-4cc1-a2c9-16abfff3d70a"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"}}\,"playBehavior"\:"ENQUEUE"}}}
...onDirectiveArrived...
----------------- default directive
2017-11-15 10:59:32.493 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"a3d5634d-140f-4cc1-a2c9-16abfff3d70a"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"}}\,"playBehavior"\:"ENQUEUE"}}}
2017-11-15 10:59:32.493 [  f] I DirectiveRouter:preHandleDirective:messageId=a3d5634d-140f-4cc1-a2c9-16abfff3d70a,action=calling
2017-11-15 10:59:32.493 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=a3d5634d-140f-4cc1-a2c9-16abfff3d70a
2017-11-15 10:59:32.494 [ 10] I DirectiveRouter:handleDirective:messageId=a3d5634d-140f-4cc1-a2c9-16abfff3d70a,action=calling
2017-11-15 10:59:32.494 [ 10] E AudioPlayer:handleDirective:name=Play,messageId=a3d5634d-140f-4cc1-a2c9-16abfff3d70a
AudioPlayer::handleDirective getName = Play
2017-11-15 10:59:32.494 [ 10] E AudioPlayer:handlePlayDirective
2017-11-15 10:59:32.498 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expiryTime
2017-11-15 10:59:32.498 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReport
2017-11-15 10:59:32.498 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-11-15 10:59:32.498 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=a3d5634d-140f-4cc1-a2c9-16abfff3d70a,directiveBeingPreHandled=(nullptr)
2017-11-15 10:59:32.498 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=a3d5634d-140f-4cc1-a2c9-16abfff3d70a
2017-11-15 10:59:32.499 [  7] E AudioPlayer:executePlay:playBehavior=ENQUEUE
2017-11-15 10:59:32.499 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=17,result=200
2017-11-15 10:59:32.500 [  a] 0 HTTP2StreamPool:releaseStream:streamId=17,numAcquiredStreams=2
2017-11-15 10:59:32.566 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:32.654 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-19
2017-11-15 10:59:32.655 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=19,result=204
2017-11-15 10:59:32.655 [  a] 0 HTTP2StreamPool:releaseStream:streamId=19,numAcquiredStreams=1
2017-11-15 10:59:32.655 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:33.566 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:34.567 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:35.568 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:36.568 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:37.569 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:38.570 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:39.572 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:40.160 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=3
2017-11-15 10:59:40.160 [  2] E AudioPlayer:onPlaybackFinished:id=3
2017-11-15 10:59:40.161 [  7] E AudioPlayer:executeOnPlaybackFinished
--> King:: AudioPlayer changeActivity  from  PLAYING to FINISHED...
2017-11-15 10:59:40.161 [  7] E AudioPlayer:changeActivity:from=PLAYING,to=FINISHED
	King:: onAudioPlayerPlayStatusChanged to 5
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onAudioPlayerPlayStatusChanged:: Start to open < Default > LED
socketfd = 54
send content is: play_music:status=0

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:40.254 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","offsetInMilliseconds":24,"playerActivity":"FINISHED"}
2017-11-15 10:59:40.254 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"FINISHED"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:40.254 [  7] E AudioPlayer:notifyObserver:playerActivity=FINISHED
2017-11-15 10:59:40.254 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackFinished
2017-11-15 10:59:40.254 [  7] 0 EventBuilder:buildJsonEventString:messageId=92a9caf3-2855-4bb3-8e14-943a030b652b,namespace=AudioPlayer,name=PlaybackFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackFinished","messageId":"92a9caf3-2855-4bb3-8e14-943a030b652b"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.0-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:40.255 [  7] E AudioPlayer:playNextItem:m_audioItems.size=1
2017-11-15 10:59:40.335 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:40.335 [  a] 0 HTTP2StreamPool:getStream:streamId=21,numAcquiredStreams=2
2017-11-15 10:59:40.430 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-15 10:59:40.433 [  7] E AudioPlayer:playNextItem:item.stream.offset=0
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 10:59:40.433 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=4,currentId=4
2017-11-15 10:59:40.434 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 10:59:40.436 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-15 10:59:40.462 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:40.462 [  2] E AudioPlayer:onTags:id=4
2017-11-15 10:59:40.463 [  7] E AudioPlayer:executeOnTags:id=4
2017-11-15 10:59:40.463 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:40.463 [  2] E AudioPlayer:onTags:id=4
2017-11-15 10:59:40.463 [  7] 0 EventBuilder:buildJsonEventString:messageId=d583748b-3afe-4fe9-9acf-55d0cae1fc63,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"d583748b-3afe-4fe9-9acf-55d0cae1fc63"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag"}}}}
2017-11-15 10:59:40.464 [  7] E AudioPlayer:executeOnTags:id=4
2017-11-15 10:59:40.470 [  7] 0 EventBuilder:buildJsonEventString:messageId=ffa2ea6e-d73e-4f32-8fa4-0ea3efc2e3aa,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"ffa2ea6e-d73e-4f32-8fa4-0ea3efc2e3aa"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000"}}}}
2017-11-15 10:59:40.471 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=4
2017-11-15 10:59:40.471 [  2] E AudioPlayer:onPlaybackStarted:id=4
2017-11-15 10:59:40.471 [  7] E AudioPlayer:executeOnPlaybackStarted:id=4
--> King:: AudioPlayer changeActivity  from  FINISHED to PLAYING...
2017-11-15 10:59:40.472 [  7] E AudioPlayer:changeActivity:from=FINISHED,to=PLAYING
	King:: onAudioPlayerPlayStatusChanged to 1
*** onAudioPlayerPlayStatusChanged:: Start to open < Speaking > LED
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11130, sample rate = 48000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 456
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 14, Topology Id 112fa
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 14 path = 0
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
socketfd = 60
send content is: play_music:status=1

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:40.554 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
2017-11-15 10:59:40.555 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":24,"playerActivity":"PLAYING"}
2017-11-15 10:59:40.556 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"PLAYING"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:40.557 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
2017-11-15 10:59:40.557 [  7] E AudioPlayer:notifyObserver:playerActivity=PLAYING
2017-11-15 10:59:40.558 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackStarted
2017-11-15 10:59:40.558 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
2017-11-15 10:59:40.559 [  7] 0 EventBuilder:buildJsonEventString:messageId=e1ee171e-fc6b-4fde-bd10-c7e838ae5c1b,namespace=AudioPlayer,name=PlaybackStarted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackStarted","messageId":"e1ee171e-fc6b-4fde-bd10-c7e838ae5c1b"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:40.560 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackNearlyFinished
2017-11-15 10:59:40.561 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
2017-11-15 10:59:40.561 [  7] 0 EventBuilder:buildJsonEventString:messageId=e699aff8-6e02-4a8f-9eca-3a9043b1a3ca,namespace=AudioPlayer,name=PlaybackNearlyFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackNearlyFinished","messageId":"e699aff8-6e02-4a8f-9eca-3a9043b1a3ca"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:40.573 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:40.745 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:40.746 [  2] E AudioPlayer:onTags:id=4
2017-11-15 10:59:40.749 [  7] E AudioPlayer:executeOnTags:id=4
2017-11-15 10:59:40.752 [  7] 0 EventBuilder:buildJsonEventString:messageId=add0a5ca-795c-4cb5-a15b-770308fd8017,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"add0a5ca-795c-4cb5-a15b-770308fd8017"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000","minimum-bitrate":"48000","maximum-bitrate":"48000","bitrate":"48000"}}}}
2017-11-15 10:59:40.769 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-21
2017-11-15 10:59:40.769 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=21,result=204
2017-11-15 10:59:40.769 [  a] 0 HTTP2StreamPool:releaseStream:streamId=21,numAcquiredStreams=1
2017-11-15 10:59:40.770 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:40.770 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:40.770 [  a] 0 HTTP2StreamPool:getStream:streamId=23,numAcquiredStreams=2
2017-11-15 10:59:41.214 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-23
2017-11-15 10:59:41.215 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=23,result=204
2017-11-15 10:59:41.215 [  a] 0 HTTP2StreamPool:releaseStream:streamId=23,numAcquiredStreams=1
2017-11-15 10:59:41.215 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:41.215 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:41.216 [  a] 0 HTTP2StreamPool:getStream:streamId=25,numAcquiredStreams=2
2017-11-15 10:59:41.573 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:41.644 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-25
2017-11-15 10:59:41.645 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=25,result=204
2017-11-15 10:59:41.645 [  a] 0 HTTP2StreamPool:releaseStream:streamId=25,numAcquiredStreams=1
2017-11-15 10:59:41.645 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:41.645 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:41.645 [  a] 0 HTTP2StreamPool:getStream:streamId=27,numAcquiredStreams=2
2017-11-15 10:59:42.163 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-27
2017-11-15 10:59:42.164 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=27,result=204
2017-11-15 10:59:42.165 [  a] 0 HTTP2StreamPool:releaseStream:streamId=27,numAcquiredStreams=1
2017-11-15 10:59:42.166 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:42.167 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:42.167 [  a] 0 HTTP2StreamPool:getStream:streamId=29,numAcquiredStreams=2
2017-11-15 10:59:42.575 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:42.815 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-29
2017-11-15 10:59:42.816 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:42.816 [  a] 0 HTTP2StreamPool:getStream:streamId=31,numAcquiredStreams=3
2017-11-15 10:59:43.119 [  e] 0 MessageInterpreter:receive:messageId=50e687c1-e985-4e0a-a068-4fe4d0b8b5da:No dialogRequestId attached to message.
2017-11-15 10:59:43.119 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"50e687c1-e985-4e0a-a068-4fe4d0b8b5da"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"}}\,"playBehavior"\:"ENQUEUE"}}}
...onDirectiveArrived...
----------------- default directive
2017-11-15 10:59:43.120 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"50e687c1-e985-4e0a-a068-4fe4d0b8b5da"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"}}\,"playBehavior"\:"ENQUEUE"}}}
2017-11-15 10:59:43.120 [  f] I DirectiveRouter:preHandleDirective:messageId=50e687c1-e985-4e0a-a068-4fe4d0b8b5da,action=calling
2017-11-15 10:59:43.120 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=50e687c1-e985-4e0a-a068-4fe4d0b8b5da
2017-11-15 10:59:43.121 [ 10] I DirectiveRouter:handleDirective:messageId=50e687c1-e985-4e0a-a068-4fe4d0b8b5da,action=calling
2017-11-15 10:59:43.121 [ 10] E AudioPlayer:handleDirective:name=Play,messageId=50e687c1-e985-4e0a-a068-4fe4d0b8b5da
AudioPlayer::handleDirective getName = Play
2017-11-15 10:59:43.121 [ 10] E AudioPlayer:handlePlayDirective
2017-11-15 10:59:43.123 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expiryTime
2017-11-15 10:59:43.124 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReport
2017-11-15 10:59:43.124 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-11-15 10:59:43.124 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=50e687c1-e985-4e0a-a068-4fe4d0b8b5da,directiveBeingPreHandled=(nullptr)
2017-11-15 10:59:43.124 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=50e687c1-e985-4e0a-a068-4fe4d0b8b5da
2017-11-15 10:59:43.124 [  7] E AudioPlayer:executePlay:playBehavior=ENQUEUE
2017-11-15 10:59:43.576 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:43.741 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-31
2017-11-15 10:59:43.742 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=31,result=204
2017-11-15 10:59:43.743 [  a] 0 HTTP2StreamPool:releaseStream:streamId=31,numAcquiredStreams=2
2017-11-15 10:59:43.743 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:43.744 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=29,result=200
2017-11-15 10:59:43.745 [  a] 0 HTTP2StreamPool:releaseStream:streamId=29,numAcquiredStreams=1
 *** testKeyWordObserverDebug:: onKeyWordDetected
openFMDuringTest : isFMOpened = 0
stopMediaPlayer 11111
stopLocalMediaPlayer 222
2017-11-15 10:59:43.975 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:43.975 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:43.975 [  2] E MediaPlayer:handleStopFailed
stopSpeakMediaPlayer 33333
2017-11-15 10:59:43.975 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:43.975 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:43.975 [  2] E MediaPlayer:handleStopFailed
stopMediaPlayer m_rendererMediaPlayer
2017-11-15 10:59:43.976 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:43.976 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:43.976 [  2] E MediaPlayer:handleStopFailed
stopMediaPlayer 44444
Nut2AVS  King:: testKeyWordObserverDebug::onKeyWordDetected.....beginIndex = 211920, endIndex = 219840,
___________________________________AIP isExpectDirectStatus: 0
--> handleOneSpeechBySensory::readOffset = 407840
--> RingBufferConsumer m_read_offset = 407840
exitAVS = 0, m_wisStatusChanged->isStopCaptureFlag = 0, isRecordingFinish = 0
		Start to open < Listening > LED --> 2017-11-15 18:59:43:997
		Start to play med_ui_voice_start_listening.wav --> 2017-11-15 18:59:44:64
SKU detect: CX/SB
Current SKU is: CX
consumer is done
SKU is CX:  To play  preRecording  sound cue
Nut2AVS  King:: wakeWordTrigger::onKeyWordDetected.....beginIndex = 75120, endIndex = 84000,
Nut2AVS King:: wakeWordTrigger::Sensory recognize.....beginIndex = 75120, endIndex = 84000
*** AudioInputProcessor::executeRecognize initiatorPayloadJson="wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":16880}
2017-11-15 10:59:44.171 [  9] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
m_expectingSpeechTimer.stop...
2017-11-15 10:59:44.171 [  6] E AudioPlayer:provideState:stateRequestToken=3
2017-11-15 10:59:44.171 [  d] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:44.179 [  7] E AudioPlayer:executeProvideState:sendToken=true,stateRequestToken=3
2017-11-15 10:59:44.181 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3672,"playerActivity":"PLAYING"}
2017-11-15 10:59:44.182 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"offsetInMilliseconds"\:3672\,"playerActivity"\:"PLAYING"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
Playing sample: 2 ch, 48000 hz, 16 bit
8
		current mediaPlayer voluem value: 8 --> 2017-11-15 18:59:44:231
2017-11-15 10:59:44.231 [  6] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:80\,"muted"\:0},namespace=Speaker,name=VolumeState
2017-11-15 10:59:44.232 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"offsetInMilliseconds"\:3672\,"playerActivity"\:"PLAYING"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:"alexa"}}\,{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:80\,"muted"\:0}}]}
2017-11-15 10:59:44.232 [  9] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context"\:[{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"offsetInMilliseconds"\:3672\,"playerActivity"\:"PLAYING"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:"alexa"}}\,{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:80\,"muted"\:0}}]}
2017-11-15 10:59:44.233 [  9] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=4d26da04-abac-4195-b6e5-d30481f30981,newValue=38f71918-6dcd-47a7-acc5-2d815561b9f8
2017-11-15 10:59:44.233 [  9] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=4d26da04-abac-4195-b6e5-d30481f30981
2017-11-15 10:59:44.233 [ 11] E AudioPlayer:onFocusChanged:newFocus=BACKGROUND
2017-11-15 10:59:44.234 [  7] E AudioPlayer:executeOnFocusChanged:from=FOREGROUND,to=BACKGROUND,m_currentActivity=PLAYING
2017-11-15 10:59:44.234 [  7] E AudioPlayer:executeOnFocusChanged:action=pauseMediaPlayer
2017-11-15 10:59:44.234 [  2] 0 MediaPlayer:handlePauseCalled:idPassed=4,currentId=4
2017-11-15 10:59:44.234 [  9] 0 EventBuilder:buildJsonEventString:messageId=bcd4f075-a80a-466a-b559-808f9f8f0223,namespace=SpeechRecognizer,name=Recognize
2017-11-15 10:59:44.265 [  2] 0 MediaPlayer:callingOnPlaybackPaused:currentId=4
2017-11-15 10:59:44.266 [  2] E AudioPlayer:onPlaybackPaused:id=4
2017-11-15 10:59:44.269 [  7] E AudioPlayer:executeOnPlaybackPaused:id=4
2017-11-15 10:59:44.270 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackPaused
2017-11-15 10:59:44.271 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
2017-11-15 10:59:44.274 [  7] 0 EventBuilder:buildJsonEventString:messageId=22d46914-d8b3-470d-88b8-ee0c66644710,namespace=AudioPlayer,name=PlaybackPaused
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackPaused","messageId":"22d46914-d8b3-470d-88b8-ee0c66644710"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3768}}}
--> King:: AudioPlayer changeActivity  from  PLAYING to PAUSED...
2017-11-15 10:59:44.277 [  7] E AudioPlayer:changeActivity:from=PLAYING,to=PAUSED
	King:: onAudioPlayerPlayStatusChanged to 3
socketfd = 61
send content is: play_music:status=0

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:44.281 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-11-15 10:59:44.281 [  9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
AVSConnectionManager::sendMessage {"context":[{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3672,"playerActivity":"PLAYING"}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#PlatformTTSRenderer_1d0f9c94-17ce-4aef-938f-c0f32b4872c0","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}},{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":80,"muted":0}}],"event":{"header":{"namespace":"SpeechRecognizer","name":"Recognize","messageId":"bcd4f075-a80a-466a-b559-808f9f8f0223","dialogRequestId":"38f71918-6dcd-47a7-acc5-2d815561b9f8"},"payload":{"profile":"NEAR_FIELD","format":"AUDIO_L16_RATE_16000_CHANNELS_1","initiator":{"type":"WAKEWORD","payload":{"wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":16880}}}}}}
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3768,"playerActivity":"PAUSED"}
2017-11-15 10:59:44.282 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"offsetInMilliseconds"\:3768\,"playerActivity"\:"PAUSED"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:44.282 [  7] E AudioPlayer:notifyObserver:playerActivity=PAUSED
2017-11-15 10:59:44.351 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:44.352 [  a] 0 HTTP2StreamPool:getStream:streamId=33,numAcquiredStreams=2
2017-11-15 10:59:44.811 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-33
2017-11-15 10:59:44.812 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=33,result=204
2017-11-15 10:59:44.813 [  a] 0 HTTP2StreamPool:releaseStream:streamId=33,numAcquiredStreams=1
2017-11-15 10:59:44.813 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:44.814 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:44.815 [  a] 0 HTTP2StreamPool:getStream:streamId=35,numAcquiredStreams=2
		End play med_ui_voice_start_listening.wav --> 2017-11-15 18:59:44:979



##### Start recording!


2017-11-15 10:59:44.990 [ 13] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:47.292 [  e] 0 MessageInterpreter:receive:messageId=fca49391-1710-4043-8724-2123bd90a9a0:No dialogRequestId attached to message.
2017-11-15 10:59:47.293 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"StopCapture"\,"messageId"\:"fca49391-1710-4043-8724-2123bd90a9a0"}\,"payload"\:{}}}
...onDirectiveArrived...
onDirectiveArrived: To stop recording...
2017-11-15 10:59:47.293 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"StopCapture"\,"messageId"\:"fca49391-1710-4043-8724-2123bd90a9a0"}\,"payload"\:{}}}
2017-11-15 10:59:47.293 [  f] I DirectiveRouter:preHandleDirective:messageId=fca49391-1710-4043-8724-2123bd90a9a0,action=calling
2017-11-15 10:59:47.293 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=fca49391-1710-4043-8724-2123bd90a9a0
2017-11-15 10:59:47.293 [ 10] I DirectiveRouter:handleDirective:messageId=fca49391-1710-4043-8724-2123bd90a9a0,action=calling
AudioInputProcessor::handleDirective --------StopCapture
2017-11-15 10:59:47.294 [  9] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2017-11-15 10:59:47.294 [  9] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-11-15 10:59:47.294 [  9] 0 DirectiveProcessor:onHandlingCompeted:messageId=fca49391-1710-4043-8724-2123bd90a9a0,directiveBeingPreHandled=(nullptr)
2017-11-15 10:59:47.294 [  9] 0 CapabilityAgent:removingMessageIdFromMap:messageId=fca49391-1710-4043-8724-2123bd90a9a0
2017-11-15 10:59:47.294 [  d] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
		End Recording!!!!!!! --> 2017-11-15 18:59:47:297
 closing input, handle(2457)
closing input
2017-11-15 10:59:47.303 [  a] I InProcessAttachmentReader:readFailed:reason=SDS is closed
		---> Get Directive start! --> 2017-11-15 18:59:47:324


 The audio recording has been saved to /data/nut2_avs/hal_rec_test_rec_original.wav. Please use adb pull to get the file and play it using audacity. The audio data has the following characteristics:
 Sample rate: 16000
 Format: 1
 Num channels: 1, handle(2457)


 Done with hal record test 
producer is done
		Start to open < Thinking > LED --> 2017-11-15 18:59:47:351
		Start to play med_ui_voice_stop_listening.wav --> 2017-11-15 18:59:47:459
SKU detect: CX/SB
Current SKU is: CX
SKU is CX:  To play  postRecording  sound cue
Playing sample: 2 ch, 48000 hz, 16 bit
2017-11-15 10:59:47.810 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-35
2017-11-15 10:59:47.824 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"fcd8da98-558e-4040-9789-aee9ab846061"\,"dialogRequestId"\:"38f71918-6dcd-47a7-acc5-2d815561b9f8"}\,"payload"\:{"url"\:"cid\:DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa_1658447908"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa"}}}
...onDirectiveArrived...
----------------- default directive
2017-11-15 10:59:47.827 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"fcd8da98-558e-4040-9789-aee9ab846061"\,"dialogRequestId"\:"38f71918-6dcd-47a7-acc5-2d815561b9f8"}\,"payload"\:{"url"\:"cid\:DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa_1658447908"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa"}}}
2017-11-15 10:59:47.828 [  f] I DirectiveRouter:preHandleDirective:messageId=fcd8da98-558e-4040-9789-aee9ab846061,action=calling
2017-11-15 10:59:47.828 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=fcd8da98-558e-4040-9789-aee9ab846061
2017-11-15 10:59:47.829 [ 10] I DirectiveRouter:handleDirective:messageId=fcd8da98-558e-4040-9789-aee9ab846061,action=calling
2017-11-15 10:59:47.829 [  8] 0 SpeechSynthesizer:executePreHandle:messageId=fcd8da98-558e-4040-9789-aee9ab846061
2017-11-15 10:59:47.840 [  a] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2017-11-15 10:59:47.841 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=35,result=200
2017-11-15 10:59:47.840 [  8] 0 SpeechSynthesizer:executeHandle:messageId=fcd8da98-558e-4040-9789-aee9ab846061
2017-11-15 10:59:47.842 [  a] 0 HTTP2StreamPool:releaseStream:streamId=35,numAcquiredStreams=1
2017-11-15 10:59:47.843 [ 11] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-11-15 10:59:47.843 [  9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-11-15 10:59:47.844 [  9] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
executeResetState  m_expectingSpeechTimer.stop...
2017-11-15 10:59:47.844 [  9] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
2017-11-15 10:59:47.844 [  8] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-11-15 10:59:47.845 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-15 10:59:47.846 [  d] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 10:59:47.854 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=5,currentId=5
2017-11-15 10:59:47.858 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 10:59:47.860 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
		---> Get Directive end! --> 2017-11-15 18:59:47:877
--> To handle the 0 directive: SpeechSynthesizer - Speak
		Wait for get response audio!!!!!!! --> 2017-11-15 18:59:47:877
2017-11-15 10:59:47.914 [  2] E MediaPlayer:handleBusMessageError:source=audio_sink,error=Could not get/set settings from/on resource.,debug=/home/peter/workspace/src/db2.1-le/apss/poky/build/tmp-glibc/work/armv7a-vfp-neon-oe-linux-gnueabi/gst-plugins/git-r0/vendor/qcom/proprietary/gst-plugins/sys/qahw/gstqahwsink.c(1585)\: gst_qahw_ring_buffer_acquire ()\: /GstPipeline\:audio-pipeline/GstQahwSink\:audio_sink\:
Failed to open output stream\: -17
2017-11-15 10:59:47.915 [  2] 0 MediaPlayer:callingOnPlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=Could not get/set settings from/on resource.,currentId=5
2017-11-15 10:59:47.916 [  8] 0 SpeechSynthesizer:executePlaybackError:type=MEDIA_ERROR_INTERNAL_DEVICE_ERROR,error=Could not get/set settings from/on resource.
2017-11-15 10:59:47.916 [  8] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-11-15 10:59:47.917 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-11-15 10:59:47.920 [  8] 0 EventBuilder:buildJsonEventString:messageId=9a9d670c-3912-47b5-8a73-5ca68939c30d,namespace=System,name=ExceptionEncountered
AVSConnectionManager::sendMessage {"context":[],"event":{"header":{"namespace":"System","name":"ExceptionEncountered","messageId":"9a9d670c-3912-47b5-8a73-5ca68939c30d"},"payload":{"unparsedDirective":"{\"directive\":{\"header\":{\"namespace\":\"SpeechSynthesizer\",\"name\":\"Speak\",\"messageId\":\"fcd8da98-558e-4040-9789-aee9ab846061\",\"dialogRequestId\":\"38f71918-6dcd-47a7-acc5-2d815561b9f8\"},\"payload\":{\"url\":\"cid:DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa_1658447908\",\"format\":\"AUDIO_MPEG\",\"token\":\"amzn1.as-ct.v1.Domain:Application:NotificationsV4#ACRI#DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa\"}}}","error":{"type":"INTERNAL_ERROR","message":"Could not get/set settings from/on resource."}}}}
2017-11-15 10:59:47.922 [  8] 0 DirectiveProcessor:onHandlingFailed:messageId=fcd8da98-558e-4040-9789-aee9ab846061,directiveBeingPreHandled=(nullptr),description=Could not get/set settings from/on resource.
2017-11-15 10:59:47.922 [  8] 0 DirectiveProcessor:scrubDialogRequestIdLocked:dialogRequestId=38f71918-6dcd-47a7-acc5-2d815561b9f8
2017-11-15 10:59:47.922 [  8] 0 CapabilityAgent:removingMessageIdFromMap:messageId=fcd8da98-558e-4040-9789-aee9ab846061
2017-11-15 10:59:47.923 [  8] 0 CapabilityAgent:removingMessageIdFromMap:messageId=fcd8da98-558e-4040-9789-aee9ab846061
TestSpeechSynthesizerObserver::onStateChanged  currentSpeechSynthesizerState: 1, newState = 1
*** onSpeechSynthesizerObserverStateChanged::  isRecordingFinish = 1
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onSpeechSynthesizerObserverStateChanged:: Start to open < Default > LED
2017-11-15 10:59:47.945 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:47.945 [  a] 0 HTTP2StreamPool:getStream:streamId=37,numAcquiredStreams=2
2017-11-15 10:59:48.071 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:48.071 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:48.071 [  2] E MediaPlayer:handleStopFailed
TestSpeechSynthesizerObserver::waitForNext------finished
mkdir: cannot create directory '/data/nut2_avs/recording': File exists
get recording file count: 5

To execute copy command: cp /data/nut2_avs/hal_rec_test_rec_send.wav /data/nut2_avs/recording/recording_20171115105948.wav
*** onSpeechSynthesizerObserverStateChanged::  isRecordingFinish = 1
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onSpeechSynthesizerObserverStateChanged:: Start to open < Default > LED
2017-11-15 10:59:48.252 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:48.268 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-37
2017-11-15 10:59:48.269 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=37,result=204
2017-11-15 10:59:48.269 [  a] 0 HTTP2StreamPool:releaseStream:streamId=37,numAcquiredStreams=1
2017-11-15 10:59:48.269 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:48.312 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 10:59:48.312 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 10:59:48.312 [  2] E MediaPlayer:handleStopFailed
^_^^^_^^^^_^^^^^^_^^^^^^_^^^^^^^^_^^^^ testCycleIndex: 1
executeResetState  m_expectingSpeechTimer.stop...
		End play med_ui_voice_stop_listening.wav --> 2017-11-15 18:59:48:441



##### End recording!


2017-11-15 10:59:49.255 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:49.846 [ 11] E SpeechSynthesizer:onFocusChangeFailed:reason=stateChangeTimeout,messageId=fcd8da98-558e-4040-9789-aee9ab846061
2017-11-15 10:59:49.848 [ 11] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-11-15 10:59:49.849 [ 11] E AudioPlayer:onFocusChanged:newFocus=FOREGROUND
2017-11-15 10:59:49.850 [  7] E AudioPlayer:executeOnFocusChanged:from=BACKGROUND,to=FOREGROUND,m_currentActivity=PAUSED
2017-11-15 10:59:49.850 [  7] E AudioPlayer:executeOnFocusChanged:action=resumeMediaPlayer
2017-11-15 10:59:49.852 [  2] 0 MediaPlayer:handleResumeCalled:idPassed=4,currentId=4
2017-11-15 10:59:49.864 [  2] 0 MediaPlayer:callingOnPlaybackResumed:currentId=4
2017-11-15 10:59:49.865 [  2] E AudioPlayer:onPlaybackResumed:id=4
2017-11-15 10:59:49.866 [  7] E AudioPlayer:executeOnPlaybackResumed:id=4
2017-11-15 10:59:49.866 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackResumed
2017-11-15 10:59:49.868 [  7] 0 EventBuilder:buildJsonEventString:messageId=72c37f97-8943-42d1-9fbc-809ebaa711ab,namespace=AudioPlayer,name=PlaybackResumed
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackResumed","messageId":"72c37f97-8943-42d1-9fbc-809ebaa711ab"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3768}}}
--> King:: AudioPlayer changeActivity  from  PAUSED to PLAYING...
2017-11-15 10:59:49.871 [  7] E AudioPlayer:changeActivity:from=PAUSED,to=PLAYING
	King:: onAudioPlayerPlayStatusChanged to 1
*** onAudioPlayerPlayStatusChanged:: Start to open < Speaking > LED
2017-11-15 10:59:49.893 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:49.894 [  a] 0 HTTP2StreamPool:getStream:streamId=39,numAcquiredStreams=2
socketfd = 61
send content is: play_music:status=1

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:49.972 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
2017-11-15 10:59:49.973 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3922,"playerActivity":"PLAYING"}
2017-11-15 10:59:49.975 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"offsetInMilliseconds"\:3922\,"playerActivity"\:"PLAYING"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:49.976 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=4,currentId=4
2017-11-15 10:59:49.977 [  7] E AudioPlayer:notifyObserver:playerActivity=PLAYING
2017-11-15 10:59:50.013 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=4
2017-11-15 10:59:50.013 [  2] E AudioPlayer:onPlaybackFinished:id=4
2017-11-15 10:59:50.014 [  7] E AudioPlayer:executeOnPlaybackFinished
--> King:: AudioPlayer changeActivity  from  PLAYING to FINISHED...
2017-11-15 10:59:50.014 [  7] E AudioPlayer:changeActivity:from=PLAYING,to=FINISHED
	King:: onAudioPlayerPlayStatusChanged to 5
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onAudioPlayerPlayStatusChanged:: Start to open < Default > LED
socketfd = 59
send content is: play_music:status=0

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:50.209 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3925,"playerActivity":"FINISHED"}
2017-11-15 10:59:50.211 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0"\,"offsetInMilliseconds"\:3925\,"playerActivity"\:"FINISHED"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:50.211 [  7] E AudioPlayer:notifyObserver:playerActivity=FINISHED
2017-11-15 10:59:50.212 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackFinished
2017-11-15 10:59:50.213 [  7] 0 EventBuilder:buildJsonEventString:messageId=1a4e1a53-f4b0-46bb-bfbe-9a6dc0d03b0d,namespace=AudioPlayer,name=PlaybackFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackFinished","messageId":"1a4e1a53-f4b0-46bb-bfbe-9a6dc0d03b0d"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.1-0","offsetInMilliseconds":3925}}}
2017-11-15 10:59:50.215 [  7] E AudioPlayer:playNextItem:m_audioItems.size=1
2017-11-15 10:59:50.258 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
		Start execute handleOneSpeechBySensory() --> 2017-11-15 18:59:50:314
___________________________________AIP isExpectDirectStatus: 0
**********  start hal_rec_test recording *********
-----> For Vick: qahw_load_module...

 start first record thread 
		qahw_open_input_stream...... --> 2017-11-15 18:59:50:316
 input opened, buffer  0xa7837200, size 640, handle(2457)2017-11-15 10:59:50.321 [ 14] I SensoryKeywordDetector:License expires on 01 Feb 2018 00:00:00 GMT
2017-11-15 10:59:50.322 [ 14] I SensoryKeywordDetector:Sensory library license does not expire for at least 60 more days.

 Please speak into the microphone for 15.000000 seconds, handle(2457)
		Start Recording!!!!!!!   Start Recording!!!!!!!   Start Recording!!!!!!! --> 2017-11-15 18:59:50:355
2017-11-15 10:59:50.355 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-39
2017-11-15 10:59:50.355 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=39,result=204
2017-11-15 10:59:50.356 [  a] 0 HTTP2StreamPool:releaseStream:streamId=39,numAcquiredStreams=1
2017-11-15 10:59:50.356 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:50.356 [  a] 0 HTTP2Transport:processNextOutgoingMessage
ACDB -> send_audio_cal, acdb_id = 4, path = 1, app id = 0x11132, sample rate = 16000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE Returned = -19
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
2017-11-15 10:59:50.356 [  a] 0 HTTP2StreamPool:getStream:streamId=41,numAcquiredStreams=2
Error: ACDB audproc returned = -19
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AudProc vol returned = -19
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 16
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 4, Topology Id 112fb
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AFE returned = -19
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 4 path = 1
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
2017-11-15 10:59:50.362 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-15 10:59:50.365 [  7] E AudioPlayer:playNextItem:item.stream.offset=0
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 10:59:50.366 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=6,currentId=6
2017-11-15 10:59:50.367 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 10:59:50.368 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-15 10:59:50.391 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:50.392 [  2] E AudioPlayer:onTags:id=6
2017-11-15 10:59:50.392 [  7] E AudioPlayer:executeOnTags:id=6
2017-11-15 10:59:50.392 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:50.392 [  2] E AudioPlayer:onTags:id=6
2017-11-15 10:59:50.393 [  7] 0 EventBuilder:buildJsonEventString:messageId=64d66ee8-1159-4070-9545-b3b0cd3e457d,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"64d66ee8-1159-4070-9545-b3b0cd3e457d"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag"}}}}
2017-11-15 10:59:50.393 [  7] E AudioPlayer:executeOnTags:id=6
2017-11-15 10:59:50.400 [  7] 0 EventBuilder:buildJsonEventString:messageId=41101e93-38c9-4adc-bf91-125b11fa9cf4,namespace=AudioPlayer,name=StreamMetadataExtracted
2017-11-15 10:59:50.400 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=6
2017-11-15 10:59:50.400 [  2] E AudioPlayer:onPlaybackStarted:id=6
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"41101e93-38c9-4adc-bf91-125b11fa9cf4"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000"}}}}
2017-11-15 10:59:50.401 [  7] E AudioPlayer:executeOnPlaybackStarted:id=6
--> King:: AudioPlayer changeActivity  from  FINISHED to PLAYING...
2017-11-15 10:59:50.402 [  7] E AudioPlayer:changeActivity:from=FINISHED,to=PLAYING
	King:: onAudioPlayerPlayStatusChanged to 1
*** onAudioPlayerPlayStatusChanged:: Start to open < Speaking > LED
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11130, sample rate = 48000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 456
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 14, Topology Id 112fa
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 14 path = 0
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
socketfd = 64
send content is: play_music:status=1

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:50.487 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
2017-11-15 10:59:50.488 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=6,currentId=6
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","offsetInMilliseconds":24,"playerActivity":"PLAYING"}
2017-11-15 10:59:50.490 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"PLAYING"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:50.490 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=6,currentId=6
2017-11-15 10:59:50.491 [  7] E AudioPlayer:notifyObserver:playerActivity=PLAYING
2017-11-15 10:59:50.491 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackStarted
2017-11-15 10:59:50.492 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=6,currentId=6
2017-11-15 10:59:50.493 [  7] 0 EventBuilder:buildJsonEventString:messageId=343921d0-67e1-480e-97b8-7659f4547c7d,namespace=AudioPlayer,name=PlaybackStarted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackStarted","messageId":"343921d0-67e1-480e-97b8-7659f4547c7d"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:50.494 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackNearlyFinished
2017-11-15 10:59:50.494 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=6,currentId=6
2017-11-15 10:59:50.496 [  7] 0 EventBuilder:buildJsonEventString:messageId=59cf779d-4de0-4a34-b64e-acb5f4acd6eb,namespace=AudioPlayer,name=PlaybackNearlyFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackNearlyFinished","messageId":"59cf779d-4de0-4a34-b64e-acb5f4acd6eb"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:50.676 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:50.676 [  2] E AudioPlayer:onTags:id=6
2017-11-15 10:59:50.676 [  7] E AudioPlayer:executeOnTags:id=6
2017-11-15 10:59:50.677 [  7] 0 EventBuilder:buildJsonEventString:messageId=005cde81-0191-4917-874c-3b9e40bbdf46,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"005cde81-0191-4917-874c-3b9e40bbdf46"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000","minimum-bitrate":"48000","maximum-bitrate":"48000","bitrate":"48000"}}}}
2017-11-15 10:59:50.834 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-41
2017-11-15 10:59:50.834 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=41,result=204
2017-11-15 10:59:50.835 [  a] 0 HTTP2StreamPool:releaseStream:streamId=41,numAcquiredStreams=1
2017-11-15 10:59:50.835 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:50.835 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:50.836 [  a] 0 HTTP2StreamPool:getStream:streamId=43,numAcquiredStreams=2
2017-11-15 10:59:51.259 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:51.284 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-43
2017-11-15 10:59:51.284 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=43,result=204
2017-11-15 10:59:51.284 [  a] 0 HTTP2StreamPool:releaseStream:streamId=43,numAcquiredStreams=1
2017-11-15 10:59:51.284 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:51.284 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:51.285 [  a] 0 HTTP2StreamPool:getStream:streamId=45,numAcquiredStreams=2
2017-11-15 10:59:51.870 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-45
2017-11-15 10:59:51.871 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=45,result=204
2017-11-15 10:59:51.871 [  a] 0 HTTP2StreamPool:releaseStream:streamId=45,numAcquiredStreams=1
2017-11-15 10:59:51.871 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:51.872 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:51.872 [  a] 0 HTTP2StreamPool:getStream:streamId=47,numAcquiredStreams=2
2017-11-15 10:59:52.260 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:52.396 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-47
2017-11-15 10:59:52.396 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=47,result=204
2017-11-15 10:59:52.397 [  a] 0 HTTP2StreamPool:releaseStream:streamId=47,numAcquiredStreams=1
2017-11-15 10:59:52.397 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:52.397 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:52.398 [  a] 0 HTTP2StreamPool:getStream:streamId=49,numAcquiredStreams=2
2017-11-15 10:59:53.073 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-49
2017-11-15 10:59:53.074 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:53.074 [  a] 0 HTTP2StreamPool:getStream:streamId=51,numAcquiredStreams=3
2017-11-15 10:59:53.260 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:53.355 [  e] 0 MessageInterpreter:receive:messageId=89edb913-dfc1-4a16-b971-5fbab588e8e5:No dialogRequestId attached to message.
2017-11-15 10:59:53.356 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"89edb913-dfc1-4a16-b971-5fbab588e8e5"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"}}\,"playBehavior"\:"ENQUEUE"}}}
...onDirectiveArrived...
----------------- default directive
2017-11-15 10:59:53.357 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"89edb913-dfc1-4a16-b971-5fbab588e8e5"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"}}\,"playBehavior"\:"ENQUEUE"}}}
2017-11-15 10:59:53.358 [  f] I DirectiveRouter:preHandleDirective:messageId=89edb913-dfc1-4a16-b971-5fbab588e8e5,action=calling
2017-11-15 10:59:53.358 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=89edb913-dfc1-4a16-b971-5fbab588e8e5
2017-11-15 10:59:53.359 [ 10] I DirectiveRouter:handleDirective:messageId=89edb913-dfc1-4a16-b971-5fbab588e8e5,action=calling
2017-11-15 10:59:53.359 [ 10] E AudioPlayer:handleDirective:name=Play,messageId=89edb913-dfc1-4a16-b971-5fbab588e8e5
AudioPlayer::handleDirective getName = Play
2017-11-15 10:59:53.359 [ 10] E AudioPlayer:handlePlayDirective
2017-11-15 10:59:53.365 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expiryTime
2017-11-15 10:59:53.366 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReport
2017-11-15 10:59:53.366 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-11-15 10:59:53.366 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=89edb913-dfc1-4a16-b971-5fbab588e8e5,directiveBeingPreHandled=(nullptr)
2017-11-15 10:59:53.366 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=89edb913-dfc1-4a16-b971-5fbab588e8e5
2017-11-15 10:59:53.367 [  7] E AudioPlayer:executePlay:playBehavior=ENQUEUE
2017-11-15 10:59:54.262 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:54.279 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-51
2017-11-15 10:59:54.281 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=51,result=204
2017-11-15 10:59:54.282 [  a] 0 HTTP2StreamPool:releaseStream:streamId=51,numAcquiredStreams=2
2017-11-15 10:59:54.283 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:54.284 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=49,result=200
2017-11-15 10:59:54.285 [  a] 0 HTTP2StreamPool:releaseStream:streamId=49,numAcquiredStreams=1
2017-11-15 10:59:55.264 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:56.265 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:57.265 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:58.266 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:59.044 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=6
2017-11-15 10:59:59.045 [  2] E AudioPlayer:onPlaybackFinished:id=6
2017-11-15 10:59:59.046 [  7] E AudioPlayer:executeOnPlaybackFinished
--> King:: AudioPlayer changeActivity  from  PLAYING to FINISHED...
2017-11-15 10:59:59.047 [  7] E AudioPlayer:changeActivity:from=PLAYING,to=FINISHED
	King:: onAudioPlayerPlayStatusChanged to 5
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onAudioPlayerPlayStatusChanged:: Start to open < Default > LED
socketfd = 63
send content is: play_music:status=0

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:59.206 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","offsetInMilliseconds":24,"playerActivity":"FINISHED"}
2017-11-15 10:59:59.207 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"FINISHED"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:59.207 [  7] E AudioPlayer:notifyObserver:playerActivity=FINISHED
2017-11-15 10:59:59.207 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackFinished
2017-11-15 10:59:59.208 [  7] 0 EventBuilder:buildJsonEventString:messageId=e8f2f6fb-ee72-4945-995b-9d67b66b4786,namespace=AudioPlayer,name=PlaybackFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackFinished","messageId":"e8f2f6fb-ee72-4945-995b-9d67b66b4786"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.2-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:59.208 [  7] E AudioPlayer:playNextItem:m_audioItems.size=1
2017-11-15 10:59:59.241 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:59.242 [  a] 0 HTTP2StreamPool:getStream:streamId=53,numAcquiredStreams=2
2017-11-15 10:59:59.267 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 10:59:59.299 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-15 10:59:59.304 [  7] E AudioPlayer:playNextItem:item.stream.offset=0
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 10:59:59.305 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=7,currentId=7
2017-11-15 10:59:59.306 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 10:59:59.309 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-15 10:59:59.341 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:59.341 [  2] E AudioPlayer:onTags:id=7
2017-11-15 10:59:59.341 [  7] E AudioPlayer:executeOnTags:id=7
2017-11-15 10:59:59.342 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:59.342 [  2] E AudioPlayer:onTags:id=7
2017-11-15 10:59:59.342 [  7] 0 EventBuilder:buildJsonEventString:messageId=5a3273d3-a8e1-4b12-9fd6-f23321be4375,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"5a3273d3-a8e1-4b12-9fd6-f23321be4375"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag"}}}}
2017-11-15 10:59:59.343 [  7] E AudioPlayer:executeOnTags:id=7
2017-11-15 10:59:59.351 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=7
2017-11-15 10:59:59.351 [  7] 0 EventBuilder:buildJsonEventString:messageId=82a2f564-6a1e-4b19-b80d-7778ed55310e,namespace=AudioPlayer,name=StreamMetadataExtracted
2017-11-15 10:59:59.351 [  2] E AudioPlayer:onPlaybackStarted:id=7
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"82a2f564-6a1e-4b19-b80d-7778ed55310e"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000"}}}}
2017-11-15 10:59:59.355 [  7] E AudioPlayer:executeOnPlaybackStarted:id=7
--> King:: AudioPlayer changeActivity  from  FINISHED to PLAYING...
2017-11-15 10:59:59.355 [  7] E AudioPlayer:changeActivity:from=FINISHED,to=PLAYING
	King:: onAudioPlayerPlayStatusChanged to 1
*** onAudioPlayerPlayStatusChanged:: Start to open < Speaking > LED
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11130, sample rate = 48000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 456
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 14, Topology Id 112fa
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 14 path = 0
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
socketfd = 66
send content is: play_music:status=1

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 10:59:59.444 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
2017-11-15 10:59:59.444 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=7,currentId=7
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","offsetInMilliseconds":24,"playerActivity":"PLAYING"}
2017-11-15 10:59:59.445 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"PLAYING"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 10:59:59.446 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=7,currentId=7
2017-11-15 10:59:59.446 [  7] E AudioPlayer:notifyObserver:playerActivity=PLAYING
2017-11-15 10:59:59.446 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackStarted
2017-11-15 10:59:59.447 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=7,currentId=7
2017-11-15 10:59:59.447 [  7] 0 EventBuilder:buildJsonEventString:messageId=21b3dad4-aea5-4b48-b68f-9d23949dbc78,namespace=AudioPlayer,name=PlaybackStarted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackStarted","messageId":"21b3dad4-aea5-4b48-b68f-9d23949dbc78"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:59.448 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackNearlyFinished
2017-11-15 10:59:59.448 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=7,currentId=7
2017-11-15 10:59:59.449 [  7] 0 EventBuilder:buildJsonEventString:messageId=1ccc2afe-bb78-4da7-a0b9-601c68e2fbe8,namespace=AudioPlayer,name=PlaybackNearlyFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackNearlyFinished","messageId":"1ccc2afe-bb78-4da7-a0b9-601c68e2fbe8"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","offsetInMilliseconds":24}}}
2017-11-15 10:59:59.635 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 10:59:59.635 [  2] E AudioPlayer:onTags:id=7
2017-11-15 10:59:59.636 [  7] E AudioPlayer:executeOnTags:id=7
2017-11-15 10:59:59.636 [  7] 0 EventBuilder:buildJsonEventString:messageId=405dcd84-105b-4b7b-9827-63b32a32e3f6,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"405dcd84-105b-4b7b-9827-63b32a32e3f6"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000","minimum-bitrate":"48000","maximum-bitrate":"48000","bitrate":"48000"}}}}
2017-11-15 10:59:59.752 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-53
2017-11-15 10:59:59.752 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=53,result=204
2017-11-15 10:59:59.752 [  a] 0 HTTP2StreamPool:releaseStream:streamId=53,numAcquiredStreams=1
2017-11-15 10:59:59.752 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 10:59:59.753 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 10:59:59.753 [  a] 0 HTTP2StreamPool:getStream:streamId=55,numAcquiredStreams=2
2017-11-15 11:00:00.176 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-55
2017-11-15 11:00:00.178 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=55,result=204
2017-11-15 11:00:00.178 [  a] 0 HTTP2StreamPool:releaseStream:streamId=55,numAcquiredStreams=1
2017-11-15 11:00:00.179 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:00.179 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:00.180 [  a] 0 HTTP2StreamPool:getStream:streamId=57,numAcquiredStreams=2
2017-11-15 11:00:00.268 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:00.621 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-57
2017-11-15 11:00:00.622 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=57,result=204
2017-11-15 11:00:00.622 [  a] 0 HTTP2StreamPool:releaseStream:streamId=57,numAcquiredStreams=1
2017-11-15 11:00:00.622 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:00.622 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:00.623 [  a] 0 HTTP2StreamPool:getStream:streamId=59,numAcquiredStreams=2
2017-11-15 11:00:01.269 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:01.273 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-59
2017-11-15 11:00:01.274 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=59,result=204
2017-11-15 11:00:01.274 [  a] 0 HTTP2StreamPool:releaseStream:streamId=59,numAcquiredStreams=1
2017-11-15 11:00:01.274 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:01.275 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:01.275 [  a] 0 HTTP2StreamPool:getStream:streamId=61,numAcquiredStreams=2
2017-11-15 11:00:02.269 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:02.305 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-61
2017-11-15 11:00:02.306 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:02.307 [  a] 0 HTTP2StreamPool:getStream:streamId=63,numAcquiredStreams=3
2017-11-15 11:00:02.594 [  e] 0 MessageInterpreter:receive:messageId=bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f:No dialogRequestId attached to message.
2017-11-15 11:00:02.596 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"}}\,"playBehavior"\:"ENQUEUE"}}}
...onDirectiveArrived...
----------------- default directive
2017-11-15 11:00:02.599 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"Play"\,"messageId"\:"bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f"}\,"payload"\:{"audioItem"\:{"audioItemId"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"stream"\:{"offsetInMilliseconds"\:0\,"streamFormat"\:"AUDIO_MPEG"\,"url"\:"cid\:b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"}}\,"playBehavior"\:"ENQUEUE"}}}
2017-11-15 11:00:02.600 [  f] I DirectiveRouter:preHandleDirective:messageId=bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f,action=calling
2017-11-15 11:00:02.600 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f
2017-11-15 11:00:02.601 [ 10] I DirectiveRouter:handleDirective:messageId=bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f,action=calling
2017-11-15 11:00:02.601 [ 10] E AudioPlayer:handleDirective:name=Play,messageId=bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f
AudioPlayer::handleDirective getName = Play
2017-11-15 11:00:02.601 [ 10] E AudioPlayer:handlePlayDirective
2017-11-15 11:00:02.605 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expiryTime
2017-11-15 11:00:02.605 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=progressReport
2017-11-15 11:00:02.605 [ 10] E JsonUtils:findNodeFailed:reason=missingDirectChild,child=expectedPreviousToken
2017-11-15 11:00:02.605 [ 10] 0 DirectiveProcessor:onHandlingCompeted:messageId=bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f,directiveBeingPreHandled=(nullptr)
2017-11-15 11:00:02.605 [ 10] 0 CapabilityAgent:removingMessageIdFromMap:messageId=bad6a2b4-97c0-4ecb-b901-9a2d34d2cc1f
2017-11-15 11:00:02.606 [  7] E AudioPlayer:executePlay:playBehavior=ENQUEUE
2017-11-15 11:00:03.154 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-63
2017-11-15 11:00:03.155 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=63,result=204
2017-11-15 11:00:03.155 [  a] 0 HTTP2StreamPool:releaseStream:streamId=63,numAcquiredStreams=2
2017-11-15 11:00:03.156 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:03.157 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=61,result=200
2017-11-15 11:00:03.157 [  a] 0 HTTP2StreamPool:releaseStream:streamId=61,numAcquiredStreams=1
2017-11-15 11:00:03.270 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:04.270 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:05.271 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
handleOneSpeechBySensory::waitForWakeword------
2017-11-15 11:00:06.271 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:07.272 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:08.273 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:09.274 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:10.037 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=7
2017-11-15 11:00:10.037 [  2] E AudioPlayer:onPlaybackFinished:id=7
2017-11-15 11:00:10.037 [  7] E AudioPlayer:executeOnPlaybackFinished
--> King:: AudioPlayer changeActivity  from  PLAYING to FINISHED...
2017-11-15 11:00:10.038 [  7] E AudioPlayer:changeActivity:from=PLAYING,to=FINISHED
	King:: onAudioPlayerPlayStatusChanged to 5
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onAudioPlayerPlayStatusChanged:: Start to open < Default > LED
socketfd = 65
send content is: play_music:status=0

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 11:00:10.147 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","offsetInMilliseconds":24,"playerActivity":"FINISHED"}
2017-11-15 11:00:10.147 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"FINISHED"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 11:00:10.148 [  7] E AudioPlayer:notifyObserver:playerActivity=FINISHED
2017-11-15 11:00:10.148 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackFinished
2017-11-15 11:00:10.148 [  7] 0 EventBuilder:buildJsonEventString:messageId=2d50e198-10e9-447b-80f7-0d3c83530fed,namespace=AudioPlayer,name=PlaybackFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackFinished","messageId":"2d50e198-10e9-447b-80f7-0d3c83530fed"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.3-0","offsetInMilliseconds":24}}}
2017-11-15 11:00:10.149 [  7] E AudioPlayer:playNextItem:m_audioItems.size=1
2017-11-15 11:00:10.230 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:10.230 [  a] 0 HTTP2StreamPool:getStream:streamId=65,numAcquiredStreams=2
2017-11-15 11:00:10.275 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:10.302 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-11-15 11:00:10.306 [  7] E AudioPlayer:playNextItem:item.stream.offset=0
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-11-15 11:00:10.307 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=8,currentId=8
2017-11-15 11:00:10.308 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-11-15 11:00:10.310 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-11-15 11:00:10.342 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 11:00:10.342 [  2] E AudioPlayer:onTags:id=8
2017-11-15 11:00:10.343 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 11:00:10.343 [  2] E AudioPlayer:onTags:id=8
2017-11-15 11:00:10.343 [  7] E AudioPlayer:executeOnTags:id=8
2017-11-15 11:00:10.353 [  7] 0 EventBuilder:buildJsonEventString:messageId=48b10c01-8995-4eb7-b44c-e6620bc99ed8,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"48b10c01-8995-4eb7-b44c-e6620bc99ed8"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag"}}}}
2017-11-15 11:00:10.354 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=8
2017-11-15 11:00:10.354 [  7] E AudioPlayer:executeOnTags:id=8
2017-11-15 11:00:10.354 [  2] E AudioPlayer:onPlaybackStarted:id=8
2017-11-15 11:00:10.355 [  7] 0 EventBuilder:buildJsonEventString:messageId=6b0ecee8-872d-41dd-bd70-cb4f99ee57f8,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"6b0ecee8-872d-41dd-bd70-cb4f99ee57f8"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000"}}}}
2017-11-15 11:00:10.356 [  7] E AudioPlayer:executeOnPlaybackStarted:id=8
--> King:: AudioPlayer changeActivity  from  FINISHED to PLAYING...
2017-11-15 11:00:10.356 [  7] E AudioPlayer:changeActivity:from=FINISHED,to=PLAYING
	King:: onAudioPlayerPlayStatusChanged to 1
*** onAudioPlayerPlayStatusChanged:: Start to open < Speaking > LED
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11130, sample rate = 48000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 456
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 14, Topology Id 112fa
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 14 path = 0
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
socketfd = 68
send content is: play_music:status=1

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 11:00:10.461 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
2017-11-15 11:00:10.462 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=8,currentId=8
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","offsetInMilliseconds":24,"playerActivity":"PLAYING"}
2017-11-15 11:00:10.463 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"PLAYING"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 11:00:10.463 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=8,currentId=8
2017-11-15 11:00:10.464 [  7] E AudioPlayer:notifyObserver:playerActivity=PLAYING
2017-11-15 11:00:10.464 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackStarted
2017-11-15 11:00:10.465 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=8,currentId=8
2017-11-15 11:00:10.466 [  7] 0 EventBuilder:buildJsonEventString:messageId=9986905b-fbca-4da5-9dbf-ae32106e49d5,namespace=AudioPlayer,name=PlaybackStarted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackStarted","messageId":"9986905b-fbca-4da5-9dbf-ae32106e49d5"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","offsetInMilliseconds":24}}}
2017-11-15 11:00:10.466 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackNearlyFinished
2017-11-15 11:00:10.467 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=8,currentId=8
2017-11-15 11:00:10.468 [  7] 0 EventBuilder:buildJsonEventString:messageId=5667bc24-3222-4b6e-8139-0b38e10d1818,namespace=AudioPlayer,name=PlaybackNearlyFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackNearlyFinished","messageId":"5667bc24-3222-4b6e-8139-0b38e10d1818"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","offsetInMilliseconds":24}}}
2017-11-15 11:00:10.634 [  2] 0 MediaPlayer:callingOnTags
2017-11-15 11:00:10.635 [  2] E AudioPlayer:onTags:id=8
2017-11-15 11:00:10.636 [  7] E AudioPlayer:executeOnTags:id=8
2017-11-15 11:00:10.636 [  7] 0 EventBuilder:buildJsonEventString:messageId=c5369d70-7038-4f2f-ba01-ffc789d6a1a5,namespace=AudioPlayer,name=StreamMetadataExtracted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"StreamMetadataExtracted","messageId":"c5369d70-7038-4f2f-ba01-ffc789d6a1a5"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","metadata":{"encoder":"Lavf57.71.100","container-format":"ID3 tag","has-crc":false,"channel-mode":"mono","audio-codec":"MPEG-1 Layer 3 (MP3)","nominal-bitrate":"48000","minimum-bitrate":"48000","maximum-bitrate":"48000","bitrate":"48000"}}}}
2017-11-15 11:00:10.685 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-65
2017-11-15 11:00:10.685 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=65,result=204
2017-11-15 11:00:10.685 [  a] 0 HTTP2StreamPool:releaseStream:streamId=65,numAcquiredStreams=1
2017-11-15 11:00:10.685 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:10.686 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:10.686 [  a] 0 HTTP2StreamPool:getStream:streamId=67,numAcquiredStreams=2
2017-11-15 11:00:11.171 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-67
2017-11-15 11:00:11.172 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=67,result=204
2017-11-15 11:00:11.173 [  a] 0 HTTP2StreamPool:releaseStream:streamId=67,numAcquiredStreams=1
2017-11-15 11:00:11.173 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:11.174 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:11.175 [  a] 0 HTTP2StreamPool:getStream:streamId=69,numAcquiredStreams=2
2017-11-15 11:00:11.276 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:11.687 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-69
2017-11-15 11:00:11.687 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=69,result=204
2017-11-15 11:00:11.687 [  a] 0 HTTP2StreamPool:releaseStream:streamId=69,numAcquiredStreams=1
2017-11-15 11:00:11.688 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:11.688 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:11.688 [  a] 0 HTTP2StreamPool:getStream:streamId=71,numAcquiredStreams=2
2017-11-15 11:00:12.194 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-71
2017-11-15 11:00:12.195 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=71,result=204
2017-11-15 11:00:12.195 [  a] 0 HTTP2StreamPool:releaseStream:streamId=71,numAcquiredStreams=1
2017-11-15 11:00:12.195 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:12.195 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:12.195 [  a] 0 HTTP2StreamPool:getStream:streamId=73,numAcquiredStreams=2
2017-11-15 11:00:12.277 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:12.689 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-73
2017-11-15 11:00:12.691 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=73,result=204
2017-11-15 11:00:12.692 [  a] 0 HTTP2StreamPool:releaseStream:streamId=73,numAcquiredStreams=1
2017-11-15 11:00:12.692 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:12.693 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:12.694 [  a] 0 HTTP2StreamPool:getStream:streamId=75,numAcquiredStreams=2
2017-11-15 11:00:13.144 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-75
2017-11-15 11:00:13.145 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=75,result=204
2017-11-15 11:00:13.145 [  a] 0 HTTP2StreamPool:releaseStream:streamId=75,numAcquiredStreams=1
2017-11-15 11:00:13.146 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:13.278 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:14.279 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:15.280 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:16.282 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:17.282 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:18.283 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:18.753 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=8
2017-11-15 11:00:18.753 [  2] E AudioPlayer:onPlaybackFinished:id=8
2017-11-15 11:00:18.755 [  7] E AudioPlayer:executeOnPlaybackFinished
--> King:: AudioPlayer changeActivity  from  PLAYING to FINISHED...
2017-11-15 11:00:18.755 [  7] E AudioPlayer:changeActivity:from=PLAYING,to=FINISHED
	King:: onAudioPlayerPlayStatusChanged to 5
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onAudioPlayerPlayStatusChanged:: Start to open < Default > LED
socketfd = 67
send content is: play_music:status=0

				send avs data ok 
--> King:: AudioPlayer executeProvideState  start ...
2017-11-15 11:00:18.845 [  7] E AudioPlayer:executeProvideState:sendToken=false,stateRequestToken=0
--> King:: AudioPlayer executeProvideState update payload to: {"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","offsetInMilliseconds":24,"playerActivity":"FINISHED"}
2017-11-15 11:00:18.846 [  7] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"FINISHED"},namespace=AudioPlayer,name=PlaybackState
--> King:: AudioPlayer executeProvideState update Success!!!
2017-11-15 11:00:18.846 [  7] E AudioPlayer:notifyObserver:playerActivity=FINISHED
2017-11-15 11:00:18.846 [  7] E AudioPlayer:sendEventWithTokenAndOffset:eventName=PlaybackFinished
2017-11-15 11:00:18.846 [  7] 0 EventBuilder:buildJsonEventString:messageId=808dfec6-a332-4c61-b27e-8640d1949aec,namespace=AudioPlayer,name=PlaybackFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"AudioPlayer","name":"PlaybackFinished","messageId":"808dfec6-a332-4c61-b27e-8640d1949aec"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","offsetInMilliseconds":24}}}
2017-11-15 11:00:18.847 [ 11] E AudioPlayer:onFocusChanged:newFocus=NONE
2017-11-15 11:00:18.848 [  7] E AudioPlayer:executeOnFocusChanged:from=FOREGROUND,to=NONE,m_currentActivity=FINISHED
2017-11-15 11:00:18.902 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:00:18.903 [  a] 0 HTTP2StreamPool:getStream:streamId=77,numAcquiredStreams=2
2017-11-15 11:00:19.284 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:19.440 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-77
2017-11-15 11:00:19.440 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=77,result=204
2017-11-15 11:00:19.441 [  a] 0 HTTP2StreamPool:releaseStream:streamId=77,numAcquiredStreams=1
2017-11-15 11:00:19.441 [  a] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-15 11:00:20.284 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
handleOneSpeechBySensory::waitForWakeword------
2017-11-15 11:00:21.285 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:22.285 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:00:23.286 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
 *** testKeyWordObserverDebug:: onKeyWordDetected
openFMDuringTest : isFMOpened = 0
stopMediaPlayer 11111
stopLocalMediaPlayer 222
2017-11-15 11:01:03.645 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 11:01:03.646 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 11:01:03.646 [  2] E MediaPlayer:handleStopFailed
stopSpeakMediaPlayer 33333
2017-11-15 11:01:03.646 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 11:01:03.647 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 11:01:03.647 [  2] E MediaPlayer:handleStopFailed
stopMediaPlayer m_rendererMediaPlayer
2017-11-15 11:01:03.647 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 11:01:03.647 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 11:01:03.647 [  2] E MediaPlayer:handleStopFailed
stopMediaPlayer 44444
Nut2AVS  King:: testKeyWordObserverDebug::onKeyWordDetected.....beginIndex = 88800, endIndex = 98400,
___________________________________AIP isExpectDirectStatus: 0
--> handleOneSpeechBySensory::readOffset = 161600
--> RingBufferConsumer m_read_offset = 161600
exitAVS = 0, m_wisStatusChanged->isStopCaptureFlag = 0, isRecordingFinish = 0
		Start to open < Listening > LED --> 2017-11-15 19:01:03:663
consumer is done
		Start to play med_ui_voice_start_listening.wav --> 2017-11-15 19:01:03:733
SKU detect: CX/SB
Current SKU is: CX
SKU is CX:  To play  preRecording  sound cue
Nut2AVS  King:: wakeWordTrigger::onKeyWordDetected.....beginIndex = 130800, endIndex = 140160,
Nut2AVS King:: wakeWordTrigger::Sensory recognize.....beginIndex = 130800, endIndex = 140160
*** AudioInputProcessor::executeRecognize initiatorPayloadJson="wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":17360}
2017-11-15 11:01:03.857 [  9] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
m_expectingSpeechTimer.stop...
2017-11-15 11:01:03.865 [  d] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
Playing sample: 2 ch, 48000 hz, 16 bit
8
		current mediaPlayer voluem value: 8 --> 2017-11-15 19:01:03:920
2017-11-15 11:01:03.920 [  6] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:80\,"muted"\:0},namespace=Speaker,name=VolumeState
2017-11-15 11:01:03.921 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:"alexa"}}\,{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:80\,"muted"\:0}}]}
2017-11-15 11:01:03.922 [  9] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context"\:[{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0"\,"offsetInMilliseconds"\:24\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:"alexa"}}\,{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:80\,"muted"\:0}}]}
2017-11-15 11:01:03.922 [  9] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=a2c3edd1-117c-4eea-96f4-4b8b01053c40
2017-11-15 11:01:03.922 [  9] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId
2017-11-15 11:01:03.923 [  9] 0 EventBuilder:buildJsonEventString:messageId=eb07da44-6fe4-40d7-87bb-79cbc270378e,namespace=SpeechRecognizer,name=Recognize
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-11-15 11:01:03.924 [  9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
AVSConnectionManager::sendMessage {"context":[{"header":{"namespace":"AudioPlayer","name":"PlaybackState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:Sports#ACRI#ssml#ACRI#b0305ab0-90c4-4f91-8d7c-f3b6ef73c279.26a9f630-e32e-4a12-abe2-d6ebecfc1427.4-0","offsetInMilliseconds":24,"playerActivity":"FINISHED"}},{"header":{"namespace":"SpeechSynthesizer","name":"SpeechState"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:NotificationsV4#ACRI#DeviceTTSRendererV4_a10b7f1b-4693-478d-9c73-663b1f8263fa","offsetInMilliseconds":0,"playerActivity":"FINISHED"}},{"header":{"namespace":"Alerts","name":"AlertsState"},"payload":{"allAlerts":[],"activeAlerts":[]}},{"header":{"namespace":"SpeechRecognizer","name":"RecognizerState"},"payload":{"wakeword":"alexa"}},{"header":{"namespace":"Speaker","name":"VolumeState"},"payload":{"volume":80,"muted":0}}],"event":{"header":{"namespace":"SpeechRecognizer","name":"Recognize","messageId":"eb07da44-6fe4-40d7-87bb-79cbc270378e","dialogRequestId":"a2c3edd1-117c-4eea-96f4-4b8b01053c40"},"payload":{"profile":"NEAR_FIELD","format":"AUDIO_L16_RATE_16000_CHANNELS_1","initiator":{"type":"WAKEWORD","payload":{"wakeWordIndices":{"startIndexInSamples":8000,"endIndexInSamples":17360}}}}}}
2017-11-15 11:01:04.016 [  a] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-15 11:01:04.017 [  a] 0 HTTP2StreamPool:getStream:streamId=79,numAcquiredStreams=2
2017-11-15 11:01:04.648 [ 17] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
		End play med_ui_voice_start_listening.wav --> 2017-11-15 19:01:04:722



##### Start recording!


2017-11-15 11:01:06.790 [  e] 0 MessageInterpreter:receive:messageId=faf72d74-378a-4b1d-8239-e0a5ae654b93:No dialogRequestId attached to message.
2017-11-15 11:01:06.790 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"StopCapture"\,"messageId"\:"faf72d74-378a-4b1d-8239-e0a5ae654b93"}\,"payload"\:{}}}
...onDirectiveArrived...
onDirectiveArrived: To stop recording...
2017-11-15 11:01:06.791 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"StopCapture"\,"messageId"\:"faf72d74-378a-4b1d-8239-e0a5ae654b93"}\,"payload"\:{}}}
2017-11-15 11:01:06.791 [  f] I DirectiveRouter:preHandleDirective:messageId=faf72d74-378a-4b1d-8239-e0a5ae654b93,action=calling
2017-11-15 11:01:06.791 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=faf72d74-378a-4b1d-8239-e0a5ae654b93
2017-11-15 11:01:06.792 [ 10] I DirectiveRouter:handleDirective:messageId=faf72d74-378a-4b1d-8239-e0a5ae654b93,action=calling
AudioInputProcessor::handleDirective --------StopCapture
2017-11-15 11:01:06.793 [  9] 0 AudioInputProcessor:stopCapture:stopImmediately=true
2017-11-15 11:01:06.794 [  9] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-11-15 11:01:06.794 [  9] 0 DirectiveProcessor:onHandlingCompeted:messageId=faf72d74-378a-4b1d-8239-e0a5ae654b93,directiveBeingPreHandled=(nullptr)
2017-11-15 11:01:06.794 [  9] 0 CapabilityAgent:removingMessageIdFromMap:messageId=faf72d74-378a-4b1d-8239-e0a5ae654b93
2017-11-15 11:01:06.794 [  d] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
		End Recording!!!!!!! --> 2017-11-15 19:01:06:798
 closing input, handle(2457)
closing input
2017-11-15 11:01:06.800 [  a] I InProcessAttachmentReader:readFailed:reason=SDS is closed


 The audio recording has been saved to /data/nut2_avs/hal_rec_test_rec_original.wav. Please use adb pull to get the file and play it using audacity. The audio data has the following characteristics:
 Sample rate: 16000
 Format: 1
 Num channels: 1, handle(2457)


 Done with hal record test 
producer is done
		Start to open < Thinking > LED --> 2017-11-15 19:01:06:851
		---> Get Directive start! --> 2017-11-15 19:01:06:886
		Start to play med_ui_voice_stop_listening.wav --> 2017-11-15 19:01:06:930
SKU detect: CX/SB
Current SKU is: CX
SKU is CX:  To play  postRecording  sound cue
Playing sample: 2 ch, 48000 hz, 16 bit
2017-11-15 11:01:07.316 [  a] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ae04dfffe102b9c-000053ae-0002c38d-84328742681b430f-60536d02-79
2017-11-15 11:01:07.595 [  e] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"fb44bfc4-0514-4561-83e9-d596e118b036"\,"dialogRequestId"\:"a2c3edd1-117c-4eea-96f4-4b8b01053c40"}\,"payload"\:{"url"\:"cid\:DeviceTTSRendererV4_864d922d-c15b-4425-a3cd-3925e3b6b9af_1681441564"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.HouseholdSpeechlet#ACRI#DeviceTTSRendererV4_864d922d-c15b-4425-a3cd-3925e3b6b9af"}}}
...onDirectiveArrived...
----------------- default directive
2017-11-15 11:01:07.597 [  f] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"fb44bfc4-0514-4561-83e9-d596e118b036"\,"dialogRequestId"\:"a2c3edd1-117c-4eea-96f4-4b8b01053c40"}\,"payload"\:{"url"\:"cid\:DeviceTTSRendererV4_864d922d-c15b-4425-a3cd-3925e3b6b9af_1681441564"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.HouseholdSpeechlet#ACRI#DeviceTTSRendererV4_864d922d-c15b-4425-a3cd-3925e3b6b9af"}}}
2017-11-15 11:01:07.598 [  f] I DirectiveRouter:preHandleDirective:messageId=fb44bfc4-0514-4561-83e9-d596e118b036,action=calling
2017-11-15 11:01:07.598 [  f] 0 CapabilityAgent:addingMessageIdToMap:messageId=fb44bfc4-0514-4561-83e9-d596e118b036
2017-11-15 11:01:07.599 [ 10] I DirectiveRouter:handleDirective:messageId=fb44bfc4-0514-4561-83e9-d596e118b036,action=calling
2017-11-15 11:01:07.599 [  8] 0 SpeechSynthesizer:executePreHandle:messageId=fb44bfc4-0514-4561-83e9-d596e118b036
2017-11-15 11:01:07.612 [  8] 0 SpeechSynthesizer:executeHandle:messageId=fb44bfc4-0514-4561-83e9-d596e118b036
2017-11-15 11:01:07.613 [  a] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2017-11-15 11:01:07.613 [  a] 0 HTTP2Transport:cleanupFinishedStream:streamId=79,result=200
2017-11-15 11:01:07.614 [  a] 0 HTTP2StreamPool:releaseStream:streamId=79,numAcquiredStreams=1
		---> Get Directive end! --> 2017-11-15 19:01:07:648
--> To handle the 0 directive: SpeechSynthesizer - Speak
		Wait for get response audio!!!!!!! --> 2017-11-15 19:01:07:648
2017-11-15 11:01:07.831 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
		End play med_ui_voice_stop_listening.wav --> 2017-11-15 19:01:07:986



##### End recording!


2017-11-15 11:01:08.834 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:09.837 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:10.840 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:11.805 [  d] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut
2017-11-15 11:01:11.806 [  d] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE
2017-11-15 11:01:11.808 [  9] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-11-15 11:01:11.809 [  9] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-11-15 11:01:11.810 [  9] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
executeResetState  m_expectingSpeechTimer.stop...
2017-11-15 11:01:11.843 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:12.846 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:13.849 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:14.850 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:15.852 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:16.854 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
TestSpeechSynthesizerObserver::waitForNext------state: 
mkdir: cannot create directory '/data/nut2_avs/recording': File exists
get recording file count: 6

To execute copy command: cp /data/nut2_avs/hal_rec_test_rec_send.wav /data/nut2_avs/recording/recording_20171115110117.wav
*** onSpeechSynthesizerObserverStateChanged::  isRecordingFinish = 1
openFMDuringTest : isFMOpened = 0 , mLastFMOpened = 0
*** onSpeechSynthesizerObserverStateChanged:: Start to open < Default > LED
2017-11-15 11:01:17.826 [  2] 0 MediaPlayer:handleStopCalled:idPassed=0,currentId=0
2017-11-15 11:01:17.827 [  2] E MediaPlayer:validateSourceAndIdFailed:reason=sourceNotSet
2017-11-15 11:01:17.827 [  2] E MediaPlayer:handleStopFailed
^_^^^_^^^^_^^^^^^_^^^^^^_^^^^^^^^_^^^^ testCycleIndex: 1
executeResetState  m_expectingSpeechTimer.stop...
2017-11-15 11:01:17.857 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:18.860 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
		Start execute handleOneSpeechBySensory() --> 2017-11-15 19:01:19:830
___________________________________AIP isExpectDirectStatus: 0
**********  start hal_rec_test recording *********
-----> For Vick: qahw_load_module...

 start first record thread 
		qahw_open_input_stream...... --> 2017-11-15 19:01:19:833
 input opened, buffer  0xaa418b00, size 640, handle(2457)
 Please speak into the microphone for 15.000000 seconds, handle(2457)
		Start Recording!!!!!!!   Start Recording!!!!!!!   Start Recording!!!!!!! --> 2017-11-15 19:01:19:840
2017-11-15 11:01:19.846 [ 18] I SensoryKeywordDetector:License expires on 01 Feb 2018 00:00:00 GMT
2017-11-15 11:01:19.848 [ 18] I SensoryKeywordDetector:Sensory library license does not expire for at least 60 more days.
ACDB -> send_audio_cal, acdb_id = 4, path = 1, app id = 0x11132, sample rate = 16000
ACDB -> send_asm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TOPOLOGY_ID
ACDB -> send_adm_topology
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TOPOLOGY_ID
ACDB -> send_audtable
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB_CMD_GET_AUDPROC_COMMON_TABLE_SIZE Returned = -19
ACDB -> ACDB_CMD_GET_AUDPROC_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB audproc returned = -19
ACDB -> AUDIO_SET_AUDPROC_CAL
ACDB -> send_audvoltable
ACDB -> ACDB_CMD_GET_AUDPROC_GAIN_DEP_STEP_TABLE, vol index 0
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AudProc vol returned = -19
ACDB -> AUDIO_SET_VOL_CAL cal type = 12
ACDB -> send_audstrmtable
ACDB -> ACDB_CMD_GET_AUDPROC_STREAM_TABLE_V2
ACDB -> audstrm_cal->cal_type.cal_data.cal_size = 16
ACDB -> send_afe_topology
ACDB -> ACDB_CMD_GET_AFE_TOPOLOGY_ID
ACDB -> GET_AFE_TOPOLOGY_ID for adcd_id 4, Topology Id 112fb
ACDB -> send_afe_cal
ACDB -> ACDB_CMD_GET_AFE_COMMON_TABLE
Failed to fetch the lookup information of the device 00000004 
Error: ACDB AFE returned = -19
ACDB -> AUDIO_SET_AFE_CAL
ACDB -> send_hw_delay : acdb_id = 4 path = 1
ACDB -> ACDB_AVSYNC_INFO: ACDB_CMD_GET_DEVICE_PROPERTY
2017-11-15 11:01:19.861 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut
2017-11-15 11:01:20.861 [  4] I AbstractKeywordDetector:readFromStreamFailed:reason=readerTimeOut