Closed netgzj closed 3 years ago
Hello @netgzj,
The C++ SampleApp is unable to establish a connection with the GUI client. The following seems to be the error:
2021-08-04 10:19:13.668 [ b] 0 EventBuilder:buildJsonEventString:event={"context":{"properties":[]},"event":{"header":{"namespace":"System","name":"ExceptionEncountered","messageId":"7a4656bb-b1f9-4dd2-a9ca-148569da638d"},"payload":{"unparsedDirective":"{\"directive\":{\"header\":{\"namespace\":\"Alexa\",\"name\":\"EventProcessed\",\"messageId\":\"9c49b010-2711-4d7d-ab72-7382291ffce8\",\"payloadVersion\":\"3\",\"eventCorrelationToken\":\"86224c9b-d028-4c9f-868a-441130a11984\"},\"payload\":{}}}","error":{"type":"UNSUPPORTED_OPERATION","message":"Unsupported operation"}}}
It seems like the custom SampleApplication built to produce these logs is missing registration of the EventProcessed event. Please take a look at: https://github.com/alexa/avs-device-sdk/blob/master/CapabilityAgents/Alexa/src/AlexaInterfaceCapabilityAgent.cpp#L142
Please ensure that this event is being registered in the custom built SampleApplication.
Closing this out due to inactivity. Please feel free to reopen the ticket if you have further questions.
The SDK versions I use are alexa-smart-screen-sdk-2.6.0, apl-core-library-1.6.0 and avs-device-sdk-1.23.0
I wrote my own program following the sample app of Alexa smart screen
Due to the development environment, I rewritten SampleApplication and SmartScreenClient
Now I have a connection timeout problem.What's the reason? The key logs are as follows:
2021-08-04 10:19:15.606 [ 1a] E CapabilitiesDelegate:onDiscoveryFailure:reason=TIMEDOUT 2021-08-04 10:19:15.607 [ 1a] 5 CapabilitiesDelegate:setCapabilitiesState:newCapabilitiesState=RETRIABLE_ERROR 2021-08-04 10:19:15.608 [ 1a] 9 CapabilitiesDelegate:callingOnCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR 2021-08-04 10:19:15.609 [ 1a] 5 EndpointRegistrationManager:onCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR,callback=true
The complete log is as follows:
2021-08-04 10:18:59.572 [ 1] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.586 [ 1] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:0 2021-08-04 10:18:59.586 [ 1] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.590 [ 1] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:18:59.598 [ 1] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:18:59.599 [ 1] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:18:59.599 [ 1] E SDKPrimitivesProvider:getTimerDelegateFactory:reason=notInitialized 2021-08-04 10:18:59.611 [ 1] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.611 [ 1] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:1 2021-08-04 10:18:59.611 [ 1] 9 PowerMonitor:isActiveLocked:isActiveLocked=false [BTMIC] I: btmic_Init Init Success. [BTMIC] D: btmic_callback_thread ENTER btmic_callback_thread. [BTMIC] I: btmic_check_poll_thread rc_thread_pid=2973. [BTMIC] I: btmic_check_poll_thread setprio rc_thread_pid success [BTMIC] I: btmic_check_poll_thread ENTER. [BTMIC] I: btmic_InotifyDevice Start watching. 2021-08-04 10:18:59.714 [ 2] I AlexaClientSdkInit:initialize:sdkversion=1.23.0 2021-08-04 10:18:59.736 [ 2] 0 ConfigurationNode:initializeSuccess 2021-08-04 10:18:59.736 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:18:59.737 [ 2] 5 SDKPrimitivesProvider:withTimerDelegateFactory 2021-08-04 10:18:59.737 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:18:59.737 [ 2] 5 SDKPrimitivesProvider:initialize 2021-08-04 10:18:59.737 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:18:59.761 [ 2] 5 SQLiteDeviceSettingStorage:create 2021-08-04 10:18:59.784 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.784 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.787 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.799 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.801 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.804 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.806 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.810 [ 2] 9 WebSocket:AccessLog 2021-08-04 10:18:59.851 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.852 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:2 2021-08-04 10:18:59.852 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.852 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.852 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:3 2021-08-04 10:18:59.852 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.852 [ 2] E ConfigurationNode:getArrayFailed:reason=emptyConfigurationNode 2021-08-04 10:18:59.855 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.855 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:4 2021-08-04 10:18:59.856 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.858 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:18:59.858 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:18:59.858 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:18:59.858 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.858 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:5 2021-08-04 10:18:59.858 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.897 [ 2] 9 ThreadPool:obtainWorker:created=0,obtained=0,releasedToPool=0,releasedFromPool=0,outstanding=0 2021-08-04 10:18:59.914 [ 2] I DeviceInfo:create:result=skipDeviceType,key=deviceType 2021-08-04 10:18:59.914 [ 2] I DeviceInfo:create:result=skipFriendlyName,key=friendlyName 2021-08-04 10:18:59.914 [ 2] I DeviceInfo:create:result=skipRegistrationKey,key=registrationKey 2021-08-04 10:18:59.914 [ 2] I DeviceInfo:create:result=skipProductIdKey,key=productIdKey 2021-08-04 10:18:59.915 [ 3] 9 TaskThread:startThread:moniker= 3,duration=17449 2021-08-04 10:18:59.917 [ 3] E ConfigurationNode:getArrayFailed:reason=emptyConfigurationNode 2021-08-04 10:18:59.918 [ 3] 9 ThreadPool:obtainWorker:created=1,obtained=1,releasedToPool=0,releasedFromPool=0,outstanding=1 2021-08-04 10:18:59.918 [ 4] 9 TaskThread:startThread:moniker= 4,duration=414 2021-08-04 10:18:59.919 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.920 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:6 2021-08-04 10:18:59.920 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.920 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.920 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:7 2021-08-04 10:18:59.920 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.931 [ 2] 5 SQLiteCapabilitiesDelegateStorage:create 2021-08-04 10:18:59.939 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:18:59.939 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:8 2021-08-04 10:18:59.939 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:18:59.940 [ 2] 5 SQLiteCapabilitiesDelegateStorage:open 2021-08-04 10:18:59.958 [ 2] 9 ThreadPool:obtainWorker:created=2,obtained=2,releasedToPool=0,releasedFromPool=0,outstanding=2 2021-08-04 10:18:59.960 [ 2] 5 CapabilitiesDelegate:addCapabilitiesObserver:observer=0xaf450590 2021-08-04 10:18:59.963 [ 5] 9 TaskThread:startThread:moniker= 5,duration=5369 2021-08-04 10:19:02.876 [ 6] 5 HttpPost:doPostSucceeded:code=200 2021-08-04 10:19:02.903 [ 6] 9 ThreadPool:obtainWorker:created=3,obtained=3,releasedToPool=3,releasedFromPool=0,outstanding=0 2021-08-04 10:19:02.905 [ 3] 9 TaskThread:startThread:moniker= 3,duration=2147 ###########################
Authorized!
###########################
2021-08-04 10:19:02.906 [ 3] 9 ThreadPool:obtainWorker:created=3,obtained=4,releasedToPool=3,releasedFromPool=0,outstanding=1 2021-08-04 10:19:02.906 [ 5] 9 TaskThread:startThread:moniker= 5,duration=212 2021-08-04 10:19:02.906 [ 5] 9 WebSocketServer:writeMessageBegin 2021-08-04 10:19:02.909 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:02.909 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:02.910 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:02.910 [ 2] 5 InternetConnectionMonitor:startMonitoring 2021-08-04 10:19:02.910 [ 5] E WebSocketServer:server::send:errorCode=15,errorCategory=websocketpp 2021-08-04 10:19:02.910 [ 5] 9 WebSocketServer:writeMessageComplete 2021-08-04 10:19:02.944 [ 7] 5 InternetConnectionMonitor:testConnection 2021-08-04 10:19:02.945 [ 7] 9 HTTPContentFetcherFactory:create::Creating a new http content fetcher 2021-08-04 10:19:02.951 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:02.951 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:9 2021-08-04 10:19:02.951 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:02.955 [ 7] 9 LibCurlHttpContentFetcher:stateTransition:oldState=INITIALIZED,newState=FETCHING_HEADER:State transition 2021-08-04 10:19:02.955 [ 8] 9 LibCurlHttpContentFetcher:transferThread::start 2021-08-04 10:19:02.955 [ 2] 5 AVSGatewayManager:create 2021-08-04 10:19:02.964 [ 2] 5 AVSGatewayManager:init:avsGateway=https\://alexa.na.gateway.devices.a2z.com 2021-08-04 10:19:02.966 [ 2] 5 SynchronizeStateSenderFactory:create 2021-08-04 10:19:02.967 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.969 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.970 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.971 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.975 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.976 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.979 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:02.979 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:10 2021-08-04 10:19:02.979 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:02.979 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.980 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:02.980 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:11 2021-08-04 10:19:02.980 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:02.980 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:02.983 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:02.983 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:02.983 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:12 2021-08-04 10:19:02.983 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:02.986 [ 2] 8 DialogUXStateAggregator:timeout values in milliseconds:m_timeoutForThinkingToIdle=8000,m_shortTimeoutForThinkingToIdle=200,m_timeoutForListeningToIdle=8000 2021-08-04 10:19:02.988 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.989 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.991 [ 2] 9 ThreadPool:obtainWorker:created=3,obtained=5,releasedToPool=3,releasedFromPool=0,outstanding=2 2021-08-04 10:19:02.991 [ 4] 9 TaskThread:startThread:moniker= 4,duration=201 2021-08-04 10:19:02.996 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:02.997 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.003 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:03.004 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:03.004 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:03.004 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.004 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:13 2021-08-04 10:19:03.004 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.004 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.016 [ 2] 5 AVSConnectionManager:create::Subscribing to InternetConnectionMonitor Callbacks 2021-08-04 10:19:03.345 [ 2] 5 AVSConnectionManager:onConnectionStatusChanged:connected=false,isEnabled=false 2021-08-04 10:19:03.352 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.353 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.358 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:03.362 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=0 2021-08-04 10:19:03.365 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.365 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:14 2021-08-04 10:19:03.365 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.365 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=1 2021-08-04 10:19:03.368 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.370 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.370 [ 2] 9 SQLiteMessageStorage:isDatabaseLegacy:reason=databaseNotLegacy 2021-08-04 10:19:03.371 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.371 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=CertifiedSender 2021-08-04 10:19:03.371 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.380 [ 9] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.381 [ 9] 9 PowerMonitor:assignThreadPowerResource:threadId=2907223008 2021-08-04 10:19:03.381 [ 9] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.381 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:03.381 [ 2] 5 CertifiedSender:onConnectionStatusChanged 2021-08-04 10:19:03.381 [ 9] 9 CertifiedSender:mainloop:reason=waitingForMessage 2021-08-04 10:19:03.382 [ 9] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:03.382 [ 2] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:03.385 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.386 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.392 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=2 2021-08-04 10:19:03.392 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.392 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=DirectiveSequencer 2021-08-04 10:19:03.392 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.398 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=3 2021-08-04 10:19:03.401 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.403 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.406 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.406 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=DirectiveProcessor 2021-08-04 10:19:03.406 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.415 [ a] 9 DirectiveProcessor:processingLoop 2021-08-04 10:19:03.415 [ a] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.415 [ a] 9 PowerMonitor:assignThreadPowerResource:threadId=2882307040 2021-08-04 10:19:03.415 [ a] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.416 [ a] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:03.418 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.419 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.422 [ b] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.423 [ b] 9 PowerMonitor:assignThreadPowerResource:threadId=2878010336 2021-08-04 10:19:03.423 [ b] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.423 [ b] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:03.430 [ 2] 5 CapabilitiesDelegate:setMessageSender 2021-08-04 10:19:03.431 [ 2] 5 AVSGatewayManager:addObserver 2021-08-04 10:19:03.434 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.436 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.436 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:03.436 [ 2] 5 CapabilitiesDelegate:onConnectionStatusChanged:connectionStatus=DISCONNECTED 2021-08-04 10:19:03.442 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.442 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:15 2021-08-04 10:19:03.442 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.444 [ 2] 5 CapabilitiesDelegate:addCapabilitiesObserver:observer=0xacb11a24 2021-08-04 10:19:03.447 [ 2] 5 EndpointRegistrationManager:onCapabilitiesStateChange:state=UNINITIALIZED,error=UNINITIALIZED,callback=true 2021-08-04 10:19:03.467 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.782 [ 2] 5 EndpointRegistrationManager:onCapabilityRegistrationStatusChanged 2021-08-04 10:19:03.784 [ 2] 9 ThreadPool:obtainWorker:created=3,obtained=6,releasedToPool=3,releasedFromPool=0,outstanding=3 2021-08-04 10:19:03.785 [ c] 9 TaskThread:startThread:moniker= c,duration=473 2021-08-04 10:19:03.786 [ 2] 5 SQLiteDeviceSettingStorage:open 2021-08-04 10:19:03.792 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.792 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:16 2021-08-04 10:19:03.792 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.800 [ 2] 5 DNDSettingProtocol:create:settingName=enabled 2021-08-04 10:19:03.800 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.800 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:17 2021-08-04 10:19:03.800 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.805 [ 2] 5 DNDSettingProtocol:restoreValue:setting=Alexa.DoNotDisturb\:\:enabled 2021-08-04 10:19:03.806 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=Alexa.DoNotDisturb\:\:enabled 2021-08-04 10:19:03.807 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:03.814 [ 2] I Setting:handleSetValue:value=false3990065800 2021-08-04 10:19:03.816 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:03.817 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=4 2021-08-04 10:19:03.818 [ 2] 5 SharedAVSSettingProtocol:create:settingName=alarmVolumeRamp 2021-08-04 10:19:03.819 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.820 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:18 2021-08-04 10:19:03.820 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.826 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:03.828 [ 2] 5 SharedAVSSettingProtocol:restoreValue:setting=Alerts\:\:alarmVolumeRamp 2021-08-04 10:19:03.829 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=Alerts\:\:alarmVolumeRamp 2021-08-04 10:19:03.829 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:03.830 [ 2] 5 SharedAVSSettingProtocol:localChange:setting=Alerts\:\:alarmVolumeRamp 2021-08-04 10:19:03.835 [ 2] 9 ThreadPool:obtainWorker:created=4,obtained=7,releasedToPool=3,releasedFromPool=0,outstanding=4 2021-08-04 10:19:03.835 [ d] 9 TaskThread:startThread:moniker= d,duration=500 2021-08-04 10:19:03.836 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=5 2021-08-04 10:19:03.836 [ 2] 5 SharedAVSSettingProtocol:create:settingName=wakeWordConfirmation 2021-08-04 10:19:03.836 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.836 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:19 2021-08-04 10:19:03.836 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:03.836 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:03.836 [ 2] 5 SharedAVSSettingProtocol:restoreValue:setting=SpeechRecognizer\:\:wakeWordConfirmation 2021-08-04 10:19:03.836 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=SpeechRecognizer\:\:wakeWordConfirmation 2021-08-04 10:19:03.837 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:03.837 [ 2] 5 SharedAVSSettingProtocol:localChange:setting=SpeechRecognizer\:\:wakeWordConfirmation 2021-08-04 10:19:03.837 [ 2] 9 ThreadPool:obtainWorker:created=5,obtained=8,releasedToPool=3,releasedFromPool=0,outstanding=5 2021-08-04 10:19:03.837 [ d] I Setting:handleSetValue:value="NONE"3990065800 2021-08-04 10:19:03.837 [ e] 9 TaskThread:startThread:moniker= e,duration=317 2021-08-04 10:19:03.837 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=6 2021-08-04 10:19:03.837 [ 2] 5 SharedAVSSettingProtocol:create:settingName=speechConfirmation 2021-08-04 10:19:03.837 [ e] I Setting:handleSetValue:value="NONE"3990065800 2021-08-04 10:19:03.838 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:03.838 [ d] 5 SQLiteDeviceSettingStorage:storeSetting:key=Alerts\:\:alarmVolumeRamp,status=LOCAL_CHANGE_IN_PROGRESS 2021-08-04 10:19:03.838 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:20 2021-08-04 10:19:03.838 [ e] 5 SQLiteDeviceSettingStorage:storeSetting:key=SpeechRecognizer\:\:wakeWordConfirmation,status=LOCAL_CHANGE_IN_PROGRESS 2021-08-04 10:19:03.843 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:03.846 [ d] 5 SettingEventSender:buildEventJson:eventName=AlarmVolumeRampChanged 2021-08-04 10:19:04.171 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:04.171 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:04.171 [ 2] 5 SharedAVSSettingProtocol:restoreValue:setting=SpeechRecognizer\:\:speechConfirmation 2021-08-04 10:19:04.171 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=SpeechRecognizer\:\:speechConfirmation 2021-08-04 10:19:04.178 [ e] 5 SettingEventSender:buildEventJson:eventName=WakeWordConfirmationChanged 2021-08-04 10:19:04.179 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:04.179 [ 2] 5 SharedAVSSettingProtocol:localChange:setting=SpeechRecognizer\:\:speechConfirmation 2021-08-04 10:19:04.179 [ 2] 9 ThreadPool:obtainWorker:created=6,obtained=9,releasedToPool=4,releasedFromPool=0,outstanding=5 2021-08-04 10:19:04.179 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=7 2021-08-04 10:19:04.179 [ 2] 5 SharedAVSSettingProtocol:create:settingName=timeZone 2021-08-04 10:19:04.179 [ 5] 9 TaskThread:startThread:moniker= 5,duration=395 2021-08-04 10:19:04.179 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:04.180 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:21 2021-08-04 10:19:04.180 [ 5] I Setting:handleSetValue:value="NONE"3990065800 2021-08-04 10:19:04.180 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:04.180 [ 5] 5 SQLiteDeviceSettingStorage:storeSetting:key=SpeechRecognizer\:\:speechConfirmation,status=LOCAL_CHANGE_IN_PROGRESS 2021-08-04 10:19:04.180 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:04.180 [ 2] 5 SharedAVSSettingProtocol:restoreValue:setting=System\:\:timeZone 2021-08-04 10:19:04.180 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=System\:\:timeZone 2021-08-04 10:19:04.184 [ d] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:04.187 [ 5] 5 SettingEventSender:buildEventJson:eventName=SpeechConfirmationChanged 2021-08-04 10:19:04.187 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:04.188 [ 2] 5 SharedAVSSettingProtocol:localChange:setting=System\:\:timeZone 2021-08-04 10:19:04.188 [ 2] 9 ThreadPool:obtainWorker:created=6,obtained=10,releasedToPool=4,releasedFromPool=0,outstanding=6 2021-08-04 10:19:04.188 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=8 2021-08-04 10:19:04.188 [ f] 9 TaskThread:startThread:moniker= f,duration=463 2021-08-04 10:19:04.188 [ 2] 5 SharedAVSSettingProtocol:create:settingName=networkInfo 2021-08-04 10:19:04.188 [ f] I Setting:handleSetValue:value="Etc/GMT"3990065800 2021-08-04 10:19:04.188 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:04.188 [ f] 5 SQLiteDeviceSettingStorage:storeSetting:key=System\:\:timeZone,status=LOCAL_CHANGE_IN_PROGRESS 2021-08-04 10:19:04.188 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:22 2021-08-04 10:19:04.189 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:04.189 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:04.191 [ 2] 5 SharedAVSSettingProtocol:restoreValue:setting=System\:\:networkInfo 2021-08-04 10:19:04.191 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=System\:\:networkInfo 2021-08-04 10:19:04.192 [ d] 0 EventBuilder:buildJsonEventString:messageId=b8e9bbed-5e6c-4d2e-87b5-447a5ae5ef23,namespace=Alerts,name=AlarmVolumeRampChanged 2021-08-04 10:19:04.192 [ d] 0 EventBuilder:buildJsonEventString:event={"event"\:{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlarmVolumeRampChanged"\,"messageId"\:"b8e9bbed-5e6c-4d2e-87b5-447a5ae5ef23"}\,"payload"\:{"alarmVolumeRamp"\:"NONE"}}} 2021-08-04 10:19:04.192 [ e] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:04.525 [ e] 0 EventBuilder:buildJsonEventString:messageId=aa4dbd56-ac1d-434a-9468-6c19fe20c660,namespace=SpeechRecognizer,name=WakeWordConfirmationChanged 2021-08-04 10:19:04.526 [ e] 0 EventBuilder:buildJsonEventString:event={"event"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"WakeWordConfirmationChanged"\,"messageId"\:"aa4dbd56-ac1d-434a-9468-6c19fe20c660"}\,"payload"\:{"wakeWordConfirmation"\:"NONE"}}} 2021-08-04 10:19:04.526 [ 5] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:04.527 [ 5] 0 EventBuilder:buildJsonEventString:messageId=f2808f5f-ffc2-457c-b23c-18ce2c9e944d,namespace=SpeechRecognizer,name=SpeechConfirmationChanged 2021-08-04 10:19:04.527 [ 5] 0 EventBuilder:buildJsonEventString:event={"event"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"SpeechConfirmationChanged"\,"messageId"\:"f2808f5f-ffc2-457c-b23c-18ce2c9e944d"}\,"payload"\:{"speechConfirmation"\:"NONE"}}} 2021-08-04 10:19:04.199 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:04.271 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:04.198 [ f] 5 SettingEventSender:buildEventJson:eventName=TimeZoneChanged 2021-08-04 10:19:04.532 [ f] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:04.532 [ f] 0 EventBuilder:buildJsonEventString:messageId=6c7921da-b130-4f20-bf77-901dd81421c8,namespace=System,name=TimeZoneChanged 2021-08-04 10:19:04.533 [ 2] 5 SharedAVSSettingProtocol:localChange:setting=System\:\:networkInfo 2021-08-04 10:19:04.533 [ f] 0 EventBuilder:buildJsonEventString:event={"event"\:{"header"\:{"namespace"\:"System"\,"name"\:"TimeZoneChanged"\,"messageId"\:"6c7921da-b130-4f20-bf77-901dd81421c8"}\,"payload"\:{"timeZone"\:"Etc/GMT"}}} 2021-08-04 10:19:04.533 [ 2] 9 ThreadPool:obtainWorker:created=7,obtained=11,releasedToPool=6,releasedFromPool=0,outstanding=5 2021-08-04 10:19:04.533 [ 3] 9 TaskThread:startThread:moniker= 3,duration=193 2021-08-04 10:19:04.535 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=connectionType 2021-08-04 10:19:04.535 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=ESSID 2021-08-04 10:19:04.536 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=BSSID 2021-08-04 10:19:04.536 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=IPAddress 2021-08-04 10:19:04.536 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=subnetMask 2021-08-04 10:19:04.536 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=MACAddress 2021-08-04 10:19:04.536 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=DHCPServerAddress 2021-08-04 10:19:04.536 [ 3] 5 JsonUtils:findNode:reason=missingDirectChild,child=staticIP 2021-08-04 10:19:04.536 [ 3] I Setting:handleSetValue:value={}3990065800 2021-08-04 10:19:04.536 [ 3] 5 SQLiteDeviceSettingStorage:storeSetting:key=System\:\:networkInfo,status=LOCAL_CHANGE_IN_PROGRESS 2021-08-04 10:19:04.538 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=9 2021-08-04 10:19:04.538 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=10 2021-08-04 10:19:04.538 [ 2] 5 LocaleWakeWordsSetting:create:settingName=LocaleWakeWords 2021-08-04 10:19:04.545 [ d] 7 SettingEventSender:sendEvent:attempt=0 2021-08-04 10:19:04.545 [ e] 7 SettingEventSender:sendEvent:attempt=0 2021-08-04 10:19:04.545 [ 5] 7 SettingEventSender:sendEvent:attempt=0 2021-08-04 10:19:04.545 [ f] 7 SettingEventSender:sendEvent:attempt=0 2021-08-04 10:19:04.546 [ d] E MessageRouter:sendFailed:reason=noActiveTransport 2021-08-04 10:19:04.546 [ 3] 5 SettingEventSender:buildEventJson:eventName=NetworkInfoChanged 2021-08-04 10:19:04.547 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:04.551 [ 3] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:04.555 [ f] E MessageRouter:sendFailed:reason=noActiveTransport 2021-08-04 10:19:04.557 [ d] 7 SettingEventSender:sendEvent:status=NOT_CONNECTED 2021-08-04 10:19:04.881 [ f] 7 SettingEventSender:sendEvent:status=NOT_CONNECTED 2021-08-04 10:19:04.881 [ 3] 0 EventBuilder:buildJsonEventString:messageId=fb8c387b-ce69-43f1-8dfe-6d9a2a6eabb0,namespace=System,name=NetworkInfoChanged 2021-08-04 10:19:04.881 [ 3] 0 EventBuilder:buildJsonEventString:event={"event"\:{"header"\:{"namespace"\:"System"\,"name"\:"NetworkInfoChanged"\,"messageId"\:"fb8c387b-ce69-43f1-8dfe-6d9a2a6eabb0"}\,"payload"\:{"networkInfo"\:{}}}} 2021-08-04 10:19:04.881 [ 3] 7 SettingEventSender:sendEvent:attempt=0 2021-08-04 10:19:04.881 [ 3] E MessageRouter:sendFailed:reason=noActiveTransport 2021-08-04 10:19:04.882 [ 3] 7 SettingEventSender:sendEvent:status=NOT_CONNECTED 2021-08-04 10:19:04.631 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:04.884 [ e] E MessageRouter:sendFailed:reason=noActiveTransport 2021-08-04 10:19:04.881 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:23 2021-08-04 10:19:04.884 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:04.884 [ 5] E MessageRouter:sendFailed:reason=noActiveTransport 2021-08-04 10:19:04.884 [ 5] 7 SettingEventSender:sendEvent:status=NOT_CONNECTED 2021-08-04 10:19:04.884 [ e] 7 SettingEventSender:sendEvent:status=NOT_CONNECTED 2021-08-04 10:19:04.885 [ d] E SharedAVSSettingProtocol:localChangeFailed:reason=sendEventFailed 2021-08-04 10:19:04.885 [ 5] E SharedAVSSettingProtocol:localChangeFailed:reason=sendEventFailed 2021-08-04 10:19:04.885 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=System.locales 2021-08-04 10:19:04.886 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:04.885 [ f] E SharedAVSSettingProtocol:localChangeFailed:reason=sendEventFailed 2021-08-04 10:19:04.885 [ 3] E SharedAVSSettingProtocol:localChangeFailed:reason=sendEventFailed 2021-08-04 10:19:04.886 [ e] E SharedAVSSettingProtocol:localChangeFailed:reason=sendEventFailed 2021-08-04 10:19:04.890 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting:key=SpeechRecognizer.wakeWords 2021-08-04 10:19:04.891 [ 2] 5 SQLiteDeviceSettingStorage:loadSetting 2021-08-04 10:19:04.896 [ 2] 2 LocaleWakeWordsSetting:restoreInitialValue:wakeWords=["ALEXA"],locale=["en-US"] 2021-08-04 10:19:04.897 [ 2] 9 ThreadPool:obtainWorker:created=7,obtained=12,releasedToPool=7,releasedFromPool=0,outstanding=5 2021-08-04 10:19:04.897 [ 4] 9 TaskThread:startThread:moniker= 4,duration=210 2021-08-04 10:19:04.897 [ 4] 5 LocaleWakeWordsSetting:executeChangeValue:RequestId=1,wwRequest=["ALEXA"],localeRequest=["en-US"] 2021-08-04 10:19:04.898 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:04.900 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:04.900 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:24 2021-08-04 10:19:04.900 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:04.900 [ 4] I LocaleAssetsManager:changeAssets:Locale=["en-US"],WakeWords=["ALEXA"] 2021-08-04 10:19:04.903 [ 2] 5 ContextManager:addStateProvider 2021-08-04 10:19:04.909 [ 4] 5 SQLiteDeviceSettingStorage:storeSettings 2021-08-04 10:19:04.910 [ 4] 5 SQLiteDeviceSettingStorage:storeSettings 2021-08-04 10:19:04.921 [ 4] 5 LocaleWakeWordsSetting:notifyObserversOfSuccess:id=1 2021-08-04 10:19:04.921 [ 4] 5 SettingEventSender:buildEventJson:eventName=WakeWordsChanged 2021-08-04 10:19:04.922 [ 4] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:04.923 [ 4] 0 EventBuilder:buildJsonEventString:messageId=bc60e06e-eacc-49d4-bf31-46fa0a0637b1,namespace=SpeechRecognizer,name=WakeWordsChanged 2021-08-04 10:19:04.923 [ 4] 0 EventBuilder:buildJsonEventString:event={"event"\:{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"WakeWordsChanged"\,"messageId"\:"bc60e06e-eacc-49d4-bf31-46fa0a0637b1"}\,"payload"\:{"wakeWords"\:["ALEXA"]}}} 2021-08-04 10:19:04.923 [ 4] 7 SettingEventSender:sendEvent:attempt=0 2021-08-04 10:19:04.930 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:04.982 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:05.256 [ 4] E MessageRouter:sendFailed:reason=noActiveTransport 2021-08-04 10:19:05.256 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:25 2021-08-04 10:19:05.256 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.256 [ 4] 7 SettingEventSender:sendEvent:status=NOT_CONNECTED 2021-08-04 10:19:05.256 [ 4] E LocaleWakeWordsSetting:synchronizeWakeWordsFailed:reason=sendEventFailed 2021-08-04 10:19:05.257 [ 4] 5 SettingEventSender:buildEventJson:eventName=LocalesChanged 2021-08-04 10:19:05.258 [ 4] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:05.258 [ 4] 0 EventBuilder:buildJsonEventString:messageId=77346c8f-4969-4793-8790-1a7a2c4b8b3a,namespace=System,name=LocalesChanged 2021-08-04 10:19:05.258 [ 4] 0 EventBuilder:buildJsonEventString:event={"event"\:{"header"\:{"namespace"\:"System"\,"name"\:"LocalesChanged"\,"messageId"\:"77346c8f-4969-4793-8790-1a7a2c4b8b3a"}\,"payload"\:{"locales"\:["en-US"]}}} 2021-08-04 10:19:05.258 [ 4] 7 SettingEventSender:sendEvent:attempt=0 2021-08-04 10:19:05.259 [ 4] E MessageRouter:sendFailed:reason=noActiveTransport 2021-08-04 10:19:05.259 [ 4] 7 SettingEventSender:sendEvent:status=NOT_CONNECTED 2021-08-04 10:19:05.259 [ 4] E LocaleWakeWordsSetting:synchronizeLocaleFailed:reason=sendEventFailed 2021-08-04 10:19:05.260 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.261 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.261 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.261 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.262 [ 2] 5 PowerMonitor:getPowerResourceManager 2021-08-04 10:19:05.262 [ 2] E PowerResource:create:error=nullPowerManager 2021-08-04 10:19:05.266 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.267 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.267 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.267 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.267 [ 2] 5 PowerMonitor:getPowerResourceManager 2021-08-04 10:19:05.267 [ 2] E PowerResource:create:error=nullPowerManager 2021-08-04 10:19:05.268 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.268 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.268 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.268 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.268 [ 2] 5 PowerMonitor:getPowerResourceManager 2021-08-04 10:19:05.268 [ 2] E PowerResource:create:error=nullPowerManager 2021-08-04 10:19:05.268 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.268 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.268 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.268 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.268 [ 2] 5 PowerMonitor:getPowerResourceManager 2021-08-04 10:19:05.269 [ 2] E PowerResource:create:error=nullPowerManager 2021-08-04 10:19:05.269 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.269 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.269 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.269 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.269 [ 2] 5 PowerMonitor:getPowerResourceManager 2021-08-04 10:19:05.269 [ 2] E PowerResource:create:error=nullPowerManager 2021-08-04 10:19:05.270 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.270 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.270 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.270 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.270 [ 2] 5 PowerMonitor:getPowerResourceManager 2021-08-04 10:19:05.356 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:05.603 [ 2] E PowerResource:create:error=nullPowerManager 2021-08-04 10:19:05.605 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.605 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.605 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.628 [ 2] 5 AudioInputProcessor:getSpeechRecognizerCapabilityConfiguration:wakeWords={"wakeWords"\:[{"scopes"\:["DEFAULT"]\,"values"\:[["ALEXA"]]}]} 2021-08-04 10:19:05.631 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.631 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.632 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.640 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.640 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:26 2021-08-04 10:19:05.640 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.644 [ 2] 9 ThreadPool:obtainWorker:created=7,obtained=13,releasedToPool=7,releasedFromPool=0,outstanding=6 2021-08-04 10:19:05.644 [ c] 9 TaskThread:startThread:moniker= c,duration=240 2021-08-04 10:19:05.646 [ c] 9 ThreadPool:obtainWorker:created=7,obtained=14,releasedToPool=7,releasedFromPool=0,outstanding=7 2021-08-04 10:19:05.647 [ 10] 9 TaskThread:startThread:moniker= 10,duration=1095 2021-08-04 10:19:05.650 [ 10] 0 AudioInputProcessor:executeOnDialogUXStateChanged:newState=IDLE 2021-08-04 10:19:05.657 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.657 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:27 2021-08-04 10:19:05.657 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.659 [ 2] 5 ContextManager:addStateProvider 2021-08-04 10:19:05.663 [ 2] 9 SpeechSynthesizer:addObserver:observer=0xacb004dc 2021-08-04 10:19:05.664 [ c] 9 ThreadPool:obtainWorker:created=8,obtained=15,releasedToPool=7,releasedFromPool=0,outstanding=8 2021-08-04 10:19:05.664 [ 11] 9 TaskThread:startThread:moniker= 11,duration=441 2021-08-04 10:19:05.674 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.675 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:28 2021-08-04 10:19:05.675 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.677 [ 2] 9 PlaybackRouter:create::called 2021-08-04 10:19:05.683 [ 2] 0 ChannelVolumeManager:getSpeakerSettings 2021-08-04 10:19:05.684 [ 2] 0 ChannelVolumeManager:getSpeakerSettings 2021-08-04 10:19:05.688 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=11 2021-08-04 10:19:05.690 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.690 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:29 2021-08-04 10:19:05.690 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.704 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:05.704 [ 2] 5 SpeakerManager:executeInitializeSpeakerSettings:type=AVS_SPEAKER_VOLUME 2021-08-04 10:19:05.705 [ 2] 0 ChannelVolumeManager:getSpeakerSettings 2021-08-04 10:19:05.709 [ 2] 9 SpeakerManager:executeGetSpeakerSettingsCalled 2021-08-04 10:19:05.709 [ 2] 9 SpeakerManager:updateContextManagerCalled:speakerType=AVS_SPEAKER_VOLUME 2021-08-04 10:19:05.710 [ 2] 5 ContextManager:setState 2021-08-04 10:19:05.713 [ 2] 9 ThreadPool:obtainWorker:created=9,obtained=16,releasedToPool=7,releasedFromPool=0,outstanding=9 2021-08-04 10:19:05.714 [ 12] 9 TaskThread:startThread:moniker= 12,duration=471 2021-08-04 10:19:05.716 [ 2] 0 SpeakerManager:addChannelVolumeInterfaceIntoSpeakerMap:type=AVS_SPEAKER_VOLUME,sizeOfSpeakerSet=1 2021-08-04 10:19:05.716 [ 2] 5 SpeakerManager:executeInitializeSpeakerSettings:type=AVS_ALERTS_VOLUME 2021-08-04 10:19:05.716 [ 2] 0 ChannelVolumeManager:getSpeakerSettings 2021-08-04 10:19:05.717 [ 2] 0 SpeakerManager:addChannelVolumeInterfaceIntoSpeakerMap:type=AVS_ALERTS_VOLUME,sizeOfSpeakerSet=1 2021-08-04 10:19:05.718 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.718 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:30 2021-08-04 10:19:05.718 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.720 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.720 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:31 2021-08-04 10:19:05.720 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.721 [ 2] 5 ContextManager:addStateProvider 2021-08-04 10:19:05.726 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.726 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:32 2021-08-04 10:19:05.726 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.727 [ 2] 5 Renderer:resetSourceId 2021-08-04 10:19:05.732 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:05.732 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:05.732 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:05.732 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:05.733 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:33 2021-08-04 10:19:05.733 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:05.804 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:06.067 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.067 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:34 2021-08-04 10:19:06.067 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.077 [ 2] 5 AlertScheduler:setTimerForNextAlertLocked 2021-08-04 10:19:06.077 [ 2] 8 AlertScheduler:executeScheduleNextAlertForRendering::no work to do. 2021-08-04 10:19:06.078 [ 2] 9 SpeakerManager:getSpeakerSettingsCalled 2021-08-04 10:19:06.084 [ 2] 9 ThreadPool:obtainWorker:created=10,obtained=17,releasedToPool=12,releasedFromPool=0,outstanding=5 2021-08-04 10:19:06.084 [ d] 9 TaskThread:startThread:moniker= d,duration=288 2021-08-04 10:19:06.085 [ d] 9 SpeakerManager:executeGetSpeakerSettingsCalled 2021-08-04 10:19:06.089 [ 2] 5 ContextManager:setState 2021-08-04 10:19:06.092 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:06.094 [ 2] 9 ThreadPool:obtainWorker:created=10,obtained=18,releasedToPool=12,releasedFromPool=0,outstanding=6 2021-08-04 10:19:06.094 [ 5] 9 TaskThread:startThread:moniker= 5,duration=362 2021-08-04 10:19:06.095 [ 2] 9 SpeakerManager:addSpeakerManagerObserverCalled 2021-08-04 10:19:06.095 [ 5] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:06.096 [ 2] 9 SpeakerManager:addSpeakerManagerObserver:observer=0xaf4dc3fc 2021-08-04 10:19:06.098 [ 5] 1 AlertsCapabilityAgent:executeAddObserver:observer=0xaf4da970 2021-08-04 10:19:06.103 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:06.103 [ c] 0 DialogUXStateAggregator:executeSetState:from=IDLE,to=IDLE,validTransition=false 2021-08-04 10:19:06.105 [ 2] 5 NotificationRenderer:create 2021-08-04 10:19:06.109 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.109 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:35 2021-08-04 10:19:06.110 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.119 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.120 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:36 2021-08-04 10:19:06.120 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.122 [ 2] 5 NotificationsCapabilityAgent:init 2021-08-04 10:19:06.126 [ 2] 9 ThreadPool:obtainWorker:created=10,obtained=19,releasedToPool=12,releasedFromPool=0,outstanding=7 2021-08-04 10:19:06.127 [ f] 9 TaskThread:startThread:moniker= f,duration=253 2021-08-04 10:19:06.127 [ f] 5 NotificationsCapabilityAgent:executeInit 2021-08-04 10:19:06.128 [ f] 5 NotificationRenderer:addObserver 2021-08-04 10:19:06.130 [ 2] 5 InteractionModel:InteractionModelCapabilityAgent 2021-08-04 10:19:06.136 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.136 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:37 2021-08-04 10:19:06.136 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.136 [ 2] 5 ContextManager:addStateProvider 2021-08-04 10:19:06.137 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.137 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:38 2021-08-04 10:19:06.137 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.137 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:06.137 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:06.137 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:06.137 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.138 [ 2] 5 PowerMonitor:getPowerResourceManager 2021-08-04 10:19:06.138 [ 2] E PowerResource:create:error=nullPowerManager 2021-08-04 10:19:06.138 [ f] 5 ContextManager:addStateProvider 2021-08-04 10:19:06.139 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:06.139 [ f] 5 NotificationsCapabilityAgent:notifyObserversOfIndicatorState:indicatorState=0 2021-08-04 10:19:06.140 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:06.140 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:06.140 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:06.140 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:06.140 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:06.141 [ f] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=false,stateRequestToken=0,isEnabled=false 2021-08-04 10:19:06.142 [ f] 5 ContextManager:setState 2021-08-04 10:19:06.154 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:06.166 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:06.475 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:06.475 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:06.479 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.479 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:39 2021-08-04 10:19:06.479 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.485 [ 2] 0 AlexaPresentation:initialize::Proactive state report timer disabled 2021-08-04 10:19:06.486 [ 2] 3 AlexaPresentation:create:visualStateProvider=On 2021-08-04 10:19:06.486 [ 2] 5 ContextManager:addStateProvider 2021-08-04 10:19:06.487 [ 2] 1 AlexaPresentation:setAPLMaxVersion:APLVersion=1.5 2021-08-04 10:19:06.487 [ c] 5 AlexaPresentation:onDialogUXStateChanged:state=IDLE 2021-08-04 10:19:06.490 [ c] 9 ThreadPool:obtainWorker:created=10,obtained=20,releasedToPool=13,releasedFromPool=0,outstanding=7 2021-08-04 10:19:06.490 [ e] 9 TaskThread:startThread:moniker= e,duration=522 2021-08-04 10:19:06.495 [ 2] 5 SDKPrimitivesProvider:getInstance 2021-08-04 10:19:06.496 [ 2] 5 SDKPrimitivesProvider:getTimerDelegateFactory 2021-08-04 10:19:06.496 [ 2] 5 SDKPrimitivesProvider:isInitialized 2021-08-04 10:19:06.504 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.504 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:40 2021-08-04 10:19:06.504 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.508 [ 2] 5 AlexaPresentation:addObserver 2021-08-04 10:19:06.509 [ e] 5 AlexaPresentation:addObserverInExecutor 2021-08-04 10:19:06.511 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.511 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:41 2021-08-04 10:19:06.511 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.513 [ 2] 9 VisualCharacteristics:getVisualCharacteristicsCapabilityConfiguration 2021-08-04 10:19:06.513 [ 2] E ConfigurationNode:getArrayFailed:reason=emptyConfigurationNode 2021-08-04 10:19:06.513 [ 2] E ConfigurationNode:getArraySizeFailed:reason=emptyConfigurationNode 2021-08-04 10:19:06.514 [ 2] 5 ContextManager:addStateProvider 2021-08-04 10:19:06.515 [ c] 5 TemplateRuntime:onDialogUXStateChanged:state=IDLE 2021-08-04 10:19:06.515 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.515 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:42 2021-08-04 10:19:06.515 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.517 [ c] 9 ThreadPool:obtainWorker:created=10,obtained=21,releasedToPool=13,releasedFromPool=0,outstanding=8 2021-08-04 10:19:06.517 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.517 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:43 2021-08-04 10:19:06.517 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.519 [ 3] 9 TaskThread:startThread:moniker= 3,duration=2317 2021-08-04 10:19:06.520 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=12 2021-08-04 10:19:06.524 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.524 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:44 2021-08-04 10:19:06.524 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.529 [ 2] 9 AbstractAVSConnectionManager:addConnectionStatusObserver:engineType=1,status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:06.535 [ 2] 5 SystemCapabilityProvider:getSystemCapabilityConfiguration:locales={"locales"\:["de-DE"\,"en-AU"\,"en-CA"\,"en-GB"\,"en-IN"\,"en-US"\,"es-ES"\,"fr-CA"\,"fr-FR"\,"it-IT"\,"ja-JP"]\,"localeCombinations"\:[["en-CA"\,"fr-CA"]\,["fr-CA"\,"en-CA"]]} 2021-08-04 10:19:06.539 [ 2] 5 ApiGateway:create 2021-08-04 10:19:06.540 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.540 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:45 2021-08-04 10:19:06.540 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.544 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:06.544 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=Executor\:46 2021-08-04 10:19:06.544 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:06.547 [ 2] 5 DefaultEndpointBuilder:createDefaultEndpointBuilderInterface 2021-08-04 10:19:06.553 [ 2] 5 EndpointBuilder:finalizeAttributes 2021-08-04 10:19:06.554 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.559 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.560 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.561 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.575 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:06.894 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapabilityConfiguration 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapabilityConfiguration 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapabilityConfiguration 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapabilityConfiguration 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.895 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.896 [ 2] 5 DefaultEndpointBuilder:withCapability 2021-08-04 10:19:06.896 [ 2] 5 DefaultEndpointBuilder:withCapabilityConfiguration 2021-08-04 10:19:06.914 [ 2] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=SetLocales,handler=0xacb3c010,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:06.917 [ 2] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=SetTimeZone,handler=0xacb3bc88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:06.918 [ 2] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=ReportState,handler=0xacb3c398,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:06.918 [ 2] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=System,name=ResetUserInactivity,handler=0xaf4d842c,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:06.920 [ 2] 9 SpeakerManager:addSpeakerManagerObserverCalled 2021-08-04 10:19:06.920 [ 2] 9 SpeakerManager:addSpeakerManagerObserver:observer=0xaf47c054 2021-08-04 10:19:06.920 [ 2] 9 SpeakerManager:addSpeakerManagerObserverCalled 2021-08-04 10:19:06.920 [ 2] 9 SpeakerManager:addSpeakerManagerObserver:observer=0xaf45059c 2021-08-04 10:19:06.921 [ 2] 5 NotificationsCapabilityAgent:addObserver 2021-08-04 10:19:06.921 [ 2] 5 NotificationsCapabilityAgent:addObserver 2021-08-04 10:19:06.922 [ 2] 5 TemplateRuntime:addObserver 2021-08-04 10:19:06.922 [ 3] 5 TemplateRuntime:addObserverInExecutor 2021-08-04 10:19:06.922 [ 2] 5 AlexaPresentation:addObserver 2021-08-04 10:19:06.922 [ e] 5 AlexaPresentation:addObserverInExecutor 2021-08-04 10:19:06.922 [ 2] 9 ThreadPool:obtainWorker:created=10,obtained=22,releasedToPool=15,releasedFromPool=0,outstanding=7 2021-08-04 10:19:06.923 [ 2] 9 ThreadPool:obtainWorker:created=10,obtained=23,releasedToPool=15,releasedFromPool=0,outstanding=8 2021-08-04 10:19:06.923 [ 4] 9 TaskThread:startThread:moniker= 4,duration=299 2021-08-04 10:19:06.924 [ 10] 9 TaskThread:startThread:moniker= 10,duration=968 2021-08-04 10:19:06.924 [ 2] 9 ThreadPool:obtainWorker:created=10,obtained=24,releasedToPool=15,releasedFromPool=0,outstanding=9 2021-08-04 10:19:06.924 [ 11] 9 TaskThread:startThread:moniker= 11,duration=725 2021-08-04 10:19:06.925 [ 11] 9 ThreadPool:obtainWorker:created=10,obtained=25,releasedToPool=15,releasedFromPool=0,outstanding=10 2021-08-04 10:19:06.925 [ 13] 9 TaskThread:startThread:moniker= 13,duration=560 2021-08-04 10:19:06.928 [ f] 9 ThreadPool:obtainWorker:created=11,obtained=26,releasedToPool=15,releasedFromPool=0,outstanding=11 2021-08-04 10:19:06.928 [ 14] 9 TaskThread:startThread:moniker= 14,duration=575 #################################################
NOTIFICATION INDICATOR STATE: OFF
#################################################
2021-08-04 10:19:06.930 [ f] 9 ThreadPool:obtainWorker:created=12,obtained=27,releasedToPool=15,releasedFromPool=0,outstanding=12 2021-08-04 10:19:06.931 [ 2] 5 CapabilitiesDelegate:addCapabilitiesObserver:observer=0xaf44edbc 2021-08-04 10:19:06.931 [ 15] 9 TaskThread:startThread:moniker= 15,duration=473 2021-08-04 10:19:06.935 [ 16] 9 WebSocket:AccessLog 2021-08-04 10:19:06.939 [ 16] 9 WebSocket:AccessLog 2021-08-04 10:19:06.944 [ 2] 2 EndpointBuilder:buildImplementation:isDefault=true,#capabilities=21 2021-08-04 10:19:06.945 [ 2] 5 EndpointRegistrationManager:registerEndpoint 2021-08-04 10:19:06.947 [ 2] 9 ThreadPool:obtainWorker:created=13,obtained=28,releasedToPool=15,releasedFromPool=0,outstanding=13 2021-08-04 10:19:06.951 [ 16] 9 WebSocket:AccessLog 2021-08-04 10:19:06.995 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:07.281 [ 17] 9 TaskThread:startThread:moniker= 17,duration=333742 2021-08-04 10:19:07.281 [ 17] 5 EndpointRegistrationManager:executeRegisterEndpoint 2021-08-04 10:19:07.284 [ 16] 9 WebSocket:AccessLog 2021-08-04 10:19:07.287 [ 17] 5 EndpointRegistrationManager:registerEndpoint:emptyHandler=System 2021-08-04 10:19:07.288 [ 17] 5 DoNotDisturbCapabilityAgent:getConfiguration 2021-08-04 10:19:07.290 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.DoNotDisturb,name=SetDoNotDisturb,handler=0xacb141a8,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.293 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=InteractionModel,name=RequestProcessingCompleted,handler=0xacb394b0,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.293 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=InteractionModel,name=RequestProcessingStarted,handler=0xacb394b0,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.294 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=InteractionModel,name=NewDialogRequest,handler=0xacb394b0,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.294 [ 17] 5 EndpointRegistrationManager:registerEndpoint:emptyHandler=VisualActivityTracker 2021-08-04 10:19:07.294 [ 17] 5 AlexaPresentation:getConfiguration 2021-08-04 10:19:07.295 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.Presentation.APL,name=SendTokenListData,handler=0xacb3a310,policy= Mediums:MEDIUM_VISUAL10 .isBlocking:False 2021-08-04 10:19:07.295 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.Presentation.APL,name=RenderDocument,handler=0xacb3a310,policy= Mediums:MEDIUM_VISUAL10 .isBlocking:True 2021-08-04 10:19:07.295 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.Presentation.APL,name=ExecuteCommands,handler=0xacb3a310,policy= Mediums:MEDIUMS_AUDIO_AND_VISUAL11 .isBlocking:True 2021-08-04 10:19:07.295 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.Presentation.APL,name=SendIndexListData,handler=0xacb3a310,policy= Mediums:MEDIUM_VISUAL10 .isBlocking:False 2021-08-04 10:19:07.296 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.Presentation.APL,name=UpdateIndexListData,handler=0xacb3a310,policy= Mediums:MEDIUM_VISUAL10 .isBlocking:False 2021-08-04 10:19:07.296 [ 17] 5 EndpointRegistrationManager:registerEndpoint:emptyHandler=PlaybackController 2021-08-04 10:19:07.296 [ 17] 5 EndpointRegistrationManager:registerEndpoint:emptyHandler=AudioActivityTracker 2021-08-04 10:19:07.296 [ 16] 9 WebSocket:AccessLog 2021-08-04 10:19:07.296 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=ClearQueue,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.296 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.FavoritesController,name=Unfavorite,handler=0xaf4dad88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.296 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.SeekController,name=SetSeekPosition,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.296 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=DisableShuffle,handler=0xaf4dad88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.296 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=EnableShuffle,handler=0xaf4dad88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.296 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=DisableRepeat,handler=0xaf4dad88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.306 [ 16] I WebSocketServer:Listening for websocket connections:interface=0.0.0.0,port=8933 2021-08-04 10:19:07.381 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=EnableRepeat,handler=0xaf4dad88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.FavoritesController,name=Favorite,handler=0xaf4dad88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaylistController,name=EnableRepeatOne,handler=0xaf4dad88,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Rewind,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=UpdateProgressReportInterval,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=StartOver,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Next,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.SeekController,name=AdjustSeekPosition,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Stop,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Previous,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Pause,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.630 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=FastForward,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.631 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.PlaybackController,name=Play,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.631 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=AudioPlayer,name=Play,handler=0xaf4dad88,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.631 [ 17] 5 ApiGateway:getConfiguration 2021-08-04 10:19:07.631 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alexa.ApiGateway,name=SetGateway,handler=0xacb3e038,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.631 [ 17] 5 TemplateRuntime:getConfiguration 2021-08-04 10:19:07.632 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=TemplateRuntime,name=RenderPlayerInfo,handler=0xacb3aee0,policy= Mediums:MEDIUM_VISUAL10 .isBlocking:False 2021-08-04 10:19:07.632 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=TemplateRuntime,name=RenderTemplate,handler=0xacb3aee0,policy= Mediums:MEDIUM_VISUAL10 .isBlocking:False 2021-08-04 10:19:07.632 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechSynthesizer,name=Speak,handler=0xaf4d91e8,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:True 2021-08-04 10:19:07.730 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:07.966 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Notifications,name=ClearIndicator,handler=0xacb1633c,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.966 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Notifications,name=SetIndicator,handler=0xacb1633c,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.967 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=SetMute,handler=0xaf4da450,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.967 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=AdjustVolume,handler=0xaf4da450,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.967 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Speaker,name=SetVolume,handler=0xaf4da450,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.967 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=SetSpeechConfirmation,handler=0xaf4d8a28,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=StopCapture,handler=0xaf4d8a28,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=ExpectSpeech,handler=0xaf4d8a28,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:True 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=SetWakeWords,handler=0xaf4d8a28,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=SetEndOfSpeechOffset,handler=0xaf4d8a28,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=SpeechRecognizer,name=SetWakeWordConfirmation,handler=0xaf4d8a28,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetAlarmVolumeRamp,handler=0xaf4dc390,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=AdjustVolume,handler=0xaf4dc390,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.968 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetAlert,handler=0xaf4dc390,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.969 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=DeleteAlerts,handler=0xaf4dc390,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.969 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=DeleteAlert,handler=0xaf4dc390,policy= Mediums:MEDIUMS_NONE00 .isBlocking:False 2021-08-04 10:19:07.969 [ 17] 9 DirectiveRouter:addDirectiveHandlers:action=added,namespace=Alerts,name=SetVolume,handler=0xaf4dc390,policy= Mediums:MEDIUM_AUDIO01 .isBlocking:False 2021-08-04 10:19:07.972 [ 17] 5 CapabilitiesDelegate:addOrUpdateEndpoint 2021-08-04 10:19:07.985 [ 17] 9 ThreadPool:obtainWorker:created=14,obtained=29,releasedToPool=28,releasedFromPool=0,outstanding=1 2021-08-04 10:19:07.985 [ 5] 9 TaskThread:startThread:moniker= 5,duration=235 2021-08-04 10:19:07.986 [ 5] 5 CapabilitiesDelegate:executeSendPendingEndpoints 2021-08-04 10:19:07.986 [ 5] 5 CapabilitiesDelegate:executeSendPendingEndpoints:Deferred=Not connected 2021-08-04 10:19:07.986 [ 17] 2 EndpointRegistrationManager:executeRegisterEndpoint:result=finished 2021-08-04 10:19:08.066 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:08.320 [ 2] 5 AVSGatewayManager:setAVSGatewayAssigner 2021-08-04 10:19:08.321 [ 2] I MessageRouter:setAVSGateway:avsGateway=https\://alexa.na.gateway.devices.a2z.com 2021-08-04 10:19:08.321 [ 2] 5 AVSConnectionManager:enable 2021-08-04 10:19:08.321 [ 2] I MessageRouter:enable 2021-08-04 10:19:08.321 [ 2] I MessageRouter:setConnectionStatusLocked:status=PENDING,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:08.321 [ 2] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=PENDING 2021-08-04 10:19:08.323 [ 2] 9 ThreadPool:obtainWorker:created=14,obtained=30,releasedToPool=28,releasedFromPool=0,outstanding=2 2021-08-04 10:19:08.323 [ 12] 9 TaskThread:startThread:moniker= 12,duration=232 2021-08-04 10:19:08.325 [ 2] 5 LibcurlHTTP2ConnectionFactory:createHTTP2Connection 2021-08-04 10:19:08.340 [ 18] 5 LibcurlHTTP2Connection:networkLoop 2021-08-04 10:19:08.345 [ 2] 5 HTTP2Transport:create:authDelegate=0xaf451460,avsGateway=https\://alexa.na.gateway.devices.a2z.com,http2Connection=0xacb3dbf8,messageConsumer=0xacb00d70,attachmentManager=0xacb00ad8,transportObserver=0xacb00d6c,postConnectFactory=0xaf4616a0,sharedRequestQueue=0xacb00f1c 2021-08-04 10:19:08.348 [ 2] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=13 2021-08-04 10:19:08.354 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:08.355 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=HTTP2Transport_mainLoop 2021-08-04 10:19:08.355 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:08.355 [ 2] 9 PowerMonitor:getInstance 2021-08-04 10:19:08.355 [ 2] 9 PowerMonitor:createLocalPowerResource:identifier=HTTP2Transport_requestActivityResource 2021-08-04 10:19:08.355 [ 2] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:08.357 [ 2] I MessageRouter:createActiveTransportLocked:transport=0xacb3e818,sizeOf m_transports=0 2021-08-04 10:19:08.358 [ 2] I HTTP2Transport:connect:this=0xacb3e818 2021-08-04 10:19:08.358 [ 2] I HTTP2Transport:setStateLocked:this=0xacb3e818,currentState=INIT,newState=AUTHORIZING,changedReason=ACL_CLIENT_REQUEST 2021-08-04 10:19:08.359 [ 2] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:08.365 [ 19] 7 HTTP2Transport:mainLoop:this=0xacb3e818 2021-08-04 10:19:08.365 [ 19] 9 PowerMonitor:getInstance 2021-08-04 10:19:08.365 [ 19] 9 PowerMonitor:assignThreadPowerResource:threadId=2813559776 2021-08-04 10:19:08.365 [ 19] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:08.366 [ 2] I MessageRouter:setAsActiveTransport:transport=0xacb3e818,sizeOf m_transports=1 2021-08-04 10:19:08.369 [ 12] 0 AVSConnectionManager:onConnectionStatusChanged:status=PENDING,engine_count=1 2021-08-04 10:19:08.377 [ 19] 5 SynchronizeStateSenderFactory:createPostConnectOperation 2021-08-04 10:19:08.377 [ 19] 5 PostConnectSynchronizeStateSender:create 2021-08-04 10:19:08.379 [ 19] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=14 2021-08-04 10:19:08.380 [ 12] 5 AbstractAVSConnectionManager:notifyObservers::EngineConnectionStatusDetail:engineType=1,status=PENDING,reason=ACL_CLIENT_REQUEST 2021-08-04 10:19:08.381 [ 12] 9 ThreadPool:obtainWorker:created=14,obtained=31,releasedToPool=28,releasedFromPool=0,outstanding=3 2021-08-04 10:19:08.381 [ 12] 5 CapabilitiesDelegate:onConnectionStatusChanged:connectionStatus=PENDING 2021-08-04 10:19:08.381 [ 12] 9 ThreadPool:obtainWorker:created=14,obtained=32,releasedToPool=28,releasedFromPool=0,outstanding=4 2021-08-04 10:19:08.381 [ d] 9 TaskThread:startThread:moniker= d,duration=407 2021-08-04 10:19:08.381 [ d] 0 DialogUXStateAggregator:executeSetState:from=IDLE,to=IDLE,validTransition=false 2021-08-04 10:19:08.381 [ 12] 9 ThreadPool:obtainWorker:created=14,obtained=33,releasedToPool=28,releasedFromPool=0,outstanding=5 2021-08-04 10:19:08.381 [ 4] 9 TaskThread:startThread:moniker= 4,duration=173 2021-08-04 10:19:08.382 [ 12] 5 CertifiedSender:onConnectionStatusChanged 2021-08-04 10:19:08.382 [ c] 9 TaskThread:startThread:moniker= c,duration=157 2021-08-04 10:19:08.382 [ 12] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:08.382 [ 4] 9 ThreadPool:obtainWorker:created=14,obtained=34,releasedToPool=28,releasedFromPool=0,outstanding=6 2021-08-04 10:19:08.382 [ c] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST #######################################
ALEXA STATE: CONNECTING
#######################################
2021-08-04 10:19:08.382 [ e] 9 TaskThread:startThread:moniker= e,duration=730 2021-08-04 10:19:08.384 [ 19] 5 AVSGatewayManager:createPostConnectOperation 2021-08-04 10:19:08.419 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:08.715 [ e] 9 WebSocketServer:writeMessageBegin 2021-08-04 10:19:08.715 [ e] E WebSocketServer:server::send:errorCode=15,errorCategory=websocketpp 2021-08-04 10:19:08.715 [ e] 9 WebSocketServer:writeMessageComplete 2021-08-04 10:19:08.715 [ 19] 5 AVSGatewayManager:createPostConnectOperation::Gateway already verified, skipping gateway verification step 2021-08-04 10:19:08.715 [ 19] 5 CapabilitiesDelegate:createPostConnectOperation 2021-08-04 10:19:08.715 [ 19] 5 CapabilitiesDelegate:resetCurrentDiscoveryEventSender 2021-08-04 10:19:08.716 [ 19] 5 CapabilitiesDelegate:moveInFlightEndpointsToPendingLocked 2021-08-04 10:19:08.718 [ 19] 5 SQLiteCapabilitiesDelegateStorage:load 2021-08-04 10:19:08.719 [ 19] 5 CapabilitiesDelegate:createPostConnectOperation:num endpoints stored=0 2021-08-04 10:19:08.719 [ 19] 5 CapabilitiesDelegate:createPostConnectOperation:num endpoints to add=1,num endpoints to delete=0 2021-08-04 10:19:08.721 [ 19] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=15 2021-08-04 10:19:08.721 [ 19] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=16 2021-08-04 10:19:08.721 [ 19] 9 ConditionVariableWrapper:ConditionVariableWrapper:id=17 2021-08-04 10:19:08.723 [ 19] 5 CapabilitiesDelegate:setDiscoveryEventSender 2021-08-04 10:19:08.724 [ 19] 5 DiscoveryEventSender:addDiscoveryStatusObserver 2021-08-04 10:19:08.728 [ 19] 9 PowerMonitor:getInstance 2021-08-04 10:19:08.728 [ 19] 9 PowerMonitor:createLocalPowerResource:identifier=PostConnectSequencer_mainLoop 2021-08-04 10:19:08.728 [ 19] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:08.731 [ 19] 5 PostConnectSequencer:doPostConnect 2021-08-04 10:19:08.739 [ 1a] 5 PostConnectSequencer:mainLoop 2021-08-04 10:19:08.739 [ 1a] 9 PowerMonitor:getInstance 2021-08-04 10:19:08.739 [ 1a] 9 PowerMonitor:assignThreadPowerResource:threadId=2948592608 2021-08-04 10:19:08.739 [ 1a] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:08.739 [ 19] I HTTP2Transport:handleAuthorizing:this=0xacb3e818 2021-08-04 10:19:08.740 [ 1a] 5 PostConnectCapabilitiesPublisher:performOperation 2021-08-04 10:19:08.740 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvents 2021-08-04 10:19:08.740 [ 19] I HTTP2Transport:onAuthStateChange:this=0xacb3e818,newState=REFRESHED,error=SUCCESS 2021-08-04 10:19:08.740 [ 19] I HTTP2Transport:setStateLocked:this=0xacb3e818,currentState=AUTHORIZING,newState=CONNECTING,changedReason=SUCCESS 2021-08-04 10:19:08.740 [ 19] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:08.740 [ 1a] 5 DiscoveryEventSender:onAuthStateChange:state=REFRESHED,error=SUCCESS 2021-08-04 10:19:08.740 [ 1a] 5 ConditionVariableWrapper:notifyOne 2021-08-04 10:19:08.740 [ 1a] 5 DiscoveryEventSender:sendAddOrUpdateReportEvents:num endpoints=1 2021-08-04 10:19:08.741 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEventWithRetries 2021-08-04 10:19:08.741 [ 1a] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:08.742 [ 19] 9 ConditionVariableWrapper:waitForInner:duration=3599999999998789417 2021-08-04 10:19:08.742 [ 1a] 5 DiscoveryUtils:getAddOrUpdateReportEventJson 2021-08-04 10:19:08.742 [ 19] I HTTP2Transport:handleConnecting:this=0xacb3e818 2021-08-04 10:19:08.743 [ 19] 9 DownchannelHandler:create:context=0xacb3e868 2021-08-04 10:19:08.743 [ 1a] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:08.743 [ 19] 5 ExchangeHandler:ExchangeHandler:context=0xacb3e868 2021-08-04 10:19:08.744 [ 19] 9 DownchannelHandler:DownchannelHandler:context=0xacb3e868 2021-08-04 10:19:08.744 [ 19] 9 PowerMonitor:getInstance 2021-08-04 10:19:08.744 [ 19] 9 PowerMonitor:createLocalPowerResource:identifier=DownchannelHandler 2021-08-04 10:19:08.744 [ 19] 9 PowerMonitor:isActiveLocked:isActiveLocked=false 2021-08-04 10:19:08.746 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent 2021-08-04 10:19:08.750 [ 19] 9 MimeResponseSink:MimeResponseSink:handler=0xaf403df0 2021-08-04 10:19:08.761 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.082 [ 1a] 7 HTTP2Transport:sendMessage:this=0xacb3e818 2021-08-04 10:19:09.084 [ 1a] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:09.084 [ 19] 9 HTTP2MimeResponseDecoder:HTTP2MimeResponseDecoder 2021-08-04 10:19:09.087 [ 19] 7 HTTP2Transport:createAndSendRequest:this=0xacb3e818,type=GET 2021-08-04 10:19:09.093 [ 19] 9 DownchannelHandler:getRequestHeaderLines 2021-08-04 10:19:09.098 [ 19] 9 ConditionVariableWrapper:waitForInner:duration=3599999999642676835 2021-08-04 10:19:09.098 [ 18] 9 LibcurlHTTP2Connection:insertActiveStream:handle=0xacb411e0,streamId=AVSDownChannel-1 2021-08-04 10:19:09.179 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.280 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.380 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.480 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.580 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.681 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.781 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.881 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.908 [ 8] 9 LibCurlHttpContentFetcher:transferThread:numTransfersLeft=1 2021-08-04 10:19:09.909 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.910 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.910 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.910 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback:type=content-length,length=419 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:headerCallback::CALLED 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:bodyCallback::End of header found. 2021-08-04 10:19:09.911 [ 8] 9 LibCurlHttpContentFetcher:stateTransition:oldState=FETCHING_HEADER,newState=HEADER_DONE:State transition 2021-08-04 10:19:09.912 [ 7] 9 InternetConnectionMonitor:testConnection:contentLength=419 2021-08-04 10:19:09.912 [ 7] 9 LibCurlHttpContentFetcher:stateTransition:oldState=HEADER_DONE,newState=FETCHING_BODY:State transition 2021-08-04 10:19:10.013 [ 8] 9 LibCurlHttpContentFetcher:bodyCallback:totalContentReceived=419,contentLength=419,currentContentReceived=419,remaining=0,totalBytesWritten=419 2021-08-04 10:19:10.013 [ 8] 7 CurlEasyHandleWrapper:getEffectiveUrl:effectiveURL=http\://spectrum.s3.amazonaws.com/kindle-wifi/wifistub.html 2021-08-04 10:19:10.016 [ 8] 9 LibCurlHttpContentFetcher:transferThread::end 2021-08-04 10:19:10.016 [ 8] 9 LibCurlHttpContentFetcher:stateTransition:oldState=FETCHING_BODY,newState=BODY_DONE:State transition 2021-08-04 10:19:10.125 [ 7] 9 InternetConnectionMonitor:testConnection::alreadyReadAllBytes 2021-08-04 10:19:10.125 [ 7] 9 InternetConnectionMonitor:testConnection::Finished reading 2021-08-04 10:19:10.125 [ 7] 5 InternetConnectionMonitor:updateConnectionStatus:connected=true 2021-08-04 10:19:10.125 [ 7] 5 InternetConnectionMonitor:notifyObserversLocked 2021-08-04 10:19:10.126 [ 7] 5 AVSConnectionManager:onConnectionStatusChanged:connected=true,isEnabled=true 2021-08-04 10:19:10.126 [ 7] I MessageRouter:onWakeConnectionRetry 2021-08-04 10:19:10.126 [ 7] I MessageRouter:onWakeConnectionRetry:m_activeTransport=0xacb3e818 2021-08-04 10:19:10.126 [ 7] I HTTP2Transport:onWakeConnectionRetry:this=0xacb3e818 2021-08-04 10:19:10.129 [ 7] 9 LibCurlHttpContentFetcher:~LibCurlHttpContentFetcher 2021-08-04 10:19:11.098 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSDownChannel-1,size=1,nmemb=13,userData=0xaf42b910 2021-08-04 10:19:11.099 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveResponseCode:responseCode=200 2021-08-04 10:19:11.099 [ 18] 9 MimeResponseSink:onReceiveResponseCode:responseCode=200 2021-08-04 10:19:11.100 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.100 [ 18] 5 DownchannelHandler:onReceiveResponseCode:responseCode=200 2021-08-04 10:19:11.100 [ 18] I HTTP2Transport:onDownchannelConnected:this=0xacb3e818 2021-08-04 10:19:11.100 [ 18] I HTTP2Transport:setStateLocked:this=0xacb3e818,currentState=CONNECTING,newState=POST_CONNECTING,changedReason=SUCCESS 2021-08-04 10:19:11.100 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:11.100 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=HTTP/2 200
2021-08-04 10:19:11.100 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=HTTP/2 200
2021-08-04 10:19:11.100 [ 19] I HTTP2Transport:handlePostConnecting:this=0xacb3e818 2021-08-04 10:19:11.100 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.100 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSDownChannel-1,size=1,nmemb=64,userData=0xaf42b910 2021-08-04 10:19:11.100 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=access-control-allow-headers\: authorization\,x-amz-access-token
2021-08-04 10:19:11.100 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=access-control-allow-headers\: authorization\,x-amz-access-token
2021-08-04 10:19:11.101 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.101 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSDownChannel-1,size=1,nmemb=32,userData=0xaf42b910 2021-08-04 10:19:11.101 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:11.101 [ 19] 7 HTTP2Transport:sendMessagesAndPings:this=0xacb3e818,whileState=POST_CONNECTING 2021-08-04 10:19:11.101 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:11.101 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.101 [ 19] 9 ConditionVariableWrapper:waitForInner:duration=299999640833 2021-08-04 10:19:11.103 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSDownChannel-1,size=1,nmemb=81,userData=0xaf42b910 2021-08-04 10:19:11.103 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=content-type\: multipart/related; boundary\=------abcde123; type\=application/json
2021-08-04 10:19:11.103 [ 19] 7 MessageRequestHandler:create:context=0xacb3e868,messageRequest=0xaf601e80 2021-08-04 10:19:11.103 [ 19] 5 ExchangeHandler:ExchangeHandler:context=0xacb3e868 2021-08-04 10:19:11.104 [ 19] 7 MessageRequestHandler:MessageRequestHandler:context=0xacb3e868,messageRequest=0xaf601e80 2021-08-04 10:19:11.105 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:boundary=------abcde123 2021-08-04 10:19:11.105 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=content-type\: multipart/related; boundary\=------abcde123; type\=application/json
2021-08-04 10:19:11.105 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.105 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSDownChannel-1,size=1,nmemb=20,userData=0xaf42b910 2021-08-04 10:19:11.105 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\:
2021-08-04 10:19:11.105 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\:
2021-08-04 10:19:11.105 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.105 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 2021-08-04 10:19:11.105 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSDownChannel-1,size=1,nmemb=2,userData=0xaf42b910 2021-08-04 10:19:11.105 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=
2021-08-04 10:19:11.106 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=
2021-08-04 10:19:11.106 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.106 [ 18] 9 LibcurlHTTP2Request:writeCallback:id=AVSDownChannel-1,size=1,nmemb=18,userData=0xaf42b910 2021-08-04 10:19:11.106 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveData:size=18 2021-08-04 10:19:11.109 [ 19] 9 HTTP2MimeRequestEncoder:HTTP2MimeRequestEncoder:boundary=WhooHooZeerOoonie\=,source=0xaf40405c 2021-08-04 10:19:11.441 [ 19] 9 MimeResponseSink:MimeResponseSink:handler=0xaf404060 2021-08-04 10:19:11.441 [ 19] 9 HTTP2MimeResponseDecoder:HTTP2MimeResponseDecoder 2021-08-04 10:19:11.441 [ 19] 7 HTTP2Transport:onMessageRequestSent:this=0xacb3e818,countOfUnfinishedMessageHandlers=1 2021-08-04 10:19:11.441 [ 19] 7 HTTP2Transport:createAndSendRequest:this=0xacb3e818,type=POST 2021-08-04 10:19:11.442 [ 19] 9 HTTP2MimeRequestEncoder:getRequestHeaderLines 2021-08-04 10:19:11.442 [ 19] 9 MessageRequestHandler:getRequestHeaderLines 2021-08-04 10:19:11.442 [ 19] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.445 [ 19] 0 MessageRequestHandler:EventSent 2021-08-04 10:19:11.445 [ 19] 9 ConditionVariableWrapper:waitForInner:duration=299997025833 2021-08-04 10:19:11.545 [ 18] 9 LibcurlHTTP2Connection:insertActiveStream:handle=0xacb42270,streamId=AVSEvent-3 2021-08-04 10:19:11.547 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-3,size=1,nmemb=65536,userData=0xaf4153f8 2021-08-04 10:19:11.547 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=NEW 2021-08-04 10:19:11.556 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=NEW,newState=GETTING_1ST_PART_HEADERS 2021-08-04 10:19:11.556 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:11.556 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.557 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_1ST_PART_HEADERS,newState=SENDING_1ST_BOUNDARY 2021-08-04 10:19:11.558 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_1ST_BOUNDARY,newState=SENDING_PART_HEADERS 2021-08-04 10:19:11.558 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_HEADERS,newState=SENDING_PART_DATA 2021-08-04 10:19:11.558 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=65429 2021-08-04 10:19:11.558 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.559 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=62472 2021-08-04 10:19:11.559 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.559 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_DATA,newState=SENDING_END_BOUNDARY 2021-08-04 10:19:11.559 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_END_BOUNDARY,newState=GETTING_NTH_PART_HEADERS 2021-08-04 10:19:11.559 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:11.559 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:11.559 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_NTH_PART_HEADERS,newState=SENDING_TERMINATING_DASHES 2021-08-04 10:19:11.559 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_TERMINATING_DASHES,newState=DONE 2021-08-04 10:19:11.561 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-3,size=1,nmemb=65536,userData=0xaf4153f8 2021-08-04 10:19:11.561 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=DONE 2021-08-04 10:19:13.260 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-3,size=1,nmemb=13,userData=0xaf4153f8 2021-08-04 10:19:13.260 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:13.260 [ 18] 9 MimeResponseSink:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:13.260 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.260 [ 18] 7 MessageRequestHandler:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:13.260 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:13.260 [ 18] 7 HTTP2Transport:onMessageRequestAcknowledged:this=0xacb3e818 2021-08-04 10:19:13.261 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:13.269 [ 18] 7 MessageRequestHandler:responseCodeTranslated:responseStatus=SUCCESS_ACCEPTED 2021-08-04 10:19:13.269 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:13.269 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:13.269 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.269 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-3,size=1,nmemb=56,userData=0xaf4153f8 2021-08-04 10:19:13.269 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: f7e139a1-9174-42de-911c-ea476bc7ebab
2021-08-04 10:19:13.269 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: f7e139a1-9174-42de-911c-ea476bc7ebab
2021-08-04 10:19:13.269 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.269 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: f7e139a1-9174-42de-911c-ea476bc7ebab 2021-08-04 10:19:13.269 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-3,size=1,nmemb=40,userData=0xaf4153f8 2021-08-04 10:19:13.269 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:13.270 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:13.270 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.270 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-3,size=1,nmemb=82,userData=0xaf4153f8 2021-08-04 10:19:13.270 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-3
2021-08-04 10:19:13.270 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-3
2021-08-04 10:19:13.270 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.270 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-3 2021-08-04 10:19:13.270 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-3,size=1,nmemb=32,userData=0xaf4153f8 2021-08-04 10:19:13.270 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:13.270 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:13.270 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.270 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-3,size=1,nmemb=2,userData=0xaf4153f8 2021-08-04 10:19:13.270 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=
2021-08-04 10:19:13.270 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=
2021-08-04 10:19:13.270 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.271 [ 18] 9 HTTP2MimeResponseDecoder:onResponseFinished:status=COMPLETE 2021-08-04 10:19:13.272 [ 18] 9 MimeResponseSink:onResponseFinished:status=COMPLETE 2021-08-04 10:19:13.272 [ 18] 7 MessageRequestHandler:onResponseFinished:status=COMPLETE,responseCode=202 2021-08-04 10:19:13.272 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:13.272 [ 18] 7 MessageRequestHandler:reportMessageRequestFinished 2021-08-04 10:19:13.272 [ 18] 7 HTTP2Transport:onMessageRequestFinished:this=0xacb3e818,countOfUnfinishedMessageHandlers=0 2021-08-04 10:19:13.272 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:13.272 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent:Discovery event status=SUCCESS_ACCEPTED 2021-08-04 10:19:13.272 [ 18] 7 LibcurlHTTP2Connection:streamFinished:streamId=AVSEvent-3,result=No error,CURLcode=0 2021-08-04 10:19:13.605 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent::waiting for Event Processed directive 2021-08-04 10:19:13.605 [ 18] 9 LibcurlHTTP2Connection:releaseStream:streamId=AVSEvent-3 2021-08-04 10:19:13.605 [ 1a] 9 ConditionVariableWrapper:waitForInner:duration=2000000000 2021-08-04 10:19:13.611 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:13.611 [ 18] 7 MessageRequestHandler:reportMessageRequestFinished 2021-08-04 10:19:13.613 [ 18] 9 LibcurlHTTP2Request:writeCallback:id=AVSDownChannel-1,size=1,nmemb=272,userData=0xaf42b910 2021-08-04 10:19:13.614 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveData:size=272 2021-08-04 10:19:13.616 [ 18] 9 MimeResponseSink:onBeginMimePart 2021-08-04 10:19:13.616 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.616 [ 18] 9 MimeResponseSink:JsonContentDetected 2021-08-04 10:19:13.617 [ 18] 9 MimeResponseSink:onReceiveMimeData:size=218 2021-08-04 10:19:13.617 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.617 [ 18] 9 MimeResponseSink:onEndMimePart 2021-08-04 10:19:13.617 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:13.618 [ 18] 9 ThreadPool:obtainWorker:created=14,obtained=35,releasedToPool=35,releasedFromPool=0,outstanding=0 2021-08-04 10:19:13.618 [ 13] 9 TaskThread:startThread:moniker= 13,duration=136 2021-08-04 10:19:13.619 [ 13] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2021-08-04 10:19:13.620 [ 13] 5 AvsDirective:parseHeader:payloadVersion=3 2021-08-04 10:19:13.620 [ 13] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2021-08-04 10:19:13.620 [ 13] 5 AvsDirective:parseHeader:eventCorrelationToken=86224c9b-d028-4c9f-868a-441130a11984 2021-08-04 10:19:13.624 [ 13] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2021-08-04 10:19:13.624 [ 13] 0 AvsDirective:parseEndpoint::noEndpoint 2021-08-04 10:19:13.648 [ 13] I DirectiveSequencer:onDirective:directive=namespace\:Alexa\,name\:EventProcessed\,messageId\:9c49b010-2711-4d7d-ab72-7382291ffce8\,dialogRequestId\:\,correlationToken\:\,eventCorrelationToken\:86224c9b-d028-4c9f-868a-441130a11984\,payloadVersion\:3\,instance\: 2021-08-04 10:19:13.649 [ 13] 5 ConditionVariableWrapper:notifyOne 2021-08-04 10:19:13.656 [ b] 5 DirectiveRouter:getHandlerAndPolicyLocked::noMatcher 2021-08-04 10:19:13.662 [ b] 5 DirectiveRouter:getHandlerAndPolicyLocked::noMatcher 2021-08-04 10:19:13.662 [ b] 0 DirectiveRouter:noHandlerFoundForDirective:namespace=Alexa,name=EventProcessed 2021-08-04 10:19:13.662 [ b] W DirectiveRouter:preHandleDirectiveFailed:messageId=9c49b010-2711-4d7d-ab72-7382291ffce8,reason=noHandlerRegistered 2021-08-04 10:19:13.664 [ b] I DirectiveSequencer:sendingExceptionEncountered:messageId=9c49b010-2711-4d7d-ab72-7382291ffce8 2021-08-04 10:19:13.665 [ b] 5 AVSContext:toJson 2021-08-04 10:19:13.668 [ b] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:13.668 [ b] 0 EventBuilder:buildJsonEventString:messageId=7a4656bb-b1f9-4dd2-a9ca-148569da638d,namespace=System,name=ExceptionEncountered 2021-08-04 10:19:13.668 [ b] 0 EventBuilder:buildJsonEventString:event={"context"\:{"properties"\:[]}\,"event"\:{"header"\:{"namespace"\:"System"\,"name"\:"ExceptionEncountered"\,"messageId"\:"7a4656bb-b1f9-4dd2-a9ca-148569da638d"}\,"payload"\:{"unparsedDirective"\:"{\"directive\"\:{\"header\"\:{\"namespace\"\:\"Alexa\"\,\"name\"\:\"EventProcessed\"\,\"messageId\"\:\"9c49b010-2711-4d7d-ab72-7382291ffce8\"\,\"payloadVersion\"\:\"3\"\,\"eventCorrelationToken\"\:\"86224c9b-d028-4c9f-868a-441130a11984\"}\,\"payload\"\:{}}}"\,"error"\:{"type"\:"UNSUPPORTED_OPERATION"\,"message"\:"Unsupported operation"}}}} 2021-08-04 10:19:13.670 [ b] 7 HTTP2Transport:onRequestEnqueued:this=0xacb3e818 2021-08-04 10:19:13.670 [ b] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:13.673 [ b] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:15.606 [ 1a] E DiscoveryEventSender:sendDiscoveryEventFailed:reason=Timeout on waiting for Event Processed Directive 2021-08-04 10:19:15.606 [ 1a] 5 DiscoveryEventSender:reportDiscoveryStatus 2021-08-04 10:19:15.606 [ 1a] 5 CapabilitiesDelegate:onDiscoveryFailure 2021-08-04 10:19:15.606 [ 1a] E CapabilitiesDelegate:onDiscoveryFailure:reason=TIMEDOUT 2021-08-04 10:19:15.607 [ 1a] 5 CapabilitiesDelegate:setCapabilitiesState:newCapabilitiesState=RETRIABLE_ERROR 2021-08-04 10:19:15.608 [ 1a] 9 CapabilitiesDelegate:callingOnCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR 2021-08-04 10:19:15.609 [ 1a] 5 EndpointRegistrationManager:onCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR,callback=true 2021-08-04 10:19:15.609 [ 1a] 9 ThreadPool:obtainWorker:created=14,obtained=36,releasedToPool=36,releasedFromPool=0,outstanding=0 2021-08-04 10:19:15.609 [ 3] 9 TaskThread:startThread:moniker= 3,duration=145 2021-08-04 10:19:15.611 [ 1a] 9 ConditionVariableWrapper:waitForInner:duration=1410000000 2021-08-04 10:19:17.021 [ 1a] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:17.021 [ 1a] 5 DiscoveryUtils:getAddOrUpdateReportEventJson 2021-08-04 10:19:17.022 [ 1a] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:17.025 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent 2021-08-04 10:19:17.026 [ 1a] 7 HTTP2Transport:sendMessage:this=0xacb3e818 2021-08-04 10:19:17.026 [ 1a] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:17.026 [ 19] 7 MessageRequestHandler:create:context=0xacb3e868,messageRequest=0xaf60d088 2021-08-04 10:19:17.026 [ 19] 5 ExchangeHandler:ExchangeHandler:context=0xacb3e868 2021-08-04 10:19:17.026 [ 19] 7 MessageRequestHandler:MessageRequestHandler:context=0xacb3e868,messageRequest=0xaf60d088 2021-08-04 10:19:17.026 [ 19] 9 HTTP2MimeRequestEncoder:HTTP2MimeRequestEncoder:boundary=WhooHooZeerOoonie\=,source=0xaf40405c 2021-08-04 10:19:17.026 [ 19] 9 MimeResponseSink:MimeResponseSink:handler=0xaf404060 2021-08-04 10:19:17.027 [ 19] 9 HTTP2MimeResponseDecoder:HTTP2MimeResponseDecoder 2021-08-04 10:19:17.027 [ 19] 7 HTTP2Transport:onMessageRequestSent:this=0xacb3e818,countOfUnfinishedMessageHandlers=1 2021-08-04 10:19:17.027 [ 19] 7 HTTP2Transport:createAndSendRequest:this=0xacb3e818,type=POST 2021-08-04 10:19:17.027 [ 19] 9 HTTP2MimeRequestEncoder:getRequestHeaderLines 2021-08-04 10:19:17.027 [ 19] 9 MessageRequestHandler:getRequestHeaderLines 2021-08-04 10:19:17.027 [ 19] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:17.027 [ 19] 0 MessageRequestHandler:EventSent 2021-08-04 10:19:17.027 [ 19] 9 ConditionVariableWrapper:waitForInner:duration=299999891416 2021-08-04 10:19:17.124 [ 18] 9 LibcurlHTTP2Connection:insertActiveStream:handle=0xacb42270,streamId=AVSEvent-5 2021-08-04 10:19:17.125 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-5,size=1,nmemb=65536,userData=0xacb3d710 2021-08-04 10:19:17.125 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=NEW 2021-08-04 10:19:17.125 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=NEW,newState=GETTING_1ST_PART_HEADERS 2021-08-04 10:19:17.125 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:17.125 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:17.125 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_1ST_PART_HEADERS,newState=SENDING_1ST_BOUNDARY 2021-08-04 10:19:17.125 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_1ST_BOUNDARY,newState=SENDING_PART_HEADERS 2021-08-04 10:19:17.125 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_HEADERS,newState=SENDING_PART_DATA 2021-08-04 10:19:17.125 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=65429 2021-08-04 10:19:17.125 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:17.125 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=62472 2021-08-04 10:19:17.126 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:17.126 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_DATA,newState=SENDING_END_BOUNDARY 2021-08-04 10:19:17.126 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_END_BOUNDARY,newState=GETTING_NTH_PART_HEADERS 2021-08-04 10:19:17.126 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:17.126 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:17.126 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_NTH_PART_HEADERS,newState=SENDING_TERMINATING_DASHES 2021-08-04 10:19:17.126 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_TERMINATING_DASHES,newState=DONE 2021-08-04 10:19:17.126 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-5,size=1,nmemb=65536,userData=0xacb3d710 2021-08-04 10:19:17.126 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=DONE 2021-08-04 10:19:18.002 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-5,size=1,nmemb=13,userData=0xacb3d710 2021-08-04 10:19:18.002 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:18.002 [ 18] 9 MimeResponseSink:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:18.002 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.002 [ 18] 7 MessageRequestHandler:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:18.002 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:18.002 [ 18] 7 HTTP2Transport:onMessageRequestAcknowledged:this=0xacb3e818 2021-08-04 10:19:18.002 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:18.003 [ 18] 7 MessageRequestHandler:responseCodeTranslated:responseStatus=SUCCESS_ACCEPTED 2021-08-04 10:19:18.003 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:18.003 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:18.003 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.003 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-5,size=1,nmemb=56,userData=0xacb3d710 2021-08-04 10:19:18.003 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: bda88465-79a1-40ed-be44-68dc076f8b0e
2021-08-04 10:19:18.003 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: bda88465-79a1-40ed-be44-68dc076f8b0e
2021-08-04 10:19:18.003 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.003 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: bda88465-79a1-40ed-be44-68dc076f8b0e 2021-08-04 10:19:18.003 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-5,size=1,nmemb=40,userData=0xacb3d710 2021-08-04 10:19:18.003 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:18.003 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:18.003 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.003 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-5,size=1,nmemb=82,userData=0xacb3d710 2021-08-04 10:19:18.003 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-5
2021-08-04 10:19:18.003 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-5
2021-08-04 10:19:18.003 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.003 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-5 2021-08-04 10:19:18.004 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-5,size=1,nmemb=32,userData=0xacb3d710 2021-08-04 10:19:18.004 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:18.004 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:18.004 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.004 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-5,size=1,nmemb=2,userData=0xacb3d710 2021-08-04 10:19:18.004 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=
2021-08-04 10:19:18.004 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=
2021-08-04 10:19:18.004 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.004 [ 18] 9 HTTP2MimeResponseDecoder:onResponseFinished:status=COMPLETE 2021-08-04 10:19:18.004 [ 18] 9 MimeResponseSink:onResponseFinished:status=COMPLETE 2021-08-04 10:19:18.004 [ 18] 7 MessageRequestHandler:onResponseFinished:status=COMPLETE,responseCode=202 2021-08-04 10:19:18.004 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:18.004 [ 18] 7 MessageRequestHandler:reportMessageRequestFinished 2021-08-04 10:19:18.004 [ 18] 7 HTTP2Transport:onMessageRequestFinished:this=0xacb3e818,countOfUnfinishedMessageHandlers=0 2021-08-04 10:19:18.337 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:18.337 [ 18] 7 LibcurlHTTP2Connection:streamFinished:streamId=AVSEvent-5,result=No error,CURLcode=0 2021-08-04 10:19:18.337 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent:Discovery event status=SUCCESS_ACCEPTED 2021-08-04 10:19:18.337 [ 18] 9 LibcurlHTTP2Connection:releaseStream:streamId=AVSEvent-5 2021-08-04 10:19:18.337 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent::waiting for Event Processed directive 2021-08-04 10:19:18.337 [ 1a] 9 ConditionVariableWrapper:waitForInner:duration=2000000000 2021-08-04 10:19:18.338 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:18.338 [ 18] 7 MessageRequestHandler:reportMessageRequestFinished 2021-08-04 10:19:18.338 [ 18] 9 LibcurlHTTP2Request:writeCallback:id=AVSDownChannel-1,size=1,nmemb=272,userData=0xaf42b910 2021-08-04 10:19:18.338 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveData:size=272 2021-08-04 10:19:18.338 [ 18] 9 MimeResponseSink:onBeginMimePart 2021-08-04 10:19:18.338 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.338 [ 18] 9 MimeResponseSink:JsonContentDetected 2021-08-04 10:19:18.338 [ 18] 9 MimeResponseSink:onReceiveMimeData:size=218 2021-08-04 10:19:18.338 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.338 [ 18] 9 MimeResponseSink:onEndMimePart 2021-08-04 10:19:18.338 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:18.338 [ 18] 9 ThreadPool:obtainWorker:created=14,obtained=37,releasedToPool=37,releasedFromPool=0,outstanding=0 2021-08-04 10:19:18.338 [ 14] 9 TaskThread:startThread:moniker= 14,duration=110 2021-08-04 10:19:18.339 [ 14] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2021-08-04 10:19:18.339 [ 14] 5 AvsDirective:parseHeader:payloadVersion=3 2021-08-04 10:19:18.339 [ 14] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2021-08-04 10:19:18.339 [ 14] 5 AvsDirective:parseHeader:eventCorrelationToken=6acbd5f8-bb46-4ab3-94c3-b3de8fb1b845 2021-08-04 10:19:18.339 [ 14] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2021-08-04 10:19:18.339 [ 14] 0 AvsDirective:parseEndpoint::noEndpoint 2021-08-04 10:19:18.339 [ 14] I DirectiveSequencer:onDirective:directive=namespace\:Alexa\,name\:EventProcessed\,messageId\:9067104a-0dcf-485b-be5b-bbd8fe7a3a9b\,dialogRequestId\:\,correlationToken\:\,eventCorrelationToken\:6acbd5f8-bb46-4ab3-94c3-b3de8fb1b845\,payloadVersion\:3\,instance\: 2021-08-04 10:19:18.339 [ 14] 5 ConditionVariableWrapper:notifyOne 2021-08-04 10:19:18.340 [ b] 5 DirectiveRouter:getHandlerAndPolicyLocked::noMatcher 2021-08-04 10:19:18.340 [ b] 5 DirectiveRouter:getHandlerAndPolicyLocked::noMatcher 2021-08-04 10:19:18.340 [ b] 0 DirectiveRouter:noHandlerFoundForDirective:namespace=Alexa,name=EventProcessed 2021-08-04 10:19:18.340 [ b] W DirectiveRouter:preHandleDirectiveFailed:messageId=9067104a-0dcf-485b-be5b-bbd8fe7a3a9b,reason=noHandlerRegistered 2021-08-04 10:19:18.340 [ b] I DirectiveSequencer:sendingExceptionEncountered:messageId=9067104a-0dcf-485b-be5b-bbd8fe7a3a9b 2021-08-04 10:19:18.340 [ b] 5 AVSContext:toJson 2021-08-04 10:19:18.341 [ b] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:18.341 [ b] 0 EventBuilder:buildJsonEventString:messageId=f1911c49-87f6-4454-990f-3f1d2960b034,namespace=System,name=ExceptionEncountered 2021-08-04 10:19:18.341 [ b] 0 EventBuilder:buildJsonEventString:event={"context"\:{"properties"\:[]}\,"event"\:{"header"\:{"namespace"\:"System"\,"name"\:"ExceptionEncountered"\,"messageId"\:"f1911c49-87f6-4454-990f-3f1d2960b034"}\,"payload"\:{"unparsedDirective"\:"{\"directive\"\:{\"header\"\:{\"namespace\"\:\"Alexa\"\,\"name\"\:\"EventProcessed\"\,\"messageId\"\:\"9067104a-0dcf-485b-be5b-bbd8fe7a3a9b\"\,\"payloadVersion\"\:\"3\"\,\"eventCorrelationToken\"\:\"6acbd5f8-bb46-4ab3-94c3-b3de8fb1b845\"}\,\"payload\"\:{}}}"\,"error"\:{"type"\:"UNSUPPORTED_OPERATION"\,"message"\:"Unsupported operation"}}}} 2021-08-04 10:19:18.675 [ b] 7 HTTP2Transport:onRequestEnqueued:this=0xacb3e818 2021-08-04 10:19:18.675 [ b] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:18.675 [ b] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:20.338 [ 1a] E DiscoveryEventSender:sendDiscoveryEventFailed:reason=Timeout on waiting for Event Processed Directive 2021-08-04 10:19:20.338 [ 1a] 5 DiscoveryEventSender:reportDiscoveryStatus 2021-08-04 10:19:20.338 [ 1a] 5 CapabilitiesDelegate:onDiscoveryFailure 2021-08-04 10:19:20.338 [ 1a] E CapabilitiesDelegate:onDiscoveryFailure:reason=TIMEDOUT 2021-08-04 10:19:20.338 [ 1a] 5 CapabilitiesDelegate:setCapabilitiesState:newCapabilitiesState=RETRIABLE_ERROR 2021-08-04 10:19:20.338 [ 1a] 9 CapabilitiesDelegate:callingOnCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR 2021-08-04 10:19:20.338 [ 1a] 5 EndpointRegistrationManager:onCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR,callback=true 2021-08-04 10:19:20.338 [ 1a] 9 ThreadPool:obtainWorker:created=14,obtained=38,releasedToPool=38,releasedFromPool=0,outstanding=0 2021-08-04 10:19:20.338 [ f] 9 TaskThread:startThread:moniker= f,duration=119 2021-08-04 10:19:20.338 [ 1a] 9 ConditionVariableWrapper:waitForInner:duration=2199000000 2021-08-04 10:19:22.538 [ 1a] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:22.538 [ 1a] 5 DiscoveryUtils:getAddOrUpdateReportEventJson 2021-08-04 10:19:22.539 [ 1a] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:22.541 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent 2021-08-04 10:19:22.541 [ 1a] 7 HTTP2Transport:sendMessage:this=0xacb3e818 2021-08-04 10:19:22.541 [ 1a] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:22.541 [ 19] 7 MessageRequestHandler:create:context=0xacb3e868,messageRequest=0xaf6021f8 2021-08-04 10:19:22.541 [ 19] 5 ExchangeHandler:ExchangeHandler:context=0xacb3e868 2021-08-04 10:19:22.541 [ 19] 7 MessageRequestHandler:MessageRequestHandler:context=0xacb3e868,messageRequest=0xaf6021f8 2021-08-04 10:19:22.542 [ 19] 9 HTTP2MimeRequestEncoder:HTTP2MimeRequestEncoder:boundary=WhooHooZeerOoonie\=,source=0xaf40405c 2021-08-04 10:19:22.542 [ 19] 9 MimeResponseSink:MimeResponseSink:handler=0xaf404060 2021-08-04 10:19:22.542 [ 19] 9 HTTP2MimeResponseDecoder:HTTP2MimeResponseDecoder 2021-08-04 10:19:22.542 [ 19] 7 HTTP2Transport:onMessageRequestSent:this=0xacb3e818,countOfUnfinishedMessageHandlers=1 2021-08-04 10:19:22.542 [ 19] 7 HTTP2Transport:createAndSendRequest:this=0xacb3e818,type=POST 2021-08-04 10:19:22.542 [ 19] 9 HTTP2MimeRequestEncoder:getRequestHeaderLines 2021-08-04 10:19:22.542 [ 19] 9 MessageRequestHandler:getRequestHeaderLines 2021-08-04 10:19:22.542 [ 19] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:22.542 [ 19] 0 MessageRequestHandler:EventSent 2021-08-04 10:19:22.542 [ 19] 9 ConditionVariableWrapper:waitForInner:duration=299999889917 2021-08-04 10:19:22.546 [ 18] 9 LibcurlHTTP2Connection:insertActiveStream:handle=0xacb42270,streamId=AVSEvent-7 2021-08-04 10:19:22.547 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-7,size=1,nmemb=65536,userData=0xaf4153f8 2021-08-04 10:19:22.547 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=NEW 2021-08-04 10:19:22.547 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=NEW,newState=GETTING_1ST_PART_HEADERS 2021-08-04 10:19:22.547 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:22.547 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:22.547 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_1ST_PART_HEADERS,newState=SENDING_1ST_BOUNDARY 2021-08-04 10:19:22.547 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_1ST_BOUNDARY,newState=SENDING_PART_HEADERS 2021-08-04 10:19:22.547 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_HEADERS,newState=SENDING_PART_DATA 2021-08-04 10:19:22.547 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=65429 2021-08-04 10:19:22.548 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:22.548 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=62472 2021-08-04 10:19:22.548 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:22.548 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_DATA,newState=SENDING_END_BOUNDARY 2021-08-04 10:19:22.548 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_END_BOUNDARY,newState=GETTING_NTH_PART_HEADERS 2021-08-04 10:19:22.548 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:22.548 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:22.548 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_NTH_PART_HEADERS,newState=SENDING_TERMINATING_DASHES 2021-08-04 10:19:22.548 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_TERMINATING_DASHES,newState=DONE 2021-08-04 10:19:22.548 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-7,size=1,nmemb=65536,userData=0xaf4153f8 2021-08-04 10:19:22.549 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=DONE 2021-08-04 10:19:23.047 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-7,size=1,nmemb=13,userData=0xaf4153f8 2021-08-04 10:19:23.047 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:23.047 [ 18] 9 MimeResponseSink:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:23.047 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:23.047 [ 18] 7 MessageRequestHandler:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:23.047 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:23.047 [ 18] 7 HTTP2Transport:onMessageRequestAcknowledged:this=0xacb3e818 2021-08-04 10:19:23.047 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:23.047 [ 18] 7 MessageRequestHandler:responseCodeTranslated:responseStatus=SUCCESS_ACCEPTED 2021-08-04 10:19:23.047 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:23.048 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:23.048 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:23.048 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-7,size=1,nmemb=56,userData=0xaf4153f8 2021-08-04 10:19:23.048 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: f39cfa96-a393-45fe-a163-e7440f644cf5
2021-08-04 10:19:23.048 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: f39cfa96-a393-45fe-a163-e7440f644cf5
2021-08-04 10:19:23.048 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:23.048 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: f39cfa96-a393-45fe-a163-e7440f644cf5 2021-08-04 10:19:23.048 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-7,size=1,nmemb=40,userData=0xaf4153f8 2021-08-04 10:19:23.048 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:23.048 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:23.048 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:23.048 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-7,size=1,nmemb=82,userData=0xaf4153f8 2021-08-04 10:19:23.048 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-7
2021-08-04 10:19:23.048 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-7
2021-08-04 10:19:23.048 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:23.048 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-7 2021-08-04 10:19:23.048 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-7,size=1,nmemb=32,userData=0xaf4153f8 2021-08-04 10:19:23.048 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:23.048 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:23.049 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:23.049 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-7,size=1,nmemb=2,userData=0xaf4153f8 2021-08-04 10:19:23.049 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=
2021-08-04 10:19:23.049 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=
2021-08-04 10:19:23.049 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:23.049 [ 18] 9 HTTP2MimeResponseDecoder:onResponseFinished:status=COMPLETE 2021-08-04 10:19:23.049 [ 18] 9 MimeResponseSink:onResponseFinished:status=COMPLETE 2021-08-04 10:19:23.049 [ 18] 7 MessageRequestHandler:onResponseFinished:status=COMPLETE,responseCode=202 2021-08-04 10:19:23.049 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:23.049 [ 18] 7 MessageRequestHandler:reportMessageRequestFinished 2021-08-04 10:19:23.049 [ 18] 7 HTTP2Transport:onMessageRequestFinished:this=0xacb3e818,countOfUnfinishedMessageHandlers=0 2021-08-04 10:19:23.382 [ 18] 5 ConditionVariableWrapper 2021-08-04 10:19:25.382 [ 1a] E DiscoveryEventSender:sendDiscoveryEventFailed:reason=Timeout on waiting for Event Processed Directive 2021-08-04 10:19:25.383 [ 1a] 5 DiscoveryEventSender:reportDiscoveryStatus 2021-08-04 10:19:25.383 [ 1a] 5 CapabilitiesDelegate:onDiscoveryFailure 2021-08-04 10:19:25.383 [ 1a] E CapabilitiesDelegate:onDiscoveryFailure:reason=TIMEDOUT 2021-08-04 10:19:25.383 [ 1a] 5 CapabilitiesDelegate:setCapabilitiesState:newCapabilitiesState=RETRIABLE_ERROR 2021-08-04 10:19:25.383 [ 1a] 9 CapabilitiesDelegate:callingOnCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR 2021-08-04 10:19:25.383 [ 1a] 5 EndpointRegistrationManager:onCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR,callback=true 2021-08-04 10:19:25.383 [ 1a] 9 ThreadPool:obtainWorker:created=14,obtained=40,releasedToPool=40,releasedFromPool=0,outstanding=0 2021-08-04 10:19:25.383 [ 11] 9 TaskThread:startThread:moniker= 11,duration=120 2021-08-04 10:19:25.383 [ 1a] 9 ConditionVariableWrapper:waitForInner:duration=5943000000
sh-3.2# 2021-08-04 10:19:31.326 [ 1a] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:31.327 [ 1a] 5 DiscoveryUtils:getAddOrUpdateReportEventJson 2021-08-04 10:19:31.328 [ 1a] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:31.330 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent 2021-08-04 10:19:31.330 [ 1a] 7 HTTP2Transport:sendMessage:this=0xacb3e818 2021-08-04 10:19:31.330 [ 1a] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:31.330 [ 19] 7 MessageRequestHandler:create:context=0xacb3e868,messageRequest=0xaf6021f8 2021-08-04 10:19:31.330 [ 19] 5 ExchangeHandler:ExchangeHandler:context=0xacb3e868 2021-08-04 10:19:31.330 [ 19] 7 MessageRequestHandler:MessageRequestHandler:context=0xacb3e868,messageRequest=0xaf6021f8 2021-08-04 10:19:31.330 [ 19] 9 HTTP2MimeRequestEncoder:HTTP2MimeRequestEncoder:boundary=WhooHooZeerOoonie\=,source=0xaf40405c 2021-08-04 10:19:31.330 [ 19] 9 MimeResponseSink:MimeResponseSink:handler=0xaf404060 2021-08-04 10:19:31.330 [ 19] 9 HTTP2MimeResponseDecoder:HTTP2MimeResponseDecoder 2021-08-04 10:19:31.330 [ 19] 7 HTTP2Transport:onMessageRequestSent:this=0xacb3e818,countOfUnfinishedMessageHandlers=1 2021-08-04 10:19:31.330 [ 19] 7 HTTP2Transport:createAndSendRequest:this=0xacb3e818,type=POST 2021-08-04 10:19:31.331 [ 19] 9 HTTP2MimeRequestEncoder:getRequestHeaderLines 2021-08-04 10:19:31.331 [ 19] 9 MessageRequestHandler:getRequestHeaderLines 2021-08-04 10:19:31.331 [ 19] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.331 [ 19] 0 MessageRequestHandler:EventSent 2021-08-04 10:19:31.331 [ 19] 9 ConditionVariableWrapper:waitForInner:duration=299999876000 2021-08-04 10:19:31.398 [ 18] 9 LibcurlHTTP2Connection:insertActiveStream:handle=0xacb42270,streamId=AVSEvent-9 2021-08-04 10:19:31.399 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-9,size=1,nmemb=65536,userData=0xacb3d710 2021-08-04 10:19:31.399 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=NEW 2021-08-04 10:19:31.399 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=NEW,newState=GETTING_1ST_PART_HEADERS 2021-08-04 10:19:31.399 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:31.399 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.399 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_1ST_PART_HEADERS,newState=SENDING_1ST_BOUNDARY 2021-08-04 10:19:31.399 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_1ST_BOUNDARY,newState=SENDING_PART_HEADERS 2021-08-04 10:19:31.399 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_HEADERS,newState=SENDING_PART_DATA 2021-08-04 10:19:31.399 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=65429 2021-08-04 10:19:31.400 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.400 [ 18] 9 MessageRequestHandler:onSendMimePartData:size=62472 2021-08-04 10:19:31.400 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.400 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_PART_DATA,newState=SENDING_END_BOUNDARY 2021-08-04 10:19:31.400 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_END_BOUNDARY,newState=GETTING_NTH_PART_HEADERS 2021-08-04 10:19:31.400 [ 18] 9 MessageRequestHandler:getMimePartHeaderLines 2021-08-04 10:19:31.400 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.400 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=GETTING_NTH_PART_HEADERS,newState=SENDING_TERMINATING_DASHES 2021-08-04 10:19:31.400 [ 18] 9 HTTP2MimeRequestEncoder:setState:state=SENDING_TERMINATING_DASHES,newState=DONE 2021-08-04 10:19:31.400 [ 18] 9 LibcurlHTTP2Request:readCallback:id=AVSEvent-9,size=1,nmemb=65536,userData=0xacb3d710 2021-08-04 10:19:31.401 [ 18] 9 HTTP2MimeRequestEncoder:onSendData:size=65536,state=DONE 2021-08-04 10:19:31.898 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-9,size=1,nmemb=13,userData=0xacb3d710 2021-08-04 10:19:31.898 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:31.898 [ 18] 9 MimeResponseSink:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:31.898 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.898 [ 18] 7 MessageRequestHandler:onReceiveResponseCode:responseCode=202 2021-08-04 10:19:31.898 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:31.899 [ 18] 7 HTTP2Transport:onMessageRequestAcknowledged:this=0xacb3e818 2021-08-04 10:19:31.899 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:31.899 [ 18] 7 MessageRequestHandler:responseCodeTranslated:responseStatus=SUCCESS_ACCEPTED 2021-08-04 10:19:31.899 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:31.899 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=HTTP/2 202
2021-08-04 10:19:31.899 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.899 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-9,size=1,nmemb=56,userData=0xacb3d710 2021-08-04 10:19:31.899 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: c429cd19-aa15-4c6d-aa15-bb8e422ee51b
2021-08-04 10:19:31.899 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: c429cd19-aa15-4c6d-aa15-bb8e422ee51b
2021-08-04 10:19:31.899 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.899 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: c429cd19-aa15-4c6d-aa15-bb8e422ee51b 2021-08-04 10:19:31.899 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-9,size=1,nmemb=40,userData=0xacb3d710 2021-08-04 10:19:31.899 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:31.899 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=content-type\: application/octet-stream
2021-08-04 10:19:31.899 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.899 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-9,size=1,nmemb=82,userData=0xacb3d710 2021-08-04 10:19:31.899 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-9
2021-08-04 10:19:31.899 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-9
2021-08-04 10:19:31.900 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.900 [ 18] 0 MimeResponseSink:receivedRequestId:value=x-amzn-requestid\: 0e9bedfffe21409f-000130c4-0013a88e-d3673deb44b406b5-217a95c4-9 2021-08-04 10:19:31.900 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-9,size=1,nmemb=32,userData=0xacb3d710 2021-08-04 10:19:31.900 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:31.900 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=access-control-allow-origin\: *
2021-08-04 10:19:31.900 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.900 [ 18] 9 LibcurlHTTP2Request:headerCallback:id=AVSEvent-9,size=1,nmemb=2,userData=0xacb3d710 2021-08-04 10:19:31.900 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveHeaderLine:line=
2021-08-04 10:19:31.900 [ 18] 9 MimeResponseSink:onReceiveHeaderLine:line=
2021-08-04 10:19:31.900 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:31.900 [ 18] 9 HTTP2MimeResponseDecoder:onResponseFinished:status=COMPLETE 2021-08-04 10:19:31.900 [ 18] 9 MimeResponseSink:onResponseFinished:status=COMPLETE 2021-08-04 10:19:31.900 [ 18] 7 MessageRequestHandler:onResponseFinished:status=COMPLETE,responseCode=202 2021-08-04 10:19:31.900 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:31.900 [ 18] 7 MessageRequestHandler:reportMessageRequestFinished 2021-08-04 10:19:31.900 [ 18] 7 HTTP2Transport:onMessageRequestFinished:this=0xacb3e818,countOfUnfinishedMessageHandlers=0 2021-08-04 10:19:32.233 [ 18] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:32.233 [ 18] 7 LibcurlHTTP2Connection:streamFinished:streamId=AVSEvent-9,result=No error,CURLcode=0 2021-08-04 10:19:32.233 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent:Discovery event status=SUCCESS_ACCEPTED 2021-08-04 10:19:32.233 [ 18] 9 LibcurlHTTP2Connection:releaseStream:streamId=AVSEvent-9 2021-08-04 10:19:32.233 [ 1a] 5 DiscoveryEventSender:sendDiscoveryEvent::waiting for Event Processed directive 2021-08-04 10:19:32.234 [ 1a] 9 ConditionVariableWrapper:waitForInner:duration=2000000000 2021-08-04 10:19:32.234 [ 18] 7 MessageRequestHandler:reportMessageRequestAcknowledged 2021-08-04 10:19:32.234 [ 18] 7 MessageRequestHandler:reportMessageRequestFinished 2021-08-04 10:19:32.234 [ 18] 9 LibcurlHTTP2Request:writeCallback:id=AVSDownChannel-1,size=1,nmemb=272,userData=0xaf42b910 2021-08-04 10:19:32.234 [ 18] 9 HTTP2MimeResponseDecoder:onReceiveData:size=272 2021-08-04 10:19:32.234 [ 18] 9 MimeResponseSink:onBeginMimePart 2021-08-04 10:19:32.234 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:32.234 [ 18] 9 MimeResponseSink:JsonContentDetected 2021-08-04 10:19:32.234 [ 18] 9 MimeResponseSink:onReceiveMimeData:size=218 2021-08-04 10:19:32.234 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:32.234 [ 18] 9 MimeResponseSink:onEndMimePart 2021-08-04 10:19:32.234 [ 18] 9 HTTP2Transport:onActivity:this=0xacb3e818 2021-08-04 10:19:32.235 [ 18] 9 ThreadPool:obtainWorker:created=14,obtained=41,releasedToPool=41,releasedFromPool=0,outstanding=0 2021-08-04 10:19:32.235 [ 15] 9 TaskThread:startThread:moniker= 15,duration=117 2021-08-04 10:19:32.235 [ 15] 5 JsonUtils:findNode:reason=missingDirectChild,child=instance 2021-08-04 10:19:32.235 [ 15] 5 AvsDirective:parseHeader:payloadVersion=3 2021-08-04 10:19:32.235 [ 15] 5 JsonUtils:findNode:reason=missingDirectChild,child=correlationToken 2021-08-04 10:19:32.235 [ 15] 5 AvsDirective:parseHeader:eventCorrelationToken=3ac0635f-a8f9-4347-b874-b6a00a399d74 2021-08-04 10:19:32.235 [ 15] 5 JsonUtils:findNode:reason=missingDirectChild,child=endpoint 2021-08-04 10:19:32.235 [ 15] 0 AvsDirective:parseEndpoint::noEndpoint 2021-08-04 10:19:32.236 [ 15] I DirectiveSequencer:onDirective:directive=namespace\:Alexa\,name\:EventProcessed\,messageId\:6a6a6c33-4f1e-446d-bc4c-5c1a807973ba\,dialogRequestId\:\,correlationToken\:\,eventCorrelationToken\:3ac0635f-a8f9-4347-b874-b6a00a399d74\,payloadVersion\:3\,instance\: 2021-08-04 10:19:32.236 [ 15] 5 ConditionVariableWrapper:notifyOne 2021-08-04 10:19:32.236 [ b] 5 DirectiveRouter:getHandlerAndPolicyLocked::noMatcher 2021-08-04 10:19:32.236 [ b] 5 DirectiveRouter:getHandlerAndPolicyLocked::noMatcher 2021-08-04 10:19:32.236 [ b] 0 DirectiveRouter:noHandlerFoundForDirective:namespace=Alexa,name=EventProcessed 2021-08-04 10:19:32.236 [ b] W DirectiveRouter:preHandleDirectiveFailed:messageId=6a6a6c33-4f1e-446d-bc4c-5c1a807973ba,reason=noHandlerRegistered 2021-08-04 10:19:32.236 [ b] I DirectiveSequencer:sendingExceptionEncountered:messageId=6a6a6c33-4f1e-446d-bc4c-5c1a807973ba 2021-08-04 10:19:32.236 [ b] 5 AVSContext:toJson 2021-08-04 10:19:32.237 [ b] W UUIDGeneration:low entropy on call to generate UUID:current entropy=0 2021-08-04 10:19:32.238 [ b] 0 EventBuilder:buildJsonEventString:messageId=cf4dada4-2295-4bae-bbed-6dce3494b9fe,namespace=System,name=ExceptionEncountered 2021-08-04 10:19:32.238 [ b] 0 EventBuilder:buildJsonEventString:event={"context"\:{"properties"\:[]}\,"event"\:{"header"\:{"namespace"\:"System"\,"name"\:"ExceptionEncountered"\,"messageId"\:"cf4dada4-2295-4bae-bbed-6dce3494b9fe"}\,"payload"\:{"unparsedDirective"\:"{\"directive\"\:{\"header\"\:{\"namespace\"\:\"Alexa\"\,\"name\"\:\"EventProcessed\"\,\"messageId\"\:\"6a6a6c33-4f1e-446d-bc4c-5c1a807973ba\"\,\"payloadVersion\"\:\"3\"\,\"eventCorrelationToken\"\:\"3ac0635f-a8f9-4347-b874-b6a00a399d74\"}\,\"payload\"\:{}}}"\,"error"\:{"type"\:"UNSUPPORTED_OPERATION"\,"message"\:"Unsupported operation"}}}} 2021-08-04 10:19:32.571 [ b] 7 HTTP2Transport:onRequestEnqueued:this=0xacb3e818 2021-08-04 10:19:32.571 [ b] 5 ConditionVariableWrapper:notifyAll 2021-08-04 10:19:32.571 [ b] 5 ConditionVariableWrapper:waitInner 2021-08-04 10:19:34.234 [ 1a] E DiscoveryEventSender:sendDiscoveryEventFailed:reason=Timeout on waiting for Event Processed Directive 2021-08-04 10:19:34.234 [ 1a] 5 DiscoveryEventSender:reportDiscoveryStatus 2021-08-04 10:19:34.234 [ 1a] 5 CapabilitiesDelegate:onDiscoveryFailure 2021-08-04 10:19:34.234 [ 1a] E CapabilitiesDelegate:onDiscoveryFailure:reason=TIMEDOUT 2021-08-04 10:19:34.234 [ 1a] 5 CapabilitiesDelegate:setCapabilitiesState:newCapabilitiesState=RETRIABLE_ERROR 2021-08-04 10:19:34.234 [ 1a] 9 CapabilitiesDelegate:callingOnCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR 2021-08-04 10:19:34.234 [ 1a] 5 EndpointRegistrationManager:onCapabilitiesStateChange:state=RETRIABLE_ERROR,error=UNKNOWN_ERROR,callback=true 2021-08-04 10:19:34.234 [ 1a] 9 ThreadPool:obtainWorker:created=14,obtained=42,releasedToPool=42,releasedFromPool=0,outstanding=0 2021-08-04 10:19:34.234 [ 5] 9 TaskThread:startThread:moniker= 5,duration=124 2021-08-04 10:19:34.234 [ 1a] 9 ConditionVariableWrapper:waitForInner:duration=8031000000