Created attachment 1694143 [details]
Reproducer script

Description of problem:

pvs/vgs/lvs commands may fail randomly when concurrent lvm commands are
modifying the same VG.  The failing commands cause failures in layered products
(such as RHV) which cannot tell if if the failed command was harmless (this
case) or caused by a data corruption. See bug 1837199 for more info.

We can reproduce these errors in stress test running pvs, vgs, and lvs in a
loop, and other commands creating lvs, changing lvs, activating lvs,
deactivating lvs, extending lvs, and removing lvs.

We start the stress test with new loop devices backed by empty sparse files.
The commands fail with first this error:

    Metadata on /dev/mapper/delay0000000000000000000000000000 at 52623872 has
    wrong VG name "" expected bz1837199-000000000000000000000-0000.\n

Later, the commands fail with:

    Metadata on /dev/mapper/delay0000000000000000000000000001 at 927232 has
    wrong VG name "= "host1"\nsegment_count = 1\n\nsegment1 {\nstart_extent =
    0\n extent_count = 8\n\ntype = "striped"\nstripe_count = 1\n\nstripes =
    [\n"pv0"," expected bz1837199-000000000000000000000-0001.\n

I think this can be explained by the metadata area wrapping around when it
becomes full.  When we start the metadata is full of zeroes, and lvm is trying
to read metadata from before the metadata was written, so it see zeroes and
report empty string "\0". Once we wrap around and we start to see older
metadata when we try to read metadata before it was written.

Running the reproducer with --verbose option, I collected errors from pvs
-vvvv, vgs -vvvv, and lvs -vvvv. Here is example failure in vgs command:

# vgs-error-0001.txt

Scan pahse:

...
#label/label.c:320         /dev/mapper/delay0000000000000000000000000000: lvm2 label detected at sector 1
#cache/lvmcache.c:2086          lvmcache /dev/mapper/delay0000000000000000000000000000: now in VG #orphans_lvm2 (#orphans_lvm2) with 0 mda(s).
#format_text/text_label.c:423           /dev/mapper/delay0000000000000000000000000000: PV header extension version 2 found
#format_text/format-text.c:330           Reading mda header sector from /dev/mapper/delay0000000000000000000000000000 at 4096
#format_text/import.c:58            Reading metadata summary from /dev/mapper/delay0000000000000000000000000000 at 66324480 size 164655 (+0)
#format_text/format-text.c:1336          Found metadata summary on /dev/mapper/delay0000000000000000000000000000 at 66324480 size 164655 for VG bz1837199-000000000000000000000-0000
...

Processing phase:

...
#toollib.c:2008        Processing VG bz1837199-000000000000000000000-0000 FR6is4-bTdC-wHve-RpJv-RdvH-G5OX-nmG8Ud
#locking/locking.c:367           Dropping cache for bz1837199-000000000000000000000-0000.
#misc/lvm-flock.c:202         Locking /run/lock/lvm/V_bz1837199-000000000000000000000-0000 RB
#libdm-common.c:984           Preparing SELinux context for /run/lock/lvm/V_bz1837199-000000000000000000000-0000 to system_u:object_r:lvm_lock_t:s0.
#misc/lvm-flock.c:100           _do_flock /run/lock/lvm/V_bz1837199-000000000000000000000-0000:aux WB
#misc/lvm-flock.c:47            _undo_flock /run/lock/lvm/V_bz1837199-000000000000000000000-0000:aux
#misc/lvm-flock.c:100           _do_flock /run/lock/lvm/V_bz1837199-000000000000000000000-0000 RB
#libdm-common.c:987           Resetting SELinux context to default value.
#metadata/metadata.c:3824        Reading VG bz1837199-000000000000000000000-0000 FR6is4-bTdC-wHve-RpJv-RdvH-G5OX-nmG8Ud
#metadata/metadata.c:3923          Skipped rescanning devices for bz1837199-000000000000000000000-0000
#metadata/metadata.c:4006          Reading VG bz1837199-000000000000000000000-0000 from /dev/mapper/delay0000000000000000000000000000
#format_text/format-text.c:330           Reading mda header sector from /dev/mapper/delay0000000000000000000000000000 at 4096
#format_text/format-text.c:484     Metadata on /dev/mapper/delay0000000000000000000000000000 at 66489344 has wrong VG name "" expected bz1837199-000000000000000000000-0000.
...

Notes the offsets:

- In the can phase we detected metadata at 66324480 size 164655
- In the processing phase we detected metadata at 66489344

>>> 66324480 + 164655
66489135

>>> 66489135 - (66489135 % 512) + 512
66489344

66324480 is the committed metadata area
66489344 is the precommitted metadata area

I think what happens here is:

1. In the scan phase we read the metadata without locks, and read precoomitted
   raw_locn[1] pointing to area on storage that does not include the metadata
   yet. Another command wrote the offset to slot 1 before writing the data.

2. In the processing phase we take a lock on the vg:

    #misc/lvm-flock.c:100           _do_flock /run/lock/lvm/V_bz1837199-000000000000000000000-0000 RB

3. And we skipped reading the vg metadata

    #metadata/metadata.c:3923          Skipped rescanning devices for bz1837199-000000000000000000000-0000

4. And we probably think that it is ok to read precommited metadata at slot 1
   since we hold the lock. But the data came from the scan phase read without
   locks.

    # from lib/format_text/format-text.c line 439

    /* Should we use precommitted metadata? */
    if (*precommitted && rlocn_precommitted->size &&
        (rlocn_precommitted->offset != rlocn->offset)) {
        rlocn = rlocn_precommitted;
    } else 
        *precommitted = 0; 

   On master we have detailed log here, but in 2.02 there are no logs.


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

lvm2-2.02.186-7.el7_8.1.x86_64


How reproducible:

- Always with lvm2-2.02.186-7.el7_8.1.x86_64 using reproducer script.
- We have one customer case showing this issue: bug 1837199
- Not reproducible with lvm2-2.03.08-3.el8.x86_64 - no error after 6 hours


Steps to Reproduce:

Using the script attached reload.py script:

1. Setup storage:

    # ./reload.py setup

2. Run the reproducer:

    # ./reload.py run --verbose 4 2>run.log

3. Watch for errors:

    # watch ls *-error-*.txt

4. To delete storage:

    # ./reload.py teardown


Actual results:

pvs/vgs/lvs commands fail with bogus error about wrong VG name while actual
metadata is fine.


Expected results:

No failures in LVM unless underling storage fails.


More info:

The reproducer script support several useful options:

--trials (default 1) - One trial takes about 75 minutes and generates 570
  errors per run. This can be useful to run several iterations to check that a
  fix actually solve the issue.

--vg-count (default 10) - I could not reproduce the issue with one VG. Looks like
  more VGs helps to reproduce the issue faster.

- lv-count (default 500) - Number lvs created, modified and removed on every
  VG.  No error is reproduced with --lv-count=50.

--pv-size (default 2t) - should be big enough to hold lv-count lvs * 2 MiB
  (test writes 2 MiB data to every lv)

--delay-msec (default 10) The delay argument passed to dm-delay device on top
  of the loop device. I did not try longer delay but it may help to reproduce
  faster. It is very hard to reproduce the issue without using a delay device,
  loop devices reads/writes are just too fast.

--verbose (default 0) - Pass -v (multiple times) to the underlying LVM pvs,
  vgs, lvs commands. The output is logged if the command fails, or if using
  --debug.

--no-udev (default False) - Use obtain_device_list_from_udev=0 in the
  underlying LVM command --config. Required to avoid random failures on RHEL
  8.2 (see bug 1837199). On RHEL 7.8 this seems to slightly lower error rate.

--no-select (default False) - Disable usage of --select in the underlying
  pvs/vgs/lvs commands (e.g. pvs --select 'pv_name = /dev/mapper/delay001') and
  specify the entity instead (e.g. pvs /dev/mapper/delay001). Using this option
  double the number of pvs,vgs,lvs commands run during on run and give 10 times
  lower error rate, but we still see errors (e.g 83 errors of 21,054 commands).

--debug (default False) - Log debug messages (command arguments, exit code,
  stdout, stderr). Mainly useful to debug the test script itself.

The test script is maintained in vdsm:
https://gerrit.ovirt.org/c/109355/

The current version of the test script is attached.