7:15 a.m.
We had a drive in our NAS fail, but afterwards one of our VM's will not
start.
The boot drive on the VM is (so near as I can tell) the only drive affected.
I confirmed that the disk images (active and snapshot) are both valid with
qemu.
I followed the instructions at
https://www.canarytek.com/2017/07/02/Recover_oVirt_Illegal_Snapshots.html to
identify the snapshot images that were marked "invalid" and marked them as
valid.
update images set imagestatus=1 where imagestatus=4;
Log excerpt from attempt to start VM:
2020-01-09 02:18:44,908-0600 INFO (vm/c5d0a42f) [vdsm.api] START
prepareImage(sdUUID='6e627364-5e0c-4250-ac95-7cd914d0175f',
spUUID='25cd9bfc-bab6-11e8-90f3-78acc0b47b4d',
imgUUID='4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
leafUUID='f8066c56-6db1-4605-8d7c-0739335d30b8', allowIllegal=False)
from=internal, task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:46)
2020-01-09 02:18:44,931-0600 INFO (vm/c5d0a42f) [vdsm.api] FINISH
prepareImage error=Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',) from=internal,
task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:50)
2020-01-09 02:18:44,932-0600 ERROR (vm/c5d0a42f) [storage.TaskManager.Task]
(Task='26053225-6569-4b73-abdd-7d6c7e15d1e9') 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 48, in
method
ret = func(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3187,
in prepareImage
raise se.prepareIllegalVolumeError(volUUID)
prepareIllegalVolumeError: Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',)
2020-01-09 02:18:44,932-0600 INFO (vm/c5d0a42f) [storage.TaskManager.Task]
(Task='26053225-6569-4b73-abdd-7d6c7e15d1e9') aborting: Task is aborted:
"Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',)"
- code 227 (task:1181)
2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [storage.Dispatcher]
FINISH prepareImage error=Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',) (dispatcher:82)
2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') The vm start process failed
(vm:949)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 878, in
_startUnderlyingVm
self._run()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2798, in
_run
self._devices = self._make_devices()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2639, in
_make_devices
disk_objs = self._perform_host_local_adjustment()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2712, in
_perform_host_local_adjustment
self._preparePathsForDrives(disk_params)
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 1023, in
_preparePathsForDrives
drive['path'] = self.cif.prepareVolumePath(drive, self.id)
File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 417, in
prepareVolumePath
raise vm.VolumeError(drive)
VolumeError: Bad volume specification {'address': {'bus': '0',
'controller': '0', 'type': 'drive', 'target':
'0', 'unit': '0'}, 'serial':
'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
'apparentsize': '36440899584', 'specParams': {}, 'cache':
'writeback',
'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'truesize':
'16916186624', 'type': 'disk', 'domainID':
'6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False}
2020-01-09 02:18:44,934-0600 INFO (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Changed state to Down: Bad
volume specification {'address': {'bus': '0',
'controller': '0', 'type':
'drive', 'target': '0', 'unit': '0'},
'serial':
'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
'apparentsize': '36440899584', 'specParams': {}, 'cache':
'writeback',
'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'truesize':
'16916186624', 'type': 'disk', 'domainID':
'6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False} (code=1)
(vm:1689)
2020-01-09 02:18:44,963-0600 INFO (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Stopping connection
(guestagent:442)
2020-01-09 02:18:44,978-0600 INFO (jsonrpc/4) [api.virt] START
destroy(gracefulAttempts=1) from=::ffff:192.168.2.15,57858,
flow_id=4b57f1a6, vmId=c5d0a42f-3b1e-43ee-a567-7844654011f5 (api:46)
2
Log excerpt from attempt to migrate the affected drive to another storage
device:
2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [storage.VolumeManifest]
ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8
info is {'status': 'OK', 'domain':
'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7',
'voltype': 'LEAF', 'description': 'None',
'parent':
'a912e388-d80d-4f56-805b-ea5e2f35d741', 'format': 'COW',
'generation': 0,
'image': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'ctime':
'1578559013',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize':
'219008', 'children': [], 'pool': '', 'capacity':
'1503238553600', 'uuid':
u'f8066c56-6db1-4605-8d7c-0739335d30b8', 'truesize': '26624',
'type':
'SPARSE', 'lease': {'path':
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
'owners': [], 'version': None, 'offset': 0}} (volume:282)
2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [vdsm.api] FINISH
getVolumeInfo return={'info': {'status': 'OK', 'domain':
'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', 'voltype': 'LEAF',
'description':
'None', 'parent': 'a912e388-d80d-4f56-805b-ea5e2f35d741',
'format': 'COW',
'generation': 0, 'image': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
'ctime':
'1578559013', 'disktype': 'DATA', 'legality':
'LEGAL', 'mtime': '0',
'apparentsize': '219008', 'children': [], 'pool':
'', 'capacity':
'1503238553600', 'uuid': u'f8066c56-6db1-4605-8d7c-0739335d30b8',
'truesize': '26624', 'type': 'SPARSE', 'lease':
{'path':
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
'owners': [], 'version': None, 'offset': 0}}}
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=28e885f7-df18-4ea5-bb6e-eaee7385b519 (api:52)
2020-01-09 05:27:14,363-0600 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC
call Volume.getInfo succeeded in 0.04 seconds (__init__:573)
2020-01-09 05:27:14,394-0600 INFO (jsonrpc/6) [vdsm.api] START
sdm_copy_data(job_id=u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
source={u'img_id': u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
u'sd_id':
u'6e627364-5e0c-4250-ac95-7cd914d0175f', u'endpoint_type':
u'div',
u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'},
destination={u'generation': 0, u'img_id':
u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', u'sd_id':
u'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', u'endpoint_type':
u'div',
u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'})
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:46)
2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [vdsm.api] FINISH
sdm_copy_data return=None from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:52)
2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC
call SDM.copy_data succeeded in 0.00 seconds (__init__:573)
2020-01-09 05:27:14,396-0600 INFO (tasks/4)
[storage.ThreadPool.WorkerThread] START task
f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (cmd=<bound method Task.commit of
<vdsm.storage.task.Task instance at 0x7ff3a42613b0>>, args=None)
(threadPool:208)
2020-01-09 05:27:14,396-0600 INFO (tasks/4) [root] Running job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'... (jobs:183)
2020-01-09 05:27:14,429-0600 INFO (jsonrpc/1) [api.host] START
getJobs(job_type=u'storage',
job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [api.host] FINISH getJobs
return={'status': {'message': 'Done', 'code': 0},
'jobs':
{u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status': 'running',
'job_type':
'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
'copy_data'}}} from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC
call Host.getJobs succeeded in 0.00 seconds (__init__:573)
2020-01-09 05:27:14,459-0600 INFO (tasks/4) [storage.SANLock] Acquiring
Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) for host id 2 (clusterlock:386)
2020-01-09 05:27:14,496-0600 INFO (tasks/4) [storage.SANLock] Successfully
acquired Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) for host id 2 (clusterlock:424)
2020-01-09 05:27:14,498-0600 INFO (tasks/4) [storage.VolumeManifest]
Volume: preparing volume
6e627364-5e0c-4250-ac95-7cd914d0175f/f8066c56-6db1-4605-8d7c-0739335d30b8
(volume:569)
2020-01-09 05:27:14,502-0600 INFO (tasks/4) [storage.SANLock] Releasing
Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) (clusterlock:487)
2020-01-09 05:27:14,504-0600 INFO (tasks/4) [storage.SANLock] Successfully
released Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) (clusterlock:496)
2020-01-09 05:27:14,504-0600 ERROR (tasks/4) [root] Job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' failed (jobs:221)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/jobs.py", line 157, in run
self._run()
File
"/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
61, in _run
with self._source.prepare(), self._dest.prepare():
File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
return self.gen.next()
File
"/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
172, in prepare
self.volume.prepare(rw=self._writable, justme=False)
File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 574,
in prepare
raise se.prepareIllegalVolumeError(self.volUUID)
prepareIllegalVolumeError: Cannot prepare illegal volume:
('f8066c56-6db1-4605-8d7c-0739335d30b8',)
2020-01-09 05:27:14,505-0600 INFO (tasks/4) [root] Job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' will be deleted in 3600 seconds
(jobs:249)
2020-01-09 05:27:14,506-0600 INFO (tasks/4)
[storage.ThreadPool.WorkerThread] FINISH task
f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (threadPool:210)
2020-01-09 05:27:16,459-0600 INFO (jsonrpc/4) [api.host] START
getJobs(job_type=u'storage',
job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
2020-01-09 05:27:16,460-0600 INFO (jsonrpc/4) [api.host] FINISH getJobs
return={'status': {'message': 'Done', 'code': 0},
'jobs':
{u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status': 'failed',
'error':
{'message': "Cannot prepare illegal volume:
('f8066c56-6db1-4605-8d7c-0739335d30b8',)", 'code': 227},
'job_type':
'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
'copy_data'}}} from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
2
Regards,
David Johnson
Director of Development, Maxis Technology
844.696.2947 ext 702 (o) | 479.531.3590 (c)
djohnson(a)maxistechnology.com
[image: Maxis Techncology] <http://www.maxistechnology.com>
www.maxistechnology.com
*stay connected <http://www.linkedin.com/in/pojoguy>*
7:24 a.m.
New subject: After NAS crash, one VM will not start up, Cannot prepare illegal volume
Did you change the volume metadata to LEGAL on the storage as well?
On Thu, Jan 9, 2020 at 2:19 PM David Johnson <djohnson(a)maxistechnology.com>
wrote:
We had a drive in our NAS fail, but afterwards one of our VM's
will not
start.
The boot drive on the VM is (so near as I can tell) the only drive
affected.
I confirmed that the disk images (active and snapshot) are both valid with
qemu.
I followed the instructions at
https://www.canarytek.com/2017/07/02/Recover_oVirt_Illegal_Snapshots.html to
identify the snapshot images that were marked "invalid" and marked them as
valid.
update images set imagestatus=1 where imagestatus=4;
Log excerpt from attempt to start VM:
2020-01-09 02:18:44,908-0600 INFO (vm/c5d0a42f) [vdsm.api] START
prepareImage(sdUUID='6e627364-5e0c-4250-ac95-7cd914d0175f',
spUUID='25cd9bfc-bab6-11e8-90f3-78acc0b47b4d',
imgUUID='4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
leafUUID='f8066c56-6db1-4605-8d7c-0739335d30b8', allowIllegal=False)
from=internal, task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:46)
2020-01-09 02:18:44,931-0600 INFO (vm/c5d0a42f) [vdsm.api] FINISH
prepareImage error=Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',) from=internal,
task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:50)
2020-01-09 02:18:44,932-0600 ERROR (vm/c5d0a42f)
[storage.TaskManager.Task] (Task='26053225-6569-4b73-abdd-7d6c7e15d1e9')
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 48, in
method
ret = func(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3187,
in prepareImage
raise se.prepareIllegalVolumeError(volUUID)
prepareIllegalVolumeError: Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',)
2020-01-09 02:18:44,932-0600 INFO (vm/c5d0a42f)
[storage.TaskManager.Task] (Task='26053225-6569-4b73-abdd-7d6c7e15d1e9')
aborting: Task is aborted: "Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',)" - code 227 (task:1181)
2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [storage.Dispatcher]
FINISH prepareImage error=Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',) (dispatcher:82)
2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') The vm start process failed
(vm:949)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 878, in
_startUnderlyingVm
self._run()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2798, in
_run
self._devices = self._make_devices()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2639, in
_make_devices
disk_objs = self._perform_host_local_adjustment()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2712, in
_perform_host_local_adjustment
self._preparePathsForDrives(disk_params)
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 1023, in
_preparePathsForDrives
drive['path'] = self.cif.prepareVolumePath(drive, self.id)
File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 417, in
prepareVolumePath
raise vm.VolumeError(drive)
VolumeError: Bad volume specification {'address': {'bus': '0',
'controller': '0', 'type': 'drive', 'target':
'0', 'unit': '0'}, 'serial':
'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
'apparentsize': '36440899584', 'specParams': {}, 'cache':
'writeback',
'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'truesize':
'16916186624', 'type': 'disk', 'domainID':
'6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False}
2020-01-09 02:18:44,934-0600 INFO (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Changed state to Down: Bad
volume specification {'address': {'bus': '0',
'controller': '0', 'type':
'drive', 'target': '0', 'unit': '0'},
'serial':
'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
'apparentsize': '36440899584', 'specParams': {}, 'cache':
'writeback',
'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'truesize':
'16916186624', 'type': 'disk', 'domainID':
'6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False} (code=1)
(vm:1689)
2020-01-09 02:18:44,963-0600 INFO (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Stopping connection
(guestagent:442)
2020-01-09 02:18:44,978-0600 INFO (jsonrpc/4) [api.virt] START
destroy(gracefulAttempts=1) from=::ffff:192.168.2.15,57858,
flow_id=4b57f1a6, vmId=c5d0a42f-3b1e-43ee-a567-7844654011f5 (api:46)
2
Log excerpt from attempt to migrate the affected drive to another storage
device:
2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [storage.VolumeManifest]
ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8
info is {'status': 'OK', 'domain':
'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7',
'voltype': 'LEAF', 'description': 'None',
'parent':
'a912e388-d80d-4f56-805b-ea5e2f35d741', 'format': 'COW',
'generation': 0,
'image': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'ctime':
'1578559013',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize':
'219008', 'children': [], 'pool': '', 'capacity':
'1503238553600', 'uuid':
u'f8066c56-6db1-4605-8d7c-0739335d30b8', 'truesize': '26624',
'type':
'SPARSE', 'lease': {'path':
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
'owners': [], 'version': None, 'offset': 0}} (volume:282)
2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [vdsm.api] FINISH
getVolumeInfo return={'info': {'status': 'OK', 'domain':
'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', 'voltype': 'LEAF',
'description':
'None', 'parent': 'a912e388-d80d-4f56-805b-ea5e2f35d741',
'format': 'COW',
'generation': 0, 'image': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
'ctime':
'1578559013', 'disktype': 'DATA', 'legality':
'LEGAL', 'mtime': '0',
'apparentsize': '219008', 'children': [], 'pool':
'', 'capacity':
'1503238553600', 'uuid':
u'f8066c56-6db1-4605-8d7c-0739335d30b8',
'truesize': '26624', 'type': 'SPARSE', 'lease':
{'path':
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
'owners': [], 'version': None, 'offset': 0}}}
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=28e885f7-df18-4ea5-bb6e-eaee7385b519 (api:52)
2020-01-09 05:27:14,363-0600 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC
call Volume.getInfo succeeded in 0.04 seconds (__init__:573)
2020-01-09 05:27:14,394-0600 INFO (jsonrpc/6) [vdsm.api] START
sdm_copy_data(job_id=u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
source={u'img_id': u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
u'sd_id':
u'6e627364-5e0c-4250-ac95-7cd914d0175f', u'endpoint_type':
u'div',
u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'},
destination={u'generation': 0, u'img_id':
u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', u'sd_id':
u'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', u'endpoint_type':
u'div',
u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'})
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:46)
2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [vdsm.api] FINISH
sdm_copy_data return=None from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:52)
2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC
call SDM.copy_data succeeded in 0.00 seconds (__init__:573)
2020-01-09 05:27:14,396-0600 INFO (tasks/4)
[storage.ThreadPool.WorkerThread] START task
f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (cmd=<bound method Task.commit of
<vdsm.storage.task.Task instance at 0x7ff3a42613b0>>, args=None)
(threadPool:208)
2020-01-09 05:27:14,396-0600 INFO (tasks/4) [root] Running job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'... (jobs:183)
2020-01-09 05:27:14,429-0600 INFO (jsonrpc/1) [api.host] START
getJobs(job_type=u'storage',
job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [api.host] FINISH getJobs
return={'status': {'message': 'Done', 'code': 0},
'jobs':
{u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status': 'running',
'job_type':
'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
'copy_data'}}} from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC
call Host.getJobs succeeded in 0.00 seconds (__init__:573)
2020-01-09 05:27:14,459-0600 INFO (tasks/4) [storage.SANLock] Acquiring
Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) for host id 2 (clusterlock:386)
2020-01-09 05:27:14,496-0600 INFO (tasks/4) [storage.SANLock]
Successfully acquired Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) for host id 2 (clusterlock:424)
2020-01-09 05:27:14,498-0600 INFO (tasks/4) [storage.VolumeManifest]
Volume: preparing volume
6e627364-5e0c-4250-ac95-7cd914d0175f/f8066c56-6db1-4605-8d7c-0739335d30b8
(volume:569)
2020-01-09 05:27:14,502-0600 INFO (tasks/4) [storage.SANLock] Releasing
Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) (clusterlock:487)
2020-01-09 05:27:14,504-0600 INFO (tasks/4) [storage.SANLock]
Successfully released Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) (clusterlock:496)
2020-01-09 05:27:14,504-0600 ERROR (tasks/4) [root] Job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' failed (jobs:221)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/jobs.py", line 157, in run
self._run()
File
"/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
61, in _run
with self._source.prepare(), self._dest.prepare():
File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
return self.gen.next()
File
"/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
172, in prepare
self.volume.prepare(rw=self._writable, justme=False)
File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line
574, in prepare
raise se.prepareIllegalVolumeError(self.volUUID)
prepareIllegalVolumeError: Cannot prepare illegal volume:
('f8066c56-6db1-4605-8d7c-0739335d30b8',)
2020-01-09 05:27:14,505-0600 INFO (tasks/4) [root] Job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' will be deleted in 3600 seconds
(jobs:249)
2020-01-09 05:27:14,506-0600 INFO (tasks/4)
[storage.ThreadPool.WorkerThread] FINISH task
f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (threadPool:210)
2020-01-09 05:27:16,459-0600 INFO (jsonrpc/4) [api.host] START
getJobs(job_type=u'storage',
job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
2020-01-09 05:27:16,460-0600 INFO (jsonrpc/4) [api.host] FINISH getJobs
return={'status': {'message': 'Done', 'code': 0},
'jobs':
{u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status': 'failed',
'error':
{'message': "Cannot prepare illegal volume:
('f8066c56-6db1-4605-8d7c-0739335d30b8',)", 'code': 227},
'job_type':
'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
'copy_data'}}} from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
2
Regards,
David Johnson
Director of Development, Maxis Technology
844.696.2947 ext 702 (o) | 479.531.3590 (c)
djohnson(a)maxistechnology.com
[image: Maxis Techncology] <http://www.maxistechnology.com>
www.maxistechnology.com
*stay connected <http://www.linkedin.com/in/pojoguy>*
_______________________________________________
Users mailing list -- users(a)ovirt.org
To unsubscribe send an email to users-leave(a)ovirt.org
Privacy Statement: https://www.ovirt.org/site/privacy-policy/
oVirt Code of Conduct:
https://www.ovirt.org/community/about/community-guidelines/
List Archives:
https://lists.ovirt.org/archives/list/users@ovirt.org/message/KKLZKSPCESY...
7:28 a.m.
New subject: After NAS crash, one VM will not start up, Cannot prepare illegal volume
Thank you for the quick response.
Where do I find that?
Regards,
David Johnson
Director of Development, Maxis Technology
844.696.2947 ext 702 (o) | 479.531.3590 (c)
djohnson(a)maxistechnology.com
[image: Maxis Techncology] <http://www.maxistechnology.com>
www.maxistechnology.com
*stay connected <http://www.linkedin.com/in/pojoguy>*
On Thu, Jan 9, 2020 at 6:24 AM Benny Zlotnik <bzlotnik(a)redhat.com> wrote:
Did you change the volume metadata to LEGAL on the storage as well?
On Thu, Jan 9, 2020 at 2:19 PM David Johnson <djohnson(a)maxistechnology.com>
wrote:
> We had a drive in our NAS fail, but afterwards one of our VM's will not
> start.
>
> The boot drive on the VM is (so near as I can tell) the only drive
> affected.
>
> I confirmed that the disk images (active and snapshot) are both valid
> with qemu.
>
> I followed the instructions at
> https://www.canarytek.com/2017/07/02/Recover_oVirt_Illegal_Snapshots.html to
> identify the snapshot images that were marked "invalid" and marked them as
> valid.
>
> update images set imagestatus=1 where imagestatus=4;
>
>
>
> Log excerpt from attempt to start VM:
> 2020-01-09 02:18:44,908-0600 INFO (vm/c5d0a42f) [vdsm.api] START
> prepareImage(sdUUID='6e627364-5e0c-4250-ac95-7cd914d0175f',
> spUUID='25cd9bfc-bab6-11e8-90f3-78acc0b47b4d',
> imgUUID='4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
> leafUUID='f8066c56-6db1-4605-8d7c-0739335d30b8', allowIllegal=False)
> from=internal, task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:46)
> 2020-01-09 02:18:44,931-0600 INFO (vm/c5d0a42f) [vdsm.api] FINISH
> prepareImage error=Cannot prepare illegal volume:
> (u'f8066c56-6db1-4605-8d7c-0739335d30b8',) from=internal,
> task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:50)
> 2020-01-09 02:18:44,932-0600 ERROR (vm/c5d0a42f)
> [storage.TaskManager.Task] (Task='26053225-6569-4b73-abdd-7d6c7e15d1e9')
> 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 48, in
> method
> ret = func(*args, **kwargs)
> File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3187,
> in prepareImage
> raise se.prepareIllegalVolumeError(volUUID)
> prepareIllegalVolumeError: Cannot prepare illegal volume:
> (u'f8066c56-6db1-4605-8d7c-0739335d30b8',)
> 2020-01-09 02:18:44,932-0600 INFO (vm/c5d0a42f)
> [storage.TaskManager.Task] (Task='26053225-6569-4b73-abdd-7d6c7e15d1e9')
> aborting: Task is aborted: "Cannot prepare illegal volume:
> (u'f8066c56-6db1-4605-8d7c-0739335d30b8',)" - code 227 (task:1181)
> 2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [storage.Dispatcher]
> FINISH prepareImage error=Cannot prepare illegal volume:
> (u'f8066c56-6db1-4605-8d7c-0739335d30b8',) (dispatcher:82)
> 2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [virt.vm]
> (vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') The vm start process failed
> (vm:949)
> Traceback (most recent call last):
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 878, in
> _startUnderlyingVm
> self._run()
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2798, in
> _run
> self._devices = self._make_devices()
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2639, in
> _make_devices
> disk_objs = self._perform_host_local_adjustment()
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2712, in
> _perform_host_local_adjustment
> self._preparePathsForDrives(disk_params)
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 1023, in
> _preparePathsForDrives
> drive['path'] = self.cif.prepareVolumePath(drive, self.id)
> File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 417, in
> prepareVolumePath
> raise vm.VolumeError(drive)
> VolumeError: Bad volume specification {'address': {'bus':
'0',
> 'controller': '0', 'type': 'drive', 'target':
'0', 'unit': '0'}, 'serial':
> '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
> 'apparentsize': '36440899584', 'specParams': {},
'cache': 'writeback',
> 'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
'truesize':
> '16916186624', 'type': 'disk', 'domainID':
> '6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
> 'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
>
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
> 'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
> 'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
> 'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False}
> 2020-01-09 02:18:44,934-0600 INFO (vm/c5d0a42f) [virt.vm]
> (vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Changed state to Down: Bad
> volume specification {'address': {'bus': '0',
'controller': '0', 'type':
> 'drive', 'target': '0', 'unit': '0'},
'serial':
> '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
> 'apparentsize': '36440899584', 'specParams': {},
'cache': 'writeback',
> 'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
'truesize':
> '16916186624', 'type': 'disk', 'domainID':
> '6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
> 'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
>
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
> 'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
> 'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
> 'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False}
(code=1)
> (vm:1689)
> 2020-01-09 02:18:44,963-0600 INFO (vm/c5d0a42f) [virt.vm]
> (vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Stopping connection
> (guestagent:442)
> 2020-01-09 02:18:44,978-0600 INFO (jsonrpc/4) [api.virt] START
> destroy(gracefulAttempts=1) from=::ffff:192.168.2.15,57858,
> flow_id=4b57f1a6, vmId=c5d0a42f-3b1e-43ee-a567-7844654011f5 (api:46)
> 2
>
>
> Log excerpt from attempt to migrate the affected drive to another storage
> device:
> 2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [storage.VolumeManifest]
>
ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8
> info is {'status': 'OK', 'domain':
'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7',
> 'voltype': 'LEAF', 'description': 'None',
'parent':
> 'a912e388-d80d-4f56-805b-ea5e2f35d741', 'format': 'COW',
'generation': 0,
> 'image': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'ctime':
'1578559013',
> 'disktype': 'DATA', 'legality': 'LEGAL',
'mtime': '0', 'apparentsize':
> '219008', 'children': [], 'pool': '',
'capacity': '1503238553600', 'uuid':
> u'f8066c56-6db1-4605-8d7c-0739335d30b8', 'truesize': '26624',
'type':
> 'SPARSE', 'lease': {'path':
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
> 'owners': [], 'version': None, 'offset': 0}} (volume:282)
> 2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [vdsm.api] FINISH
> getVolumeInfo return={'info': {'status': 'OK',
'domain':
> 'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', 'voltype': 'LEAF',
'description':
> 'None', 'parent': 'a912e388-d80d-4f56-805b-ea5e2f35d741',
'format': 'COW',
> 'generation': 0, 'image':
'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'ctime':
> '1578559013', 'disktype': 'DATA', 'legality':
'LEGAL', 'mtime': '0',
> 'apparentsize': '219008', 'children': [], 'pool':
'', 'capacity':
> '1503238553600', 'uuid':
u'f8066c56-6db1-4605-8d7c-0739335d30b8',
> 'truesize': '26624', 'type': 'SPARSE',
'lease': {'path':
>
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
> 'owners': [], 'version': None, 'offset': 0}}}
> from=::ffff:192.168.2.15,57858,
> flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
> task_id=28e885f7-df18-4ea5-bb6e-eaee7385b519 (api:52)
> 2020-01-09 05:27:14,363-0600 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer]
> RPC call Volume.getInfo succeeded in 0.04 seconds (__init__:573)
> 2020-01-09 05:27:14,394-0600 INFO (jsonrpc/6) [vdsm.api] START
> sdm_copy_data(job_id=u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
> source={u'img_id': u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
u'sd_id':
> u'6e627364-5e0c-4250-ac95-7cd914d0175f', u'endpoint_type':
u'div',
> u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'},
> destination={u'generation': 0, u'img_id':
> u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', u'sd_id':
> u'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', u'endpoint_type':
u'div',
> u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'})
> from=::ffff:192.168.2.15,57858,
> flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
> task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:46)
> 2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [vdsm.api] FINISH
> sdm_copy_data return=None from=::ffff:192.168.2.15,57858,
> flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
> task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:52)
> 2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer]
> RPC call SDM.copy_data succeeded in 0.00 seconds (__init__:573)
> 2020-01-09 05:27:14,396-0600 INFO (tasks/4)
> [storage.ThreadPool.WorkerThread] START task
> f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (cmd=<bound method Task.commit of
> <vdsm.storage.task.Task instance at 0x7ff3a42613b0>>, args=None)
> (threadPool:208)
> 2020-01-09 05:27:14,396-0600 INFO (tasks/4) [root] Running job
> u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'... (jobs:183)
> 2020-01-09 05:27:14,429-0600 INFO (jsonrpc/1) [api.host] START
> getJobs(job_type=u'storage',
> job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
> from=::ffff:192.168.2.15,57858,
> flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
> 2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [api.host] FINISH getJobs
> return={'status': {'message': 'Done', 'code': 0},
'jobs':
> {u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status':
'running', 'job_type':
> 'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
> 'copy_data'}}} from=::ffff:192.168.2.15,57858,
> flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
> 2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer]
> RPC call Host.getJobs succeeded in 0.00 seconds (__init__:573)
> 2020-01-09 05:27:14,459-0600 INFO (tasks/4) [storage.SANLock] Acquiring
> Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
>
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
> offset=0) for host id 2 (clusterlock:386)
> 2020-01-09 05:27:14,496-0600 INFO (tasks/4) [storage.SANLock]
> Successfully acquired Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
>
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
> offset=0) for host id 2 (clusterlock:424)
> 2020-01-09 05:27:14,498-0600 INFO (tasks/4) [storage.VolumeManifest]
> Volume: preparing volume
> 6e627364-5e0c-4250-ac95-7cd914d0175f/f8066c56-6db1-4605-8d7c-0739335d30b8
> (volume:569)
> 2020-01-09 05:27:14,502-0600 INFO (tasks/4) [storage.SANLock] Releasing
> Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
>
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
> offset=0) (clusterlock:487)
> 2020-01-09 05:27:14,504-0600 INFO (tasks/4) [storage.SANLock]
> Successfully released Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
>
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
> offset=0) (clusterlock:496)
> 2020-01-09 05:27:14,504-0600 ERROR (tasks/4) [root] Job
> u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' failed (jobs:221)
> Traceback (most recent call last):
> File "/usr/lib/python2.7/site-packages/vdsm/jobs.py", line 157, in run
> self._run()
> File
> "/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
> 61, in _run
> with self._source.prepare(), self._dest.prepare():
> File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
> return self.gen.next()
> File
> "/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
> 172, in prepare
> self.volume.prepare(rw=self._writable, justme=False)
> File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line
> 574, in prepare
> raise se.prepareIllegalVolumeError(self.volUUID)
> prepareIllegalVolumeError: Cannot prepare illegal volume:
> ('f8066c56-6db1-4605-8d7c-0739335d30b8',)
> 2020-01-09 05:27:14,505-0600 INFO (tasks/4) [root] Job
> u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' will be deleted in 3600 seconds
> (jobs:249)
> 2020-01-09 05:27:14,506-0600 INFO (tasks/4)
> [storage.ThreadPool.WorkerThread] FINISH task
> f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (threadPool:210)
> 2020-01-09 05:27:16,459-0600 INFO (jsonrpc/4) [api.host] START
> getJobs(job_type=u'storage',
> job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
> from=::ffff:192.168.2.15,57858,
> flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
> 2020-01-09 05:27:16,460-0600 INFO (jsonrpc/4) [api.host] FINISH getJobs
> return={'status': {'message': 'Done', 'code': 0},
'jobs':
> {u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status':
'failed', 'error':
> {'message': "Cannot prepare illegal volume:
> ('f8066c56-6db1-4605-8d7c-0739335d30b8',)", 'code': 227},
'job_type':
> 'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
> 'copy_data'}}} from=::ffff:192.168.2.15,57858,
> flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
> 2
>
> Regards,
> David Johnson
> Director of Development, Maxis Technology
> 844.696.2947 ext 702 (o) | 479.531.3590 (c)
> djohnson(a)maxistechnology.com
>
>
> [image: Maxis Techncology] <http://www.maxistechnology.com>
> www.maxistechnology.com
>
>
> *stay connected <http://www.linkedin.com/in/pojoguy>*
> _______________________________________________
> Users mailing list -- users(a)ovirt.org
> To unsubscribe send an email to users-leave(a)ovirt.org
> Privacy Statement: https://www.ovirt.org/site/privacy-policy/
> oVirt Code of Conduct:
> https://www.ovirt.org/community/about/community-guidelines/
> List Archives:
>
https://lists.ovirt.org/archives/list/users@ovirt.org/message/KKLZKSPCESY...
>
7:33 a.m.
Additional info:
The failure appears to be from a simple legality check:
def isLegal(self):
try:
legality = self.getMetaParam(sc.LEGALITY)
return legality != sc.ILLEGAL_VOL
except se.MetaDataKeyNotFoundError:
return True
Looking at the metadata above, the legality is 'LEGAL'
Regards,
David Johnson
Director of Development, Maxis Technology
844.696.2947 ext 702 (o) | 479.531.3590 (c)
djohnson(a)maxistechnology.com
[image: Maxis Techncology] <http://www.maxistechnology.com>
www.maxistechnology.com
*stay connected <http://www.linkedin.com/in/pojoguy>*
On Thu, Jan 9, 2020 at 6:15 AM David Johnson <djohnson(a)maxistechnology.com>
wrote:
We had a drive in our NAS fail, but afterwards one of our VM's
will not
start.
The boot drive on the VM is (so near as I can tell) the only drive
affected.
I confirmed that the disk images (active and snapshot) are both valid with
qemu.
I followed the instructions at
https://www.canarytek.com/2017/07/02/Recover_oVirt_Illegal_Snapshots.html to
identify the snapshot images that were marked "invalid" and marked them as
valid.
update images set imagestatus=1 where imagestatus=4;
Log excerpt from attempt to start VM:
2020-01-09 02:18:44,908-0600 INFO (vm/c5d0a42f) [vdsm.api] START
prepareImage(sdUUID='6e627364-5e0c-4250-ac95-7cd914d0175f',
spUUID='25cd9bfc-bab6-11e8-90f3-78acc0b47b4d',
imgUUID='4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
leafUUID='f8066c56-6db1-4605-8d7c-0739335d30b8', allowIllegal=False)
from=internal, task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:46)
2020-01-09 02:18:44,931-0600 INFO (vm/c5d0a42f) [vdsm.api] FINISH
prepareImage error=Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',) from=internal,
task_id=26053225-6569-4b73-abdd-7d6c7e15d1e9 (api:50)
2020-01-09 02:18:44,932-0600 ERROR (vm/c5d0a42f)
[storage.TaskManager.Task] (Task='26053225-6569-4b73-abdd-7d6c7e15d1e9')
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 48, in
method
ret = func(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3187,
in prepareImage
raise se.prepareIllegalVolumeError(volUUID)
prepareIllegalVolumeError: Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',)
2020-01-09 02:18:44,932-0600 INFO (vm/c5d0a42f)
[storage.TaskManager.Task] (Task='26053225-6569-4b73-abdd-7d6c7e15d1e9')
aborting: Task is aborted: "Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',)" - code 227 (task:1181)
2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [storage.Dispatcher]
FINISH prepareImage error=Cannot prepare illegal volume:
(u'f8066c56-6db1-4605-8d7c-0739335d30b8',) (dispatcher:82)
2020-01-09 02:18:44,933-0600 ERROR (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') The vm start process failed
(vm:949)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 878, in
_startUnderlyingVm
self._run()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2798, in
_run
self._devices = self._make_devices()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2639, in
_make_devices
disk_objs = self._perform_host_local_adjustment()
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2712, in
_perform_host_local_adjustment
self._preparePathsForDrives(disk_params)
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 1023, in
_preparePathsForDrives
drive['path'] = self.cif.prepareVolumePath(drive, self.id)
File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 417, in
prepareVolumePath
raise vm.VolumeError(drive)
VolumeError: Bad volume specification {'address': {'bus': '0',
'controller': '0', 'type': 'drive', 'target':
'0', 'unit': '0'}, 'serial':
'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
'apparentsize': '36440899584', 'specParams': {}, 'cache':
'writeback',
'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'truesize':
'16916186624', 'type': 'disk', 'domainID':
'6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False}
2020-01-09 02:18:44,934-0600 INFO (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Changed state to Down: Bad
volume specification {'address': {'bus': '0',
'controller': '0', 'type':
'drive', 'target': '0', 'unit': '0'},
'serial':
'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'index': 0, 'iface':
'scsi',
'apparentsize': '36440899584', 'specParams': {}, 'cache':
'writeback',
'imageID': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'truesize':
'16916186624', 'type': 'disk', 'domainID':
'6e627364-5e0c-4250-ac95-7cd914d0175f', 'reqsize': '0',
'format': 'cow',
'poolID': '25cd9bfc-bab6-11e8-90f3-78acc0b47b4d', 'device':
'disk', 'path':
'/rhev/data-center/25cd9bfc-bab6-11e8-90f3-78acc0b47b4d/6e627364-5e0c-4250-ac95-7cd914d0175f/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8',
'propagateErrors': 'off', 'name': 'sda',
'bootOrder': '1', 'volumeID':
'f8066c56-6db1-4605-8d7c-0739335d30b8', 'diskType': 'file',
'alias':
'ua-4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'discard': False} (code=1)
(vm:1689)
2020-01-09 02:18:44,963-0600 INFO (vm/c5d0a42f) [virt.vm]
(vmId='c5d0a42f-3b1e-43ee-a567-7844654011f5') Stopping connection
(guestagent:442)
2020-01-09 02:18:44,978-0600 INFO (jsonrpc/4) [api.virt] START
destroy(gracefulAttempts=1) from=::ffff:192.168.2.15,57858,
flow_id=4b57f1a6, vmId=c5d0a42f-3b1e-43ee-a567-7844654011f5 (api:46)
2
Log excerpt from attempt to migrate the affected drive to another storage
device:
2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [storage.VolumeManifest]
ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8
info is {'status': 'OK', 'domain':
'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7',
'voltype': 'LEAF', 'description': 'None',
'parent':
'a912e388-d80d-4f56-805b-ea5e2f35d741', 'format': 'COW',
'generation': 0,
'image': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', 'ctime':
'1578559013',
'disktype': 'DATA', 'legality': 'LEGAL', 'mtime':
'0', 'apparentsize':
'219008', 'children': [], 'pool': '', 'capacity':
'1503238553600', 'uuid':
u'f8066c56-6db1-4605-8d7c-0739335d30b8', 'truesize': '26624',
'type':
'SPARSE', 'lease': {'path':
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
'owners': [], 'version': None, 'offset': 0}} (volume:282)
2020-01-09 05:27:14,362-0600 INFO (jsonrpc/2) [vdsm.api] FINISH
getVolumeInfo return={'info': {'status': 'OK', 'domain':
'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', 'voltype': 'LEAF',
'description':
'None', 'parent': 'a912e388-d80d-4f56-805b-ea5e2f35d741',
'format': 'COW',
'generation': 0, 'image': '4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
'ctime':
'1578559013', 'disktype': 'DATA', 'legality':
'LEGAL', 'mtime': '0',
'apparentsize': '219008', 'children': [], 'pool':
'', 'capacity':
'1503238553600', 'uuid':
u'f8066c56-6db1-4605-8d7c-0739335d30b8',
'truesize': '26624', 'type': 'SPARSE', 'lease':
{'path':
u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
'owners': [], 'version': None, 'offset': 0}}}
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=28e885f7-df18-4ea5-bb6e-eaee7385b519 (api:52)
2020-01-09 05:27:14,363-0600 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC
call Volume.getInfo succeeded in 0.04 seconds (__init__:573)
2020-01-09 05:27:14,394-0600 INFO (jsonrpc/6) [vdsm.api] START
sdm_copy_data(job_id=u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
source={u'img_id': u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6',
u'sd_id':
u'6e627364-5e0c-4250-ac95-7cd914d0175f', u'endpoint_type':
u'div',
u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'},
destination={u'generation': 0, u'img_id':
u'4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6', u'sd_id':
u'ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7', u'endpoint_type':
u'div',
u'vol_id': u'f8066c56-6db1-4605-8d7c-0739335d30b8'})
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:46)
2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [vdsm.api] FINISH
sdm_copy_data return=None from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731,
task_id=f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (api:52)
2020-01-09 05:27:14,395-0600 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC
call SDM.copy_data succeeded in 0.00 seconds (__init__:573)
2020-01-09 05:27:14,396-0600 INFO (tasks/4)
[storage.ThreadPool.WorkerThread] START task
f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (cmd=<bound method Task.commit of
<vdsm.storage.task.Task instance at 0x7ff3a42613b0>>, args=None)
(threadPool:208)
2020-01-09 05:27:14,396-0600 INFO (tasks/4) [root] Running job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'... (jobs:183)
2020-01-09 05:27:14,429-0600 INFO (jsonrpc/1) [api.host] START
getJobs(job_type=u'storage',
job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [api.host] FINISH getJobs
return={'status': {'message': 'Done', 'code': 0},
'jobs':
{u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status': 'running',
'job_type':
'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
'copy_data'}}} from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
2020-01-09 05:27:14,430-0600 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC
call Host.getJobs succeeded in 0.00 seconds (__init__:573)
2020-01-09 05:27:14,459-0600 INFO (tasks/4) [storage.SANLock] Acquiring
Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) for host id 2 (clusterlock:386)
2020-01-09 05:27:14,496-0600 INFO (tasks/4) [storage.SANLock]
Successfully acquired Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) for host id 2 (clusterlock:424)
2020-01-09 05:27:14,498-0600 INFO (tasks/4) [storage.VolumeManifest]
Volume: preparing volume
6e627364-5e0c-4250-ac95-7cd914d0175f/f8066c56-6db1-4605-8d7c-0739335d30b8
(volume:569)
2020-01-09 05:27:14,502-0600 INFO (tasks/4) [storage.SANLock] Releasing
Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) (clusterlock:487)
2020-01-09 05:27:14,504-0600 INFO (tasks/4) [storage.SANLock]
Successfully released Lease(name='f8066c56-6db1-4605-8d7c-0739335d30b8',
path=u'/rhev/data-center/mnt/192.168.2.223:_mnt_ovirt-main-pool/ec6ccb14-03c2-49cc-9cc0-b1a87d582ed7/images/4081ce8f-1ce1-4ee1-aa43-69af2dfc5ab6/f8066c56-6db1-4605-8d7c-0739335d30b8.lease',
offset=0) (clusterlock:496)
2020-01-09 05:27:14,504-0600 ERROR (tasks/4) [root] Job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' failed (jobs:221)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/jobs.py", line 157, in run
self._run()
File
"/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
61, in _run
with self._source.prepare(), self._dest.prepare():
File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
return self.gen.next()
File
"/usr/lib/python2.7/site-packages/vdsm/storage/sdm/api/copy_data.py", line
172, in prepare
self.volume.prepare(rw=self._writable, justme=False)
File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line
574, in prepare
raise se.prepareIllegalVolumeError(self.volUUID)
prepareIllegalVolumeError: Cannot prepare illegal volume:
('f8066c56-6db1-4605-8d7c-0739335d30b8',)
2020-01-09 05:27:14,505-0600 INFO (tasks/4) [root] Job
u'9a47a14f-d398-4fe8-81fa-59cba7122aa0' will be deleted in 3600 seconds
(jobs:249)
2020-01-09 05:27:14,506-0600 INFO (tasks/4)
[storage.ThreadPool.WorkerThread] FINISH task
f1504b2d-c6c2-4866-97ce-e0476b0ba9a2 (threadPool:210)
2020-01-09 05:27:16,459-0600 INFO (jsonrpc/4) [api.host] START
getJobs(job_type=u'storage',
job_ids=[u'9a47a14f-d398-4fe8-81fa-59cba7122aa0'])
from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:46)
2020-01-09 05:27:16,460-0600 INFO (jsonrpc/4) [api.host] FINISH getJobs
return={'status': {'message': 'Done', 'code': 0},
'jobs':
{u'9a47a14f-d398-4fe8-81fa-59cba7122aa0': {'status': 'failed',
'error':
{'message': "Cannot prepare illegal volume:
('f8066c56-6db1-4605-8d7c-0739335d30b8',)", 'code': 227},
'job_type':
'storage', 'id': u'9a47a14f-d398-4fe8-81fa-59cba7122aa0',
'description':
'copy_data'}}} from=::ffff:192.168.2.15,57858,
flow_id=94ad3bf0-c5f5-4d45-af2a-49aa4eaa6731 (api:52)
2
Regards,
David Johnson
Director of Development, Maxis Technology
844.696.2947 ext 702 (o) | 479.531.3590 (c)
djohnson(a)maxistechnology.com
[image: Maxis Techncology] <http://www.maxistechnology.com>
www.maxistechnology.com
*stay connected <http://www.linkedin.com/in/pojoguy>*
1814
days inactive
1814
days old
3 comments
2 participants
participants (2)
-
Benny Zlotnik -
David Johnson