Memory leak: old transport not released upon server side disconnection #329

gws-hjyu · 2017-11-12T06:18:51Z

When a server side disconnection happens (it happens hourly), the old HTTP2 transport is not released properly. A quick way to verify is to use the same configuration JSON file to launch 2 SampleApp. They will disconnect each other constantly and we can observe the process memory increments. It is very easy to prove that the transport is not released as we can add the following line into MessageRouter::onServerSideDisconnect() to log the transport count:

ACSDK_DEBUG(LX("onServerSideDisconnect").d("transports", m_transports.size()));

Here are some lines from the log output:

2017-11-12 06:07:55.357 [  9] 0 MessageRouter:onServerSideDisconnect:transports=1
2017-11-12 06:07:55.357 [  9] 0 MessageRouter:connectionStatusChanged:reason=SERVER_SIDE_DISCONNECT,newStatus=PENDING
2017-11-12 06:07:55.357 [  9] W HTTP2Transport:Unable to parse OpenSSL version!:version=LibreSSL/2.0.20,required=1.0.2
2017-11-12 06:07:55.357 [  9] 0 HTTP2StreamPool:getStream:streamId=5,numAcquiredStreams=1
2017-11-12 06:07:55.357 [  9] 0 PostConnectSynchronize:onServerSideDisconnect()
2017-11-12 06:07:55.357 [  9] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
#############################
#       Connecting...       #
#############################

2017-11-12 06:07:55.357 [  9] 0 HTTP2StreamPool:releaseStream:streamId=1,numAcquiredStreams=0
2017-11-12 06:07:55.357 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState
2017-11-12 06:07:55.357 [  9] 0 PostConnectSynchronize:onDisconnected()
2017-11-12 06:07:55.357 [  9] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
2017-11-12 06:07:55.358 [  4] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:100\,"muted"\:false}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}]}
2017-11-12 06:07:55.358 [  4] 0 EventBuilder:buildJsonEventString:messageId=e899fc36-97da-4a8a-aef9-6f60f802a774,namespace=System,name=SynchronizeState
2017-11-12 06:07:55.358 [  4] 0 PostConnectSynchronize:onContextAvailable : Send PostConnectMessage to transport
2017-11-12 06:07:57.813 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0aff6dfffeb6be02-0000059b-0003dc6e-cb28e41fc048853a-c34d486e-1
2017-11-12 06:07:57.813 [  b] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-12 06:07:57.813 [  b] 0 HTTP2StreamPool:getStream:streamId=7,numAcquiredStreams=2
2017-11-12 06:07:59.465 [  b] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0aff6dfffeb6be02-0000059b-0003dc6e-cb28e41fc048853a-c34d486e-3
2017-11-12 06:07:59.465 [  b] 0 PostConnectSynchronize:onSendCompleted:status=SUCCESS_NO_CONTENT
2017-11-12 06:07:59.465 [  b] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED
2017-11-12 06:07:59.465 [  b] 0 PostConnectSynchronize:onConnected()
2017-11-12 06:07:59.465 [  b] 0 HTTP2Transport:cleanupFinishedStream:streamId=7,result=204
########################################
#       Alexa is currently idle!       #
########################################

2017-11-12 06:07:59.465 [  b] 0 HTTP2StreamPool:releaseStream:streamId=7,numAcquiredStreams=1
2017-11-12 06:07:59.466 [  b] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-12 06:08:00.272 [  b] 0 MessageRouter:onServerSideDisconnect:transports=2
2017-11-12 06:08:00.272 [  b] 0 MessageRouter:connectionStatusChanged:reason=SERVER_SIDE_DISCONNECT,newStatus=PENDING
2017-11-12 06:08:00.272 [  b] W HTTP2Transport:Unable to parse OpenSSL version!:version=LibreSSL/2.0.20,required=1.0.2
2017-11-12 06:08:00.272 [  b] 0 HTTP2StreamPool:getStream:streamId=9,numAcquiredStreams=1
2017-11-12 06:08:00.272 [  b] 0 PostConnectSynchronize:onServerSideDisconnect()
2017-11-12 06:08:00.272 [  b] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
#############################
#       Connecting...       #
#############################

2017-11-12 06:08:00.272 [  b] 0 HTTP2StreamPool:releaseStream:streamId=5,numAcquiredStreams=0
2017-11-12 06:08:00.272 [  b] 0 PostConnectSynchronize:onDisconnected()
2017-11-12 06:08:00.272 [  b] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
2017-11-12 06:08:00.272 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState
2017-11-12 06:08:00.272 [  4] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:100\,"muted"\:false}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}]}
2017-11-12 06:08:00.272 [  4] 0 EventBuilder:buildJsonEventString:messageId=0694bfab-7767-4b89-8be0-8d01b7676c6d,namespace=System,name=SynchronizeState
2017-11-12 06:08:00.273 [  4] 0 PostConnectSynchronize:onContextAvailable : Send PostConnectMessage to transport
2017-11-12 06:08:02.729 [  c] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0a3070fffe993f2c-000076ba-0003da50-edda5332c438709e-c10ced19-1
2017-11-12 06:08:02.729 [  c] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-12 06:08:02.729 [  c] 0 HTTP2StreamPool:getStream:streamId=11,numAcquiredStreams=2
2017-11-12 06:08:04.377 [  c] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0a3070fffe993f2c-000076ba-0003da50-edda5332c438709e-c10ced19-3
2017-11-12 06:08:04.377 [  c] 0 PostConnectSynchronize:onSendCompleted:status=SUCCESS_NO_CONTENT
2017-11-12 06:08:04.377 [  c] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED
2017-11-12 06:08:04.377 [  c] 0 PostConnectSynchronize:onConnected()
2017-11-12 06:08:04.377 [  c] 0 HTTP2Transport:cleanupFinishedStream:streamId=11,result=204
2017-11-12 06:08:04.377 [  c] 0 HTTP2StreamPool:releaseStream:streamId=11,numAcquiredStreams=1
2017-11-12 06:08:04.377 [  c] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
########################################
#       Alexa is currently idle!       #
########################################

