In the poor network , SDK may stuck after login and logout.

[cameled]

Briefly summarize your issue:

In the poor network , SDK may stuck after login and logout.

What is the expected behavior?

SDK can successfully logout.

What behavior are you observing?

After the CBL Auth is completed, SDK attempts to connect to the AVS server and blocked at the place where DownchannelHandler waiting for response.

After a moment, Logout the device from app. As I know, it will call AVSConnectionManager::disable(). But DownchannelHandler are still waiting for a response, and then SDK stucked.

Provide the steps to reproduce the issue, if applicable:

Occasionally occurs when the network environment is poor.

Tell us about your environment:

What version of the AVS Device SDK are you using?

  V1.13

Tell us what hardware you're using:

• [ ] Desktop / Laptop
• [ ] Raspberry Pi
• [ ] Other - tell us more: ARMV8 embedded device.

Tell us about your OS (Type & version):

• [* ] Linux
• [ ] MacOS
• [ ] Raspbian Stretch
• [ ] Raspbian Jessy
• [ ] Other - tell us more:

[cameled]

Provide log.

2019-07-30 04:12:16.986 [ 87] 0 PostConnectSynchronizer:doPostConnect 2019-07-30 04:12:16.989 [ 87] 5 PostConnectSynchronizer:setState:from=IDLE,to=RUNNING 2019-07-30 04:12:16.990 [ 1e] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST 2019-07-30 04:12:16.991 [ 87] 5 HTTP2Transport:handleAuthorizing 2019-07-30 04:12:16.991 [ 88] 5 PostConnectSynchronizer:mainLoop 2019-07-30 04:12:16.991 [ 87] 5 CBLAuthDelegate:addAuthObserver:observer=0xef78efb0 2019-07-30 04:12:16.991 [ 88] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-07-30 04:12:16.994 [ 87] 5 HTTP2Transport:onAuthStateChange:newState=REFRESHED,error=SUCCESS 2019-07-30 04:12:16.994 [ 2a] 5 VisualActivityTracker:provideState 2019-07-30 04:12:16.994 [ 87] 5 HTTP2Transport:setStateLocked:newState=CONNECTING,changedReason=SUCCESS 2019-07-30 04:12:16.995 [ 87] 5 HTTP2Transport:handleConnecting 2019-07-30 04:12:16.996 [ 87] 9 DownchannelHandler:create:context=0xef78efb4 2019-07-30 04:12:16.996 [ 2a] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=31 2019-07-30 04:12:16.997 [ 87] 5 ExchangeHandler:ExchangeHandler:context=0xef78efb4 2019-07-30 04:12:16.998 [ 25] 5 VisualActivityTracker:executeProvideState 2019-07-30 04:12:16.998 [ 2a] 5 AudioActivityTracker:provideState 2019-07-30 04:12:16.999 [ 87] 9 DownchannelHandler:DownchannelHandler:context=0xef78efb4 2019-07-30 04:12:16.999 [ 20] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=31 2019-07-30 04:12:16.999 [ 25] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:17.001 [ 87] 5 MimeResponseSink:MimeResponseSink:handler=0xf21027e8 2019-07-30 04:12:17.001 [ d] 5 AudioActivityTracker:executeProvideState 2019-07-30 04:12:17.003 [ 87] 5 HTTP2MimeResponseDecoder:HTTP2MimeResponseDecoder 2019-07-30 04:12:17.003 [ 87] 5 HTTP2Transport:createAndSendRequest:type=GET 2019-07-30 04:12:17.003 [ 20] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-07-30 04:12:17.007 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:17.375 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-07-30 04:12:17.375 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-07-30 04:12:17.009 [ 87] 9 DownchannelHandler:getRequestHeaderLines 2019-07-30 04:12:17.375 [ 2a] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:17.375 [ 86] 9 LibcurlHTTP2Connection:insertActiveStream:handle=0xf2160000,streamId=AVSDownChannel-91 2019-07-30 04:12:17.375 [ 2a] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:17.376 [ 2a] 5 ContextManager:buildContextSuccessful 2019-07-30 04:12:17.376 [ 2a] 5 PostConnectSynchronizer:onContextAvailable 2019-07-30 04:12:17.376 [ 2a] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-07-30 04:12:17.376 [ 2a] 0 EventBuilder:buildJsonEventString:messageId=1256892d-26ed-4381-a99a-f3e9f1037414,namespace=System,name=SynchronizeState 2019-07-30 04:12:17.376 [ 2a] 5 HTTP2Transport:sendPostConnectMessage 2019-07-30 04:12:17.376 [ 2a] 5 HTTP2Transport:enqueueRequest:beforeConnected=true

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

recive notify event from conan server : alexa_logout

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

2019-07-30 04:12:52.457 [ 2d] 0 RegistrationManager:logout 2019-07-30 04:12:52.457 [ 2d] 5 AVSConnectionManager:disable 2019-07-30 04:12:52.457 [ 2d] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=DISCONNECTED 2019-07-30 04:12:52.457 [ 2d] 5 HTTP2Transport:doShutdown 2019-07-30 04:12:52.457 [ 2d] 5 HTTP2Transport:setStateLocked:newState=SHUTDOWN,changedReason=ACL_CLIENT_REQUEST 2019-07-30 04:12:52.457 [ a] 5 SoftwareInfoSender:onConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2019-07-30 04:12:52.457 [ 87] 5 HTTP2Transport:handleShutdown 2019-07-30 04:12:52.457 [ 2d] 5 HTTP2Transport:disconnect 2019-07-30 04:12:52.457 [ a] 5 MRMCloudDelegate:onConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST onConnectionStatusChanged reason : ACL_CLIENT_REQUEST,status: DISCONNECTED 2019-07-30 04:12:52.457 [ 87] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-07-30 04:12:52.457 [ 87] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING #####################################

Client not connected!

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

