search

alexa / avs-device-sdk

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

Bluetooth Issue: Audio issue when music is already played on device using BT and avs-sdk comes up #1265

Closed sumit3817 closed 4 years ago

sumit3817 commented 5 years ago

Hello AVS Team,

I am facing the issue with audio. Scenario: The music is already played on device via Bluetooth. I start run avs-device-sdk (1.9 build with bluetooth), avs-device-sdk comes up but the bluetooth songs stopped. And I am not able to play any audio file using mplayer. It gives me the following error:- Failed to load cookie file from cookie: No such file or directory AO: [pulse] 22050Hz 2ch s16le (2 bytes per sample) Video: no video Starting playback... A: 0.0 (00.0) of 2.0 (02.0) ??,?% Audio device got stuck! A: 0.3 (00.3) of 2.0 (02.0) ??,?% Audio device got stuck! A: 0.3 (00.3) of 2.0 (02.0) ??,?% Audio device got stuck!

Following are the avs-device-sdk critical logs:-

Running app with log level: DEBUG9 2019-03-08 06:57:54.384 [ 1] 0 ConfigurationNode:initializeSuccess:configuration={"cblAuthDelegate"\:{"databaseFilePath"\:"/root/magicbox/alexa_magicbox_1.9/db/cblAuth} 2019-03-08 06:57:54.401 [ 1] 9 MediaPlayer:createCalled 2019-03-08 06:57:55.003 [ 1] I MediaPlayer:outputConversion:string=audio/x-raw\, format\=(string)S16LE 2019-03-08 06:57:55.034 [ 1] 9 MediaPlayer:createCalled 2019-03-08 06:57:55.037 [ 1] I MediaPlayer:outputConversion:string=audio/x-raw\, format\=(string)S16LE 2019-03-08 06:57:55.043 [ 1] 9 MediaPlayer:createCalled 2019-03-08 06:57:55.045 [ 1] I MediaPlayer:outputConversion:string=audio/x-raw\, format\=(string)S16LE 2019-03-08 06:57:55.052 [ 1] 9 MediaPlayer:createCalled 2019-03-08 06:57:55.053 [ 1] I MediaPlayer:outputConversion:string=audio/x-raw\, format\=(string)S16LE 2019-03-08 06:57:55.058 [ 1] 9 MediaPlayer:createCalled 2019-03-08 06:57:55.059 [ 1] I MediaPlayer:outputConversion:string=audio/x-raw\, format\=(string)S16LE 2019-03-08 06:57:55.066 [ 1] 9 MediaPlayer:createCalled 2019-03-08 06:57:55.066 [ 1] I MediaPlayer:outputConversion:string=audio/x-raw\, format\=(string)S16LE 2019-03-08 06:57:55.074 [ 1] 5 SQLiteBluetoothStorage:create 2019-03-08 06:57:55.079 [ 1] 5 CBLAuthDelegate:create 2019-03-08 06:57:55.082 [ 1] 5 CBLAuthDelegate:CBLAuthDelegate 2019-03-08 06:57:55.082 [ 1] 5 CBLAuthDelegate:init 2019-03-08 06:57:55.083 [ 1] 5 CBLAuthDelegateConfiguration:create 2019-03-08 06:57:55.083 [ 1] 5 CBLAuthDelegateConfiguration:init 2019-03-08 06:57:55.083 [ 1] 5 CBLAuthDelegateConfiguration:initScopeData 2019-03-08 06:57:55.084 [ 1] 9 CBLAuthDelegateConfiguration:initScopeDataSucceeded:scopeData={"alexa\:all"\:{"productID"\:"13131313"\,"productInstanceAttributes"\:{"de} 2019-03-08 06:57:55.084 [ 1] 5 SQLiteCBLAuthDelegateStorage:open 2019-03-08 06:57:55.090 [ 2] 5 CBLAuthDelegate:handleAuthorizationFlow 2019-03-08 06:57:55.090 [ 2] 5 CBLAuthDelegate:handleStarting 2019-03-08 06:57:55.091 [ 2] 5 SQLiteCBLAuthDelegateStorage:getRefreshToken 2019-03-08 06:57:55.092 [ 2] 5 CBLAuthDelegate:handleRefreshingToken 2019-03-08 06:57:55.093 [ 2] 5 CBLAuthDelegate:requestRefresh 2019-03-08 06:57:55.096 [ 1] 5 CBLAuthDelegate:addAuthObserver:observer=0x492d84 2019-03-08 06:57:55.098 [ 1] 5 CBLAuthDelegate:addAuthObserver:observer=0x44b290 2019-03-08 06:57:55.100 [ 1] 5 CapabilitiesDelegate:addCapabilitiesObserver:observer=0x44b294 2019-03-08 06:57:55.106 [ 1] 5 InternetConnectionMonitor:startMonitoring 2019-03-08 06:57:55.119 [ 3] 5 InternetConnectionMonitor:testConnection 2019-03-08 06:57:55.217 [ 1] 9 MediaPlayer:setObserverCalled 2019-03-08 06:57:55.217 [ 4] 0 MediaPlayer:handleSetObserverCalled 2019-03-08 06:57:55.220 [ 1] 9 SpeechSynthesizer:addObserver:observer=0x45fc14 2019-03-08 06:57:55.225 [ 1] 9 PlaybackRouter:create::called 2019-03-08 06:57:55.230 [ 1] 9 MediaPlayer:setObserverCalled 2019-03-08 06:57:55.231 [ 5] 0 MediaPlayer:handleSetObserverCalled 2019-03-08 06:57:55.235 [ 1] 9 MediaPlayer:getSpeakerTypeCalled 2019-03-08 06:57:55.237 [ 1] 9 MediaPlayer:getSpeakerTypeCalled 2019-03-08 06:57:55.239 [ 1] 9 MediaPlayer:getSpeakerTypeCalled 2019-03-08 06:57:55.239 [ 1] 9 MediaPlayer:getSpeakerTypeCalled 2019-03-08 06:57:55.239 [ 1] 9 MediaPlayer:getSpeakerTypeCalled 2019-03-08 06:57:55.239 [ 1] 9 MediaPlayer:getSpeakerTypeCalled 2019-03-08 06:57:55.241 [ 1] 0 SpeakerManager:mapCreated:numSpeakerVolume=5,numAlertsVolume=1 2019-03-08 06:57:55.242 [ 1] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:55.243 [ 4] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:55.243 [ 1] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:55.244 [ 5] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:55.244 [ 1] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:55.244 [ 6] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:55.244 [ 1] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:55.244 [ 7] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:55.244 [ 1] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:55.245 [ 8] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:55.245 [ 1] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true 2019-03-08 06:57:55.245 [ 1] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false 2019-03-08 06:57:55.246 [ 1] 9 SpeakerManager:updateContextManagerCalled:speakerType=AVS_SPEAKER_VOLUME 2019-03-08 06:57:55.249 [ 1] 9 MediaPlayer:setObserverCalled 2019-03-08 06:57:55.249 [ 9] 0 MediaPlayer:handleSetObserverCalled 2019-03-08 06:57:55.256 [ 1] 9 AlertScheduler:setTimerForNextAlertLocked 2019-03-08 06:57:55.257 [ 1] 9 AlertScheduler:executeScheduleNextAlertForRendering::no work to do. 2019-03-08 06:57:55.257 [ 1] 9 SpeakerManager:getSpeakerSettingsCalled 2019-03-08 06:57:55.259 [ a] 9 SpeakerManager:executeGetSpeakerSettingsCalled 2019-03-08 06:57:55.259 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:55.259 [ 9] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:55.260 [ a] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true 2019-03-08 06:57:55.260 [ a] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false 2019-03-08 06:57:55.264 [ 1] 9 SpeakerManager:addSpeakerManagerObserverCalled 2019-03-08 06:57:55.264 [ b] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2019-03-08 06:57:55.265 [ 1] 9 SpeakerManager:addSpeakerManagerObserver:observer=0x4dfa6c 2019-03-08 06:57:55.266 [ 1] 5 NotificationsRenderer:create 2019-03-08 06:57:55.267 [ 1] 9 MediaPlayer:setObserverCalled 2019-03-08 06:57:55.267 [ 6] 0 MediaPlayer:handleSetObserverCalled 2019-03-08 06:57:55.270 [ 1] 5 NotificationsCapabilityAgent:init 2019-03-08 06:57:55.270 [ 1] 5 NotificationsRenderer:addObserver 2019-03-08 06:57:55.274 [ c] 5 NotificationsCapabilityAgent:executeInit 2019-03-08 06:57:55.275 [ c] 5 NotificationsCapabilityAgent:notifyObservers:indicatorState=0 2019-03-08 06:57:55.276 [ c] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=false,stateRequestToken=0 2019-03-08 06:57:55.276 [ 1] 5 InteractionModel:InteractionModelCapabilityAgent 2019-03-08 06:57:55.278 [ c] 9 ContextManager:updateStateLocked:action=updatedState,state={"isEnabled"\:false\,"isVisualIndicatorPersisted"\:false},namespace=Notificate 2019-03-08 06:57:55.288 [ 1] 0 ExternalMediaPlayer:createAdapters 2019-03-08 06:57:55.297 [ 1] 1 AudioPlayer:addObserver 2019-03-08 06:57:55.300 [ d] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE 2019-03-08 06:57:55.303 [ 1] 5 BlueZDeviceManager:create 2019-03-08 06:57:55.305 [ 1] 5 BlueZDeviceManager:init 2019-03-08 06:57:55.305 [ 1] 5 BlueZDeviceManager:Creating connection... 2019-03-08 06:57:55.322 [ 1] 5 BlueZDeviceManager:Creating ObjectManagerProxy... 2019-03-08 06:57:55.332 [ 1] 5 BlueZDeviceManager:Retrieving BlueZ state... 2019-03-08 06:57:55.339 [ 1] 3 BlueZDeviceManager:Found bluetooth adapter:Path=/org/bluez/hci0 2019-03-08 06:57:55.339 [ 1] 5 BlueZBluetoothDevice:create 2019-03-08 06:57:55.341 [ 1] 5 BlueZBluetoothDevice:init:path=/org/bluez/hci0/dev_60_9A_C1_E3_29_19 2019-03-08 06:57:55.352 [ 1] 5 BlueZBluetoothDevice:updateFriendlyName 2019-03-08 06:57:55.352 [ 1] 9 DBusPropertiesProxy:getStringProperty:object=/org/bluez/hci0/dev_60_9A_C1_E3_29_19,interface=org.bluez.Device1,property=Alias 2019-03-08 06:57:55.354 [ 1] 5 BlueZBluetoothDevice:queryDeviceProperty:name=Paired 2019-03-08 06:57:55.355 [ 1] 5 BlueZBluetoothDevice:init::deviceIsPaired 2019-03-08 06:57:55.355 [ 1] 5 BlueZBluetoothDevice:getServiceUuids 2019-03-08 06:57:55.356 [ 1] 5 DBusPropertiesProxy:getVariantProperty 2019-03-08 06:57:55.357 [ 1] 5 BlueZBluetoothDevice:getServiceUuids 2019-03-08 06:57:55.358 [ 1] 5 BlueZBluetoothDevice:operator():uuid=00000000-deca-fade-deca-deafdecacafe 2019-03-08 06:57:55.359 [ 1] 5 BlueZBluetoothDevice:operator():uuid=00001000-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.693 [ 1] 5 BlueZBluetoothDevice:operator():uuid=0000110a-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.693 [ 1] 5 BlueZBluetoothDevice:operator():uuid=0000110c-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.693 [ 1] 5 BlueZBluetoothDevice:operator():uuid=0000110d-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.693 [ 1] 5 BlueZBluetoothDevice:operator():uuid=0000110e-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.693 [ 1] 5 BlueZBluetoothDevice:operator():uuid=00001116-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.694 [ 1] 5 BlueZBluetoothDevice:operator():uuid=0000111f-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.694 [ 1] 5 BlueZBluetoothDevice:operator():uuid=0000112f-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.694 [ 1] 5 BlueZBluetoothDevice:operator():uuid=00001132-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.694 [ 1] 5 BlueZBluetoothDevice:operator():uuid=00001200-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.694 [ 1] 5 BlueZBluetoothDevice:operator():uuid=02030302-1d19-415f-86f2-22a2106a0a77 2019-03-08 06:57:55.694 [ 1] 5 BlueZBluetoothDevice:initializeServices 2019-03-08 06:57:55.695 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=0000110a-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.698 [ 1] 5 BlueZBluetoothDevice:initializeServices:supports=AudioSource 2019-03-08 06:57:55.708 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=00001000-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.708 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=00000000-deca-fade-deca-deafdecacafe 2019-03-08 06:57:55.708 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=00001200-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.708 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=0000110d-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.708 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=0000112f-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.708 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=02030302-1d19-415f-86f2-22a2106a0a77 2019-03-08 06:57:55.708 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=0000110e-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.709 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=00001116-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.709 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=0000111f-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.709 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=0000110c-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.709 [ 1] 5 BlueZBluetoothDevice:initializeServices:supports=A/V_RemoteControlTarget 2019-03-08 06:57:55.725 [ 1] 5 BlueZAVRCPTarget:create 2019-03-08 06:57:55.732 [ 1] 9 BlueZBluetoothDevice:initializeServices:supportedUUID=00001132-0000-1000-8000-00805f9b34fb 2019-03-08 06:57:55.744 [ 3] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed 2019-03-08 06:57:55.744 [ 1] 7 BlueZDeviceManager:addDevice 2019-03-08 06:57:55.744 [ 3] 5 InternetConnectionMonitor:updateConnectionStatus:connected=true 2019-03-08 06:57:55.744 [ 3] 5 InternetConnectionMonitor:notifyObserversLocked 2019-03-08 06:57:55.747 [ 3] 9 LibCurlHttpContentFetcher:~LibCurlHttpContentFetcher 2019-03-08 06:57:55.751 [ 1] 5 BlueZBluetoothDevice:getMac 2019-03-08 06:57:55.752 [ 1] 5 BlueZBluetoothDevice:getFriendlyName 2019-03-08 06:57:55.752 [ 1] 7 BlueZDeviceManager:Device added:path=/org/bluez/hci0/dev_60_9A_C1_E3_29_19,mac=60\:9A\:C1\:E3\:29\:19,alias=sumit 2019-03-08 06:57:55.753 [ 1] 5 BlueZDeviceManager:Initializing Host Controller... 2019-03-08 06:57:55.753 [ 1] 5 BlueZHostController:create:adapterObjectPath=/org/bluez/hci0 2019-03-08 06:57:55.755 [ 1] 5 BlueZHostController:init 2019-03-08 06:57:55.771 [ 1] 9 DBusPropertiesProxy:getStringProperty:object=/org/bluez/hci0,interface=org.bluez.Adapter1,property=Address 2019-03-08 06:57:55.773 [ 1] 9 DBusPropertiesProxy:getStringProperty:object=/org/bluez/hci0,interface=org.bluez.Adapter1,property=Alias 2019-03-08 06:57:55.775 [ 1] 5 BlueZHostController:adapterProperties:mac=28\:6D\:97\:42\:13\:AF,friendlyName=artik 2019-03-08 06:57:55.780 [ e] 5 BlueZDeviceManager:Connecting signals... 2019-03-08 06:57:55.781 [ e] 7 DBusConnection:Subscribed to signal:service=org.bluez,interface=org.freedesktop.DBus.ObjectManager,member=InterfacesAdded,result=19 2019-03-08 06:57:55.783 [ e] 7 DBusConnection:Subscribed to signal:service=org.bluez,interface=org.freedesktop.DBus.ObjectManager,member=InterfacesRemoved,result=20 2019-03-08 06:57:55.784 [ e] 7 DBusConnection:Subscribed to signal:service=org.bluez,interface=org.freedesktop.DBus.Properties,member=PropertiesChanged,result=21 2019-03-08 06:57:55.784 [ e] 5 BlueZDeviceManager:init::Initializing Bluetooth Media 2019-03-08 06:57:55.799 [ e] 5 DBusObjectBase:registerWithDBus 2019-03-08 06:57:55.800 [ e] 5 DBusObjectBase:Object registered:Object path=/com/amazon/alexa/sdk/sinkendpoint,Interface=org.bluez.MediaEndpoint1 2019-03-08 06:57:56.141 [ e] 5 BlueZDeviceManager:init::Initializing Pairing Agent 2019-03-08 06:57:56.161 [ e] 5 DBusObjectBase:registerWithDBus 2019-03-08 06:57:56.166 [ e] 5 DBusObjectBase:Object registered:Object path=/ACSDK/Bluetooth/Agent,Interface=org.bluez.Agent1 2019-03-08 06:57:56.180 [ e] 5 PairingAgent:registerAgent 2019-03-08 06:57:56.183 [ e] 5 PairingAgent:registerAgent::registerAgentDone 2019-03-08 06:57:56.183 [ e] 5 PairingAgent:requestDefaultAgent 2019-03-08 06:57:56.185 [ e] 5 PairingAgent:requestDefaultAgent::requestDefaultAgentSuccessful 2019-03-08 06:57:56.189 [ 1] 5 BlueZDeviceManager:BlueZDeviceManager initialized... 2019-03-08 06:57:56.191 [ 1] 5 Bluetooth:create 2019-03-08 06:57:56.200 [ 1] 5 Bluetooth:init 2019-03-08 06:57:56.200 [ 1] 5 SQLiteBluetoothStorage:open 2019-03-08 06:57:56.208 [ 1] 9 MediaPlayer:setObserverCalled 2019-03-08 06:57:56.208 [ 7] 0 MediaPlayer:handleSetObserverCalled 2019-03-08 06:57:56.209 [ 1] 5 BlueZHostController:getFriendlyName 2019-03-08 06:57:56.210 [ 1] 5 SQLiteBluetoothStorage:getMacToUuid 2019-03-08 06:57:56.210 [ 1] 5 SQLiteBluetoothStorage:getMappingsLocked:keyPreference=mac 2019-03-08 06:57:56.213 [ 1] 5 SQLiteBluetoothStorage:getSingleRowLocked 2019-03-08 06:57:56.214 [ 1] 5 SQLiteBluetoothStorage:getSingleRowLocked 2019-03-08 06:57:56.215 [ 1] I SQLiteBluetoothStorage:getSingleRowLocked:reason=getStepResultFailed 2019-03-08 06:57:56.215 [ 1] 5 BlueZDeviceManager:getDiscoveredDevices 2019-03-08 06:57:56.217 [ 1] 5 BlueZBluetoothDevice:getFriendlyName 2019-03-08 06:57:56.217 [ 1] 5 BlueZBluetoothDevice:getMac 2019-03-08 06:57:56.217 [ 1] 5 BlueZBluetoothDevice:isPaired 2019-03-08 06:57:56.218 [ f] 5 BlueZBluetoothDevice:executeIsPaired 2019-03-08 06:57:56.219 [ 1] 9 Bluetooth:executeUpdateContext:friendlyName=sumit,mac=60\:9A\:C1\:E3\:29\:19,paired=true 2019-03-08 06:57:56.219 [ 1] 5 BlueZBluetoothDevice:isPaired 2019-03-08 06:57:56.219 [ f] 5 BlueZBluetoothDevice:executeIsPaired 2019-03-08 06:57:56.219 [ 1] 5 BlueZBluetoothDevice:getMac 2019-03-08 06:57:56.219 [ 1] 5 BlueZBluetoothDevice:getFriendlyName 2019-03-08 06:57:56.220 [ 1] 5 BlueZBluetoothDevice:getSupportedServices 2019-03-08 06:57:56.224 [ 1] I Bluetooth:executeUpdateContext:buffer={"alexaDevice"\:{"friendlyName"\:"artik"}\,"pairedDevices"\:[{"uniqueDeviceId"\:"53dd1437-617d-454} 2019-03-08 06:57:56.238 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechSynthesizer,name=Speak,handler=0x501200,policy=BLOCKING 2019-03-08 06:57:56.240 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=ClearQueue,handler=0x500b00,policy=NON_BLOCKING 2019-03-08 06:57:56.241 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Stop,handler=0x500b00,policy=NON_BLOCKING 2019-03-08 06:57:56.241 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Play,handler=0x500b00,policy=NON_BLOCKING 2019-03-08 06:57:56.242 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=ExternalMediaPlayer,name=Play,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.242 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=ExternalMediaPlayer,name=Logout,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.242 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=ExternalMediaPlayer,name=Login,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.SeekController,name=SetSeekPosition,handler=0x4a5b00,policy=NON_BLOCKIG 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Play,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.FavoritesController,name=Unfavorite,handler=0x4a5b00,policy=NON_BLOCKIG 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=EnableShuffle,handler=0x4a5b00,policy=NON_BLOCG 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Pause,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Next,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Rewind,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=EnableRepeat,handler=0x4a5b00,policy=NON_BLOCKG 2019-03-08 06:57:56.243 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Previous,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.356 [ 2] 5 HttpPost:doPostSucceeded:code=200 2019-03-08 06:57:56.578 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=StartOver,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.578 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=FastForward,handler=0x4a5b00,policy=NON_BLOCKIG 2019-03-08 06:57:56.578 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.FavoritesController,name=Favorite,handler=0x4a5b00,policy=NON_BLOCKING 2019-03-08 06:57:56.578 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=DisableShuffle,handler=0x4a5b00,policy=NON_BLOG 2019-03-08 06:57:56.578 [ 2] 5 CBLAuthDelegate:receiveTokenResponse:code=200,body={"access_token"\:"Atza|IwEBIEdnlPSmgYfduTQgAvMs0VnjmzV_8LFV1mV_zQRfHYrULAXaFHEVhTRMWr} 2019-03-08 06:57:56.578 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=EnableRepeatOne,handler=0x4a5b00,policy=NON_BLG 2019-03-08 06:57:56.579 [ 2] 5 CBLAuthDelegate:mapHTTPStatusToError:code=200,error=SUCCESS 2019-03-08 06:57:56.579 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=DisableRepeat,handler=0x4a5b00,policy=NON_BLOCG 2019-03-08 06:57:56.579 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.SeekController,name=AdjustSeekPosition,handler=0x4a5b00,policy=NON_BLOG 2019-03-08 06:57:56.580 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=ExpectSpeech,handler=0x50d000,policy=NON_BLOCKING 2019-03-08 06:57:56.580 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=StopCapture,handler=0x50d000,policy=NON_BLOCKING 2019-03-08 06:57:56.580 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=AdjustVolume,handler=0x4dfa00,policy=NON_BLOCKING 2019-03-08 06:57:56.581 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetAlert,handler=0x4dfa00,policy=NON_BLOCKING 2019-03-08 06:57:56.581 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=DeleteAlerts,handler=0x4dfa00,policy=NON_BLOCKING 2019-03-08 06:57:56.581 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=DeleteAlert,handler=0x4dfa00,policy=NON_BLOCKING 2019-03-08 06:57:56.581 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetVolume,handler=0x4dfa00,policy=NONBLOCKING 2019-03-08 06:57:56.582 [ 2] 5 CBLAuthDelegate:setAuthError:authError=SUCCESS 2019-03-08 06:57:56.915 [ 2] 5 CBLAuthDelegate:setRefreshToken:refreshToken=Atzr|IwEBIBGMb4qDzpr15XmczgaQJatbaYQ9nr53gqKs9osCx5nD9wodh1bZW8bL0sVgy3KKJ-8jzQMFR-Wt-A071Y 2019-03-08 06:57:56.916 [ 2] 5 SQLiteCBLAuthDelegateStorage:setRefreshToken 2019-03-08 06:57:56.918 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=SetEndpoint,handler=0x4835a0,policy=NON_BLOCKING 2019-03-08 06:57:56.919 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=ResetUserInactivity,handler=0x4d8804,policy=NON_BLOCKING 2019-03-08 06:57:56.920 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=AdjustVolume,handler=0x4a2400,policy=NON_BLOCKING 2019-03-08 06:57:56.920 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=SetMute,handler=0x4a2400,policy=NON_BLOCKING 2019-03-08 06:57:56.920 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=SetVolume,handler=0x4a2400,policy=NON_BLOCKING 2019-03-08 06:57:56.920 [ 1] 5 TemplateRuntime:getConfiguration 2019-03-08 06:57:56.921 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=TemplateRuntime,name=RenderPlayerInfo,handler=0x488fe8,policy=HANDLE_IMMEDIAY 2019-03-08 06:57:56.921 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=TemplateRuntime,name=RenderTemplate,handler=0x488fe8,policy=HANDLE_IMMEDIATEY 2019-03-08 06:57:56.921 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Notifications,name=ClearIndicator,handler=0x4d3a04,policy=HANDLE_IMMEDIATELY 2019-03-08 06:57:56.921 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Notifications,name=SetIndicator,handler=0x4d3a04,policy=HANDLE_IMMEDIATELY 2019-03-08 06:57:56.922 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=InteractionModel,name=NewDialogRequest,handler=0x4b7ff8,policy=HANDLE_IMMEDIY 2019-03-08 06:57:56.922 [ 1] 5 Bluetooth:getConfiguration 2019-03-08 06:57:56.923 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=Previous,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.923 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=PairDevice,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.923 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=ExitDiscoverableMode,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.924 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=Stop,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.927 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=EnterDiscoverableMode,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.927 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=ConnectByProfile,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.928 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=ScanDevices,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.930 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=UnpairDevice,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.930 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=DisconnectDevice,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.931 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=ConnectByDeviceId,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:56.946 [ 2] 5 CBLAuthDelegate:setAuthState:newAuthState=REFRESHED 2019-03-08 06:57:57.264 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=Next,handler=0x505200,policy=NON_BLOCKING 2019-03-08 06:57:57.265 [ 2] 9 CBLAuthDelegate:callingOnAuthStateChange:state=REFRESHED,error=SUCCESS 2019-03-08 06:57:57.265 [ 1] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Bluetooth,name=Play,handler=0x505200,policy=NON_BLOCKING ###########################

Authorized!

###########################

2019-03-08 06:57:57.278 [ 1] 9 SpeakerManager:addSpeakerManagerObserverCalled 2019-03-08 06:57:57.278 [ 1] 9 SpeakerManager:addSpeakerManagerObserver:observer=0x44b2a0 2019-03-08 06:57:57.279 [ 1] 5 NotificationsCapabilityAgent:addObserver 2019-03-08 06:57:57.279 [ 1] 5 TemplateRuntime:addObserver #################################################

NOTIFICATION INDICATOR STATE: OFF

#################################################

2019-03-08 06:57:57.284 [ 10] 5 TemplateRuntime:addObserverInExecutor ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.front ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.rear ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.center_lfe ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.side ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround21 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround21 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround40 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround41 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround50 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround51 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.surround71 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.iec958 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.iec958 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.iec958 ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.hdmi ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.hdmi ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.modem ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.modem ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.phoneline ALSA lib pcm.c:2266:(snd_pcm_open_noupdate) Unknown PCM cards.pcm.phoneline ALSA lib pcm_dsnoop.c:545:(snd_pcm_dsnoop_open) The dsnoop plugin supports only capture stream ALSA lib pcm_dsnoop.c:545:(snd_pcm_dsnoop_open) The dsnoop plugin supports only capture stream ALSA lib pcm_dmix.c:1029:(snd_pcm_dmix_open) unable to open slave ALSA lib pcm_dmix.c:1029:(snd_pcm_dmix_open) unable to open slave 2019-03-08 06:57:57.397 [ 1] 9 PryonLiteKeywordDetector:init 2019-03-08 06:57:57.404 [ 1] I PryonLiteKeywordDetector:sessionInfo:engineVersion=1.0.1,modelVersion=en-IN_D_ALEXA+STOP_2017Thanksgiving_v1.0,requiredSamplesPerFramePe0 2019-03-08 06:57:57.410 [ 1] 5 CBLAuthDelegate:addAuthObserver:observer=0x4cd4a8 2019-03-08 06:57:57.411 [ 1] 5 CapabilitiesDelegate:addCapabilitiesObserver:observer=0x4cd4ac 2019-03-08 06:57:57.411 [ 1] 5 CapabilitiesDelegate:addCapabilitiesObserver:observer=0x3ff730 Socket creation - Success!! Socket bind - Success!!

             # #   #     # #     #    #     # #     # #   #               
            #   #  #     # #          #       #     # #  #                
           #     # #     #  #####      #####  #     # ###                 
           #######  #   #        #          # #     # #  #                
           #     #   # #   #     #    #     # #     # #   #               
           #     #    #     #####      #####  ######  #    #              

   #####                                           #                      
  #     #   ##   #    # #####  #      ######      # #   #####  #####      
  #        #  #  ##  ## #    # #      #          #   #  #    # #    #     
   #####  #    # # ## # #    # #      #####     #     # #    # #    #     
        # ###### #    # #####  #      #         ####### #####  #####      
  #     # #    # #    # #      #      #         #     # #      #          
   #####  #    # #    # #      ###### ######    #     # #      #          

   SDK Version 1.9.0

+----------------------------------------------------------------------------+ | Options: | | Wake word: | | Simply say Alexa and begin your query. | | Tap to talk: | | Press 't' and Enter followed by your query (no need for the 'Alexa').| | Hold to talk: | | Press 'h' followed by Enter to simulate holding a button. | | Then say your query (no need for the 'Alexa'). | | Press 'h' followed by Enter to simulate releasing a button. | | Stop an interaction: | | Press 's' and Enter to stop an ongoing interaction. | | Privacy mode (microphone off): | | Press 'm' and Enter to turn on and off the microphone. | | Echo Spatial Perception (ESP): This is for testing purpose only! | | Press 'e' followed by Enter at any time to adjust ESP settings. | | Playback Controls: | | Press '1' for a 'PLAY' button press. | | Press '2' for a 'PAUSE' button press. | | Press '3' for a 'NEXT' button press. | | Press '4' for a 'PREVIOUS' button press. | | Settings: | | Press 'c' followed by Enter at any time to see the settings screen. | | Speaker Control: | | Press 'p' followed by Enter at any time to adjust speaker settings. | | Firmware Version: | | Press 'f' followed by Enter at any time to report a different | | firmware version. | | Info: | | Press 'i' followed by Enter at any time to see the help screen. | | Reset device: | | Press 'k' followed by Enter at any time to reset your device. This | | will erase any data stored in the device and you will have to | | re-register your device. | | This option will also exit the application. | | Quit: | | Press 'q' followed by Enter at any time to quit the application. | +----------------------------------------------------------------------------+

2019-03-08 06:57:57.420 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.755 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.755 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.755 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.755 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.756 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.756 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.756 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.756 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.756 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.757 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.757 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:57.777 [ 12] 9 SpeakerManager:setMuteCalled:mute=false 2019-03-08 06:57:58.091 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:58.091 [ a] 9 SpeakerManager:executeSetMuteCalled:mute=false 2019-03-08 06:57:58.091 [ 11] 0 CapabilitiesDelegate:getCapabilityConfigsStringFromJsonFailed::Interface configurations not available 2019-03-08 06:57:58.093 [ 11] 5 CapabilitiesDelegate:setCapabilitiesState:newCapabilitiesState=SUCCESS 2019-03-08 06:57:58.091 [ a] 9 MediaPlayer:setMuteCalled 2019-03-08 06:57:58.094 [ 4] 9 MediaPlayer:handleSetMuteCalled 2019-03-08 06:57:58.094 [ a] 9 MediaPlayer:setMuteCalled 2019-03-08 06:57:58.095 [ 5] 9 MediaPlayer:handleSetMuteCalled 2019-03-08 06:57:58.095 [ a] 9 MediaPlayer:setMuteCalled 2019-03-08 06:57:58.095 [ 6] 9 MediaPlayer:handleSetMuteCalled 2019-03-08 06:57:58.095 [ a] 9 MediaPlayer:setMuteCalled 2019-03-08 06:57:58.095 [ 7] 9 MediaPlayer:handleSetMuteCalled 2019-03-08 06:57:58.095 [ a] 9 MediaPlayer:setMuteCalled 2019-03-08 06:57:58.095 [ 8] 9 MediaPlayer:handleSetMuteCalled 2019-03-08 06:57:58.095 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ 4] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ 5] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ 6] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ 7] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.096 [ 8] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.097 [ a] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true 2019-03-08 06:57:58.097 [ a] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false 2019-03-08 06:57:58.097 [ a] 9 SpeakerManager:updateContextManagerCalled:speakerType=AVS_SPEAKER_VOLUME 2019-03-08 06:57:58.097 [ a] 9 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState 2019-03-08 06:57:58.097 [ a] I SpeakerManager:executeSetMute::Skipping sending notifications:reason=forceNoNotifications 2019-03-08 06:57:58.097 [ 12] 9 SpeakerManager:adjustVolumeCalled:delta=10 2019-03-08 06:57:58.097 [ 11] 9 CapabilitiesDelegate:callingOnCapabilitiesStateChange:state=SUCCESS,error=SUCCESS 2019-03-08 06:57:58.098 [ 11] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=PENDING 2019-03-08 06:57:58.101 [ a] 9 SpeakerManager:executeAdjustVolumeCalled:delta=10 2019-03-08 06:57:58.101 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.102 [ 4] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.102 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ 5] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ 6] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ 7] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ 8] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.103 [ a] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true 2019-03-08 06:57:58.103 [ a] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false 2019-03-08 06:57:58.103 [ a] 9 MediaPlayer:adjustVolumeCalled 2019-03-08 06:57:58.104 [ 4] 9 MediaPlayer:handleAdjustVolumeCalled 2019-03-08 06:57:58.104 [ a] 9 MediaPlayer:adjustVolumeCalled 2019-03-08 06:57:58.113 [ 11] 5 CBLAuthDelegate:addAuthObserver:observer=0xb3904ad8 2019-03-08 06:57:58.445 [ 5] 9 MediaPlayer:handleAdjustVolumeCalled 2019-03-08 06:57:58.445 [ a] 9 MediaPlayer:adjustVolumeCalled 2019-03-08 06:57:58.445 [ b] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST 2019-03-08 06:57:58.445 [ 6] 9 MediaPlayer:handleAdjustVolumeCalled #############################