2017-11-12 06:08:05.187 [  c] 0 MessageRouter:onServerSideDisconnect:transports=3
2017-11-12 06:08:05.187 [  c] 0 MessageRouter:connectionStatusChanged:reason=SERVER_SIDE_DISCONNECT,newStatus=PENDING
2017-11-12 06:08:05.187 [  c] W HTTP2Transport:Unable to parse OpenSSL version!:version=LibreSSL/2.0.20,required=1.0.2
2017-11-12 06:08:05.187 [  c] 0 HTTP2StreamPool:getStream:streamId=13,numAcquiredStreams=1
2017-11-12 06:08:05.188 [  c] 0 PostConnectSynchronize:onServerSideDisconnect()
2017-11-12 06:08:05.188 [  c] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
#############################
#       Connecting...       #
#############################

2017-11-12 06:08:05.188 [  c] 0 HTTP2StreamPool:releaseStream:streamId=9,numAcquiredStreams=0
2017-11-12 06:08:05.188 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState
2017-11-12 06:08:05.188 [  c] 0 PostConnectSynchronize:onDisconnected()
2017-11-12 06:08:05.188 [  c] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
2017-11-12 06:08:05.188 [  4] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:100\,"muted"\:false}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}]}
2017-11-12 06:08:05.188 [  4] 0 EventBuilder:buildJsonEventString:messageId=d96da7db-9968-43f7-ba1f-b855235ad55c,namespace=System,name=SynchronizeState
2017-11-12 06:08:05.188 [  4] 0 PostConnectSynchronize:onContextAvailable : Send PostConnectMessage to transport
2017-11-12 06:08:07.643 [  d] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ab153fffe0011a2-00002e89-0003d765-3efb9fa548432fbf-fe871341-1
2017-11-12 06:08:07.644 [  d] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-12 06:08:07.644 [  d] 0 HTTP2StreamPool:getStream:streamId=15,numAcquiredStreams=2
2017-11-12 06:08:09.283 [  d] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0ab153fffe0011a2-00002e89-0003d765-3efb9fa548432fbf-fe871341-3
2017-11-12 06:08:09.283 [  d] 0 PostConnectSynchronize:onSendCompleted:status=SUCCESS_NO_CONTENT
2017-11-12 06:08:09.283 [  d] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED
2017-11-12 06:08:09.283 [  d] 0 PostConnectSynchronize:onConnected()
2017-11-12 06:08:09.283 [  d] 0 HTTP2Transport:cleanupFinishedStream:streamId=15,result=204
########################################
#       Alexa is currently idle!       #
########################################

2017-11-12 06:08:09.283 [  d] 0 HTTP2StreamPool:releaseStream:streamId=15,numAcquiredStreams=1
2017-11-12 06:08:09.283 [  d] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT
2017-11-12 06:08:10.102 [  d] 0 MessageRouter:onServerSideDisconnect:transports=4
2017-11-12 06:08:10.102 [  d] 0 MessageRouter:connectionStatusChanged:reason=SERVER_SIDE_DISCONNECT,newStatus=PENDING
2017-11-12 06:08:10.102 [  d] W HTTP2Transport:Unable to parse OpenSSL version!:version=LibreSSL/2.0.20,required=1.0.2
2017-11-12 06:08:10.102 [  d] 0 HTTP2StreamPool:getStream:streamId=17,numAcquiredStreams=1
2017-11-12 06:08:10.103 [  d] 0 PostConnectSynchronize:onServerSideDisconnect()
2017-11-12 06:08:10.103 [  d] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
#############################
#       Connecting...       #
#############################

