Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1656815

Summary: [downstream clone - 4.2.8] vdsm fails with Invalid index metadata (invalid magic: 0) when trying to add a VM lease
Product: Red Hat Enterprise Virtualization Manager Reporter: RHV bug bot <rhv-bugzilla-bot>
Component: vdsmAssignee: Vojtech Juranek <vjuranek>
Status: CLOSED CURRENTRELEASE QA Contact: Yosi Ben Shimon <ybenshim>
Severity: high Docs Contact:
Priority: high    
Version: 4.2.7CC: bugs, dfodor, germano, gveitmic, lsurette, mmartinv, mtessun, nsoffer, srevivo, tnisan, vjuranek, ycui
Target Milestone: ovirt-4.2.8Keywords: ZStream
Target Release: ---Flags: lsvaty: testing_plan_complete-
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: v4.20.45 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1654417 Environment:
Last Closed: 2019-02-14 14:57:31 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1654417    
Bug Blocks:    

Description RHV bug bot 2018-12-06 11:48:52 UTC 
+++ This bug is a downstream clone. The original bug is: +++
+++   bug 1654417 +++
======================================================================

Description of problem:

vdsm fails with the following error when trying to add a VM lease:
~~~
ERROR (tasks/3) [storage.TaskManager.Task] (Task='11111111-1111-1111-1111-111111111111') 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 "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 336, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 79, in wrapper
    return method(self, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 2061, in create_lease
    dom.create_lease(lease.lease_id)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 1241, in create_lease
    with self._manifest.external_leases_volume() as vol:
  File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 659, in external_leases_volume
    vol = xlease.LeasesVolume(backend)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 493, in __init__
    self._md = self._index.read_metadata()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 734, in read_metadata
    return IndexMetadata.fromebytes(data)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 308, in fromebytes
    raise InvalidMetadata("invalid magic: %s" % magic, data)
InvalidMetadata: Invalid index metadata (invalid magic: 0), the index must be formatted or rebuilt from storage: '\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00'
~~~


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


How reproducible:
Always with a unformatted xleases volume

Steps to Reproduce:
1. Try to add a lease to an HA VM


Actual results:
The operation fails with the error above

Expected results:
The operation finish with no errors.


Additional info:

The xleases volume seems to be unformatted/uninitialized.
The SD domain format is V4 within the engine database.
The SD domain volume group tags contain MDT_VERSION=4.

The vdsm logs were rotated and do not contain any information about the SD upgrade to V4 format or about its creation.

There is no way to reformat the xleases volume via the API or the vdsm-{tool,client} commands.

(Originally by Miguel Martin Villamuelas)
Comment 2 RHV bug bot 2018-12-06 11:49:05 UTC 
(In reply to Miguel Martin from comment #0)
The failure to add a lease is expected, the xleases volume index is invalid:

InvalidMetadata: Invalid index metadata (invalid magic: 0), the index must be
formatted or rebuilt from storage:
'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\...

According to Miguel, the entire volume is empty and was never used. It looks
like a volume that was created but not formatted, or wiped by someone.

There are 2 issues:

1. Why the xleases volume is wiped? Is this a bug in the system failing to
   format the volume and leaving the domain with unformatted volume, or a user
   error?

2. There is no easy way to recover from this situation.

Migual:

- Can you explain here what is the workaround, or link to an support article
  about this?
- Please attach vdsm logs since this domain was created until this error.

(Originally by Nir Soffer)
Comment 3 RHV bug bot 2018-12-06 11:49:14 UTC 
(In reply to Miguel Martin from comment #0)
The failure to add a lease is expected, the xleases volume index is invalid:

InvalidMetadata: Invalid index metadata (invalid magic: 0), the index must be
formatted or rebuilt from storage:
'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\...

According to Miguel, the entire volume is empty and was never used. It looks
like a volume that was created but not formatted, or wiped by someone.

There are 2 issues:

1. Why the xleases volume is wiped? Is this a bug in the system failing to
   format the volume and leaving the domain with unformatted volume, or a user
   error?

2. There is no easy way to recover from this situation.

Migual:

- Can you explain here what is the workaround, or link to an support article
  about this?
- Please attach vdsm logs since this domain was created until this error.

(Originally by Nir Soffer)
Comment 4 RHV bug bot 2018-12-06 11:49:19 UTC 
Germano, please review the patches, and maybe get other people from the team to
review them.

Lets me explain the solution:

- https://gerrit.ovirt.org/c/69189 - implement rebuilding index from storage
  contents. We assume that sanlock leases on storage are the truth.

- https://gerrit.ovirt.org/c/69190 - wire up Lease.rebuild_leases so it can be
  used from vdsm-client. This is a safe way to rebuild the leases, but it will
  work only on the SPM, and only if the domain is active, and only if vdsm is 
  running. This is safe operation.

- https://gerrit.ovirt.org/c/69193 - allow rebuilding on any host even if vdsm is
  not running. This goes directly to storage and is like "sanlock direct xxx"
  commands, or like writing to storage directly with dd. This is dangerous and
  require that the storage domain is not active!

- https://gerrit.ovirt.org/c/69069 - allow formatting the index, dropping all
  entries. This is even more dangerous than rebuilding the index. However this
  does not drop the sanlock leases on storage, so you can rebuild the index after
  formatting.

These patches give support lot of power, but this also means you are responsible
when you use these commands incorrectly.

(Originally by Nir Soffer)
Comment 8 RHV bug bot 2018-12-06 11:49:39 UTC 
*** Bug 1654419 has been marked as a duplicate of this bug. ***

(Originally by Miguel Martin Villamuelas)
Comment 9 RHV bug bot 2018-12-06 11:49:43 UTC 
Hi Nir!

(In reply to Nir Soffer from comment #2)
> Germano, please review the patches, and maybe get other people from the team
> to review them.

Done.

> These patches give support lot of power, but this also means you are
> responsible when you use these commands incorrectly.

I can see it ;)

Nice tool, will certainly be useful. Thanks!

(Originally by Germano Veit Michel)
Comment 12 Yosi Ben Shimon 2019-01-15 16:16:54 UTC 
Tested using:
ovirt-engine-4.2.8.2-0.1.el7ev.noarch
vdsm-4.20.46-1.el7ev.x86_64
vdsm-client-4.20.46-1.el7ev.noarch

Reproduced according to the steps in comment #14 & #15 https://bugzilla.redhat.com/show_bug.cgi?id=1654417#c14

Actual result:
Failed to create a new VM while the xleases is corrupted and the rebuild/format did fixed the issue. So after rebuild/format, a VM could be created successfully.

But there were exceptions in the VDSM logs (same as the one in the bug description):

2019-01-15 17:46:27,027+0200 INFO  (jsonrpc/0) [vdsm.api] FINISH lease_info error=Invalid index metadata (invalid magic: 0), the index must be formatted or
 rebuilt from storage: '\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0
0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0
0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0
0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x
00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0
0\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00' from=::1,34358, task_id=ff8b33cb-a082-4848-b606-f6b2c9efab21 (api:50)
2019-01-15 17:46:27,029+0200 ERROR (jsonrpc/0) [storage.TaskManager.Task] (Task='ff8b33cb-a082-4848-b606-f6b2c9efab21') 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 lease_info
  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 3693, in lease_info
    info = dom.lease_info(lease.lease_id)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 671, in lease_info
    with self.external_leases_volume() as vol:
  File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 659, in external_leases_volume
    vol = xlease.LeasesVolume(backend)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 516, in __init__
    self._md = self._index.read_metadata()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 819, in read_metadata
    return IndexMetadata.fromebytes(data)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/xlease.py", line 331, in fromebytes
    raise InvalidMetadata("invalid magic: %s" % magic, data)
InvalidMetadata: Invalid index metadata (invalid magic: 0), the index must be formatted or rebuilt from storage: '\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00'


According to comment #14 here: https://bugzilla.redhat.com/show_bug.cgi?id=1654417#c14 :
  * when you run `vdsm-client -f lease Lease info` you should see very similar output to one described in this BZ (without exception, just messages that command failed and index must be rebuild and lots of \x00)

The exception is here.
Comment 13 Vojtech Juranek 2019-01-16 10:17:02 UTC 
python exception in the log is fine (actually even better as it proves you tested the scenario end-to-end:-), it's not present when you test it only with vdsm-client.
Comment 14 Yosi Ben Shimon 2019-01-16 10:22:20 UTC 
(In reply to Vojtech Juranek from comment #13)
> python exception in the log is fine (actually even better as it proves you
> tested the scenario end-to-end:-), it's not present when you test it only
> with vdsm-client.

So, in that case, I'm moving this bug to VERIFIED as this is the expected result.
Comment 16 Daniel Gur 2019-08-28 13:13:38 UTC 
sync2jira
Comment 17 Daniel Gur 2019-08-28 13:17:52 UTC 
sync2jira