Connecting...

#############################

2019-03-08 06:57:58.445 [ a] 9 MediaPlayer:adjustVolumeCalled 2019-03-08 06:57:58.446 [ 7] 9 MediaPlayer:handleAdjustVolumeCalled 2019-03-08 06:57:58.447 [ a] 9 MediaPlayer:adjustVolumeCalled 2019-03-08 06:57:58.447 [ 8] 9 MediaPlayer:handleAdjustVolumeCalled 2019-03-08 06:57:58.447 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.447 [ 4] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.447 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.447 [ 5] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.448 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.448 [ 6] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.448 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.448 [ 7] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.448 [ a] 9 MediaPlayer:getSpeakerSettingsCalled 2019-03-08 06:57:58.448 [ 8] 9 MediaPlayer:handleGetSpeakerSettingsCalled 2019-03-08 06:57:58.448 [ a] 9 SpeakerManager:validateSpeakerSettingsConsistencyResult:consistent=true 2019-03-08 06:57:58.448 [ a] 9 SpeakerManager:validateSpeakerSettings:volume=100,mute=false 2019-03-08 06:57:58.448 [ a] 0 SpeakerManager:executeAdjustVolumeSuccess:newVolume=100 2019-03-08 06:57:58.448 [ a] 9 SpeakerManager:updateContextManagerCalled:speakerType=AVS_SPEAKER_VOLUME 2019-03-08 06:57:58.449 [ a] 9 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState 2019-03-08 06:57:58.449 [ a] 9 SpeakerManager:executeNotifyObserverCalled ##########################################################################