2019-07-30 04:12:52.457 [ 87] 5 LibcurlHTTP2Connection:disconnect 2019-07-30 04:12:52.457 [ 88] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-07-30 04:12:52.457 [ 2a] 5 VisualActivityTracker:provideState 2019-07-30 04:12:52.457 [ 1e] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2019-07-30 04:12:52.457 [ 25] 5 VisualActivityTracker:executeProvideState 2019-07-30 04:12:52.457 [ 2a] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=32 2019-07-30 04:12:52.457 [ 25] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:52.458 [ 2a] 5 AudioActivityTracker:provideState 2019-07-30 04:12:52.458 [ d] 5 AudioActivityTracker:executeProvideState 2019-07-30 04:12:52.458 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:52.460 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-07-30 04:12:52.460 [ 20] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=32 2019-07-30 04:12:52.460 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-07-30 04:12:52.461 [ 20] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-07-30 04:12:52.461 [ 2a] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:52.461 [ 2a] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:52.461 [ 2a] 5 ContextManager:buildContextSuccessful 2019-07-30 04:12:52.461 [ 2a] 5 PostConnectSynchronizer:onContextAvailable 2019-07-30 04:12:52.461 [ 2a] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-07-30 04:12:52.461 [ 2a] 0 EventBuilder:buildJsonEventString:messageId=a7eac5a8-d914-4059-9117-e3ec071edbf3,namespace=System,name=SynchronizeState 2019-07-30 04:12:52.461 [ 2a] 5 HTTP2Transport:sendPostConnectMessage 2019-07-30 04:12:52.461 [ 2a] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-07-30 04:12:52.462 [ 2a] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-07-30 04:12:52.462 [ 2a] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-07-30 04:12:52.793 [ 2a] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-07-30 04:12:52.793 [ 88] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=667 2019-07-30 04:12:53.460 [ 88] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-07-30 04:12:53.460 [ 2a] 5 VisualActivityTracker:provideState 2019-07-30 04:12:53.461 [ 2a] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=33 2019-07-30 04:12:53.461 [ 2a] 5 AudioActivityTracker:provideState 2019-07-30 04:12:53.461 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-07-30 04:12:53.461 [ 20] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=33 2019-07-30 04:12:53.461 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-07-30 04:12:53.461 [ d] 5 AudioActivityTracker:executeProvideState 2019-07-30 04:12:53.461 [ 20] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-07-30 04:12:53.461 [ 25] 5 VisualActivityTracker:executeProvideState 2019-07-30 04:12:53.462 [ 25] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:53.462 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:53.462 [ 2a] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:53.462 [ 2a] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:53.462 [ 2a] 5 ContextManager:buildContextSuccessful 2019-07-30 04:12:53.462 [ 2a] 5 PostConnectSynchronizer:onContextAvailable 2019-07-30 04:12:53.462 [ 2a] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-07-30 04:12:53.462 [ 2a] 0 EventBuilder:buildJsonEventString:messageId=585560bd-5891-4cd1-b6b1-3dd33a02d8f7,namespace=System,name=SynchronizeState 2019-07-30 04:12:53.463 [ 2a] 5 HTTP2Transport:sendPostConnectMessage 2019-07-30 04:12:53.463 [ 2a] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-07-30 04:12:53.463 [ 2a] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-07-30 04:12:53.463 [ 2a] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-07-30 04:12:53.463 [ 2a] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-07-30 04:12:53.463 [ 88] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=2027 2019-07-30 04:12:55.490 [ 88] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-07-30 04:12:55.490 [ 2a] 5 VisualActivityTracker:provideState 2019-07-30 04:12:55.490 [ 25] 5 VisualActivityTracker:executeProvideState 2019-07-30 04:12:55.490 [ 2a] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=34 2019-07-30 04:12:55.490 [ 2a] 5 AudioActivityTracker:provideState 2019-07-30 04:12:55.490 [ 20] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=34 2019-07-30 04:12:55.491 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-07-30 04:12:55.491 [ d] 5 AudioActivityTracker:executeProvideState 2019-07-30 04:12:55.491 [ 25] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:55.491 [ 20] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-07-30 04:12:55.491 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-07-30 04:12:55.491 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:55.491 [ 2a] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:55.491 [ 2a] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:55.491 [ 2a] 5 ContextManager:buildContextSuccessful 2019-07-30 04:12:55.491 [ 2a] 5 PostConnectSynchronizer:onContextAvailable 2019-07-30 04:12:55.491 [ 2a] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-07-30 04:12:55.491 [ 2a] 0 EventBuilder:buildJsonEventString:messageId=4090ab5f-e24e-4c15-bc80-625c47f227f5,namespace=System,name=SynchronizeState 2019-07-30 04:12:55.492 [ 2a] 5 HTTP2Transport:sendPostConnectMessage 2019-07-30 04:12:55.492 [ 2a] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-07-30 04:12:55.492 [ 2a] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-07-30 04:12:55.492 [ 2a] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-07-30 04:12:55.492 [ 2a] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-07-30 04:12:55.492 [ 88] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=4116 2019-07-30 04:12:59.608 [ 88] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-07-30 04:12:59.608 [ 2a] 5 VisualActivityTracker:provideState 2019-07-30 04:12:59.608 [ 25] 5 VisualActivityTracker:executeProvideState 2019-07-30 04:12:59.608 [ 2a] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=35 2019-07-30 04:12:59.608 [ 25] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:59.608 [ 2a] 5 AudioActivityTracker:provideState 2019-07-30 04:12:59.608 [ 20] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=35 2019-07-30 04:12:59.609 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-07-30 04:12:59.609 [ d] 5 AudioActivityTracker:executeProvideState 2019-07-30 04:12:59.609 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:59.609 [ 20] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-07-30 04:12:59.609 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-07-30 04:12:59.609 [ 2a] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-07-30 04:12:59.609 [ 2a] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-07-30 04:12:59.609 [ 2a] 5 ContextManager:buildContextSuccessful 2019-07-30 04:12:59.609 [ 2a] 5 PostConnectSynchronizer:onContextAvailable 2019-07-30 04:12:59.609 [ 2a] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-07-30 04:12:59.610 [ 2a] 0 EventBuilder:buildJsonEventString:messageId=592e3770-aca8-4bd7-a7a0-629e30c0b757,namespace=System,name=SynchronizeState 2019-07-30 04:12:59.610 [ 2a] 5 HTTP2Transport:sendPostConnectMessage 2019-07-30 04:12:59.610 [ 2a] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-07-30 04:12:59.610 [ 2a] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-07-30 04:12:59.610 [ 2a] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-07-30 04:12:59.610 [ 2a] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-07-30 04:12:59.610 [ 88] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=10555

[kjkh]

Hi @cameled,

Thanks for bringing this to our attention. We have filed a ticket internally and are investigating it further.

[cameled]

Hi,

New discoveries.

When singout occur, SDK main thread will disconnect to AVS server. It will called LibcurlHTTP2Connection::disconnect(). LibcurlHTTP2Connection::disconnect() will wait for LibcurlHTTP2Connection::networkLoop() finished.

when stuck happen, m_networkThread.join() will never return. because networkLoop stuck at below instruction.

auto result = m_multi->perform(&numTransfersLeft);

Attach a modified version of the source files and logs.

[cameled]

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

Checking for authorization (3)...

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

2019-08-02 03:04:13.555 [175] 5 HttpPost:doPostSucceeded:code=400 2019-08-02 03:04:13.555 [175] 5 CBLAuthDelegate:receiveTokenResponse:code=400 2019-08-02 03:04:13.555 [175] 5 CBLAuthDelegate:mapHTTPStatusToError:code=400,error=INVALID_REQUEST 2019-08-02 03:04:13.555 [175] 5 CBLAuthDelegate:errorInLwaResponseBody:error=authorization_pending,errorCode=AUTHORIZATION_PENDING 2019-08-02 03:04:13.555 [175] 5 CBLAuthDelegate:setAuthError:authError=AUTHORIZATION_PENDING 2019-08-02 03:04:13.555 [175] 0 CBLAuthDelegate:receiveTokenResponseFailed:result=AUTHORIZATION_PENDING 2019-08-02 03:04:18.556 [175] 5 CBLAuthDelegate:requestToken #################################################

Checking for authorization (4)...

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

2019-08-02 03:04:18.859 [175] 5 HttpPost:doPostSucceeded:code=200 2019-08-02 03:04:18.859 [175] 5 CBLAuthDelegate:receiveTokenResponse:code=200 2019-08-02 03:04:18.859 [175] 5 CBLAuthDelegate:mapHTTPStatusToError:code=200,error=SUCCESS 2019-08-02 03:04:18.859 [175] 5 CBLAuthDelegate:setAuthError:authError=SUCCESS 2019-08-02 03:04:18.860 [175] 5 CBLAuthDelegate:setRefreshToken 2019-08-02 03:04:18.860 [175] 5 SQLiteCBLAuthDelegateStorage:setRefreshToken 2019-08-02 03:04:18.867 [175] 5 CBLAuthDelegate:handleRefreshingToken 2019-08-02 03:04:18.867 [175] 5 CBLAuthDelegate:requestRefresh 2019-08-02 03:04:19.169 [175] 5 HttpPost:doPostSucceeded:code=200 2019-08-02 03:04:19.170 [175] 5 CBLAuthDelegate:receiveTokenResponse:code=200 2019-08-02 03:04:19.170 [175] 5 CBLAuthDelegate:mapHTTPStatusToError:code=200,error=SUCCESS 2019-08-02 03:04:19.170 [175] 5 CBLAuthDelegate:setAuthError:authError=SUCCESS 2019-08-02 03:04:19.170 [175] 5 CBLAuthDelegate:setRefreshToken 2019-08-02 03:04:19.170 [175] 5 SQLiteCBLAuthDelegateStorage:setRefreshToken 2019-08-02 03:04:19.177 [175] 5 CBLAuthDelegate:setAuthState:newAuthState=REFRESHED 2019-08-02 03:04:19.177 [17a] 5 CBLAuthDelegate:requestUserProfile 2019-08-02 03:04:19.177 [175] 9 CBLAuthDelegate:callingOnAuthStateChange:state=REFRESHED,error=SUCCESS

