boyce-xx/WisAlertsIntegrationTest

## WisAlertsIntegrationTest
$ adb shell
/ # cd usr/nut2_avs/
/usr/nut2_avs # ./WisAlertsIntegrationTest
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from AlertsTest
[ RUN      ] AlertsTest.handleOneTimerWithLocalStop
2017-12-15 12:06:56.061 [  1] I ConfigurationNode:initializeSuccess
2017-12-15 12:06:56.289 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-12-15 12:06:56.293 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechSynthesizer,name=Speak,handler=0x331590,policy=BLOCKING
2017-12-15 12:06:56.299 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-12-15 12:06:56.302 [  1] E SQLiteMessageStorage:openFailed::File specified does not exist.:file path=/usr/nut2_avs/inputs/certifiedSender.db
2017-12-15 12:06:56.303 [  1] I CertifiedSender:init : Database file does not exist.  Creating.
2017-12-15 12:06:56.389 [  1] E SQLiteAlertStorage:openFailed::File specified does not exist.:file path=/usr/nut2_avs/inputs/alerts.db
2017-12-15 12:06:56.389 [  1] I AlertScheduler:initialize::storage file does not exist.  Creating.
2017-12-15 12:06:56.455 [  1] I AlertScheduler:executeScheduleNextAlertForRendering::no work to do.
2017-12-15 12:06:56.459 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=DeleteAlert,handler=0x36c338,policy=NON_BLOCKING
2017-12-15 12:06:56.460 [  1] I DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetAlert,handler=0x36c338,policy=NON_BLOCKING
2017-12-15 12:06:57.826 [  3] 0 HttpPost:doPostSucceeded:code=200
2017-12-15 12:06:57.832 [  3] 0 AuthDelegate:handleLwaResponseSucceeded:expiresInSeconds=3600
***********************authToken: Atza|IwEBIJxe4XN-TOjOpu0I_129CxzmC1jqXOVTTgGlHb-wh7tZn4FyztqTSt1Kdsc4mX6b91_J2SEaAdxxTW6Sr6P1AC8pXQ7EPH54EPFdd7ucOfkpwVZftrfkzfQjgBwEuLmLSfh-SNE3tesDRonAeNNQ2UVPKtiSSkTmGeGe5OvRWRbxmFyu1650c_NZiTWMTEMWv2FI7HsUHbx9hR6_iCQC51KjgBbStFjplw1dQGue56LTCfL0N8YIFzwJnVTbLPUIwBP2dinLXSD6CJWRhWuVPUFpAUDK1aGHBuu-iLdhfzVHb4LNuoHNXy1rDfDXnTHA1Re1eN11lzIJrk1std7Wea_6_C6x80Qb8KOKT23zvLhMqkL77-YefXuZK-Yaxcl27cmNQ-ZsOXPICda9vJpjIEYvmLR3VBSTeT26vH_Ex1cnsY5YzAB8lTrGWlCEa10pMwkGhCscS_ctSmD70mB8WK-7YbG1KktRb4sezk2SihBOdfkmeF4R36j2xybqbFixR-OqXgdiK0ED7ChSuNgNW5CJ_1lgedXp9_kxwkJKZinKJbh2g0VoDmwRqgl6kS5lEA-MP3zS3rMm1i7YkGqaivLVhxDr1O2gwTBnQyRseM-BPTPmobyDtkLdtmQ9skm9WUU
2017-12-15 12:06:57.836 [  3] 0 AuthDelegate:onAuthStateChangeCalled:state=1,error=0
2017-12-15 12:06:57.839 [  1] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=PENDING
2017-12-15 12:06:57.871 [  1] I HTTP2Transport:setupDownchannelStream:url=https\://avs-alexa-na.amazon.com/v20160207/directives
2017-12-15 12:06:57.884 [  1] 0 HTTP2StreamPool:getStream:streamId=1,numAcquiredStreams=1
2017-12-15 12:06:57.898 [  4] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=1
King AVSConnectionManager::onConnectionStatusChanged: status = 1, reason=0
2017-12-15 12:06:57.902 [  5] 0 ContextManager:updateStateLocked:action=updatedState,state={"wakeword" \: ""},namespace=SpeechRecognizer,name=RecognizerState
2017-12-15 12:06:57.907 [  4] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
2017-12-15 12:06:57.910 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"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"\:""}}]}
2017-12-15 12:06:57.916 [  6] 0 EventBuilder:buildJsonEventString:messageId=ccc802be-8eae-4c71-8892-b0bddb78d5e4,namespace=System,name=SynchronizeState
2017-12-15 12:06:57.923 [  6] 0 PostConnectSynchronize:onContextAvailable : Send PostConnectMessage to transport
2017-12-15 12:06:59.249 [  7] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 060fe8fffeb4a200-00000641-000323e8-ea97763eb3b6fd29-5c76a2d2-1
2017-12-15 12:06:59.258 [  7] 0 HTTP2Transport:processNextOutgoingMessage
2017-12-15 12:06:59.264 [  7] 0 HTTP2StreamPool:getStream:streamId=3,numAcquiredStreams=2
2017-12-15 12:06:59.271 [  7] I HTTP2Transport:insertActiveStream:handle=0xb06f01c0

	^^^^^^ ______ ^^^^^^ HTTP2Transport::processNextOutgoingMessage insertActiveStream id= 3

