Description of problem:
++++++++++++++++++++++++
We had an OCP 3.10 + OCS 3.10 setup with gluster-bits=3.12.2-15. Gluser-block version = gluster-block-0.2.1-24.el7rhgs.x86_64. The setup has logging pods configured and the metrics pods couldn't come up.

# oc get pod -o wide|grep gluster
glusterblock-storage-provisioner-dc-1-l567j   1/1       Running             1          3d        10.128.4.11    dhcp47-86.lab.eng.blr.redhat.com
glusterfs-storage-9j9nk                       1/1       Running             1          3d        10.70.46.150   dhcp46-150.lab.eng.blr.redhat.com
glusterfs-storage-hr8ht                       1/1       Running             1          3d        10.70.46.219   dhcp46-219.lab.eng.blr.redhat.com
glusterfs-storage-q22cl                       1/1       Running             1          3d        10.70.46.231   dhcp46-231.lab.eng.blr.redhat.com

Steps Performed
==================

1. We updated the docker and gluster client packages on each oc node which resulted in the gluster pod restarts as well.

2. Created 1 block device of 1 GB , hence free size on  vol_9f93ae4c845f3910f5d1558cc5ae9f0a 97 GB (2 GB reserved)

3. Created around 50 block pvcs in two loops and then attached them to app pods 

For 50 pvcs of 2 gb each, a total of 2 block hosting vols were created:

1. First block-host = vol_9f93ae4c845f3910f5d1558cc5ae9f0a
2. 2nd block-hosting = vol_1fda560284e932cae1e384fe779b430f

Details :
=============

A) Created 1 block device of 1 GB , space was allocated from vol_9f93ae4c845f3910f5d1558cc5ae9f0a. 2GB was reserved by heketi at start.

B) For pvc bk101 -bk148, space was allocated from vol_9f93ae4c845f3910f5d1558cc5ae9f0a. Each block-volume creation succeeded(as seen from heketi-logs).  = Total size = 96GB

Hence, free size on vol_9f93ae4c845f3910f5d1558cc5ae9f0a = 100 - 96(GB) -1 (GB) -2GB(rserved)=  1 GB

C) For block request bk 149, it is seen from heketi logs(2018/08/20 10:00:56 ) , initially , heketi sent the create request on vol_9f93ae4c845f3910f5d1558cc5ae9f0a. 
Issue: As free size was 1 GB, heketi should not have picked up old block-hosting volume for a create request of 2G

D) As per heketi logs, request for #C failed , and a new block-hosting vol (vol_1fda560284e932cae1e384fe779b430f) was created to for pvc bk149. But gluster backend reported a different scene.


Overall issue:
===============

1. Even though heketi finally lists a block device with name bk149 on the new vol_1fda560284e932cae1e384fe779b430f, it had tried to create bk149 on old vol as well, even though free size < requested size

2. On gluster backend, for a single pvc request of bk149, we see 2 volumes getting created, one on the vol_9f93ae4c845f3910f5d1558cc5ae9f0a and one on  vol_1fda560284e932cae1e384fe779b430f. This is not expected.

--------------------------------------------------------
sh-4.2# gluster-block list vol_9f93ae4c845f3910f5d1558cc5ae9f0a |grep 149
bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b

sh-4.2# gluster-block list vol_1fda560284e932cae1e384fe779b430f|grep 149
bk_glusterfs_bk149_f765daa2-a45f-11e8-b773-0a580a81040b

--------------------------------------------------------

3. Thus for vol_9f93ae4c845f3910f5d1558cc5ae9f0a, if we calculate used size based on gluster-backend usage ,  used size = 96 + 1 + 2 = 99GB, even though 2GB was reserved by heketi.

4. Number of block volumes as per heketi = 51
   Numbe of block volumes as per gluster = 52


GLuster backend
==================
 
[root@dhcp46-137 pod-error]# oc rsh glusterfs-storage-hr8ht 
sh-4.2# gluster v list
heketidbstorage
vol_1fda560284e932cae1e384fe779b430f
vol_9f93ae4c845f3910f5d1558cc5ae9f0a

sh-4.2# gluster-block list vol_1fda560284e932cae1e384fe779b430f  |wc -l
2
sh-4.2# gluster-block list vol_9f93ae4c845f3910f5d1558cc5ae9f0a  |wc -l
50

