HTTPSConnectionPool read timed out - could not update sdm

Problem description

Log files: lib.log:

2016-10-11 15:49:54 96600 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 59 - INFO - 10.100.199.152: Upgrading SDM
2016-10-11 15:50:16 01300 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 60 - WARNING - Attempt 3 to update SDM failed, trying again
2016-10-11 15:50:46 16300 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 61 - WARNING - Attempt 4 to update SDM failed, trying again
2016-10-11 15:51:16 28900 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 62 - WARNING - Attempt 5 to update SDM failed, trying again
2016-10-11 15:51:46 35100 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 63 - WARNING - Attempt 6 to update SDM failed, trying again
2016-10-11 15:52:16 51100 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 64 - WARNING - Attempt 7 to update SDM failed, trying again
2016-10-11 15:52:46 64000 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 65 - WARNING - Attempt 8 to update SDM failed, trying again
2016-10-11 15:53:16 71200 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 66 - WARNING - Attempt 9 to update SDM failed, trying again
2016-10-11 15:53:46 86500 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 67 - WARNING - Attempt 10 to update SDM failed, trying again
2016-10-11 15:54:16 95300 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 68 - WARNING - Attempt 11 to update SDM failed, trying again
2016-10-11 15:54:47 10000 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 69 - WARNING - Attempt 12 to update SDM failed, trying again
2016-10-11 15:54:47 10000 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 70 - ERROR - 10.100.199.152: Error during update: HTTPSConnectionPool(host='10.100.199.152', port=8500): Read timed out. (read timeout=20)
2016-10-11 15:54:57 13200 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 71 - ERROR - 10.100.199.152: Failed to perform SDM update. Please check /var/log/upstart/alba-asdmanager.log on the appropriate node
2016-10-11 15:54:57 13300 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 72 - ERROR - 10.100.199.152 : Post upgrade action failed with error: Status after upgrade is "running"
2016-10-11 15:54:57 15400 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 73 - INFO - 10.100.199.153 : Executing action: restart_arakoon_clusters
2016-10-11 15:54:57 20200 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 74 - INFO - 10.100.199.153 : Executing action: upgrade_alba_plugin
2016-10-11 15:54:57 20500 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 76 - INFO - 10.100.199.153 : Executing action: upgrade_sdm
2016-10-11 15:56:57 95300 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 77 - ERROR - 10.100.199.153 : Post upgrade action failed with error: HTTPSConnectionPool(host='10.100.199.152', port=8500): Read timed out. (read timeout=120)
2016-10-11 15:56:57 97500 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 78 - INFO - 10.100.199.151 : Executing action: restart_arakoon_clusters
2016-10-11 15:56:58 25600 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 79 - INFO - Restarting cluster mybackend-abm
2016-10-11 15:57:02 32500 +0200 - ovs-node3 - 13871/140394728724288 - lib/alba - 87 - INFO - Restarting cluster mybackend-nsm_0
2016-10-11 15:57:06 34300 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 95 - INFO - 10.100.199.151 : Executing action: upgrade_alba_plugin
2016-10-11 15:57:07 45100 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 97 - INFO - 10.100.199.151 : Executing action: upgrade_sdm
2016-10-11 15:59:08 52000 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 98 - ERROR - 10.100.199.151 : Post upgrade action failed with error: HTTPSConnectionPool(host='10.100.199.152', port=8500): Read timed out. (read timeout=120)
2016-10-11 15:59:08 52000 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 99 - INFO - 10.100.199.153 : Starting services
2016-10-11 15:59:09 25100 +0200 - ovs-node3 - 13871/140394728724288 - lib/update - 103 - INFO - +++ Finished updating +++

asd-manager:

2016-10-11 15:49:55 42500 +0200 - ovs-node2 - 1580/140090656868096 - asd-manager/update - 7807 - INFO - Updating package openvstorage-sdm
2016-10-11 15:49:55 44200 +0200 - ovs-node2 - 1580/140090656868096 - asd-manager/werkzeug - 7808 - INFO - 10.100.199.153 - - [11/Oct/2016 15:49:55] "POST /update/execute/started HTTP/1.1" 200 -
2016-10-11 15:49:55 89400 +0200 - ovs-node2 - 1580/140090656868096 - asd-manager/update - 7809 - INFO - Installed version for package openvstorage-sdm: 1.6.3-rev.372.0cfe8a2-1
2016-10-11 15:49:55 89500 +0200 - ovs-node2 - 1580/140090656868096 - asd-manager/update - 7810 - INFO - Candidate version for package openvstorage-sdm: 1.6.4-rev.380.cfbfc0a-1
2016-10-11 15:49:55 89600 +0200 - ovs-node2 - 1580/140090656868096 - asd-manager/werkzeug - 7811 - INFO - 10.100.199.153 - - [11/Oct/2016 15:49:55] "POST /update/execute/running HTTP/1.1" 200 -
2016-10-11 16:00:00 14100 +0200 - ovs-node2 - 1580/140088260417280 - asd-manager/api - 7812 - INFO - Listing maintenance services
2016-10-11 16:00:00 14200 +0200 - ovs-node2 - 1580/140088260417280 - asd-manager/werkzeug - 7813 - INFO - 10.100.199.151 - - [11/Oct/2016 16:00:00] "GET /maintenance HTTP/1.1" 200

upgrade-openvstorage-sdm.log:

2016-10-11 15:49:55 55800 +0200 - ovs-node2 - 14849/139906340247360 - asd-manager/upgrade-package - 0 - INFO - Upgrading package openvstorage-sdm
2016-10-11 15:49:55 89500 +0200 - ovs-node2 - 14849/139906340247360 - asd-manager/upgrade-package - 1 - INFO - Lock in place, starting upgrade
debconf: unable to initialize frontend: Dialog
debconf: (TERM is not set, so the dialog frontend is not usable.)
debconf: falling back to frontend: Readline
debconf: unable to initialize frontend: Readline
debconf: (This frontend requires a controlling tty.)
debconf: falling back to frontend: Teletype
dpkg-preconfigure: unable to re-open stdin:

Possible root of the problem

Lock file? /var/lock/asd-manager_flock_package_update

Temporary solution

rm /var/lock/asd-manager_flock_package_update on the node that is updating

Setup

Hyperconverged setup

Three nodes with each three disks for the back-end
Package information
openvstorage 2.7.3-rev.4059.6d404af-1 amd64 openvStorage
openvstorage-backend 1.7.3-rev.721.b4724e5-1 amd64 openvStorage Backend plugin
openvstorage-backend-core 1.7.3-rev.721.b4724e5-1 amd64 openvStorage Backend plugin core
openvstorage-backend-webapps 1.7.3-rev.721.b4724e5-1 amd64 openvStorage Backend plugin Web Applications
openvstorage-cinder-plugin 1.2.2-rev.38.dcc3b76-1 amd64 OpenvStorage Cinder plugin for OpenStack
openvstorage-core 2.7.3-rev.4059.6d404af-1 amd64 openvStorage core
openvstorage-hc 1.7.3-rev.721.b4724e5-1 amd64 openvStorage Backend plugin HyperConverged
openvstorage-sdm 1.6.3-rev.372.0cfe8a2-1 amd64 Open vStorage Backend ASD Manager
openvstorage-webapps 2.7.3-rev.4059.6d404af-1 amd64 openvStorage Web Applications

Steps

Reverted back to the snapshot where it happened
Updated ovs framework
Updated SDM

Output