{ MSG[1]: EVT_AVS_CONAN_LOGINED(38) } MessageProcessor onEvent msg: EVT_AVS_CONAN_LOGINED 2019-08-02 03:04:19.177 [ 5] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT { MSG[0]: EVT_AVS_IOT_LOGINED(41) } MessageProcessor onEvent msg: EVT_AVS_IOT_LOGINED ###########################

Authorized!

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

{ MSG[0]: EVT_AVS_AUTHORIZED(48) } MessageProcessor onEvent msg: EVT_AVS_AUTHORIZED 2019-08-02 03:04:19.347 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:04:19.347 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs

2019-08-02 03:04:19.466 [17a] 5 HttpGet_Sugr:doGet_SugrSucceeded:code=200 2019-08-02 03:04:19.466 [17a] 5 CBLAuthDelegate:receiveUserProfileResponse:code=200 2019-08-02 03:04:19.466 [17a] 5 CBLAuthDelegate:mapHTTPStatusToError:code=200,error=SUCCESS 2019-08-02 03:04:19.466 [17a] 5 CBLAuthDelegate:setAuthError:authError=SUCCESS

{ MSG[1]: EVT_AVS_CONAN_LOGINED(38) } MessageProcessor onEvent msg: EVT_AVS_CONAN_LOGINED { MSG[0]: EVT_AVS_IOT_LOGINED(41) } MessageProcessor onEvent msg: EVT_AVS_IOT_LOGINED

2019-08-02 03:04:21.096 [ 5] 5 CapabilitiesDelegate:setCapabilitiesState:newCapabilitiesState=SUCCESS 2019-08-02 03:04:21.096 [ 5] 9 CapabilitiesDelegate:callingOnCapabilitiesStateChange:state=SUCCESS,error=SUCCESS 2019-08-02 03:04:21.096 [ 5] 5 AVSConnectionManager:enable 2019-08-02 03:04:21.096 [ 5] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=PENDING 2019-08-02 03:04:21.096 [ 5] 5 LibcurlHTTP2ConnectionFactory:createHTTP2Connection 2019-08-02 03:04:21.096 [ 5] 5 HTTP2Transport:create:authDelegate=0xef65a418,avsEndpoint=https\://alexa.na.gateway.devices.a2z.com,http2Connection=0xcfb9ab70,messageConsumer=0xe1a321c8,attachmentManager=0xef6eaef0,transportObserver=0xe1a321c4,postConnectFactory=0xef6d9678 2019-08-02 03:04:21.096 [17b] 5 LibcurlHTTP2Connection:networkLoop 2019-08-02 03:04:21.096 [ 5] 5 HTTP2Transport:HTTP2Transport:authDelegate=0xef65a418,avsEndpoint=https\://alexa.na.gateway.devices.a2z.com,http2Connection=0xcfb9ab70,messageConsumer=0xe1a321c8,attachmentManager=0xef6eaef0,transportObserver=0xe1a321c4,postConnectFactory=0xef6d9678 2019-08-02 03:04:21.097 [ 5] 5 HTTP2Transport:connect 2019-08-02 03:04:21.097 [ 5] 5 HTTP2Transport:setStateLocked:newState=AUTHORIZING,changedReason=ACL_CLIENT_REQUEST 2019-08-02 03:04:21.097 [ a] 5 SoftwareInfoSender:onConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST 2019-08-02 03:04:21.097 [ a] 5 CallManager:onConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST 2019-08-02 03:04:21.097 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.097 [17c] 5 HTTP2Transport:mainLoop 2019-08-02 03:04:21.097 [17c] 0 PostConnectSynchronizer:doPostConnect 2019-08-02 03:04:21.097 [17c] 5 PostConnectSynchronizer:setState:from=IDLE,to=RUNNING 2019-08-02 03:04:21.097 [17c] 5 HTTP2Transport:handleAuthorizing 2019-08-02 03:04:21.097 [17d] 5 PostConnectSynchronizer:mainLoop onConnectionStatusChanged reason : ACL_CLIENT_REQUEST,status: PENDING 2019-08-02 03:04:21.097 [17c] 5 CBLAuthDelegate:addAuthObserver:observer=0xf397ba48 2019-08-02 03:04:21.098 [ a] 5 MRMCloudDelegate:onConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST 2019-08-02 03:04:21.097 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:04:21.098 [ 1f] 5 SipUserAgent:handleAVSConnectivityStatusChange:Connected to AVS=false 2019-08-02 03:04:21.098 [ 2e] 5 AudioActivityTracker:provideState #############################

Connecting...

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

2019-08-02 03:04:21.098 [ 1c] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=PENDING,reason=ACL_CLIENT_REQUEST 2019-08-02 03:04:21.098 [ 2e] 5 CallManager:provideState:stateRequestToken=18 2019-08-02 03:04:21.098 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:04:21.098 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=18 2019-08-02 03:04:21.098 [17c] 5 HTTP2Transport:onAuthStateChange:newState=REFRESHED,error=SUCCESS 2019-08-02 03:04:21.098 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:04:21.098 [17c] 5 HTTP2Transport:setStateLocked:newState=CONNECTING,changedReason=SUCCESS 2019-08-02 03:04:21.098 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=18 2019-08-02 03:04:21.098 [17c] 5 HTTP2Transport:handleConnecting 2019-08-02 03:04:21.099 [17c] 9 DownchannelHandler:create:context=0xf397ba4c 2019-08-02 03:04:21.099 [17c] 5 ExchangeHandler:ExchangeHandler:context=0xf397ba4c 2019-08-02 03:04:21.099 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:04:21.099 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:04:21.099 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:04:21.099 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:04:21.099 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=18 2019-08-02 03:04:21.099 [17c] 9 DownchannelHandler:DownchannelHandler:context=0xf397ba4c 2019-08-02 03:04:21.100 [17c] 5 MimeResponseSink:MimeResponseSink:handler=0xef6db428 2019-08-02 03:04:21.100 [17c] 5 HTTP2MimeResponseDecoder:HTTP2MimeResponseDecoder 2019-08-02 03:04:21.100 [17c] 5 HTTP2Transport:createAndSendRequest:type=GET 2019-08-02 03:04:21.101 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:04:21.101 [17c] 9 DownchannelHandler:getRequestHeaderLines 2019-08-02 03:04:21.101 [17b] 9 LibcurlHTTP2Connection:insertActiveStream:handle=0xe1a62288,streamId=AVSDownChannel-227 2019-08-02 03:04:21.101 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.102 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.102 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.102 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.102 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.102 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:04:21.107 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=18 2019-08-02 03:04:21.108 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:04:21.108 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=18 2019-08-02 03:04:21.108 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:04:21.108 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:04:21.108 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:04:21.108 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:04:21.108 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:04:21.108 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:04:21.108 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=f2d369bc-1b56-40c0-a13f-fe134df7b745,namespace=System,name=SynchronizeState 2019-08-02 03:04:21.109 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:04:21.109 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:04:21.202 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.202 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.202 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.202 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.202 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.203 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.303 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.303 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.303 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.303 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.303 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.303 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.403 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.403 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.403 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.403 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.403 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.403 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.504 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.504 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.504 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.504 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.504 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.504 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.604 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.604 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.605 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.605 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.605 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.605 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.705 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.705 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.705 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.705 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.705 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.705 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.805 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.806 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.806 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.806 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.806 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.806 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:21.906 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:21.906 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:21.906 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:21.906 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:21.906 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:21.906 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.006 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.007 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.007 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.007 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.007 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.007 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.107 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.107 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.107 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.107 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.107 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.107 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.208 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.208 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.208 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.208 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.208 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.208 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.308 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.308 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.308 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.308 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.308 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.308 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.409 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.409 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.409 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.409 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.409 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.409 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.509 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.509 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.509 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.510 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.510 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.510 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.610 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.610 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.610 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.610 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.610 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.610 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.710 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.710 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.711 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.711 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.711 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.711 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.811 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.811 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.811 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.811 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.811 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.811 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:22.911 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:22.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:22.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:22.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:22.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:22.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.012 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.012 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.012 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.012 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.012 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.012 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.113 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.113 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.113 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.113 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.113 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.113 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.213 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.213 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.213 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.213 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.213 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.213 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.314 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.314 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.314 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.314 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.314 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.314 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.414 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.414 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.414 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.414 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.414 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.414 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.515 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.515 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.515 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.515 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.515 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.515 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.615 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.615 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.615 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.616 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.616 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.616 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.716 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.716 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.716 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.716 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.716 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.716 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.816 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.817 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.817 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.817 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.817 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.817 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.912 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.913 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.914 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.914 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.914 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.914 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.914 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.923 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.923 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.923 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.923 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.923 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.924 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:23.948 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:23.948 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:23.948 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:23.948 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:23.948 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:23.948 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.049 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.049 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.049 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.049 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.049 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.049 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.149 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.149 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.150 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.150 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.150 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.150 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.250 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.250 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.250 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.250 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.250 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.250 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.350 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.351 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.351 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.351 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.351 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.351 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.451 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.451 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.451 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.451 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.451 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.451 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.552 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.552 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.552 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.552 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.552 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.552 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.592 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.593 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.593 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.593 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.593 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.593 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.693 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.693 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.693 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.693 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.693 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.693 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.794 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.794 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.794 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.794 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.794 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.794 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.894 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.894 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.894 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.894 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.894 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.894 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:24.995 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:24.995 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:24.995 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:24.995 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:24.995 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:24.995 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.095 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.095 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.096 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.096 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.096 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.096 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.196 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.196 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.196 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.196 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.196 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.196 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.296 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.296 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.297 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.297 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.297 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.297 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.397 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.397 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.397 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.397 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.397 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.397 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.497 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.498 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.498 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.498 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.498 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.498 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.598 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.598 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.598 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.598 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.598 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.598 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.699 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.699 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.699 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.699 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.699 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.699 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.799 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.799 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.799 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.799 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.799 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.800 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:25.900 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:25.900 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:25.900 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:25.900 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:25.900 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:25.900 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:26.000 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:26.001 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:26.001 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:26.001 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:26.001 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:26.001 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:26.100 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D 2019-08-02 03:04:26.100 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter 2019-08-02 03:04:26.100 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=quit 2019-08-02 03:04:26.100 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=A 2019-08-02 03:04:26.100 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=B 2019-08-02 03:04:26.100 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=C 2019-08-02 03:04:26.101 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:networkLoop=D

