1:11 p.m.
After this
(https://devconfcz2020a.sched.com/event/YOtG/ovirt-4k-teaching-an-old-dog-...)
I sure do not expect this (log below):
Actually I am trying to evaluate just how portable oVirt storage is and this case I had
prepared a USB3 HDD with VDO, which I could literally move between farms to transport
VMs.
Logical disks are typically large for simplicity within the VMs, QCOW2 and VDO assumed to
compensate for this 'lack of planning' while the allocated storage easily fits the
HDD.
Once I got beyond the initial issues, I came across this somewhat unexpected issue: VDO
storage uses 4k blocks all around, but evidently when you mount an export domain (or I
guess any domain) as POSIX, 512byte blocks are assumed somewhere and 4k blocks rejected.
I'd say that is a bug in VDSM, right?
Or is there anything in the mount options to fix this?
020-08-31 18:44:40,424+0200 INFO (periodic/0) [vdsm.api] START repoStats(domains=())
from=internal, task_id=7a293dec-85b3-4b82-92b7-4e7d03b40343 (api:48)
2020-08-31 18:44:40,425+0200 INFO (periodic/0) [vdsm.api] FINISH repoStats
return={'9992dc21-edf2-4951-9020-7c78f1220e02': {'code': 0,
'lastCheck': '1.6', 'delay': '0.00283651',
'valid': True, 'version': 5, 'acquired': True, 'actual':
True}, '25d95783-44df-4fda-b642-55fe09162149': {'code': 0,
'lastCheck': '2.2', 'delay': '0.00256944',
'valid': True, 'version': 5, 'acquired': True, 'actual':
True}, '148d9e9e-d7b8-4220-9ee8-057da96e608c': {'code': 0,
'lastCheck': '2.2', 'delay': '0.00050217',
'valid': True, 'version': 5, 'acquired': True, 'actual':
True}} from=internal, task_id=7a293dec-85b3-4b82-92b7-4e7d03b40343 (api:54)
2020-08-31 18:44:41,121+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.ping2
succeeded in 0.00 seconds (__init__:312)
2020-08-31 18:44:41,412+0200 INFO (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.ping2
succeeded in 0.00 seconds (__init__:312)
2020-08-31 18:44:41,414+0200 INFO (jsonrpc/2) [vdsm.api] START
repoStats(domains=['9992dc21-edf2-4951-9020-7c78f1220e02']) from=::1,44782,
task_id=657c820e-e2eb-4b1d-b2fb-1772b3af6f32 (api:48)
2020-08-31 18:44:41,414+0200 INFO (jsonrpc/2) [vdsm.api] FINISH repoStats
return={'9992dc21-edf2-4951-9020-7c78f1220e02': {'code': 0,
'lastCheck': '2.6', 'delay': '0.00283651',
'valid': True, 'version': 5, 'acquired': True, 'actual':
True}} from=::1,44782, task_id=657c820e-e2eb-4b1d-b2fb-1772b3af6f32 (api:54)
2020-08-31 18:44:41,414+0200 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call
Host.getStorageRepoStats succeeded in 0.00 seconds (__init__:312)
2020-08-31 18:44:41,965+0200 INFO (jsonrpc/3) [IOProcessClient] (Global) Starting client
(__init__:308)
2020-08-31 18:44:41,984+0200 INFO (ioprocess/87332) [IOProcess] (Global) Starting
ioprocess (__init__:434)
2020-08-31 18:44:42,006+0200 INFO (jsonrpc/3) [storage.StorageDomainCache] Removing
domain fe9fb0db-2743-457a-80f0-9a4edc509e9d from storage domain cache (sdc:211)
2020-08-31 18:44:42,006+0200 INFO (jsonrpc/3) [storage.StorageDomainCache] Invalidating
storage domain cache (sdc:74)
2020-08-31 18:44:42,006+0200 INFO (jsonrpc/3) [vdsm.api] FINISH connectStorageServer
return={'statuslist': [{'id':
'00000000-0000-0000-0000-000000000000', 'status': 0}]}
from=::ffff:192.168.0.87,40378, flow_id=05fe72ef-c8ac-4e03-8453-5171e5fc5f8b,
task_id=b92d4144-a9db-4423-ba6b-35934d4f9200 (api:54)
2020-08-31 18:44:42,008+0200 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call
StoragePool.connectStorageServer succeeded in 3.11 seconds (__init__:312)
2020-08-31 18:44:42,063+0200 INFO (jsonrpc/5) [vdsm.api] START
getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000',
domainClass=3, storageType='', remotePath='/dev/mapper/vdo1',
options=None) from=::ffff:192.168.0.87,40378,
flow_id=eff548f9-b663-45dd-b8a5-5854f9b5dde8, task_id=98ca66a5-edee-40d4-9253-6a46409241cc
(api:48)
2020-08-31 18:44:42,063+0200 INFO (jsonrpc/5) [storage.StorageDomainCache] Refreshing
storage domain cache (resize=True) (sdc:80)
2020-08-31 18:44:42,063+0200 INFO (jsonrpc/5) [storage.ISCSI] Scanning iSCSI devices
(iscsi:442)
2020-08-31 18:44:42,101+0200 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.ping2
succeeded in 0.00 seconds (__init__:312)
2020-08-31 18:44:42,128+0200 INFO (jsonrpc/5) [storage.ISCSI] Scanning iSCSI devices:
0.06 seconds (utils:390)
2020-08-31 18:44:42,129+0200 INFO (jsonrpc/5) [storage.HBA] Scanning FC devices (hba:60)
2020-08-31 18:44:42,182+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.ping2
succeeded in 0.00 seconds (__init__:312)
2020-08-31 18:44:42,184+0200 INFO (jsonrpc/4) [vdsm.api] START
repoStats(domains=['9992dc21-edf2-4951-9020-7c78f1220e02']) from=::1,44782,
task_id=7b3f1eb8-f7e3-4467-93a1-27ef9721c90c (api:48)
2020-08-31 18:44:42,184+0200 INFO (jsonrpc/4) [vdsm.api] FINISH repoStats
return={'9992dc21-edf2-4951-9020-7c78f1220e02': {'code': 0,
'lastCheck': '3.4', 'delay': '0.00283651',
'valid': True, 'version': 5, 'acquired': True, 'actual':
True}} from=::1,44782, task_id=7b3f1eb8-f7e3-4467-93a1-27ef9721c90c (api:54)
2020-08-31 18:44:42,184+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call
Host.getStorageRepoStats succeeded in 0.00 seconds (__init__:312)
2020-08-31 18:44:42,277+0200 INFO (jsonrpc/5) [storage.HBA] Scanning FC devices: 0.15
seconds (utils:390)
2020-08-31 18:44:42,309+0200 INFO (jsonrpc/5) [storage.Multipath] Resizing multipath
devices (multipath:104)
2020-08-31 18:44:42,312+0200 INFO (jsonrpc/5) [storage.Multipath] Resizing multipath
devices: 0.00 seconds (utils:390)
2020-08-31 18:44:42,312+0200 INFO (jsonrpc/5) [storage.StorageDomainCache] Refreshing
storage domain cache: 0.25 seconds (utils:390)
2020-08-31 18:44:42,418+0200 INFO (tmap-569/0) [IOProcessClient] (_dev_mapper_vdo1)
Starting client (__init__:308)
2020-08-31 18:44:42,445+0200 INFO (tmap-569/1) [IOProcessClient]
(glusterSD/nucvirt.mtk.hoberg.net:_data) Starting client (__init__:308)
2020-08-31 18:44:42,449+0200 INFO (ioprocess/87496) [IOProcess] (_dev_mapper_vdo1)
Starting ioprocess (__init__:434)
2020-08-31 18:44:42,457+0200 INFO (tmap-569/2) [IOProcessClient]
(glusterSD/nucvirt.mtk.hoberg.net:_vmstore) Starting client (__init__:308)
2020-08-31 18:44:42,465+0200 INFO (ioprocess/87508) [IOProcess]
(glusterSD/nucvirt.mtk.hoberg.net:_data) Starting ioprocess (__init__:434)
2020-08-31 18:44:42,478+0200 INFO (tmap-569/3) [IOProcessClient]
(glusterSD/nucvirt.mtk.hoberg.net:_engine) Starting client (__init__:308)
2020-08-31 18:44:42,486+0200 INFO (ioprocess/87516) [IOProcess]
(glusterSD/nucvirt.mtk.hoberg.net:_vmstore) Starting ioprocess (__init__:434)
2020-08-31 18:44:42,514+0200 INFO (ioprocess/87533) [IOProcess]
(glusterSD/nucvirt.mtk.hoberg.net:_engine) Starting ioprocess (__init__:434)
2020-08-31 18:44:42,522+0200 INFO (jsonrpc/5) [IOProcessClient]
(fe9fb0db-2743-457a-80f0-9a4edc509e9d) Starting client (__init__:308)
2020-08-31 18:44:42,553+0200 INFO (ioprocess/87552) [IOProcess]
(fe9fb0db-2743-457a-80f0-9a4edc509e9d) Starting ioprocess (__init__:434)
2020-08-31 18:44:42,582+0200 ERROR (jsonrpc/5) [storage.HSM] Unexpected error (hsm:2843)
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 2829, in
getStorageDomainsList
dom = sdCache.produce(sdUUID=sdUUID)
File "/usr/lib/python3.6/site-packages/vdsm/storage/sdc.py", line 115, in
produce
domain.getRealDomain()
File "/usr/lib/python3.6/site-packages/vdsm/storage/sdc.py", line 51, in
getRealDomain
return self._cache._realProduce(self._sdUUID)
File "/usr/lib/python3.6/site-packages/vdsm/storage/sdc.py", line 139, in
_realProduce
domain = self._findDomain(sdUUID)
File "/usr/lib/python3.6/site-packages/vdsm/storage/sdc.py", line 156, in
_findDomain
return findMethod(sdUUID)
File "/usr/lib/python3.6/site-packages/vdsm/storage/nfsSD.py", line 146, in
findDomain
return NfsStorageDomain(NfsStorageDomain.findDomainPath(sdUUID))
File "/usr/lib/python3.6/site-packages/vdsm/storage/fileSD.py", line 390, in
__init__
manifest.block_size, storage_block_size)
File "/usr/lib/python3.6/site-packages/vdsm/storage/sd.py", line 939, in
_validate_storage_block_size
raise se.StorageDomainBlockSizeMismatch(block_size, storage_block_size)
vdsm.storage.exception.StorageDomainBlockSizeMismatch: Block size does not match storage
block size: 'block_size=512, storage_block_size=4096'
2020-08-31 18:44:42,582+0200 INFO (jsonrpc/5) [vdsm.api] FINISH getStorageDomainsList
return={'domlist': []} from=::ffff:192.168.0.87,40378,
flow_id=eff548f9-b663-45dd-b8a5-5854f9b5dde8, task_id=98ca66a5-edee-40d4-9253-6a46409241cc
(api:54)
2020-08-31 18:44:42,582+0200 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call
Host.getStorageDomains succeeded in 0.52 seconds (__init__:312)
2020-08-31 18:44:42,801+0200 INFO (jsonrpc/7) [vdsm.api] START
disconnectStorageServer(domType=6, spUUID='00000000-0000-0000-0000-000000000000',
conList=[{'password': '********', 'vfs_type': 'xfs',
'port': '', 'mnt_options':
'rw,relatime,seclabel,attr2,inode64,noquota,_netdev,x-systemd.device-timeout=0',
'iqn': '', 'connection': '/dev/mapper/vdo1',
'ipv6_enabled': 'false', 'id':
'b4a73d6a-344c-446b-a33d-7b665e78578d', 'user': '',
'tpgt': '1'}], options=None) from=::ffff:192.168.0.87,40378,
flow_id=6678917a-b29c-416c-aa2d-5abc1d5351a3, task_id=3d0cf36e-427d-4000-8857-a8a2af641b10
(api:48)
2020-08-31 18:44:42,801+0200 INFO (jsonrpc/7) [storage.Mount] unmounting
/rhev/data-center/mnt/_dev_mapper_vdo1 (mount:215)
2020-08-31 18:44:42,806+0200 INFO (jsonrpc/0) [vdsm.api] START
disconnectStorageServer(domType=6, spUUID='00000000-0000-0000-0000-000000000000',
conList=[{'password': '********', 'vfs_type': 'xfs',
'port': '', 'mnt_options':
'rw,relatime,seclabel,attr2,inode64,noquota,_netdev,x-systemd.device-timeout=0',
'iqn': '', 'connection': '/dev/mapper/vdo1',
'ipv6_enabled': 'false', 'id':
'b4a73d6a-344c-446b-a33d-7b665e78578d', 'user': '',
'tpgt': '1'}], options=None) from=::ffff:192.168.0.87,40378,
flow_id=bb449405-5b78-4b65-a352-e2e94a269df9, task_id=09783e0a-933c-448d-b0ca-1b5d351eb042
(api:48)
2020-08-31 18:44:42,806+0200 INFO (jsonrpc/0) [storage.Mount] unmounting
/rhev/data-center/mnt/_dev_mapper_vdo1 (mount:215)
2020-08-31 18:44:42,821+0200 ERROR (jsonrpc/0) [storage.HSM] Could not disconnect from
storageServer (hsm:2528)
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 2524, in
disconnectStorageServer
conObj.disconnect()
File "/usr/lib/python3.6/site-packages/vdsm/storage/storageServer.py", line
201, in disconnect
self._mount.umount(True, True)
File "/usr/lib/python3.6/site-packages/vdsm/storage/mount.py", line 217, in
umount
umount(self.fs_file, force=force, lazy=lazy, freeloop=freeloop)
File "/usr/lib/python3.6/site-packages/vdsm/common/supervdsm.py", line 56, in
__call__
return callMethod()
File "/usr/lib/python3.6/site-packages/vdsm/common/supervdsm.py", line 54, in
<lambda>
**kwargs)
File "<string>", line 2, in umount
File "/usr/lib64/python3.6/multiprocessing/managers.py", line 772, in
_callmethod
raise convert_to_error(kind, result)
vdsm.storage.mount.MountError: Command ['/usr/bin/umount', '-f',
'-l', '/rhev/data-center/mnt/_dev_mapper_vdo1'] failed with rc=32
out=b'' err=b'umount: /rhev/data-center/mnt/_dev_mapper_vdo1: not
mounted.\n'
2020-08-31 18:44:42,821+0200 INFO (jsonrpc/0) [storage.StorageDomainCache] Refreshing
storage domain cache (resize=False) (sdc:80)