Heketi
==================

[root@dhcp46-137 pod-error]# heketi-cli blockvolume list|wc -l
51

pvcs
==================

[root@dhcp46-137 pod-error]# oc get pvc |grep -v NAME|wc -l
50    <------------ not including heketidb vol
   


Some snippet from heketi logs
==============================

[root@dhcp46-137 pod-error]# cat heketi_logs |grep bk149
[kubeexec] ERROR 2018/08/20 10:00:56 /src/github.com/heketi/heketi/executors/kubeexec/kubeexec.go:242: Failed to run command [gluster-block create vol_9f93ae4c845f3910f5d1558cc5ae9f0a/bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b  ha 3 auth enable prealloc full 10.70.46.231,10.70.46.150,10.70.46.219 2GiB --json] on glusterfs-storage-9j9nk: Err[command terminated with exit code 255]: Stdout [{ "IQN": "iqn.2016-12.org.gluster-block:7d351894-126a-4147-9fb1-d30cb90aab32", "USERNAME": "7d351894-126a-4147-9fb1-d30cb90aab32", "PASSWORD": "4c8bc088-066c-4278-a1b5-072240b0435c", "PORTAL(S)": [ "10.70.46.231:3260", "10.70.46.150:3260", "10.70.46.219:3260" ], "ROLLBACK FAILED ON": [ "10.70.46.150", "10.70.46.219", "10.70.46.231" ], "RESULT": "FAIL" }

[kubeexec] ERROR 2018/08/20 10:01:01 /src/github.com/heketi/heketi/executors/kubeexec/kubeexec.go:242: Failed to run command [gluster-block delete vol_9f93ae4c845f3910f5d1558cc5ae9f0a/bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b --json] on glusterfs-storage-9j9nk: Err[command terminated with exit code 255]: Stdout [{ "RESULT": "FAIL" }
[cmdexec] ERROR 2018/08/20 10:01:01 /src/github.com/heketi/heketi/executors/cmdexec/block_volume.go:102: Unable to delete volume bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b: Unable to execute command on glusterfs-storage-9j9nk: 


[kubeexec] ERROR 2018/08/20 10:01:03 /src/github.com/heketi/heketi/executors/kubeexec/kubeexec.go:242: Failed to run command [gluster-block delete vol_9f93ae4c845f3910f5d1558cc5ae9f0a/bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b --json] on glusterfs-storage-9j9nk: Err[command terminated with exit code 255]: Stdout [{ "RESULT": "FAIL" }
[cmdexec] ERROR 2018/08/20 10:01:03 /src/github.com/heketi/heketi/executors/cmdexec/block_volume.go:102: Unable to delete volume bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b: Unable to execute command on glusterfs-storage-9j9nk: 

[kubeexec] DEBUG 2018/08/20 10:01:15 /src/github.com/heketi/heketi/executors/kubeexec/kubeexec.go:246: Host: dhcp46-150.lab.eng.blr.redhat.com Pod: glusterfs-storage-9j9nk Command: gluster-block create vol_1fda560284e932cae1e384fe779b430f/bk_glusterfs_bk149_f765daa2-a45f-11e8-b773-0a580a81040b  ha 3 auth enable prealloc full 10.70.46.219,10.70.46.231,10.70.46.150 2GiB --json
Result: { "IQN": "iqn.2016-12.org.gluster-block:b7833764-db9d-40de-b8d4-1180e7808cda", "USERNAME": "b7833764-db9d-40de-b8d4-1180e7808cda", "PASSWORD": "0f3be6fd-de50-4d15-ab75-f944bf2dfc40", "PORTAL(S)": [ "10.70.46.219:3260", "10.70.46.231:3260", "10.70.46.150:3260" ], "RESULT": "SUCCESS" }
[heketi] INFO 2018/08/20 10:01:15 Create Block Volume succeeded
[asynchttp] INFO 2018/08/20 10:01:15 asynchttp.go:292: Completed job 12ec4911229287361890692f620ca4f3 in 3.987686056s




sh-4.2# cat /var/log/glusterfs/gluster-block/gluster-blockd.log |grep bk149
[2018-08-20 10:00:48.893089] INFO: create cli request, volume=vol_9f93ae4c845f3910f5d1558cc5ae9f0a blockname=bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b mpath=3 blockhosts=10.70.46.231,10.70.46.150,10.70.46.219 authmode=1 size=2147483648, rbsize=0 [at block_svc_routines.c+3778 :<block_create_cli_1_svc_st>]
[2018-08-20 10:00:50.314260] INFO: create request, volume=vol_9f93ae4c845f3910f5d1558cc5ae9f0a blockname=bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b blockhosts=10.70.46.231,10.70.46.150,10.70.46.219 filename=7d351894-126a-4147-9fb1-d30cb90aab32 authmode=1 passwd=4c8bc088-066c-4278-a1b5-072240b0435c size=2147483648 [at block_svc_routines.c+4191 :<block_create_common>]
[2018-08-20 10:00:53.870585] ERROR: glfs_write(bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b): on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a failed[No space left on device] [at block_svc_routines.c+934 :<glusterBlockCreateRemote>]
[2018-08-20 10:00:53.916116] ERROR: glfs_write(bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b): on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a failed[No space left on device] [at block_svc_routines.c+934 :<glusterBlockCreateRemote>]
[2018-08-20 10:00:53.947845] ERROR: glfs_write(bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b): on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a failed[No space left on device] [at block_svc_routines.c+934 :<glusterBlockCreateRemote>]
[2018-08-20 10:00:53.948256] WARNING: glusterBlockCreateRemoteAsync: return -1 failed in remote async create for block bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a with hosts 10.70.46.231,10.70.46.150,10.70.46.219 [at block_svc_routines.c+3901 :<block_create_cli_1_svc_st>]
[2018-08-20 10:00:54.151426] WARNING: No Spare nodes to create (bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b): rollingback creation of target on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a with given hosts 10.70.46.231,10.70.46.150,10.70.46.219 [at block_svc_routines.c+2978 :<glusterBlockAuditRequest>]
[2018-08-20 10:00:56.144468] ERROR: glfs_write(bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b): on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a failed[No space left on device] [at block_svc_routines.c+2891 :<glusterBlockCleanUp>]
[2018-08-20 10:00:56.145214] ERROR: glusterBlockAuditRequest: return -1volume: vol_9f93ae4c845f3910f5d1558cc5ae9f0a hosts: 10.70.46.231,10.70.46.150,10.70.46.219 blockname bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b [at block_svc_routines.c+3909 :<block_create_cli_1_svc_st>]
[2018-08-20 10:00:58.282445] INFO: delete cli request, volume=vol_9f93ae4c845f3910f5d1558cc5ae9f0a blockname=bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b [at block_svc_routines.c+4493 :<block_delete_cli_1_svc_st>]
[2018-08-20 10:01:01.252879] ERROR: glfs_write(bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b): on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a failed[No space left on device] [at block_svc_routines.c+2891 :<glusterBlockCleanUp>]
[2018-08-20 10:01:01.253126] WARNING: glusterBlockCleanUp: return -1 on block bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b for volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a [at block_svc_routines.c+4566 :<block_delete_cli_1_svc_st>]
[2018-08-20 10:01:01.793451] INFO: delete cli request, volume=vol_9f93ae4c845f3910f5d1558cc5ae9f0a blockname=bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b [at block_svc_routines.c+4493 :<block_delete_cli_1_svc_st>]
[2018-08-20 10:01:03.416957] ERROR: glfs_write(bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b): on volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a failed[No space left on device] [at block_svc_routines.c+2891 :<glusterBlockCleanUp>]
[2018-08-20 10:01:03.417464] WARNING: glusterBlockCleanUp: return -1 on block bk_glusterfs_bk149_e4f79e2b-a45f-11e8-b773-0a580a81040b for volume vol_9f93ae4c845f3910f5d1558cc5ae9f0a [at block_svc_routines.c+4566 :<block_delete_cli_1_svc_st>]
[2018-08-20 10:01:12.362894] INFO: create cli request, volume=vol_1fda560284e932cae1e384fe779b430f blockname=bk_glusterfs_bk149_f765daa2-a45f-11e8-b773-0a580a81040b mpath=3 blockhosts=10.70.46.219,10.70.46.231,10.70.46.150 authmode=1 size=2147483648, rbsize=0 [at block_svc_routines.c+3778 :<block_create_cli_1_svc_st>]
[2018-08-20 10:01:12.551537] INFO: create request, volume=vol_1fda560284e932cae1e384fe779b430f blockname=bk_glusterfs_bk149_f765daa2-a45f-11e8-b773-0a580a81040b blockhosts=10.70.46.219,10.70.46.231,10.70.46.150 filename=b7833764-db9d-40de-b8d4-1180e7808cda authmode=1 passwd=0f3be6fd-de50-4d15-ab75-f944bf2dfc40 size=2147483648 [at block_svc_routines.c+4191 :<block_create_common>]
[2018-08-20 10:01:15.347930] INFO: Block create request satisfied for target: bk_glusterfs_bk149_f765daa2-a45f-11e8-b773-0a580a81040b on volume vol_1fda560284e932cae1e384fe779b430f with given hosts 10.70.46.219,10.70.46.231,10.70.46.150 [at block_svc_routines.c+2967 :<glusterBlockAuditRequest>]
sh-4.2# 




Version-Release number of selected component (if applicable):
++++++++++++++++++++++++

[root@dhcp46-137 ~]# oc version
oc v3.10.14
kubernetes v1.10.0+b81c8f8
features: Basic-Auth GSSAPI Kerberos SPNEGO

Server https://dhcp46-137.lab.eng.blr.redhat.com:8443
openshift v3.10.14
kubernetes v1.10.0+b81c8f8
[root@dhcp46-137 ~]# 


Gluster 3.4.0
==============

[root@dhcp46-137 ~]# oc rsh glusterfs-storage-q22cl rpm -qa|grep gluster
glusterfs-client-xlators-3.12.2-15.el7rhgs.x86_64
glusterfs-cli-3.12.2-15.el7rhgs.x86_64
python2-gluster-3.12.2-15.el7rhgs.x86_64
glusterfs-geo-replication-3.12.2-15.el7rhgs.x86_64
glusterfs-libs-3.12.2-15.el7rhgs.x86_64
glusterfs-3.12.2-15.el7rhgs.x86_64
glusterfs-api-3.12.2-15.el7rhgs.x86_64
glusterfs-fuse-3.12.2-15.el7rhgs.x86_64
glusterfs-server-3.12.2-15.el7rhgs.x86_64
gluster-block-0.2.1-24.el7rhgs.x86_64
[root@dhcp46-137 ~]# 


[root@dhcp46-137 ~]# oc rsh heketi-storage-1-px7jd rpm -qa|grep heketi
python-heketi-7.0.0-6.el7rhgs.x86_64
heketi-7.0.0-6.el7rhgs.x86_64
heketi-client-7.0.0-6.el7rhgs.x86_64
[root@dhcp46-137 ~]# 


gluster client version
=========================
[root@dhcp46-65 ~]# rpm -qa|grep gluster
glusterfs-libs-3.12.2-15.el7.x86_64
glusterfs-3.12.2-15.el7.x86_64
glusterfs-fuse-3.12.2-15.el7.x86_64
glusterfs-client-xlators-3.12.2-15.el7.x86_64
[root@dhcp46-65 ~]# 




How reproducible:
++++++++++++++++++++++++
Tried once.

Steps to Reproduce:
++++++++++++++++++++++++
1. Create an OCP +OCS 3.10 setup with logging & metrics, registry configured,
2. Upgrade the docker version to 1.13.1.74 and also update the gluster client packages. The pods will be restarted as docker is upgraded.
3. Create one block device of 1GB using heketi-cli. This will automatically create a block hosting volume. Default block-hosting vol size=100Gb
4. Once setup is up, create 50 block pvcs of 2 GB each . Heketi should only create 48*(2 GB) vols as the free space will then become 1 GB. Reserved size=2 GB(as per heketi).
5. 49th and 50th vol should only get created on a new block hosting volume.
6. Check the volume count and confirm that proper implementation of Resevred and free size is performed by heketi. 


Actual results:
++++++++++++++++++++++++

It seems the reserved size is not being honored in some corner cases and also for a single pvc request, 2 block devices are created, on 2 different block hosting volumes.

Expected results:
++++++++++++++++++++++++
With reserved size = 2 GB, and free size = 97 GB before starting pvc creation in loop, only 48 new block devices(if size=2Gb) should get created on the old block hosting vol. Beyond that, a new block hosting volume should be used for further pvc requests.