2019-08-02 03:04:26.101 [17b] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:perform=enter

2019-08-02 03:04:29.347 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:04:29.348 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:04:39.348 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:04:39.348 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:04:39.348 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingTo\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:04:39.348 [17f] 0 MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:remote\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:04:39.348 [17f] 0 MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:url\=https\://xxx/connectivity-test\, port\=55443\, body\=cmd\=heartBeat&seq\=60&uniqueId\=616D7A6E312E616C6578612E7768612E33623237623630622D636235352D343461642D386334302D6230633162613863363561302365643632\, timeout\=6 2019-08-02 03:04:39.348 [17f] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:04:45.349 [17f] E MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curl_easy_perform failed\, err\=28 2019-08-02 03:04:45.349 [17f] W MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curlDebug\=[5999] Connection timed out after 6000 milliseconds

2019-08-02 03:04:45.349 [17f] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:04:45.349 [17f] W MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:seq\=60\,error\=28\,remote\=XX1LLF 2019-08-02 03:04:45.349 [17f] 0 MRMLoggerDelegate:WHA:text=Device\:addReachabilityResult\:uniqueId\=XX1LLF\,newReachabilityResult\=2 2019-08-02 03:04:45.349 [17f] 0 MRMLoggerDelegate:WHA:text=Device\:setDeviceReachability\:5 most recent results\:uniqieId\=XX1LLF\,successNum\=0\,softFailNum\=5\,hardFailNum\=0 2019-08-02 03:04:49.348 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:04:49.348 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:04:59.349 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:04:59.349 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:05:09.349 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:05:09.349 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:05:19.349 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:05:19.349 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:05:19.349 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingTo\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:05:19.350 [180] 0 MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:remote\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:05:19.350 [180] 0 MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:url\=https\://xxx/connectivity-test\, port\=55443\, body\=cmd\=heartBeat&seq\=64&uniqueId\=616D7A6E312E616C6578612E7768612E33623237623630622D636235352D343461642D386334302D6230633162613863363561302365643632\, timeout\=6 2019-08-02 03:05:19.350 [180] 5 MRMTimeDelegate:getLocalTimeNs ####################################################################

recive notify event from conan server : alexa_logout

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

{ MSG[0]: EVT_CONAN_ALEXA_LOGOUT(171) } MessageProcessor onEvent msg: EVT_CONAN_ALEXA_LOGOUT sqlString SELECT COUNT(*) FROM sugrvoice WHERE key=?; sqlString UPDATE sugrvoice SET value=?WHERE key=?; EVT_ALEXA_LOGOUT 2019-08-02 03:05:22.057 [ 2a] 0 RegistrationManager:logout 2019-08-02 03:05:22.058 [ 2a] 5 AVSConnectionManager:disable 2019-08-02 03:05:22.058 [ 2a] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=DISCONNECTED 2019-08-02 03:05:22.058 [ 2a] 5 HTTP2Transport:doShutdown 2019-08-02 03:05:22.058 [ 2a] 5 HTTP2Transport:setStateLocked:newState=SHUTDOWN,changedReason=ACL_CLIENT_REQUEST 2019-08-02 03:05:22.058 [ a] 5 SoftwareInfoSender:onConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2019-08-02 03:05:22.058 [ 2a] 5 HTTP2Transport:disconnect 2019-08-02 03:05:22.058 [ a] 5 CallManager:onConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2019-08-02 03:05:22.058 [17c] 5 HTTP2Transport:handleShutdown 2019-08-02 03:05:22.058 [17c] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED onConnectionStatusChanged reason : ACL_CLIENT_REQUEST,status: DISCONNECTED 2019-08-02 03:05:22.058 [17c] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:05:22.058 [17c] 5 LibcurlHTTP2Connection:disconnect 2019-08-02 03:05:22.058 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:05:22.058 [ 1f] 5 SipUserAgent:handleAVSConnectivityStatusChange:Connected to AVS=false #####################################

Client not connected!

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

2019-08-02 03:05:22.058 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:05:22.058 [ a] 5 MRMCloudDelegate:onConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2019-08-02 03:05:22.058 [ 2e] 5 CallManager:provideState:stateRequestToken=19 2019-08-02 03:05:22.059 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:05:22.058 [17c] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:setIsStopping=enter 2019-08-02 03:05:22.059 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=19 2019-08-02 03:05:22.059 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:22.059 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:05:22.059 [17c] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:setIsStopping=quit 2019-08-02 03:05:22.060 [17c] E LibcurlHTTP2Connection:XXXXXXXXXXXXXXXXXXXXX:join=enter 2019-08-02 03:05:22.060 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=19 2019-08-02 03:05:22.061 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:05:22.062 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:05:22.062 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=19 2019-08-02 03:05:22.062 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:05:22.064 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:05:22.065 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:22.067 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=19 2019-08-02 03:05:22.067 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:05:22.067 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=19 2019-08-02 03:05:22.067 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:05:22.067 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:22.067 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:22.068 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:05:22.068 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:05:22.068 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:05:22.068 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=73c3dee4-fb91-4803-b24e-4f701c556b64,namespace=System,name=SynchronizeState 2019-08-02 03:05:22.068 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:05:22.068 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:05:22.068 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:05:22.068 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:05:22.068 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:05:22.068 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=1282 2019-08-02 03:05:22.072 [ 1c] 1 AlertsCapabilityAgent:executeOnConnectionStatusChanged:status=DISCONNECTED,reason=ACL_CLIENT_REQUEST 2019-08-02 03:05:23.350 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:05:23.350 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:05:23.351 [ 2e] 5 CallManager:provideState:stateRequestToken=20 2019-08-02 03:05:23.351 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=20 2019-08-02 03:05:23.351 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:05:23.351 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:05:23.351 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:23.351 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:05:23.351 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:23.355 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=20 2019-08-02 03:05:23.355 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=20 2019-08-02 03:05:23.355 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:05:23.355 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=20 2019-08-02 03:05:23.355 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:05:23.355 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:05:23.355 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=20 2019-08-02 03:05:23.356 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:05:23.356 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:05:23.356 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:23.356 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:23.356 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:05:23.356 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:05:23.356 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:05:23.356 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=00366baa-c264-477e-a315-8e82449aa4c4,namespace=System,name=SynchronizeState 2019-08-02 03:05:23.357 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:05:23.357 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:05:23.357 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:05:23.357 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:05:23.357 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:05:23.357 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=3317 2019-08-02 03:05:25.350 [180] E MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curl_easy_perform failed\, err\=28 2019-08-02 03:05:25.350 [180] W MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curlDebug\=[5999] Connection timed out after 6000 milliseconds

