10:57 a.m.
Hi Simone,Nir,
Adding also Nir on this, the whole sequence is tracked here:
I'd suggest to check ovirt-imageio and vdsm logs on ovirt2.localdomain about the same
time.
I have tested again (first wiped current transfers) and it is happening the
same (phase 10).
engine=# \x
Expanded display is on.
engine=# select * from image_transfers;
-[ RECORD 1 ]-------------+-------------------------------------
command_id | 11b2c162-29e0-46ef-b0a4-f41ebe3c2910
command_type | 1024
phase | 10
last_updated | 2019-03-13 09:38:30.365+02
message |
vds_id |
disk_id | 94ade632-6ecc-4901-8cec-8e39f3d69cb0
imaged_ticket_id |
proxy_uri |
signed_ticket |
bytes_sent | 0
bytes_total | 134217728
type | 1
active | f
daemon_uri |
client_inactivity_timeout | 60
engine=# delete from image_transfers where
disk_id='94ade632-6ecc-4901-8cec-8e39f3d69cb0';
This is the VDSM log from the last test:
2019-03-13 09:38:23,229+0200 INFO (jsonrpc/4) [vdsm.api] START
prepareImage(sdUUID=u'808423f9-8a5c-40cd-bc9f-2568c85b8c74',
spUUID=u'b803f7e4-2543-11e9-ba9a-00163e6272c8',
imgUUID=u'94ade632-6ecc-4901-8cec-8e39f3d69cb0',
leafUUID=u'9460fc4b-54f3-48e3-b7b6-da962321ecf4', allowIllegal=True)
from=::ffff:192.168.1.2,42644, flow_id=d48d9272-2e65-438d-a7b2-46979309833b,
task_id=bb534320-451c-45c0-b7a6-0cce017ec7cb (api:48)
2019-03-13 09:38:23,253+0200 INFO (jsonrpc/4) [storage.StorageDomain] Fixing permissions
on
/rhev/data-center/mnt/glusterSD/ovirt1.localdomain:_engine/808423f9-8a5c-40cd-bc9f-2568c85b8c74/images/94ade632-6ecc-4901-8cec-8e39f3d69cb0/9460fc4b-54f3-48e3-b7b6-da962321ecf4
(fileSD:623)
2019-03-13 09:38:23,254+0200 INFO (jsonrpc/4) [storage.StorageDomain] Creating domain run
directory u'/var/run/vdsm/storage/808423f9-8a5c-40cd-bc9f-2568c85b8c74'
(fileSD:577)
2019-03-13 09:38:23,254+0200 INFO (jsonrpc/4) [storage.fileUtils] Creating directory:
/var/run/vdsm/storage/808423f9-8a5c-40cd-bc9f-2568c85b8c74 mode: None (fileUtils:199)
2019-03-13 09:38:23,254+0200 INFO (jsonrpc/4) [storage.StorageDomain] Creating symlink
from
/rhev/data-center/mnt/glusterSD/ovirt1.localdomain:_engine/808423f9-8a5c-40cd-bc9f-2568c85b8c74/images/94ade632-6ecc-4901-8cec-8e39f3d69cb0
to
/var/run/vdsm/storage/808423f9-8a5c-40cd-bc9f-2568c85b8c74/94ade632-6ecc-4901-8cec-8e39f3d69cb0
(fileSD:580)
2019-03-13 09:38:23,260+0200 INFO (jsonrpc/4) [vdsm.api] FINISH prepareImage error=Volume
does not exist: (u'9460fc4b-54f3-48e3-b7b6-da962321ecf4',)
from=::ffff:192.168.1.2,42644, flow_id=d48d9272-2e65-438d-a7b2-46979309833b,
task_id=bb534320-451c-45c0-b7a6-0cce017ec7cb (api:52)
2019-03-13 09:38:23,261+0200 ERROR (jsonrpc/4) [storage.TaskManager.Task]
(Task='bb534320-451c-45c0-b7a6-0cce017ec7cb') Unexpected error (task:875)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in
_run
return fn(*args, **kargs)
File "<string>", line 2, in prepareImage
File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in
method
ret = func(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3212, in
prepareImage
leafInfo = dom.produceVolume(imgUUID, leafUUID).getVmVolumeInfo()
File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 822, in
produceVolume
volUUID)
File "/usr/lib/python2.7/site-packages/vdsm/storage/glusterVolume.py", line
45, in __init__
volUUID)
File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 801, in
__init__
self._manifest = self.manifestClass(repoPath, sdUUID, imgUUID, volUUID)
File "/usr/lib/python2.7/site-packages/vdsm/storage/fileVolume.py", line 71,
in __init__
volUUID)
File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 86, in
__init__
self.validate()
File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 112, in
validate
self.validateVolumePath()
File "/usr/lib/python2.7/site-packages/vdsm/storage/fileVolume.py", line 136,
in validateVolumePath
self.validateMetaVolumePath()
File "/usr/lib/python2.7/site-packages/vdsm/storage/fileVolume.py", line 118,
in validateMetaVolumePath
raise se.VolumeDoesNotExist(self.volUUID)
VolumeDoesNotExist: Volume does not exist:
(u'9460fc4b-54f3-48e3-b7b6-da962321ecf4',)
2019-03-13 09:38:23,261+0200 INFO (jsonrpc/4) [storage.TaskManager.Task]
(Task='bb534320-451c-45c0-b7a6-0cce017ec7cb') aborting: Task is aborted:
"Volume does not exist: (u'9460fc4b-54f3-48e3-b7b6-da962321ecf4',)" -
code 201 (task:1181)
2019-03-13 09:38:23,261+0200 ERROR (jsonrpc/4) [storage.Dispatcher] FINISH prepareImage
error=Volume does not exist: (u'9460fc4b-54f3-48e3-b7b6-da962321ecf4',)
(dispatcher:83)
Yet, the volume is there and is accessible:
[root@ovirt1 94ade632-6ecc-4901-8cec-8e39f3d69cb0]# tar -tvf
/var/run/vdsm/storage/808423f9-8a5c-40cd-bc9f-2568c85b8c74/94ade632-6ecc-4901-8cec-8e39f3d69cb0/9460fc4b-54f3-48e3-b7b6-da962321ecf4
-rw-r--r-- 0/0 138 2019-03-12 08:06 info.json
-rw-r--r-- 0/0 21164 2019-03-12 08:06 8474ae07-f172-4a20-b516-375c73903df7.ovf
-rw-r--r-- 0/0 72 2019-03-12 08:06 metadata.json
[root@ovirt1 94ade632-6ecc-4901-8cec-8e39f3d69cb0]# tar -tvf
/rhev/data-center/mnt/glusterSD/ovirt1.localdomain:_engine/808423f9-8a5c-40cd-bc9f-2568c85b8c74/images/94ade632-6ecc-4901-8cec-8e39f3d69cb0/9460fc4b-54f3-48e3-b7b6-da962321ecf4
-rw-r--r-- 0/0 138 2019-03-12 08:06 info.json
-rw-r--r-- 0/0 21164 2019-03-12 08:06 8474ae07-f172-4a20-b516-375c73903df7.ovf
-rw-r--r-- 0/0 72 2019-03-12 08:06 metadata.json
Best Regards,Strahil Nikolov