SOURCE:LOCAL_API TYPE:AVS_SPEAKER_VOLUME VOLUME:100 MUTE:0

##########################################################################

2019-03-08 06:57:58.450 [ a] 9 SpeakerManager:executeSendSpeakerSettingsChangedEvent 2019-03-08 06:57:58.451 [ a] 0 EventBuilder:buildJsonEventString:messageId=35556d26-277e-49de-a15c-c2d2ec7a78e8,namespace=Speaker,name=VolumeChanged 2019-03-08 06:57:58.456 [ 13] 0 PostConnectSynchronizer:doPostConnect 2019-03-08 06:57:58.457 [ a] E HTTP2Transport:enqueueRequestFailed:reason=isNotConnected 2019-03-08 06:57:58.462 [ 13] 5 PostConnectSynchronizer:setState:from=IDLE,to=RUNNING 2019-03-08 06:57:58.465 [ 13] 3 HTTP2Transport:setupDownchannelStream:url=https\://avs-alexa-na.amazon.com/v20160207/directives 2019-03-08 06:57:58.470 [ 13] 0 HTTP2StreamPool:getStream:streamId=1,numAcquiredStreams=1 2019-03-08 06:57:58.472 [ 14] 5 PostConnectSynchronizer:mainLoop 2019-03-08 06:57:58.473 [ 14] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-03-08 06:57:58.476 [ 16] 9 ContextManager:updateStateLocked:action=updatedState,state={"wakeword" \: ""},namespace=SpeechRecognizer,name=RecognizerState 2019-03-08 06:57:58.476 [ 15] 0 AudioPlayer:provideState:stateRequestToken=1 2019-03-08 06:57:58.479 [ 17] 0 AudioPlayer:executeProvideState:sendToken=true,stateRequestToken=1 2019-03-08 06:57:58.482 [ 15] 9 SpeechSynthesizer:provideState:token=1 2019-03-08 06:57:58.482 [ 17] 9 ContextManager:updateStateLocked:action=updatedState,state={"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"},namespace=e 2019-03-08 06:57:58.482 [ 18] 0 SpeechSynthesizer:executeProvideState:stateRequestToken=1 2019-03-08 06:57:58.483 [ 18] 9 ContextManager:updateStateLocked:action=updatedState,state={"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"},namespe 2019-03-08 06:57:58.483 [ 15] 5 AudioActivityTracker:provideState 2019-03-08 06:57:58.484 [ 19] 5 AudioActivityTracker:executeProvideState 2019-03-08 06:57:58.484 [ 19] 9 ContextManager:updateStateLocked:action=updatedState,state=,namespace=AudioActivityTracker,name=ActivityState 2019-03-08 06:57:58.510 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= Trying 54.239.25.188... 2019-03-08 06:57:58.820 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TCP_NODELAY set 2019-03-08 06:57:58.821 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:57:58.821 [ 15] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=1 2019-03-08 06:57:58.821 [ c] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=1 2019-03-08 06:57:58.823 [ c] 9 ContextManager:updateStateLocked:action=updatedState,state={"isEnabled"\:false\,"isVisualIndicatorPersisted"\:false},namespace=Notificate 2019-03-08 06:57:58.833 [ 15] 5 VisualActivityTracker:provideState 2019-03-08 06:57:58.833 [ 1a] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=1 2019-03-08 06:57:58.834 [ 1a] 9 ContextManager:updateStateLocked:action=updatedState,state={"playerInFocus"\:""\,"players"\:[]},namespace=ExternalMediaPlayer,name=Extere 2019-03-08 06:57:58.835 [ 1a] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=1 2019-03-08 06:57:58.836 [ 1a] 9 ContextManager:updateStateLocked:action=updatedState,state={"state"\:"IDLE"\,"supportedOperations"\:[]\,"shuffle"\:"NOT_SHUFFLED"\,"repee 2019-03-08 06:57:58.836 [ 1b] 5 VisualActivityTracker:executeProvideState 2019-03-08 06:57:58.836 [ 1b] 9 ContextManager:updateStateLocked:action=updatedState,state=,namespace=VisualActivityTracker,name=ActivityState 2019-03-08 06:57:58.838 [ 15] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-03-08 06:57:58.839 [ 15] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-03-08 06:57:58.840 [ 15] 5 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"pay} 2019-03-08 06:57:58.841 [ 15] 5 PostConnectSynchronizer:onContextAvailable:context={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}} 2019-03-08 06:57:58.921 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:57:59.175 [ 15] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-03-08 06:57:59.175 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Connected to avs-alexa-na.amazon.com (54.239.25.188) port 443 (#0) 2019-03-08 06:57:59.175 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=ALPN\, offering h2 2019-03-08 06:57:59.175 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=ALPN\, offering http/1.1 2019-03-08 06:57:59.176 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Cipher selection\: ALL\:!EXPORT\:!EXPORT40\:!EXPORT56\:!aNULL\:!LOW\:!RC4\:@STRENGTH 2019-03-08 06:57:59.176 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=successfully set certificate verify locations\: 2019-03-08 06:57:59.176 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= CAfile\: none CApath\: /etc/ssl/certs 2019-03-08 06:57:59.176 [ 15] 0 EventBuilder:buildJsonEventString:messageId=277ac295-600e-410b-a713-31c9298d0ff9,namespace=System,name=SynchronizeState 2019-03-08 06:57:59.177 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (OUT)\, TLS header\, Certificate Status (22)\: 2019-03-08 06:57:59.177 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (OUT)\, TLS handshake\, Client hello (1)\: 2019-03-08 06:57:59.177 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:57:59.180 [ 15] 9 HTTP2Transport:enqueueRequest:jsonContent={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload} 2019-03-08 06:57:59.515 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (IN)\, TLS handshake\, Server hello (2)\: 2019-03-08 06:57:59.515 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (IN)\, TLS handshake\, Certificate (11)\: 2019-03-08 06:57:59.533 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (IN)\, TLS handshake\, Server key exchange (12)\: 2019-03-08 06:57:59.538 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (IN)\, TLS handshake\, Server finished (14)\: 2019-03-08 06:57:59.557 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (OUT)\, TLS handshake\, Client key exchange (16)\: 2019-03-08 06:57:59.557 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (OUT)\, TLS change cipher\, Client hello (1)\: 2019-03-08 06:57:59.558 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (OUT)\, TLS handshake\, Finished (20)\: 2019-03-08 06:57:59.558 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:57:59.658 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:57:59.759 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:57:59.780 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (IN)\, TLS change cipher\, Client hello (1)\: 2019-03-08 06:57:59.781 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=TLSv1.2 (IN)\, TLS handshake\, Finished (20)\: 2019-03-08 06:57:59.781 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 2019-03-08 06:57:59.781 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=ALPN\, server accepted to use h2 2019-03-08 06:57:59.781 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Server certificate\: 2019-03-08 06:57:59.781 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= subject\: CN\=latinum.amazon.com 2019-03-08 06:57:59.782 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= start date\: Aug 7 00\:00\:00 2018 GMT 2019-03-08 06:57:59.782 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= expire date\: Aug 7 12\:00\:00 2019 GMT 2019-03-08 06:57:59.782 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= subjectAltName\: host "avs-alexa-na.amazon.com" matched cert's "avs-alexa-na.amazon.com" 2019-03-08 06:57:59.782 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= issuer\: C\=US; O\=Amazon; OU\=Server CA 1B; CN\=Amazon 2019-03-08 06:57:59.783 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text= SSL certificate verify ok. 2019-03-08 06:57:59.785 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Using HTTP2\, server supports multi-use 2019-03-08 06:57:59.785 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Connection state changed (HTTP/2 confirmed) 2019-03-08 06:57:59.785 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Copying HTTP/2 data in stream buffer to connection buffer after upgrade\: len\=0 2019-03-08 06:57:59.787 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Using Stream ID\: 1 (easy handle 0xb2603a70) 2019-03-08 06:57:59.788 [ 13] 9 HTTP2Stream:libcurl:streamId=1,text=Connection state changed (MAX_CONCURRENT_STREAMS updated)! 2019-03-08 06:57:59.889 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:57:59.989 [ 13] 9 HTTP2Transport:establishConnectionWaitingForActivity 2019-03-08 06:58:00.086 [ 13] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0af365fffed5a584-00004d00-00004c97-f4df069170fce174-14287d34-1 2019-03-08 06:58:00.089 [ 13] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState= 2019-03-08 06:58:00.090 [ 13] 0 HTTP2StreamPool:getStream:streamId=3,numAcquiredStreams=2 2019-03-08 06:58:00.091 [ 13] 9 HTTP2Transport:insertActiveStream:handle=0xb260e628 2019-03-08 06:58:00.093 [ 13] 9 HTTP2Stream:libcurl:streamId=3,text=Found bundle for host avs-alexa-na.amazon.com\: 0xb260cc88 [can multiplex] 2019-03-08 06:58:00.094 [ 13] 9 HTTP2Stream:libcurl:streamId=3,text=Conn\: 0 (0xb260c520) Receive pipe weight\: (-1/0)\, penalized\: (nil) 2019-03-08 06:58:00.094 [ 13] 9 HTTP2Stream:libcurl:streamId=3,text=Multiplexed connection found! 2019-03-08 06:58:00.094 [ 13] 9 HTTP2Stream:libcurl:streamId=3,text=Found connection 0\, with requests in the pipe (1) 2019-03-08 06:58:00.094 [ 13] 9 HTTP2Stream:libcurl:streamId=3,text=Re-using existing connection! (#0) with host avs-alexa-na.amazon.com 2019-03-08 06:58:00.094 [ 13] 9 HTTP2Stream:libcurl:streamId=3,text=Using Stream ID\: 3 (easy handle 0xb260e628) 2019-03-08 06:58:00.547 [ 13] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0af365fffed5a584-00004d00-00004c97-f4df069170fce174-14287d34-3 2019-03-08 06:58:00.548 [ 13] 5 PostConnectSynchronizer:onSendCompleted:status=SUCCESS_NO_CONTENT 2019-03-08 06:58:00.549 [ 13] 5 PostConnectSynchronizer:stop 2019-03-08 06:58:00.549 [ 13] 5 PostConnectSynchronizer:setState:from=SENDING,to=STOPPING 2019-03-08 06:58:00.549 [ 14] 5 PostConnectSynchronizer:mainLoopReturning 2019-03-08 06:58:00.550 [ 13] 5 PostConnectSynchronizer:setState:from=STOPPING,to=STOPPED 2019-03-08 06:58:00.553 [ 13] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED 2019-03-08 06:58:00.554 [ b] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=CONNECTED,reason=ACL_CLIENT_REQUEST