2017-12-15 12:07:00.704 [  7] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 060fe8fffeb4a200-00000641-000323e8-ea97763eb3b6fd29-5c76a2d2-3
2017-12-15 12:07:00.713 [  7] 0 PostConnectSynchronize:onSendCompleted:status=SUCCESS_NO_CONTENT
2017-12-15 12:07:00.726 [  7] 0 PostConnectSynchronize:onConnected()
2017-12-15 12:07:00.731 [  7] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED
King AVSConnectionManager::onConnectionStatusChanged: status = 2, reason=0
*** AudioInputProcessor::executeRecognize initiatorPayloadJson=
2017-12-15 12:07:00.737 [  7] 0 HTTP2Transport:cleanupFinishedStream:streamId=3,result=204

	^^^^^^ ______ ^^^^^^ HTTP2Transport::releaseStream  id = 3

2017-12-15 12:07:00.740 [  5] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING
2017-12-15 12:07:00.740 [  7] 0 HTTP2StreamPool:releaseStream:streamId=3,numAcquiredStreams=1
2017-12-15 12:07:00.740 [  7] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
m_expectingSpeechTimer.stop...
2017-12-15 12:07:00.741 [  8] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING
2017-12-15 12:07:00.742 [  6] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"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"\:""}}]}
2017-12-15 12:07:00.743 [  5] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context"\:[{"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"\:""}}]}
2017-12-15 12:07:00.744 [  5] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=e31ab022-d063-4d79-a19e-c1b603375356
2017-12-15 12:07:00.745 [  5] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId
2017-12-15 12:07:00.746 [  5] 0 EventBuilder:buildJsonEventString:messageId=3355434d-d3be-4add-8e78-a7e7539146b6,namespace=SpeechRecognizer,name=Recognize
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-12-15 12:07:00.749 [  5] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND
AVSConnectionManager::sendMessage {"context":[{"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":""}}],"event":{"header":{"namespace":"SpeechRecognizer","name":"Recognize","messageId":"3355434d-d3be-4add-8e78-a7e7539146b6","dialogRequestId":"e31ab022-d063-4d79-a19e-c1b603375356"},"payload":{"profile":"CLOSE_TALK","format":"AUDIO_L16_RATE_16000_CHANNELS_1","initiator":{"type":"PRESS_AND_HOLD","payload":{}}}}}
2017-12-15 12:07:00.750 [  5] 0 AudioInputProcessor:stopCapture:stopImmediately=false
2017-12-15 12:07:00.751 [  5] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY
2017-12-15 12:07:00.752 [  8] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING
2017-12-15 12:07:00.844 [  7] 0 HTTP2Transport:processNextOutgoingMessage
2017-12-15 12:07:00.845 [  7] 0 HTTP2StreamPool:getStream:streamId=5,numAcquiredStreams=2
2017-12-15 12:07:00.846 [  7] I HTTP2Transport:insertActiveStream:handle=0xb06f01c0

	^^^^^^ ______ ^^^^^^ HTTP2Transport::processNextOutgoingMessage insertActiveStream id= 5