2016-10-11 17:29:56 39900 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 16 - INFO - Packages which will be installed --> volumedriver-no-dedup-base, volumedriver-no-dedup-server
2016-10-11 17:29:56 98500 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 17 - INFO - 10.100.199.152 : Installing volumedriver-no-dedup-base
2016-10-11 17:29:59 81600 +0200 - ovs-node3 - 4843/140707867387712 - lib/packager - 19 - ERROR - Install failed, trying again: Reading package lists...
2016-10-11 17:30:02 96900 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 20 - INFO - 10.100.199.152 : Installed volumedriver-no-dedup-base
2016-10-11 17:30:02 97000 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 21 - INFO - 10.100.199.152 : Installing volumedriver-no-dedup-server
2016-10-11 17:30:05 45900 +0200 - ovs-node3 - 4843/140707867387712 - lib/packager - 23 - ERROR - Install failed, trying again: Reading package lists...
2016-10-11 17:30:13 87900 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 24 - INFO - 10.100.199.152 : Installed volumedriver-no-dedup-server
2016-10-11 17:30:14 58900 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 25 - INFO - 10.100.199.153 : Installing volumedriver-no-dedup-base
2016-10-11 17:30:19 03500 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 26 - INFO - 10.100.199.153 : Installed volumedriver-no-dedup-base
2016-10-11 17:30:19 03500 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 27 - INFO - 10.100.199.153 : Installing volumedriver-no-dedup-server
2016-10-11 17:30:26 21300 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 28 - INFO - 10.100.199.153 : Installed volumedriver-no-dedup-server
2016-10-11 17:30:26 80700 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 29 - INFO - 10.100.199.151 : Installing volumedriver-no-dedup-base
2016-10-11 17:30:29 46100 +0200 - ovs-node3 - 4843/140707867387712 - lib/packager - 31 - ERROR - Install failed, trying again: Reading package lists...
2016-10-11 17:30:32 98800 +0200 - ovs-node3 - 4843/140707867387712 - lib/packager - 33 - ERROR - Install failed, trying again: Reading package lists...
2016-10-11 17:30:34 25600 +0200 - ovs-node3 - 4843/140707867387712 - lib/packager - 35 - ERROR - Install failed, trying again: Reading package lists...
2016-10-11 17:30:37 85500 +0200 - ovs-node3 - 4843/140707867387712 - lib/packager - 37 - ERROR - Install failed, trying again: Reading package lists...
2016-10-11 17:30:41 29900 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 38 - INFO - 10.100.199.151 : Installed volumedriver-no-dedup-base
2016-10-11 17:30:41 30000 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 39 - INFO - 10.100.199.151 : Installing volumedriver-no-dedup-server
2016-10-11 17:30:49 58000 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 40 - INFO - 10.100.199.151 : Installed volumedriver-no-dedup-server
2016-10-11 17:30:49 68900 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 41 - INFO - 10.100.199.153 : Executing post upgrade actions
2016-10-11 17:30:49 71000 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 42 - INFO - 10.100.199.152 : Executing action: restart_arakoon_clusters
2016-10-11 17:30:49 75200 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 43 - INFO - 10.100.199.152 : Executing action: upgrade_alba_plugin
2016-10-11 17:30:49 75600 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 44 - INFO - 10.100.199.152 : Executing action: upgrade_sdm
2016-10-11 17:30:50 79100 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 45 - INFO - 10.100.199.153 : Executing action: restart_arakoon_clusters
2016-10-11 17:30:50 83100 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 46 - INFO - 10.100.199.153 : Executing action: upgrade_alba_plugin
2016-10-11 17:30:50 83500 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 47 - INFO - 10.100.199.153 : Executing action: upgrade_sdm
2016-10-11 17:30:51 83800 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 48 - INFO - 10.100.199.151 : Executing action: restart_arakoon_clusters
2016-10-11 17:30:51 88000 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 49 - INFO - 10.100.199.151 : Executing action: upgrade_alba_plugin
2016-10-11 17:30:51 88400 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 50 - INFO - 10.100.199.151 : Executing action: upgrade_sdm
2016-10-11 17:30:52 87200 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 51 - INFO - 10.100.199.153 : Starting services
2016-10-11 17:30:53 26100 +0200 - ovs-node3 - 4843/140707867387712 - lib/update - 52 - INFO - +++ Finished updating +++
Waiting for data... (interrupt to abort)

No HTTPSConnectionPool error.

Test result

Test passed

openvstorage / alba-asdmanager

HTTPSConnectionPool read timed out - could not update sdm #126