[Users] Fibre channel - LVM problems

[Łukasz Faber]

Hello,

I'm trying to set up an oVirt 3.2.1 cluster with FC storage.
However, I have encountered a problem when adding the storage to the
cluster. The action fails with the error shown in the log fragment
below.

Thread-628::DEBUG::2013-07-25 21:07:56,385::task::568::TaskManager.Task::(_updateState) Task=`2a9c1ec3-3ab7-467c-949d-f47260e95dda`::moving from state init -> state preparing
Thread-628::INFO::2013-07-25 21:07:56,386::logUtils::41::dispatcher::(wrapper) Run and protect: createVG(vgname='7d6f6cd0-608a-4221-aca4-67fffb874b45', devlist=['3600a0b800074a36e000006e951f14e7d'], force=False, options=None)
Thread-628::DEBUG::2013-07-25 21:07:56,387::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/lvm pvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%3600a0b800074a36e000006e951f14e7d%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/3600a0b800074a36e000006e951f14e7d' (cwd None)
Thread-628::DEBUG::2013-07-25 21:07:56,427::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-628::DEBUG::2013-07-25 21:07:56,428::lvm::471::OperationMutex::(_invalidatepvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-628::DEBUG::2013-07-25 21:07:56,428::lvm::474::OperationMutex::(_invalidatepvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-628::DEBUG::2013-07-25 21:07:56,429::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/lvm pvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%3600a0b800074a36e000006e951f14e7d%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --metadataignore n /dev/mapper/3600a0b800074a36e000006e951f14e7d' (cwd None)
Thread-628::DEBUG::2013-07-25 21:07:56,468::misc::84::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  No device found for PV W8eewg-xskW-2b4S-NJf6-6aux-ySua-1kAU9J.\n  /dev/mapper/3600a0b800074a36e000006e951f14e7d: lseek 18446744073575333888 failed: Invalid argument\n  /dev/mapper/3600a0b800074a36e000006e951f14e7d: lseek 18446744073575333888 failed: Invalid argument\n  Failed to store physical volume "/dev/mapper/3600a0b800074a36e000006e951f14e7d"\n'; <rc> = 5
Thread-628::ERROR::2013-07-25 21:07:56,470::task::833::TaskManager.Task::(_setError) Task=`2a9c1ec3-3ab7-467c-949d-f47260e95dda`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 840, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 42, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 1951, in createVG
    (force.capitalize() == "True")))
  File "/usr/share/vdsm/storage/lvm.py", line 865, in createVG
    raise se.PhysDevInitializationError(pvs[0])
PhysDevInitializationError: Failed to initialize physical device: ('/dev/mapper/3600a0b800074a36e000006e951f14e7d',)
Thread-628::DEBUG::2013-07-25 21:07:56,473::task::852::TaskManager.Task::(_run) Task=`2a9c1ec3-3ab7-467c-949d-f47260e95dda`::Task._run: 2a9c1ec3-3ab7-467c-949d-f47260e95dda ('7d6f6cd0-608a-4221-aca4-67fffb874b45', ['3600a0b800074a36e000006e951f14e7d'], False) {} failed - stopping task


As you can see, the PV is created but the next action (pvchange) fails
due to a wrong lseek parameter value. I have pinpointed the problem to the
metadatacopies parameter (a manually created PV without this parameter
works fine).

I have found a similar issue here:
https://www.redhat.com/archives/lvm-devel/2011-February/msg00127.html

List of PVs after the error:
# pvs
  PV                                            VG     Fmt  Attr PSize   PFree  
  /dev/mapper/3600a0b800074a36e000006e951f14e7d        lvm2 a--  100,00g 100,00g
  /dev/sdb2                                     fedora lvm2 a--  556,44g      0 

# pvck -v /dev/mapper/3600a0b800074a36e000006e951f14e7d
  Scanning /dev/mapper/3600a0b800074a36e000006e951f14e7d
  Found label on /dev/mapper/3600a0b800074a36e000006e951f14e7d, sector 1, type=LVM2 001
  Found text metadata area: offset=4096, size=135262208
  Huge memory allocation (size 50003968) rejected - metadata corruption?
  Bounce buffer malloc failed
  Read from /dev/mapper/3600a0b800074a36e000006e951f14e7d failed
  Found text metadata area: offset=107239964672, size=134217728

  Huge memory allocation (size 50003968) rejected - metadata corruption?
  Bounce buffer malloc failed
  Read from /dev/mapper/3600a0b800074a36e000006e951f14e7d failed

The OS is Fedora 19.

# lvm version
  LVM version:     2.02.98(2) (2012-10-15)
  Library version: 1.02.77 (2012-10-15)
  Driver version:  4.24.0

Best regards,
Łukasz