2017-12-15 12:07:01.744 [  7] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-12-15 12:07:03.660 [  7] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 060fe8fffeb4a200-00000641-000323e8-ea97763eb3b6fd29-5c76a2d2-5
2017-12-15 12:07:03.944 [  9] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"821fae73-82b7-4c64-9485-65721d5935be"\,"dialogRequestId"\:"e31ab022-d063-4d79-a19e-c1b603375356"}\,"payload"\:{"url"\:"cid\:SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927_967581272"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927"}}}
2017-12-15 12:07:03.947 [  a] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"Speak"\,"messageId"\:"821fae73-82b7-4c64-9485-65721d5935be"\,"dialogRequestId"\:"e31ab022-d063-4d79-a19e-c1b603375356"}\,"payload"\:{"url"\:"cid\:SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927_967581272"\,"format"\:"AUDIO_MPEG"\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927"}}}
2017-12-15 12:07:03.948 [  a] I DirectiveRouter:preHandleDirective:messageId=821fae73-82b7-4c64-9485-65721d5935be,action=calling
2017-12-15 12:07:03.949 [  a] 0 CapabilityAgent:addingMessageIdToMap:messageId=821fae73-82b7-4c64-9485-65721d5935be
2017-12-15 12:07:03.954 [  4] 0 SpeechSynthesizer:executePreHandle:messageId=821fae73-82b7-4c64-9485-65721d5935be
2017-12-15 12:07:03.954 [  b] I DirectiveRouter:handleDirective:messageId=821fae73-82b7-4c64-9485-65721d5935be,action=calling
2017-12-15 12:07:03.966 [  7] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS
2017-12-15 12:07:03.966 [  7] 0 HTTP2Transport:cleanupFinishedStream:streamId=5,result=200

	^^^^^^ ______ ^^^^^^ HTTP2Transport::releaseStream  id = 5

2017-12-15 12:07:03.967 [  4] 0 SpeechSynthesizer:executeHandle:messageId=821fae73-82b7-4c64-9485-65721d5935be
2017-12-15 12:07:03.967 [  7] 0 HTTP2StreamPool:releaseStream:streamId=5,numAcquiredStreams=1
			 AudioInputProcessor::executeOnFocusChanged***********************
2017-12-15 12:07:03.969 [  c] 0 SpeechSynthesizer:onFocusChanged:newFocus=FOREGROUND
2017-12-15 12:07:03.969 [  5] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE
2017-12-15 12:07:03.970 [  5] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus
executeResetState  m_expectingSpeechTimer.stop...
2017-12-15 12:07:03.970 [  5] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE
TestSpeechSynthesizerObserver::onStateChanged  currentSpeechSynthesizerState: 1, newState = 2
2017-12-15 12:07:03.971 [  4] 0 SpeechSynthesizer:executeStateChange:newState=PLAYING
2017-12-15 12:07:03.973 [  2] 0 MediaPlayer:handleSetSourceCalled
2017-12-15 12:07:03.974 [  2] E MediaPlayer:saveOffsetBeforeTeardown - gst_element_query_position failed
>>>>>>>>>>>MediaPlayer::play 1
>>>>>>>>>>>MediaPlayer::play 2
2017-12-15 12:07:04.022 [  2] 0 MediaPlayer:handlePlayCalled:idPassed=1,currentId=1
2017-12-15 12:07:04.023 [  2] 0 MediaPlayer:handlePlay:attemptBuffering=0
ACDB -> found 0 form factor & soundcard independant files
ACDB -> Load file: /etc//Bluetooth_cal.acdb
ACDB -> Load file: /etc//General_cal.acdb
ACDB -> Load file: /etc//Global_cal.acdb
ACDB -> Load file: /etc//Handset_cal.acdb
ACDB -> Load file: /etc//Hdmi_cal.acdb
ACDB -> Load file: /etc//Headset_cal.acdb
ACDB -> Load file: /etc//Speaker_cal.acdb
ACDB -> Load file: /etc//workspaceFile.qwsp
ACDB -> ACDB_CMD_INITIALIZE_V2
[ACDB Command]->SW Minor/Major/Revision version info for /etc//Bluetooth_cal.acdb
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
[ACDB Command]->SW Minor/Major/Revision version info for /etc//General_cal.acdb
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
[ACDB Command]->SW Minor/Major/Revision version info for /etc//Global_cal.acdb
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
[ACDB Command]->SW Minor/Major/Revision version info for /etc//Handset_cal.acdb
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
[ACDB Command]->SW Minor/Major/Revision version info for /etc//Hdmi_cal.acdb
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
[ACDB Command]->SW Minor/Major/Revision version info for /etc//Headset_cal.acdb
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
[ACDB Command]->SW Minor/Major/Revision version info for /etc//Speaker_cal.acdb
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
[ACDB Command]->SW Minor/Major/Revision version info for /etc//workspaceFile.qwsp
[ACDB Command]->ACDB Sw Major = 9, ACDB Sw Minor = 0, ACDB Sw Revision = 4, ACDB Sw Cpl Number = 0
[ACDB Command]->ACDB File Major = 9, ACDB File Minor = 0, ACDB File Revision = 11
ACDB -> ACPH INIT
[ACPH]->Online service registered with ACPH
[ACPH]->ACPH init success
ACDB -> RTAC INIT
[ACPH]->DSP RTC service registered with ACPH
ACDB -> ADIE RTAC INIT
[ACPH]->ADIE RTC service registered with ACPH
ACDB -> ACDB_CMD_GET_VOC_PROC_DYNAMIC_TABLE_SIZE
ACDB -> send_common_custom_topology
ACDB -> ACDB_CMD_GET_AVCS_CUSTOM_TOPO_INFO
ACDB -> ACDB_CMD_GET_AVCS_CUSTOM_TOPO_INFO: size:0x74 ret=0
ACDB -> CORE_CUSTOM_TOPOLOGIES
ACDB -> acdb_loader_send_common_custom_topology: Common custom topology in useACDB -> init done!
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001A
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001A
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001A
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001B
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001B
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001B
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001C
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001C
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001C
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001D
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001D
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001D
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001E
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001E
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001E
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001F
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001F
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 0000001F
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000067
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000067
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000067
Error: ACDB ANC returned = -19
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000056
Error: ACDB ANC returned = -20
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000056
Error: ACDB ANC returned = -20
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000056
Error: ACDB ANC returned = -20
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000059
Error: ACDB ANC returned = -20
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000059
Error: ACDB ANC returned = -20
ACDB -> ACDB_CMD_GET_ANC_SETTING
Failed to fetch the lookup information of the device 00000059
Error: ACDB ANC returned = -20
send mbhc data
ACDB -> MBHC ACDB_PID_GENERAL_CONFIG
ACDB -> MBHC ACDB_PID_PLUG_REMOVAL_DETECTION
ACDB -> MBHC ACDB_PID_PLUG_TYPE_DETECTION
ACDB -> MBHC ACDB_PID_BUTTON_PRESS_DETECTION
ACDB -> MBHC ACDB_PID_IMPEDANCE_DETECTION
send vbat data
ACDB -> VBAT ACDB_PID_ADC_CAL
ACDB -> VBAT ACDB_PID_GAIN_PROC
send vbat data, calling convert_vbat_data
Vbat Registers Size: 17
copied vbat cal size =72
2017-12-15 12:07:04.647 [  2] 0 MediaPlayer:handlePlay:startingState=PLAYING,stateReturn=ASYNC
2017-12-15 12:07:04.650 [  2] I InProcessAttachmentReader:readFailed:reason=SDS is closed
2017-12-15 12:07:04.767 [  2] 0 MediaPlayer:callingOnTags
2017-12-15 12:07:04.768 [  2] 0 MediaPlayer:callingOnTags
2017-12-15 12:07:04.774 [  2] 0 MediaPlayer:callingOnPlaybackStarted:currentId=1
2017-12-15 12:07:04.776 [  4] 0 SpeechSynthesizer:executePlaybackStarted
2017-12-15 12:07:04.776 [  4] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-12-15 12:07:04.777 [  2] 0 MediaPlayer:handleGetOffsetCalled:idPassed=1,currentId=1
2017-12-15 12:07:04.779 [  4] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"PLAYING"},namespace=SpeechSynthesizer,name=SpeechState
TestSpeechSynthesizerObserver::onStateChanged  currentSpeechSynthesizerState: 2, newState = 0
2017-12-15 12:07:04.779 [  8] 0 DialogUXStateAggregator:setState:from=THINKING,to=SPEAKING
2017-12-15 12:07:04.780 [  4] 0 EventBuilder:buildJsonEventString:messageId=f254241d-4404-41c6-a79b-fe12eda2ed39,namespace=SpeechSynthesizer,name=SpeechStarted
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"SpeechSynthesizer","name":"SpeechStarted","messageId":"f254241d-4404-41c6-a79b-fe12eda2ed39"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:NotificationsV4#ACRI#SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927"}}}
ACDB -> send_audio_cal, acdb_id = 14, path = 0, app id = 0x11131, 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 = 16
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-12-15 12:07:04.874 [  7] 0 HTTP2Transport:processNextOutgoingMessage
2017-12-15 12:07:04.874 [  7] 0 HTTP2StreamPool:getStream:streamId=7,numAcquiredStreams=2
2017-12-15 12:07:04.875 [  7] I HTTP2Transport:insertActiveStream:handle=0xb06f01c0

	^^^^^^ ______ ^^^^^^ HTTP2Transport::processNextOutgoingMessage insertActiveStream id= 7