2019-08-02 03:05:25.350 [180] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:05:25.350 [180] W MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:seq\=64\,error\=28\,remote\=XX1LLF 2019-08-02 03:05:25.350 [180] 0 MRMLoggerDelegate:WHA:text=Device\:addReachabilityResult\:uniqueId\=XX1LLF\,newReachabilityResult\=2 2019-08-02 03:05:25.350 [180] 0 MRMLoggerDelegate:WHA:text=Device\:setDeviceReachability\:5 most recent results\:uniqieId\=XX1LLF\,successNum\=0\,softFailNum\=5\,hardFailNum\=0 2019-08-02 03:05:26.674 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:05:26.674 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:05:26.674 [ 2e] 5 CallManager:provideState:stateRequestToken=21 2019-08-02 03:05:26.674 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:05:26.674 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:26.674 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=21 2019-08-02 03:05:26.674 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=21 2019-08-02 03:05:26.675 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:05:26.675 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:05:26.675 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=21 2019-08-02 03:05:26.675 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:05:26.675 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:05:26.675 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=21 2019-08-02 03:05:26.675 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:05:26.676 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=21 2019-08-02 03:05:26.676 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:05:26.676 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:05:26.676 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:26.676 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:26.676 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:26.676 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:05:26.676 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:05:26.676 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:05:26.676 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=fe656e16-456d-47c5-8c84-3f88cd3856e9,namespace=System,name=SynchronizeState 2019-08-02 03:05:26.677 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:05:26.677 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:05:26.677 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:05:26.677 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:05:26.677 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:05:26.677 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=5997 2019-08-02 03:05:29.350 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:05:29.350 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:05:32.674 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:05:32.674 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:05:32.674 [ 2e] 5 CallManager:provideState:stateRequestToken=22 2019-08-02 03:05:32.674 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=22 2019-08-02 03:05:32.675 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:05:32.675 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:05:32.675 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:32.675 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:05:32.675 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:32.675 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=22 2019-08-02 03:05:32.676 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:05:32.676 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=22 2019-08-02 03:05:32.677 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=22 2019-08-02 03:05:32.676 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:05:32.677 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:05:32.677 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=22 2019-08-02 03:05:32.677 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:05:32.677 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:05:32.677 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:32.677 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:32.677 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:05:32.677 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:05:32.677 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:05:32.677 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=655d565d-de65-4d1a-83dd-0b94e4fa14a5,namespace=System,name=SynchronizeState 2019-08-02 03:05:32.678 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:05:32.678 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:05:32.678 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:05:32.678 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:05:32.678 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:05:32.678 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=12599 2019-08-02 03:05:39.350 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:05:39.350 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:05:45.277 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:05:45.277 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:05:45.277 [ 2e] 5 CallManager:provideState:stateRequestToken=23 2019-08-02 03:05:45.277 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:05:45.277 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:45.277 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=23 2019-08-02 03:05:45.277 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=23 2019-08-02 03:05:45.278 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:05:45.278 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:05:45.278 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:45.278 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:05:45.278 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:05:45.279 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=23 2019-08-02 03:05:45.279 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:05:45.279 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=23 2019-08-02 03:05:45.279 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:05:45.279 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=23 2019-08-02 03:05:45.279 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:05:45.279 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:05:45.280 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:05:45.280 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:05:45.280 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:05:45.280 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:05:45.280 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=2bfc5409-1d53-4248-bd1d-e27870ae4db7,namespace=System,name=SynchronizeState 2019-08-02 03:05:45.280 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:05:45.280 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:05:45.280 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:05:45.280 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:05:45.280 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:05:45.280 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=21685 2019-08-02 03:05:49.350 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:05:49.350 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:05:59.351 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:05:59.351 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:05:59.351 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingTo\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:05:59.351 [181] 0 MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:remote\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:05:59.351 [181] 0 MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:url\=https\://xxx/connectivity-test\, port\=55443\, body\=cmd\=heartBeat&seq\=68&uniqueId\=616D7A6E312E616C6578612E7768612E33623237623630622D636235352D343461642D386334302D6230633162613863363561302365643632\, timeout\=6 2019-08-02 03:05:59.351 [181] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:06:05.352 [181] E MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curl_easy_perform failed\, err\=28 2019-08-02 03:06:05.352 [181] W MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curlDebug\=[6000] Connection timed out after 6000 milliseconds

2019-08-02 03:06:05.352 [181] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:06:05.352 [181] W MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:seq\=68\,error\=28\,remote\=XX1LLF 2019-08-02 03:06:05.352 [181] 0 MRMLoggerDelegate:WHA:text=Device\:addReachabilityResult\:uniqueId\=XX1LLF\,newReachabilityResult\=2 2019-08-02 03:06:05.352 [181] 0 MRMLoggerDelegate:WHA:text=Device\:setDeviceReachability\:5 most recent results\:uniqieId\=XX1LLF\,successNum\=0\,softFailNum\=5\,hardFailNum\=0 2019-08-02 03:06:06.965 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:06:06.966 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:06:06.966 [ 2e] 5 CallManager:provideState:stateRequestToken=24 2019-08-02 03:06:06.966 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:06:06.966 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:06.966 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=24 2019-08-02 03:06:06.966 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=24 2019-08-02 03:06:06.966 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=24 2019-08-02 03:06:06.966 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:06:06.967 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:06:06.969 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:06:06.970 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:06:06.970 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:06:06.970 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:06.970 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=24 2019-08-02 03:06:06.970 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:06:06.970 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=24 2019-08-02 03:06:06.970 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:06:06.970 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:06.971 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:06.971 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:06:06.971 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:06:06.971 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:06:06.971 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=63b1c27f-d16a-4bb8-a755-fbeb61646066,namespace=System,name=SynchronizeState 2019-08-02 03:06:06.971 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:06:06.971 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:06:06.971 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:06:06.971 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:06:06.971 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:06:06.971 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=13247 2019-08-02 03:06:09.351 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:06:09.351 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:06:19.352 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:06:19.352 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:06:20.218 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:06:20.219 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:06:20.219 [ 2e] 5 CallManager:provideState:stateRequestToken=25 2019-08-02 03:06:20.219 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=25 2019-08-02 03:06:20.219 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=25 2019-08-02 03:06:20.219 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:06:20.219 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:06:20.219 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:06:20.219 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:06:20.219 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:20.219 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:20.220 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:06:20.220 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=25 2019-08-02 03:06:20.220 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:06:20.220 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=25 2019-08-02 03:06:20.220 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:06:20.220 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=25 2019-08-02 03:06:20.221 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:06:20.221 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:20.221 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:20.221 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:06:20.221 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:06:20.221 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:06:20.222 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=9408a200-b14c-4d8b-8299-e6e9ef4ef1e9,namespace=System,name=SynchronizeState 2019-08-02 03:06:20.222 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:06:20.222 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:06:20.222 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:06:20.222 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:06:20.222 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:06:20.222 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=18194 2019-08-02 03:06:29.352 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:06:29.352 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:06:38.416 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:06:38.416 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:06:38.416 [ 2e] 5 CallManager:provideState:stateRequestToken=26 2019-08-02 03:06:38.416 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=26 2019-08-02 03:06:38.416 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=26 2019-08-02 03:06:38.417 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:06:38.417 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:06:38.417 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:06:38.417 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:38.417 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:06:38.417 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:38.418 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:06:38.418 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=26 2019-08-02 03:06:38.418 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:06:38.418 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=26 2019-08-02 03:06:38.418 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:06:38.418 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=26 2019-08-02 03:06:38.418 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:06:38.419 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:38.419 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:38.419 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:06:38.419 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:06:38.419 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:06:38.419 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=ce326b4a-f488-41d1-be14-1e9615e61909,namespace=System,name=SynchronizeState 2019-08-02 03:06:38.419 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:06:38.419 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:06:38.419 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:06:38.419 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:06:38.419 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:06:38.419 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=19508 2019-08-02 03:06:39.352 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:06:39.352 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:06:39.352 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingTo\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:06:39.353 [182] 0 MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:remote\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:06:39.353 [182] 0 MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:url\=https\://xxx/connectivity-test\, port\=55443\, body\=cmd\=heartBeat&seq\=72&uniqueId\=616D7A6E312E616C6578612E7768612E33623237623630622D636235352D343461642D386334302D6230633162613863363561302365643632\, timeout\=6 2019-08-02 03:06:39.353 [182] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:06:45.353 [182] E MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curl_easy_perform failed\, err\=28 2019-08-02 03:06:45.353 [182] W MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curlDebug\=[5999] Connection timed out after 6000 milliseconds