2017-11-12 06:08:10.103 [  d] 0 HTTP2StreamPool:releaseStream:streamId=13,numAcquiredStreams=0
2017-11-12 06:08:10.103 [  d] 0 PostConnectSynchronize:onDisconnected()
2017-11-12 06:08:10.103 [  d] 0 PostConnectSynchronize:PostConnectSynchronizer::doShutdown().
2017-11-12 06:08:10.103 [  8] 0 ContextManager:updateStateLocked:action=updatedState,state={"volume"\:100\,"muted"\:false},namespace=Speaker,name=VolumeState
2017-11-12 06:08:10.103 [  4] 0 ContextManager:buildContextSuccessful:context={"context"\:[{"header"\:{"namespace"\:"Speaker"\,"name"\:"VolumeState"}\,"payload"\:{"volume"\:100\,"muted"\:false}}\,{"header"\:{"namespace"\:"Alerts"\,"name"\:"AlertsState"}\,"payload"\:{"allAlerts"\:[]\,"activeAlerts"\:[]}}\,{"header"\:{"namespace"\:"SpeechSynthesizer"\,"name"\:"SpeechState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"FINISHED"}}\,{"header"\:{"namespace"\:"AudioPlayer"\,"name"\:"PlaybackState"}\,"payload"\:{"token"\:""\,"offsetInMilliseconds"\:0\,"playerActivity"\:"IDLE"}}\,{"header"\:{"namespace"\:"SpeechRecognizer"\,"name"\:"RecognizerState"}\,"payload"\:{"wakeword"\:""}}]}
2017-11-12 06:08:10.103 [  4] 0 EventBuilder:buildJsonEventString:messageId=7eb54615-5eb8-4ac1-a4ef-39cf269ef93f,namespace=System,name=SynchronizeState
2017-11-12 06:08:10.103 [  4] 0 PostConnectSynchronize:onContextAvailable : Send PostConnectMessage to transport
2017-11-12 06:08:12.008 [  e] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0adef1fffe7551a6-00001bab-0003d37a-739f4d11984312f6-9d6e139e-1
2017-11-12 06:08:12.008 [  e] 0 HTTP2Transport:processNextOutgoingMessage
2017-11-12 06:08:12.008 [  e] 0 HTTP2StreamPool:getStream:streamId=19,numAcquiredStreams=2
2017-11-12 06:08:14.197 [  e] 0 HTTP2Stream:receivedRequestId:value=x-amzn-requestid\: 0adef1fffe7551a6-00001bab-0003d37a-739f4d11984312f6-9d6e139e-3
2017-11-12 06:08:14.197 [  e] 0 PostConnectSynchronize:onSendCompleted:status=SUCCESS_NO_CONTENT
2017-11-12 06:08:14.197 [  e] 0 MessageRouter:connectionStatusChanged:reason=ACL_CLIENT_REQUEST,newStatus=CONNECTED
2017-11-12 06:08:14.197 [  e] 0 PostConnectSynchronize:onConnected()
2017-11-12 06:08:14.197 [  e] 0 HTTP2Transport:cleanupFinishedStream:streamId=19,result=204
########################################
#       Alexa is currently idle!       #
########################################

2017-11-12 06:08:14.198 [  e] 0 HTTP2StreamPool:releaseStream:streamId=19,numAcquiredStreams=1
2017-11-12 06:08:14.198 [  e] 0 CurlEasyHandleWrapper:reset:responseCode=HTTP_RESPONSE_SUCCESS_NO_CONTENT

As we can see the transport count keeps increasing.

The text was updated successfully, but these errors were encountered:

scotthea-amazon · 2017-11-13T17:46:07Z

Hi gws-hjyu,

Thank you very much for bringing this to our attention! We will look in to it and let you know what we find.

Regards,
-SWH

Changes in this update * **Enhancements**.. * Added comments to `AlexaClientSDKConfig.json`. These descriptions provide additional guidance for what is expected for each field... * Enabled pause and resume controls for Pandora... * **Bug Fixes**.. * Bug fix for [issue #329](#329) - `HTTP2Transport` instances no longer leak when `SERVER_SIDE * Bug fix for [issue #189](#189) - Fixed a race condition in the `Timer` class that sometimes * Bug fix for a race condition that caused `SpeechSynthesizer` to ignore subsequent `Speak` directives... * Bug fix for corrupted mime attachments.

sanjayrd · 2017-12-12T01:34:27Z

Hi @gws-hjyu,

This has been resolved in v1.2.1.

Thanks,
Sanjay

Changes in this update * **Enhancements**.. * Added comments to `AlexaClientSDKConfig.json`. These descriptions provide additional guidance for what is expected for each field... * Enabled pause and resume controls for Pandora... * **Bug Fixes**.. * Bug fix for [issue #329](alexa/avs-device-sdk#329) - `HTTP2Transport` instances no longer leak when `SERVER_SIDE * Bug fix for [issue #189](alexa/avs-device-sdk#189) - Fixed a race condition in the `Timer` class that sometimes * Bug fix for a race condition that caused `SpeechSynthesizer` to ignore subsequent `Speak` directives... * Bug fix for corrupted mime attachments.

sanjayrd closed this as completed Dec 12, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Memory leak: old transport not released upon server side disconnection #329

Memory leak: old transport not released upon server side disconnection #329

gws-hjyu commented Nov 12, 2017

scotthea-amazon commented Nov 13, 2017

sanjayrd commented Dec 12, 2017

Memory leak: old transport not released upon server side disconnection #329

Memory leak: old transport not released upon server side disconnection #329

Comments

gws-hjyu commented Nov 12, 2017

scotthea-amazon commented Nov 13, 2017

sanjayrd commented Dec 12, 2017