2017-12-15 12:07:05.058 [  2] 0 MediaPlayer:callingOnTags
2017-12-15 12:07:05.237 [  7] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 060fe8fffeb4a200-00000641-000323e8-ea97763eb3b6fd29-5c76a2d2-7
2017-12-15 12:07:05.239 [  7] 0 HTTP2Transport:cleanupFinishedStream:streamId=7,result=204

	^^^^^^ ______ ^^^^^^ HTTP2Transport::releaseStream  id = 7

2017-12-15 12:07:05.252 [  7] 0 HTTP2StreamPool:releaseStream:streamId=7,numAcquiredStreams=1
2017-12-15 12:07:05.254 [  7] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-12-15 12:07:07.722 [  2] 0 MediaPlayer:callingOnPlaybackFinished:currentId=1
2017-12-15 12:07:07.725 [  4] 0 SpeechSynthesizer:executePlaybackFinished
2017-12-15 12:07:07.726 [  4] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=0
2017-12-15 12:07:07.727 [  2] 0 MediaPlayer:saveOffsetBeforeTeardown:offset=2592
2017-12-15 12:07:07.727 [  4] 0 ContextManager:updateStateLocked:action=updatedState,state={"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#ACRI#SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927"\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespace=SpeechSynthesizer,name=SpeechState
TestSpeechSynthesizerObserver::onStateChanged  currentSpeechSynthesizerState: 0, newState = 1
2017-12-15 12:07:07.730 [  4] 0 EventBuilder:buildJsonEventString:messageId=cb8ad698-50cd-42df-a58f-0a02a0fc9b68,namespace=SpeechSynthesizer,name=SpeechFinished
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"SpeechSynthesizer","name":"SpeechFinished","messageId":"cb8ad698-50cd-42df-a58f-0a02a0fc9b68"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:NotificationsV4#ACRI#SetReminderPrompt-91d13782-29c0-4462-b7f1-95f692cfa927"}}}
2017-12-15 12:07:07.733 [  4] 0 DirectiveProcessor:onHandlingCompeted:messageId=821fae73-82b7-4c64-9485-65721d5935be,directiveBeingPreHandled=(nullptr)
2017-12-15 12:07:07.736 [  4] 0 CapabilityAgent:removingMessageIdFromMap:messageId=821fae73-82b7-4c64-9485-65721d5935be
2017-12-15 12:07:07.782 [  7] 0 HTTP2Transport:processNextOutgoingMessage
2017-12-15 12:07:07.784 [  7] 0 HTTP2StreamPool:getStream:streamId=9,numAcquiredStreams=2
2017-12-15 12:07:07.787 [  7] I HTTP2Transport:insertActiveStream:handle=0xb06f01c0

	^^^^^^ ______ ^^^^^^ HTTP2Transport::processNextOutgoingMessage insertActiveStream id= 9

2017-12-15 12:07:07.933 [  8] 0 DialogUXStateAggregator:setState:from=SPEAKING,to=IDLE
2017-12-15 12:07:07.937 [  c] 0 SpeechSynthesizer:onFocusChanged:newFocus=NONE
2017-12-15 12:07:08.347 [  9] 0 MessageInterpreter:receive:messageId=e2314fe2-5e57-490e-972b-dd2c62c5f9f6:No dialogRequestId attached to message.
2017-12-15 12:07:08.349 [  9] I DirectiveSequencer:onDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"Alerts"\,"name"\:"SetAlert"\,"messageId"\:"e2314fe2-5e57-490e-972b-dd2c62c5f9f6"}\,"payload"\:{"type"\:"REMINDER"\,"scheduledTime"\:"2017-12-19T12\:12\:10+0000"\,"assets"\:[{"assetId"\:"ed7edb59-6b25-323a-a878-a96032d0f11f"\,"url"\:"https\://s3.amazonaws.com/deeappservice.prod.usamazon.reminder.earcons/echo_system_alerts_reminder_start_v01.mp3"}\,{"assetId"\:"9f855ff5-0419-3457-9b3d-b137e5d828cb"\,"url"\:"https\://tinytts.amazon.com/2/d0da99f5-e4b5-11e7-af16-3b6682c4c587-ae6649/3/1513771920216/d9762ccd1cf04fcd0978e8976132d673bb4226feedaef95f3ec6a24eb3290ff9/resource.mp3"}]\,"assetPlayOrder"\:["ed7edb59-6b25-323a-a878-a96032d0f11f"\,"9f855ff5-0419-3457-9b3d-b137e5d828cb"]\,"loopCount"\:2\,"loopPauseInMilliSeconds"\:6000\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#DNID#ee4e4efa-c520-3389-a792-638d16602f34"\,"backgroundAlertAsset"\:"ed7edb59-6b25-323a-a878-a96032d0f11f"}}}
2017-12-15 12:07:08.351 [  a] I DirectiveRouter:preHandleDirective:UnparsedDirective={"directive"\:{"header"\:{"namespace"\:"Alerts"\,"name"\:"SetAlert"\,"messageId"\:"e2314fe2-5e57-490e-972b-dd2c62c5f9f6"}\,"payload"\:{"type"\:"REMINDER"\,"scheduledTime"\:"2017-12-19T12\:12\:10+0000"\,"assets"\:[{"assetId"\:"ed7edb59-6b25-323a-a878-a96032d0f11f"\,"url"\:"https\://s3.amazonaws.com/deeappservice.prod.usamazon.reminder.earcons/echo_system_alerts_reminder_start_v01.mp3"}\,{"assetId"\:"9f855ff5-0419-3457-9b3d-b137e5d828cb"\,"url"\:"https\://tinytts.amazon.com/2/d0da99f5-e4b5-11e7-af16-3b6682c4c587-ae6649/3/1513771920216/d9762ccd1cf04fcd0978e8976132d673bb4226feedaef95f3ec6a24eb3290ff9/resource.mp3"}]\,"assetPlayOrder"\:["ed7edb59-6b25-323a-a878-a96032d0f11f"\,"9f855ff5-0419-3457-9b3d-b137e5d828cb"]\,"loopCount"\:2\,"loopPauseInMilliSeconds"\:6000\,"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#DNID#ee4e4efa-c520-3389-a792-638d16602f34"\,"backgroundAlertAsset"\:"ed7edb59-6b25-323a-a878-a96032d0f11f"}}}
2017-12-15 12:07:08.352 [  a] I DirectiveRouter:preHandleDirective:messageId=e2314fe2-5e57-490e-972b-dd2c62c5f9f6,action=calling
2017-12-15 12:07:08.353 [  a] 0 CapabilityAgent:addingMessageIdToMap:messageId=e2314fe2-5e57-490e-972b-dd2c62c5f9f6
2017-12-15 12:07:08.354 [  b] I DirectiveRouter:handleDirective:messageId=e2314fe2-5e57-490e-972b-dd2c62c5f9f6,action=calling
2017-12-15 12:07:08.452 [  7] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 060fe8fffeb4a200-00000641-000323e8-ea97763eb3b6fd29-5c76a2d2-9
2017-12-15 12:07:08.453 [  7] 0 HTTP2Transport:cleanupFinishedStream:streamId=9,result=204

	^^^^^^ ______ ^^^^^^ HTTP2Transport::releaseStream  id = 9

2017-12-15 12:07:08.454 [  7] 0 HTTP2StreamPool:releaseStream:streamId=9,numAcquiredStreams=1
2017-12-15 12:07:08.454 [  7] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-12-15 12:07:08.481 [  d] 0 ContextManager:updateStateLocked:action=updatedState,state={"allAlerts"\:[{"token"\:"amzn1.as-ct.v1.Domain\:Application\:NotificationsV4#DNID#ee4e4efa-c520-3389-a792-638d16602f34"\,"type"\:"REMINDER"\,"scheduledTime"\:"2017-12-19T12\:12\:10+0000"}]\,"activeAlerts"\:[]},namespace=Alerts,name=AlertsState
2017-12-15 12:07:08.482 [  d] 0 EventBuilder:buildJsonEventString:messageId=88360f3f-62d3-4098-b2dc-3ba0ffab9e13,namespace=Alerts,name=SetAlertSucceeded
AVSConnectionManager::sendMessage {"event":{"header":{"namespace":"Alerts","name":"SetAlertSucceeded","messageId":"88360f3f-62d3-4098-b2dc-3ba0ffab9e13"},"payload":{"token":"amzn1.as-ct.v1.Domain:Application:NotificationsV4#DNID#ee4e4efa-c520-3389-a792-638d16602f34"}}}
Wait Alert set success...
Wait Alert ready...
2017-12-15 12:07:08.555 [  7] 0 HTTP2Transport:processNextOutgoingMessage
2017-12-15 12:07:08.555 [  7] 0 HTTP2StreamPool:getStream:streamId=11,numAcquiredStreams=2
2017-12-15 12:07:08.556 [  7] I HTTP2Transport:insertActiveStream:handle=0xb06f01c0

	^^^^^^ ______ ^^^^^^ HTTP2Transport::processNextOutgoingMessage insertActiveStream id= 11

2017-12-15 12:07:08.977 [  7] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 060fe8fffeb4a200-00000641-000323e8-ea97763eb3b6fd29-5c76a2d2-11
2017-12-15 12:07:08.982 [  7] 0 HTTP2Transport:cleanupFinishedStream:streamId=11,result=204

	^^^^^^ ______ ^^^^^^ HTTP2Transport::releaseStream  id = 11

2017-12-15 12:07:08.995 [  7] 0 HTTP2StreamPool:releaseStream:streamId=11,numAcquiredStreams=1
2017-12-15 12:07:08.996 [  7] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
Sleep start...
Sleep end...
2017-12-15 12:07:53.517 [  1] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=DISCONNECTED
King HTTP2Transport::setIsStoppingLocked disconnectReason = 0
King AVSConnectionManager::onConnectionStatusChanged: status = 0, reason=0
2017-12-15 12:07:53.518 [  1] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
King HTTP2Transport::setIsStoppingLocked disconnectReason = 10

	^^^^^^ ______ ^^^^^^ HTTP2Transport::releaseStream  id = 1

2017-12-15 12:07:53.589 [  7] 0 HTTP2StreamPool:releaseStream:streamId=1,numAcquiredStreams=0
2017-12-15 12:07:53.596 [  7] 0 PostConnectSynchronize:onDisconnected()
2017-12-15 12:07:53.596 [  7] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
executeResetState  m_expectingSpeechTimer.stop...
2017-12-15 12:07:53.605 [  1] I DirectiveSequencer:doShutdown
2017-12-15 12:07:53.612 [  1] I DirectiveRouter:removeDirectiveHandlers:action=removed,namespace=Alerts,name=DeleteAlert,handler=0x36c338,policy=NON_BLOCKING
2017-12-15 12:07:53.612 [  1] I DirectiveRouter:removeDirectiveHandlers:action=removed,namespace=Alerts,name=SetAlert,handler=0x36c338,policy=NON_BLOCKING
2017-12-15 12:07:53.614 [  1] I DirectiveRouter:removeDirectiveHandlers:action=removed,namespace=SpeechSynthesizer,name=Speak,handler=0x331590,policy=BLOCKING
2017-12-15 12:07:53.615 [  1] I DirectiveRouter:onDeregisteredCalled:handler=0x36c338
2017-12-15 12:07:53.615 [  1] I DirectiveRouter:onDeregisteredCalled:handler=0x331590
2017-12-15 12:07:53.616 [  2] 0 MediaPlayer:handleSetObserverCalled
2017-12-15 12:07:53.632 [  1] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=
2017-12-15 12:07:53.643 [  e] I CertifiedSender:CertifiedSender worker thread done.  exiting mainloop.
2017-12-15 12:07:53.650 [  1] E RequiresShutdown:~RequiresShutdownFailed:reason=notShutdown,name=MessageRouter
[       OK ] AlertsTest.handleOneTimerWithLocalStop (57619 ms)
[----------] 1 test from AlertsTest (57619 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (57620 ms total)
[  PASSED  ] 1 test.
2017-12-15 12:07:53.688 [  1] W RequiresShutdown:ShutdownMonitor:reason=no shutdown() call,name: =
2017-12-15 12:07:53.688 [  1] W RequiresShutdown:ShutdownMonitor:reason=never deleted,name=
/usr/nut2_avs #