2019-08-02 03:06:45.353 [182] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:06:45.353 [182] W MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:seq\=72\,error\=28\,remote\=XX1LLF 2019-08-02 03:06:45.353 [182] 0 MRMLoggerDelegate:WHA:text=Device\:addReachabilityResult\:uniqueId\=XX1LLF\,newReachabilityResult\=2 2019-08-02 03:06:45.354 [182] 0 MRMLoggerDelegate:WHA:text=Device\:setDeviceReachability\:5 most recent results\:uniqieId\=XX1LLF\,successNum\=0\,softFailNum\=5\,hardFailNum\=0 2019-08-02 03:06:49.353 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:06:49.353 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:06:57.928 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:06:57.928 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:06:57.928 [ 2e] 5 CallManager:provideState:stateRequestToken=27 2019-08-02 03:06:57.928 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:06:57.928 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=27 2019-08-02 03:06:57.928 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:57.928 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:06:57.928 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=27 2019-08-02 03:06:57.928 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:06:57.928 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=27 2019-08-02 03:06:57.928 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=27 2019-08-02 03:06:57.928 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:06:57.929 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:06:57.929 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:06:57.928 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:06:57.929 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:57.929 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=27 2019-08-02 03:06:57.930 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:06:57.930 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:06:57.930 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:06:57.930 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:06:57.930 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:06:57.930 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:06:57.931 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=1fc24fb1-e5b8-4b38-b78c-ac4ae6a6a132,namespace=System,name=SynchronizeState 2019-08-02 03:06:57.931 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:06:57.931 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:06:57.931 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:06:57.931 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:06:57.931 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:06:57.931 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=18147 2019-08-02 03:06:59.353 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:06:59.353 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:07:09.353 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:07:09.354 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:07:16.078 [17d] 5 PostConnectSynchronizer:setState:from=RUNNING,to=FETCHING 2019-08-02 03:07:16.078 [ 2e] 5 AudioActivityTracker:provideState 2019-08-02 03:07:16.078 [ 2e] 5 CallManager:provideState:stateRequestToken=28 2019-08-02 03:07:16.078 [ 2e] 5 NotificationsCapabilityAgent:provideState:stateRequestToken=28 2019-08-02 03:07:16.079 [ 2e] 5 VisualActivityTracker:provideState 2019-08-02 03:07:16.079 [ 23] 5 VisualActivityTracker:executeProvideState 2019-08-02 03:07:16.079 [ 23] 9 ContextManager:updateStateLocked:action=updatedState,namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:07:16.079 [ d] 5 AudioActivityTracker:executeProvideState 2019-08-02 03:07:16.079 [ d] 9 ContextManager:updateStateLocked:action=updatedState,namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:07:16.080 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=28 2019-08-02 03:07:16.081 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=ExternalMediaPlayer,name=ExternalMediaPlayerState 2019-08-02 03:07:16.081 [ 22] 0 ExternalMediaPlayer:executeProvideState:sendToken=true,stateRequestToken=28 2019-08-02 03:07:16.081 [ 22] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Alexa.PlaybackStateReporter,name=playbackState 2019-08-02 03:07:16.081 [ 1f] 5 CallManager:executeProvideState:sendToken=true,stateRequestToken=28 2019-08-02 03:07:16.081 [ 1f] 5 SipUserAgent:getSipUserAgentStateContext 2019-08-02 03:07:16.082 [ 1f] 9 ContextManager:updateStateLocked:action=updatedState,namespace=SipUserAgent,name=SipUserAgentState 2019-08-02 03:07:16.082 [ 1e] 5 NotificationsCapabilityAgent:executeProvideState:sendToken=true,stateRequestToken=28 2019-08-02 03:07:16.083 [ 1e] 9 ContextManager:updateStateLocked:action=updatedState,namespace=Notifications,name=IndicatorState 2019-08-02 03:07:16.083 [ 2e] 9 ContextManager:buildContextIgnored:namespace=AudioActivityTracker,name=ActivityState 2019-08-02 03:07:16.083 [ 2e] 9 ContextManager:buildContextIgnored:namespace=VisualActivityTracker,name=ActivityState 2019-08-02 03:07:16.083 [ 2e] 5 ContextManager:buildContextSuccessful 2019-08-02 03:07:16.083 [ 2e] 5 PostConnectSynchronizer:onContextAvailable 2019-08-02 03:07:16.083 [ 2e] 5 PostConnectSynchronizer:setState:from=FETCHING,to=SENDING 2019-08-02 03:07:16.083 [ 2e] 0 EventBuilder:buildJsonEventString:messageId=f37b87db-45dd-4dec-a7ea-367c9859ee52,namespace=System,name=SynchronizeState 2019-08-02 03:07:16.083 [ 2e] 5 HTTP2Transport:sendPostConnectMessage 2019-08-02 03:07:16.084 [ 2e] 5 HTTP2Transport:enqueueRequest:beforeConnected=true 2019-08-02 03:07:16.084 [ 2e] E HTTP2Transport:enqueueRequestFailed:reason=notInAllowedState,m_state=SHUTDOWN 2019-08-02 03:07:16.084 [ 2e] 5 PostConnectSynchronizer:onSendCompleted:status=NOT_CONNECTED 2019-08-02 03:07:16.084 [ 2e] 5 PostConnectSynchronizer:setState:from=SENDING,to=RUNNING 2019-08-02 03:07:16.084 [17d] W PostConnectSynchronizer:waitingToRetryPostConnectOperation:timeoutMs=24586 2019-08-02 03:07:19.354 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:07:19.354 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs 2019-08-02 03:07:19.354 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingTo\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:07:19.354 [183] 0 MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:remote\=amzn1.alexa.wha.d1420504-8d2b-4d2c-8fa8-610c0d8011a0#1LLF 2019-08-02 03:07:19.354 [183] 0 MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:url\=https\://xxx/connectivity-test\, port\=55443\, body\=cmd\=heartBeat&seq\=76&uniqueId\=616D7A6E312E616C6578612E7768612E33623237623630622D636235352D343461642D386334302D6230633162613863363561302365643632\, timeout\=6 2019-08-02 03:07:19.354 [183] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:07:25.355 [183] E MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curl_easy_perform failed\, err\=28 2019-08-02 03:07:25.355 [183] W MRMLoggerDelegate:WHA:text=Device\:sendRemoteCommand\:curlDebug\=[5999] Connection timed out after 6000 milliseconds

