search

hpe-storage / python-hpedockerplugin

HPE Native Docker Plugin
Apache License 2.0
36 stars 64 forks source link

Docker CI 3.3 lock call: test cases failing due to recently added lock call functionality. #744

Closed vishal-rane closed 4 years ago

vishal-rane commented 4 years ago

Please find the attached logs for few failed test case.

plugin_nightbuild_vishal_failed.log

vishal-rane commented 4 years ago

CI builds post 25th September's merge failing due to recently added lock call functionality. William has shared analysis to imaran and swapnil.

wdurairaj commented 4 years ago

My analysis:

I’m able to recreate this problem in my local box, which these commands of volume snapshot delete

root@csosbe03b10:~# docker run -it -v vol6_3par3:/data1 --rm busybox /bin/sh
/ # exit
root@csosbe03b10:~# docker volume create -d hpe --name snap_of_vol6_3par3 -o virtualCopyOf=vol6_3par3
snap_of_vol6_3par3
root@csosbe03b10:~# docker volume rm snap_of_vol6_3par3
Error response from daemon: unable to remove volume: remove snap_of_vol6_3par3: Post http://%2Frun%2Fdocker%2Fplugins%2Fhpe.sock/VolumeDriver.Remove: context deadline exceeded

Logs:

2019-10-07 12:17:38,770 [DEBUG] hpedockerplugin.backend_orchestrator [139966102092680] MainThread Removing entry for volume v1_snap_test1 from cache
2019-10-07 12:17:38,770 [INFO] hpedockerplugin.backend_orchestrator [139965935704808] PoolThread-twisted.internet.reactor-1  Operating on backend : DEFAULT on volume v1_snap_test1
2019-10-07 12:17:38,772 [INFO] hpedockerplugin.backend_orchestrator [139965935704808] PoolThread-twisted.internet.reactor-1  Request remove_volume
2019-10-07 12:17:38,772 [INFO] hpedockerplugin.backend_orchestrator [139965935704808] PoolThread-twisted.internet.reactor-1  with  args ()
2019-10-07 12:17:38,772 [INFO] hpedockerplugin.backend_orchestrator [139965935704808] PoolThread-twisted.internet.reactor-1  with  kwargs is {}
2019-10-07 12:17:38,773 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Initiating lock for /_locks/{volname} with uuid ef20b8f3426e46aaa0ce292d5cbd64f2
2019-10-07 12:17:38,773 [DEBUG] hpedockerplugin.etcdutil [139965935704808] PoolThread-twisted.internet.reactor-1 Try locking name {volname}
2019-10-07 12:17:38,774 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Issuing read for key /_locks/{volname} with args {'recursive': True}
2019-10-07 12:17:38,775 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Lock not found, writing it to /_locks/{volname}
2019-10-07 12:17:38,776 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Writing ef20b8f3426e46aaa0ce292d5cbd64f2 to key /_locks/{volname} ttl=300 dir=False append=True
2019-10-07 12:17:38,778 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Lock key /_locks/{volname}/00000000000000000119 written, sequence is 00000000000000000119
2019-10-07 12:17:38,778 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Issuing read for key /_locks/{volname} with args {'recursive': True}
2019-10-07 12:17:38,780 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Lock keys found: ['/_locks/{volname}/00000000000000000113', '/_locks/{volname}/00000000000000000114', '/_locks/{volname}/00000000000000000119']
2019-10-07 12:17:38,780 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Locker: /_locks/{volname}/00000000000000000113, key to watch: /_locks/{volname}/00000000000000000114
2019-10-07 12:17:38,780 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Lock not acquired, now watching /_locks/{volname}/00000000000000000114
2019-10-07 12:17:38,781 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 About to wait on key /_locks/{volname}/00000000000000000114, index 115
2019-10-07 12:17:38,781 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Issuing read for key /_locks/{volname}/00000000000000000114 with args {'wait': True, 'waitIndex': 115, 'timeout': 300, 'recursive': None}
2019-10-07 12:22:06,794 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Detected variation for /_locks/{volname}/00000000000000000113: expire
2019-10-07 12:22:06,794 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Issuing read for key /_locks/{volname} with args {'recursive': True}
2019-10-07 12:22:06,797 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Lock keys found: ['/_locks/{volname}/00000000000000000114', '/_locks/{volname}/00000000000000000119']
2019-10-07 12:22:06,797 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 No key before our one, we are the locker
2019-10-07 12:22:06,798 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Lock acquired!
2019-10-07 12:22:06,798 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Issuing read for key /_locks/{volname}/00000000000000000114 with args {}
2019-10-07 12:22:06,800 [DEBUG] hpedockerplugin.etcdutil [139965937027816] PoolThread-twisted.internet.reactor-0 Name is locked : {volname}
2019-10-07 12:22:06,801 [INFO] hpedockerplugin.synchronization [139965937027816] PoolThread-twisted.internet.reactor-0 Lock acquired: [caller=remove_snapshot, lock-name=v1_snap_test1]
2019-10-07 12:22:06,801 [INFO] hpedockerplugin.volume_manager [139965937027816] PoolThread-twisted.internet.reactor-0 volumedriver_remove_snapshot - getting volume v1_snap_test1
2019-10-07 12:22:06,802 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Issuing read for key /volumes/ with args {'recursive': True}
2019-10-07 12:22:06,804 [INFO] hpedockerplugin.etcdutil [139965937027816] PoolThread-twisted.internet.reactor-0 Get volbyname: volname is v1_snap_test1
2019-10-07 12:22:06,805 [INFO] hpedockerplugin.volume_manager [139965937027816] PoolThread-twisted.internet.reactor-0 Getting snapshot by name: snap_of_v1_snap_test1
2019-10-07 12:22:06,805 [ERROR] hpedockerplugin.volume_manager [139965937027816] PoolThread-twisted.internet.reactor-0 snapshot snap_of_v1_snap_test1 does not exist!
2019-10-07 12:22:06,805 [DEBUG] hpedockerplugin.etcdutil [139965937027816] PoolThread-twisted.internet.reactor-0 Try unlocking name {volname}
2019-10-07 12:22:06,805 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Releasing existing lock /_locks/{volname}/00000000000000000114
2019-10-07 12:22:06,806 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Deleting /_locks/{volname}/00000000000000000114 recursive=None dir=None extra args={}
2019-10-07 12:22:06,806 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Calculated params = {}
2019-10-07 12:22:06,807 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Lock not taken
2019-10-07 12:22:06,808 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Detected variation for /_locks/{volname}/00000000000000000114: delete
2019-10-07 12:22:06,808 [DEBUG] hpedockerplugin.etcdutil [139965937027816] PoolThread-twisted.internet.reactor-0 Name is unlocked : {volname}
2019-10-07 12:22:06,808 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Issuing read for key /_locks/{volname} with args {'recursive': True}
2019-10-07 12:22:06,809 [INFO] hpedockerplugin.synchronization [139965937027816] PoolThread-twisted.internet.reactor-0 Lock released: [caller=remove_snapshot, lock-name=v1_snap_test1]
2019-10-07 12:22:06,810 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Deleting /volumes/20fe7968-d263-4654-a226-4c4f8f988ca7 recursive=None dir=None extra args={}
2019-10-07 12:22:06,811 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Lock keys found: ['/_locks/{volname}/00000000000000000119']
2019-10-07 12:22:06,812 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Calculated params = {}
2019-10-07 12:22:06,812 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 No key before our one, we are the locker
2019-10-07 12:22:06,813 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Lock acquired!
2019-10-07 12:22:06,813 [DEBUG] hpedockerplugin.etcdutil [139965937027816] PoolThread-twisted.internet.reactor-0 Try unlocking name {volname}
2019-10-07 12:22:06,814 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Issuing read for key /_locks/{volname}/00000000000000000119 with args {}
2019-10-07 12:22:06,815 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Releasing existing lock /_locks/{volname}/00000000000000000113
2019-10-07 12:22:06,816 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Deleting /_locks/{volname}/00000000000000000113 recursive=None dir=None extra args={}
2019-10-07 12:22:06,817 [DEBUG] hpedockerplugin.etcdutil [139965935704808] PoolThread-twisted.internet.reactor-1 Name is locked : {volname}
2019-10-07 12:22:06,817 [DEBUG] etcd.client [139965937027816] PoolThread-twisted.internet.reactor-0 Calculated params = {}
2019-10-07 12:22:06,818 [INFO] hpedockerplugin.synchronization [139965935704808] PoolThread-twisted.internet.reactor-1 Lock acquired: [caller=remove_volume, lock-name=v1_snap_test1]
2019-10-07 12:22:06,819 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Issuing read for key /volumes/ with args {'recursive': True}
2019-10-07 12:22:06,819 [INFO] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Lock /_locks/{volname}/00000000000000000113 not found, nothing to release
2019-10-07 12:22:06,820 [DEBUG] etcd.lock [139965937027816] PoolThread-twisted.internet.reactor-0 Lock not taken
2019-10-07 12:22:06,821 [INFO] hpedockerplugin.etcdutil [139965935704808] PoolThread-twisted.internet.reactor-1 Get volbyname: volname is v1_snap_test1
2019-10-07 12:22:06,821 [DEBUG] hpedockerplugin.etcdutil [139965937027816] PoolThread-twisted.internet.reactor-0 Name is unlocked : {volname}
2019-10-07 12:22:06,824 [INFO] hpedockerplugin.synchronization [139965937027816] PoolThread-twisted.internet.reactor-0 Lock released: [caller=remove_volume, lock-name=snap_of_v1_snap_test1]
2019-10-07 12:22:06,899 [DEBUG] hpedockerplugin.hpe.hpe_3par_common [139965935704808] PoolThread-twisted.internet.reactor-1 Connecting to 3PAR
2019-10-07 12:22:06,949 [INFO] hpedockerplugin.hpe.hpe_3par_common [139965935704808] PoolThread-twisted.internet.reactor-1 DELETE_VOLUME:{'id': '0e7e57a4-ff4c-400d-8745-4c57f328ec1a', 'name': '0e7e57a4-ff4c-400d-8745-4c57f328ec1a', '3par_vol_name': 'dcv-Dn5XpP9MQA2HRUxX8yjsGg', 'host': '', 'size': 1, 'availability_zone': '', 'status': '', 'attach_status': '', 'display_name': 'v1_snap_test1', 'volume_id': '', 'volume_type': None, 'volume_attachment': None, 'provider_location': None, 'path_info': None, 'provisioning': 'thin', 'flash_cache': None, 'qos_name': None, 'compression': None, 'snapshots': [], 'mount_conflict_delay': 30, 'is_snap': False, 'backend': 'DEFAULT', 'snap_metadata': None, 'cpg': 'Docker_CI', 'snap_cpg': 'Docker_CI', 'has_schedule': False, 'rcg_info': None, 'fsOwner': None, 'fsMode': None}
2019-10-07 12:22:07,049 [DEBUG] hpedockerplugin.hpe.hpe_3par_common [139965935704808] PoolThread-twisted.internet.reactor-1 Disconnect from 3PAR REST and SSH f2a4281d-6cc1-4c28-8186-ea7e07a80c0d
2019-10-07 12:22:07,088 [INFO] hpedockerplugin.volume_manager [139965935704808] PoolThread-twisted.internet.reactor-1 volume: v1_snap_test1,was successfully deleted
2019-10-07 12:22:07,088 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Deleting /volumes/0e7e57a4-ff4c-400d-8745-4c57f328ec1a recursive=None dir=None extra args={}
2019-10-07 12:22:07,089 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Calculated params = {}
2019-10-07 12:22:07,091 [INFO] hpedockerplugin.etcdutil [139965935704808] PoolThread-twisted.internet.reactor-1 Deleted key: /volumes/0e7e57a4-ff4c-400d-8745-4c57f328ec1a from etcd
2019-10-07 12:22:07,092 [DEBUG] hpedockerplugin.etcdutil [139965935704808] PoolThread-twisted.internet.reactor-1 Try unlocking name {volname}
2019-10-07 12:22:07,092 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Releasing existing lock /_locks/{volname}/00000000000000000119
2019-10-07 12:22:07,093 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Deleting /_locks/{volname}/00000000000000000119 recursive=None dir=None extra args={}
2019-10-07 12:22:07,093 [DEBUG] etcd.client [139965935704808] PoolThread-twisted.internet.reactor-1 Calculated params = {}
2019-10-07 12:22:07,095 [DEBUG] etcd.lock [139965935704808] PoolThread-twisted.internet.reactor-1 Lock not taken
2019-10-07 12:22:07,096 [DEBUG] hpedockerplugin.etcdutil [139965935704808] PoolThread-twisted.internet.reactor-1 Name is unlocked : {volname}
2019-10-07 12:22:07,096 [INFO] hpedockerplugin.synchronization [139965935704808] PoolThread-twisted.internet.reactor-1 Lock released: [caller=remove_volume, lock-name=v1_snap_test1]
vishal-rane commented 4 years ago

Issue is not seen anymore on latest CI run: http://16.184.15.6:8080/job/docker-3par-iscsi-plugin-ubuntu/779/consoleFull Hence marking the issue as verified/closed