INFO,Message {"api_id":"HCS_MB_ALEXA_TO_AC_LED_NOTIFICATION","transaction_id":"1", "dest_module_id":"HCS_MB_MODULE_AC","src_module_id":"HCS_MB_MODULE_ALEXA","msg":{"al 2019-03-08 06:58:00.555 [ 13] 0 HTTP2Transport:cleanupFinishedStream:streamId=3,result=204 2019-03-08 06:58:00.558 [ 13] 0 HTTP2StreamPool:releaseStream:streamId=3,numAcquiredStreams=1 2019-03-08 06:58:00.558 [ 13] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT 2019-03-08 06:58:00.559 [ 13] 0 PostConnectSynchronizer:~PostConnectSynchronizer 2019-03-08 06:58:00.559 [ 13] 5 PostConnectSynchronizer:stop 2019-03-08 06:58:00.559 [ 13] 5 PostConnectSynchronizer:stopIgnored:reason=alreadyStopped ########################################

Alexa is currently idle!

########################################

2019-03-08 06:58:24.540 [ e] 5 BlueZDeviceManager:propertiesChangedCallback 2019-03-08 06:58:24.540 [ e] 7 BlueZDeviceManager:Properties changed:objectPath=/org/bluez/hci0/dev_60_9A_C1_E3_29_19/player0 2019-03-08 06:58:24.541 [ e] 9 BlueZDeviceManager:Details:=('org.bluez.MediaPlayer1'\, {'Position'\: <uint32 43308>}\, @as []) 2019-03-08 07:01:19.606 [ 1c] 9 PryonLiteKeywordDetector:resultCallback 2019-03-08 07:01:19.617 [ 16] 5 UserInactivityMonitor:onUserActive 2019-03-08 07:01:19.621 [ 16] 0 AudioInputProcessor:setState:from=IDLE,to=RECOGNIZING 2019-03-08 07:01:19.622 [ d] 0 DialogUXStateAggregator:setState:from=IDLE,to=LISTENING

INFO,Message {"api_id":"HCS_MB_ALEXA_TO_AC_LED_NOTIFICATION","transaction_id":"2", "dest_module_id":"HCS_MB_MODULE_AC","src_module_id":"HCS_MB_MODULE_ALEXA","msg":{"al ############################

Listening...

############################

2019-03-08 07:01:19.624 [ d] 5 TemplateRuntime:onDialogUXStateChanged:state=LISTENING 2019-03-08 07:01:19.622 [ 16] 9 ContextManager:updateStateLocked:action=updatedState,state={"wakeword" \: "ALEXA"},namespace=SpeechRecognizer,name=RecognizerState 2019-03-08 07:01:19.643 [ 15] 5 AudioActivityTracker:provideState 2019-03-08 07:01:19.644 [ 15] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=2 2019-03-08 07:01:19.644 [ 15] 5 VisualActivityTracker:provideState 2019-03-08 07:01:19.645 [ c] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=2 2019-03-08 07:01:19.646 [ c] 9 ContextManager:updateStateLocked:action=updatedState,state={"isEnabled"\:false\,"isVisualIndicatorPersisted"\:false},namespace=Notificate 2019-03-08 07:01:19.647 [ 1a] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=2 2019-03-08 07:01:19.647 [ 1a] 9 ContextManager:updateStateLocked:action=updatedState,state={"playerInFocus"\:""\,"players"\:[]},namespace=ExternalMediaPlayer,name=Extere 2019-03-08 07:01:19.647 [ 1b] 5 VisualActivityTracker:executeProvideState 2019-03-08 07:01:19.647 [ 19] 5 AudioActivityTracker:executeProvideState 2019-03-08 07:01:19.648 [ 1b] 9 ContextManager:updateStateLocked:action=updatedState,state=,namespace=VisualActivityTracker,name=ActivityState 2019-03-08 07:01:19.648 [ 19] 9 ContextManager:updateStateLocked:action=updatedState,state=,namespace=AudioActivityTracker,name=ActivityState 2019-03-08 07:01:19.648 [ 1a] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=2 2019-03-08 07:01:19.649 [ 1a] 9 ContextManager:updateStateLocked:action=updatedState,state={"state"\:"IDLE"\,"supportedOperations"\:[]\,"shuffle"\:"NOT_SHUFFLED"\,"repee 2019-03-08 07:01:19.649 [ 15] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-03-08 07:01:19.651 [ 15] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-03-08 07:01:19.652 [ 15] 5 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"pay} 2019-03-08 07:01:19.657 [ 16] 0 AudioInputProcessor:executeOnContextAvailable:jsonContext={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerS} 2019-03-08 07:01:19.991 [ 16] 1 FocusManager:acquireChannel:channelName=Dialog,interface=SpeechRecognizer 2019-03-08 07:01:19.993 [ 16] I DirectiveProcessor:setDialogRequestIdLocked:oldValue=,newValue=887713a0-76b5-4550-9ab5-96f35fa8c09d 2019-03-08 07:01:19.994 [ 16] 0 DirectiveProcessor:scrubDialogRequestIdLocked:reason=emptyDialogRequestId 2019-03-08 07:01:19.995 [ 16] 0 EventBuilder:buildJsonEventString:messageId=ee803041-9aea-4517-810a-69c288707194,namespace=SpeechRecognizer,name=Recognize 2019-03-08 07:01:19.996 [ 1d] 9 AudioInputProcessor:onFocusChanged:newFocus=FOREGROUND 2019-03-08 07:01:19.999 [ 16] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=FOREGROUND 2019-03-08 07:01:19.999 [ 16] 9 HTTP2Transport:enqueueRequest:jsonContent={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload} 2019-03-08 07:01:20.001 [ 1d] 5 AudioActivityTracker:notifyOfActivityUpdates 2019-03-08 07:01:20.334 [ 13] 0 HTTP2Transport:processNextOutgoingMessage:jsonContent={"context"\:[{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState= 2019-03-08 07:01:20.335 [ 13] 0 HTTP2StreamPool:getStream:streamId=5,numAcquiredStreams=2 2019-03-08 07:01:20.336 [ 19] 5 AudioActivityTracker:executeNotifyOfActivityUpdates 2019-03-08 07:01:20.338 [ 13] 9 HTTP2Transport:insertActiveStream:handle=0xb260e480 2019-03-08 07:01:20.338 [ 13] 9 HTTP2Stream:libcurl:streamId=5,text=Found bundle for host avs-alexa-na.amazon.com\: 0xb260cc88 [can multiplex] 2019-03-08 07:01:20.339 [ 13] 9 HTTP2Stream:libcurl:streamId=5,text=Conn\: 0 (0xb260c520) Receive pipe weight\: (-1/0)\, penalized\: (nil) 2019-03-08 07:01:20.339 [ 13] 9 HTTP2Stream:libcurl:streamId=5,text=Multiplexed connection found! 2019-03-08 07:01:20.339 [ 13] 9 HTTP2Stream:libcurl:streamId=5,text=Found connection 0\, with requests in the pipe (1) 2019-03-08 07:01:20.339 [ 13] 9 HTTP2Stream:libcurl:streamId=5,text=Re-using existing connection! (#0) with host avs-alexa-na.amazon.com 2019-03-08 07:01:20.339 [ 13] 9 HTTP2Stream:libcurl:streamId=5,text=Using Stream ID\: 5 (easy handle 0xb260e480) 2019-03-08 07:01:26.546 [ 1e] I DirectiveSequencer:onDirective:directive={"namespace\:"SpeechRecognizer"\,name\:"StopCapture"\,messageId\:"8f6ae257-9d39-430c-a1ae-1820e} 2019-03-08 07:01:26.550 [ 1f] I DirectiveRouter:preHandleDirective:messageId=8f6ae257-9d39-430c-a1ae-1820e2f577d5,action=calling 2019-03-08 07:01:26.551 [ 1f] 0 CapabilityAgent:addingMessageIdToMap:messageId=8f6ae257-9d39-430c-a1ae-1820e2f577d5 2019-03-08 07:01:26.554 [ 20] I DirectiveRouter:handleDirective:messageId=8f6ae257-9d39-430c-a1ae-1820e2f577d5,action=calling 2019-03-08 07:01:26.555 [ 16] 0 AudioInputProcessor:stopCapture:stopImmediately=true 2019-03-08 07:01:26.555 [ 16] 5 UserInactivityMonitor:onUserActive 2019-03-08 07:01:26.555 [ 16] 0 AudioInputProcessor:setState:from=RECOGNIZING,to=BUSY 2019-03-08 07:01:26.556 [ d] 0 DialogUXStateAggregator:setState:from=LISTENING,to=THINKING 2019-03-08 07:01:26.556 [ d] 5 TemplateRuntime:onDialogUXStateChanged:state=THINKING 2019-03-08 07:01:26.556 [ 16] 0 DirectiveProcessor:onHandlingCompeted:messageId=8f6ae257-9d39-430c-a1ae-1820e2f577d5,directiveBeingPreHandled=(nullptr)

INFO,Message {"api_id":"HCS_MB_ALEXA_TO_AC_LED_NOTIFICATION","transaction_id":"3", "dest_module_id":"HCS_MB_MODULE_AC","src_module_id":"HCS_MB_MODULE_ALEXA","msg":{"al 2019-03-08 07:01:26.557 [ 16] 0 CapabilityAgent:removingMessageIdFromMap:messageId=8f6ae257-9d39-430c-a1ae-1820e2f577d5 ###########################

Thinking...

###########################

2019-03-08 07:01:26.568 [ 13] 0 InProcessAttachmentReader:readFailed:reason=SDS is closed 2019-03-08 07:01:26.882 [ 13] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0af365fffed5a584-00004d00-00004c97-f4df069170fce174-14287d34-5 2019-03-08 07:01:26.882 [ 13] 0 AudioInputProcessor:onSendCompleted:status=SUCCESS_NO_CONTENT 2019-03-08 07:01:26.883 [ 13] 0 HTTP2Transport:cleanupFinishedStream:streamId=5,result=204 2019-03-08 07:01:26.883 [ 13] 0 HTTP2StreamPool:releaseStream:streamId=5,numAcquiredStreams=1 2019-03-08 07:01:26.883 [ 13] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT 2019-03-08 07:01:31.573 [ d] 0 DialogUXStateAggregator:transitionFromThinkingTimedOut 2019-03-08 07:01:31.573 [ d] 0 DialogUXStateAggregator:setState:from=THINKING,to=IDLE 2019-03-08 07:01:31.574 [ d] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE

INFO,Message {"api_id":"HCS_MB_ALEXA_TO_AC_LED_NOTIFICATION","transaction_id":"4", "dest_module_id":"HCS_MB_MODULE_AC","src_module_id":"HCS_MB_MODULE_ALEXA","msg":{"al ########################################

Alexa is currently idle!

########################################

2019-03-08 07:01:31.575 [ 16] 1 FocusManager:releaseChannel:channelName=Dialog 2019-03-08 07:01:31.575 [ 16] 0 AudioInputProcessor:setState:from=BUSY,to=IDLE 2019-03-08 07:01:31.579 [ 1d] 9 AudioInputProcessor:onFocusChanged:newFocus=NONE 2019-03-08 07:01:31.579 [ 16] 0 AudioInputProcessor:executeOnFocusChanged:newFocus=NONE 2019-03-08 07:01:31.579 [ 16] 0 AudioInputProcessor:executeOnFocusChanged:reason=Lost focus 2019-03-08 07:01:31.581 [ 1d] 5 AudioActivityTracker:notifyOfActivityUpdates 2019-03-08 07:01:31.581 [ 19] 5 AudioActivityTracker:executeNotifyOfActivityUpdates 2019-03-08 07:01:46.500 [ e] 5 BlueZDeviceManager:propertiesChangedCallback 2019-03-08 07:01:46.501 [ e] 7 BlueZDeviceManager:Properties changed:objectPath=/org/bluez/hci0/dev_60_9A_C1_E3_29_19/player0 2019-03-08 07:01:46.501 [ e] 9 BlueZDeviceManager:Details:=('org.bluez.MediaPlayer1'\, {'Track'\: <{'Title'\: <"Don't Leave Me Alone (feat. Anne-Marie)">\, 'Album'\: <) 2019-03-08 07:01:46.508 [ e] 5 BlueZDeviceManager:propertiesChangedCallback 2019-03-08 07:01:46.509 [ e] 7 BlueZDeviceManager:Properties changed:objectPath=/org/bluez/hci0/dev_60_9A_C1_E3_29_19/player0 2019-03-08 07:01:46.509 [ e] 9 BlueZDeviceManager:Details:=('org.bluez.MediaPlayer1'\, {'Track'\: <{'Title'\: <"Don't Leave Me Alone (feat. Anne-Marie)">\, 'Duration') 2019-03-08 07:01:48.110 [ e] 5 BlueZDeviceManager:propertiesChangedCallback 2019-03-08 07:01:48.110 [ e] 7 BlueZDeviceManager:Properties changed:objectPath=/org/bluez/hci0/dev_60_9A_C1_E3_29_19/player0 2019-03-08 07:01:48.111 [ e] 9 BlueZDeviceManager:Details:=('org.bluez.MediaPlayer1'\, {'Position'\: <uint32 826>}\, @as [])

kjkh commented 5 years ago

Hi @sumit3817,

Thanks for providing the logs. Can you give an overview of what you are using mplayer for? The SDK provides a reference implementation which is able to interact with BlueZ and PulseAudio to stream media playback as both a source and a sink. It seems like mplayer is interfering with the data flow.

Can you also tell us which platform (Ubuntu, PI, etc?) you are using and how mplayer is set up on your system to work in in conjunction with BlueZ? Are you also using PulseAudio on your system?

sumit3817 commented 5 years ago

The platform is Ubuntu Linux (arm 32 bit) No I am not using pulse audio.

mplayer is already installed in the system.

It happens only when I run avs-device-sdk.

And I am able to play any audio using command mplayer xyz.mp3

caleighatamazon commented 5 years ago

Hi there, sorry for our late response on this. Are you still having problems?

caleighatamazon commented 4 years ago

Closing this due to inactivity. Please feel free to re-open if you encounter further problems. Thanks!