2019-08-02 03:07:25.355 [183] 5 MRMTimeDelegate:getLocalTimeNs 2019-08-02 03:07:25.355 [183] W MRMLoggerDelegate:WHA:text=Device\:sendHeartBeat\:seq\=76\,error\=28\,remote\=XX1LLF 2019-08-02 03:07:25.355 [183] 0 MRMLoggerDelegate:WHA:text=Device\:addReachabilityResult\:uniqueId\=XX1LLF\,newReachabilityResult\=2 2019-08-02 03:07:25.355 [183] 0 MRMLoggerDelegate:WHA:text=Device\:setDeviceReachability\:5 most recent results\:uniqieId\=XX1LLF\,successNum\=0\,softFailNum\=5\,hardFailNum\=0 2019-08-02 03:07:29.354 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:appendingPendingRequests 2019-08-02 03:07:29.354 [ a8] 0 MRMLoggerDelegate:WHA:text=DeviceClusterManager\:heartBeatSenderThread\:sendingHBs

[cameled]

/*

• Copyright 2018-2019 Amazon.com, Inc. or its affiliates. All Rights Reserved.
• Licensed under the Apache License, Version 2.0 (the "License").
• You may not use this file except in compliance with the License.
• A copy of the License is located at
• http://aws.amazon.com/apache2.0/
• or in the "license" file accompanying this file. This file is distributed
• on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either
• express or implied. See the License for the specific language governing
• permissions and limitations under the License. */

include <curl/multi.h>

include <AVSCommon/Utils/Logger/Logger.h>

include <AVSCommon/Utils/LibcurlUtils/CurlEasyHandleWrapper.h>

include "AVSCommon/Utils/LibcurlUtils/LibcurlHTTP2Connection.h"

include "AVSCommon/Utils/LibcurlUtils/LibcurlHTTP2Request.h"

namespace alexaClientSDK { namespace avsCommon { namespace utils { namespace libcurlUtils {

using namespace avsCommon::utils::http2; using namespace avsCommon::utils::libcurlUtils;

/// String to identify log entries originating from this file. static const std::string TAG("LibcurlHTTP2Connection");

/**

• Create a LogEntry using this file's TAG and the specified event string.
• @param The event string for this @c LogEntry. */

  define LX(event) alexaClientSDK::avsCommon::utils::logger::LogEntry(TAG, event)

/// Timeout for curl_multi_wait const static std::chrono::milliseconds WAIT_FOR_ACTIVITY_TIMEOUT(100); /// Timeout for curl_multi_wait while all non-intermittent HTTP/2 streams are paused. const static std::chrono::milliseconds WAIT_FOR_ACTIVITY_WHILE_STREAMS_PAUSED_TIMEOUT(10);

ifdef ACSDK_OPENSSL_MIN_VER_REQUIRED

/**

• This function checks the minimum version of OpenSSL required and prints a warning if the version is too old or

• the version string parsing failed. / static void verifyOpenSslVersion(curl_version_info_data data) { // There are three numbers in OpenSSL version: major.minor.patch static const int NUM_OF_VERSION_NUMBER = 3;

  unsigned int versionUsed[NUM_OF_VERSION_NUMBER]; unsigned int minVersionRequired[NUM_OF_VERSION_NUMBER];

  if (!data) { ACSDK_ERROR(LX("verifyOpenSslVersionFailed").d("reason", "nullData")); return; } else if (!data->ssl_version) { ACSDK_ERROR(LX("verifyOpenSslVersionFailed").d("reason", "nullSslVersion")); return; }

  // parse ssl_version int matchedVersionUsed = sscanf(data->ssl_version, "OpenSSL/%u.%u.%u", &versionUsed[0], &versionUsed[1], &versionUsed[2]);

  // parse minimum OpenSSL version required int matchedVersionRequired = sscanf( ACSDK_STRINGIFY(ACSDK_OPENSSL_MIN_VER_REQUIRED), "%u.%u.%u", &minVersionRequired[0], &minVersionRequired[1], &minVersionRequired[2]);

  if (matchedVersionUsed == matchedVersionRequired && matchedVersionUsed == NUM_OF_VERSION_NUMBER) { bool versionRequirementFailed = false;

  for (int i = 0; i < NUM_OF_VERSION_NUMBER; i++) {
      if (versionUsed[i] < minVersionRequired[i]) {
          versionRequirementFailed = true;
          break;
      } else if (versionUsed[i] > minVersionRequired[i]) {
          break;
      }
  }
  if (versionRequirementFailed) {
      ACSDK_WARN(LX("OpenSSL minimum version requirement failed!")
                     .d("version", data->ssl_version)
                     .d("required", ACSDK_STRINGIFY(ACSDK_OPENSSL_MIN_VER_REQUIRED)));
  }

  } else { ACSDK_WARN(LX("Unable to parse OpenSSL version!") .d("version", data->ssl_version) .d("required", ACSDK_STRINGIFY(ACSDK_OPENSSL_MIN_VER_REQUIRED))); } }

  endif

/**

• This function logs a warning if the version of curl is not recent enough for use with the ACL.
• @return true if check passes, false if it fails / static bool performCurlChecks() { curl_version_info_data data = curl_version_info(CURLVERSION_NOW); if (data && !(data->features & CURL_VERSION_HTTP2)) { ACSDK_CRITICAL(LX("libcurl not built with HTTP/2 support!")); return false; }

  ifdef ACSDK_OPENSSL_MIN_VER_REQUIRED

  verifyOpenSslVersion(data);

  endif

  return true; }

LibcurlHTTP2Connection::LibcurlHTTP2Connection() : m_isStopping{false} { m_networkThread = std::thread(&LibcurlHTTP2Connection::networkLoop, this); }

bool LibcurlHTTP2Connection::createMultiHandle() { m_multi = CurlMultiHandleWrapper::create(); if (!m_multi) { ACSDK_ERROR(LX("initFailed").d("reason", "curlMultiHandleWrapperCreateFailed")); return false; } if (curl_multi_setopt(m_multi->getCurlHandle(), CURLMOPT_PIPELINING, 2L) != CURLM_OK) { m_multi.reset(); ACSDK_ERROR(LX("initFailed").d("reason", "enableHTTP2PipeliningFailed")); return false; }

return true;

}

std::shared_ptr LibcurlHTTP2Connection::create() { if (!performCurlChecks()) { return nullptr; } return std::shared_ptr(new LibcurlHTTP2Connection()); }

LibcurlHTTP2Connection::~LibcurlHTTP2Connection() { ACSDK_DEBUG5(LX(func)); disconnect(); }

bool LibcurlHTTP2Connection::isStopping() { std::lock_guard lock(m_mutex); return m_isStopping; }

void LibcurlHTTP2Connection::setIsStopping() { ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("setIsStopping", "enter")); std::lock_guard lock(m_mutex); m_isStopping = true; m_cv.notify_one(); ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("setIsStopping", "quit")); }

std::shared_ptr LibcurlHTTP2Connection::dequeueRequest() { std::lock_guard lock(m_mutex); if (m_isStopping || m_requestQueue.empty()) { return nullptr; } auto result = m_requestQueue.front(); m_requestQueue.pop_front(); return result; }

void LibcurlHTTP2Connection::processNextRequest() { auto stream = dequeueRequest(); if (!stream) { return; } stream->setTimeOfLastTransfer(); auto result = m_multi->addHandle(stream->getCurlHandle()); if (CURLM_OK == result) { auto handle = stream->getCurlHandle(); ACSDK_DEBUG9(LX("insertActiveStream").d("handle", handle).d("streamId", stream->getId())); m_activeStreams[handle] = stream; } else { ACSDK_ERROR(LX("processNextRequest").d("reason", "addHandleFailed").d("error", curl_multi_strerror(result))); stream->reportCompletion(HTTP2ResponseFinishedStatus::INTERNAL_ERROR); } }

void LibcurlHTTP2Connection::networkLoop() { ACSDK_DEBUG5(LX(func));

while (!isStopping()) {
    if (!createMultiHandle()) {
        setIsStopping();
        break;
    }
    {
        ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("perform", "enter"));
        // wait until we have at least one request
        std::unique_lock<std::mutex> lock(m_mutex);
        m_cv.wait(lock, [this] { return m_isStopping || !m_requestQueue.empty(); });
        if (m_isStopping) {
            break;
        }
    }

    processNextRequest();

    int numTransfersLeft = 1;  // just dequeued the first request.
    // Call perform repeatedly to transfer data on active streams.
    while (numTransfersLeft > 0 && !isStopping()) {
        ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("perform", "enter"));
        auto result = m_multi->perform(&numTransfersLeft);
        ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("perform", "quit"));
        if (result == CURLM_CALL_MULTI_PERFORM) {
            continue;
        }
        if (result != CURLM_OK) {
            ACSDK_ERROR(LX("networkLoopStopping").d("reason", "performFailed"));
            setIsStopping();
            break;
        }

        ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("networkLoop", "A"));
        cleanupFinishedStreams();
        ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("networkLoop", "B"));
        cleanupCancelledAndStalledStreams();
        ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("networkLoop", "C"));

        if (isStopping()) {
            break;
        }

        processNextRequest();

        auto before = std::chrono::time_point<std::chrono::steady_clock>::max();
        auto multiWaitTimeout = WAIT_FOR_ACTIVITY_TIMEOUT;
        bool paused = areStreamsPaused();
        if (paused) {
            multiWaitTimeout = WAIT_FOR_ACTIVITY_WHILE_STREAMS_PAUSED_TIMEOUT;
            before = std::chrono::steady_clock::now();
        }

        int numTransfersUpdated = 0;
        result = m_multi->wait(multiWaitTimeout, &numTransfersUpdated);
        if (result != CURLM_OK) {
            ACSDK_ERROR(
                LX("networkLoopStopping").d("reason", "multiWaitFailed").d("error", curl_multi_strerror(result)));
            setIsStopping();
            break;
        }

        // @note curl_multi_wait will return immediately even if all streams are paused, because HTTP/2 streams
        // are full-duplex - so activity may have occurred on the other side. Therefore, if our intent is to pause
        // transfers to give the readers / writers time to catch up, we must perform a local sleep of our own.
        if (paused) {
            auto after = std::chrono::steady_clock::now();
            auto elapsed = after - before;
            auto remaining = multiWaitTimeout - elapsed;

            // sanity check that remainingMs is valid before performing a sleep.
            if (remaining.count() > 0 && remaining <= WAIT_FOR_ACTIVITY_WHILE_STREAMS_PAUSED_TIMEOUT) {
                std::this_thread::sleep_for(remaining);
            }
        }
        ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("networkLoop", "D"));
        unPauseActiveStreams();
    }
    ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("networkLoop", "E"));
    cancelAllStreams();
    ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("networkLoop", "F"));
    m_multi.reset();
    ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("networkLoop", "G"));
}

ACSDK_DEBUG5(LX("networkLoopExiting"));

}

std::shared_ptr LibcurlHTTP2Connection::createAndSendRequest(const HTTP2RequestConfig& config) { auto req = std::make_shared(config, config.getId()); addStream(req); return req; }

void LibcurlHTTP2Connection::disconnect() { ACSDK_DEBUG5(LX(func)); setIsStopping(); if (m_networkThread.joinable()) { ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("join", "enter")); m_networkThread.join(); ACSDK_ERROR(LX("XXXXXXXXXXXXXXXXXXXXX").d("join", "quit")); } }

bool LibcurlHTTP2Connection::addStream(std::shared_ptr stream) { if (!stream) { ACSDK_ERROR(LX("addStream").d("failed", "null stream")); return false; } std::lock_guard lock(m_mutex); if (m_isStopping) { ACSDK_ERROR(LX("addStream").d("failed", "network loop stopping")); return false; } m_requestQueue.push_back(std::move(stream)); m_cv.notify_one(); return true; }

void LibcurlHTTP2Connection::cleanupFinishedStreams() { CURLMsg* message = nullptr; do { int messagesLeft = 0; message = m_multi->infoRead(&messagesLeft); if (message && message->msg == CURLMSG_DONE) { auto it = m_activeStreams.find(message->easy_handle); if (it != m_activeStreams.end()) { it->second->reportResponseCode();

            if (CURLE_OPERATION_TIMEDOUT == message->data.result) {
                it->second->reportCompletion(HTTP2ResponseFinishedStatus::TIMEOUT);
            } else {
                it->second->reportCompletion(HTTP2ResponseFinishedStatus::COMPLETE);
            }
            ACSDK_DEBUG(LX("streamFinished")
                            .d("streamId", it->second->getId())
                            .d("result", curl_easy_strerror(message->data.result))
                            .d("CURLcode", message->data.result));
            releaseStream(*(it->second));
        } else {
            ACSDK_ERROR(
                LX("cleanupFinishedStreamError").d("reason", "streamNotFound").d("handle", message->easy_handle));
        }
    }
} while (message);

}

void LibcurlHTTP2Connection::cleanupCancelledAndStalledStreams() { auto it = m_activeStreams.begin(); while (it != m_activeStreams.end()) { auto stream = (it++)->second; if (stream->isCancelled()) { cancelStream(stream); } else if (stream->hasProgressTimedOut()) { ACSDK_WARN(LX("streamProgressTimedOut").d("streamId", stream->getId())); stream->reportCompletion(HTTP2ResponseFinishedStatus::TIMEOUT); releaseStream(stream); } } }

bool LibcurlHTTP2Connection::areStreamsPaused() { size_t numberNonIntermittentStreams = 0; size_t numberPausedStreams = 0; for (const auto& entry : m_activeStreams) { const auto& stream = entry.second; if (!stream->isIntermittentTransferExpected()) { numberNonIntermittentStreams++; if (entry.second->isPaused()) { numberPausedStreams++; } } } return numberPausedStreams > 0 && (numberPausedStreams == numberNonIntermittentStreams); }

void LibcurlHTTP2Connection::unPauseActiveStreams() { for (auto& stream : m_activeStreams) { stream.second->unPause(); } }

bool LibcurlHTTP2Connection::cancelStream(LibcurlHTTP2Request& stream) { ACSDK_INFO(LX("cancelStream").d("streamId", stream.getId())); stream.reportCompletion(HTTP2ResponseFinishedStatus::CANCELLED); return releaseStream(stream); }

void LibcurlHTTP2Connection::cancelAllStreams() { auto it = m_activeStreams.begin(); while (it != m_activeStreams.end()) { cancelStream(*(it++)->second); } }

bool LibcurlHTTP2Connection::releaseStream(LibcurlHTTP2Request& stream) { auto handle = stream.getCurlHandle(); ACSDK_DEBUG9(LX("releaseStream").d("streamId", stream.getId())); auto result = m_multi->removeHandle(handle); m_activeStreams.erase(handle); if (result != CURLM_OK) { ACSDK_ERROR(LX("releaseStreamFailed").d("reason", "removeHandleFailed").d("streamId", stream.getId())); return false; } return true; }

} // namespace libcurlUtils } // namespace utils } // namespace avsCommon } // namespace alexaClientSDK

[celinval]

Hi @cameled, Which version of libcurl are you using? Is it possible for you to update to a newer version and see if the problem is fixed? This seems to be related to this old issue on libcurl which has been solved in newer versions.

[cameled]

Hi @celinval, libcurl version is 7.64.1. I have upgrade it to 7.65.3, looks stuck not happen now.