[Users] Fibre channel - LVM problems
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
Hi Lukasz, ----- Original Message -----
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
After discussing this with Peter Rajnoha, it looks like the specific issue in the above thread has been resolved and your issue is probably a reincarnation of the problem. Can you manually run the pvchange with -vvvv to get more info? Thanks.
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
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
Hi Ayal, On Mon, 2013-07-29 at 10:13 -0400, Ayal Baron wrote:>
I have found a similar issue here: https://www.redhat.com/archives/lvm-devel/2011-February/msg00127.html
After discussing this with Peter Rajnoha, it looks like the specific issue in the above thread has been resolved and your issue is probably a reincarnation of the problem. Can you manually run the pvchange with -vvvv to get more info?
Thanks.
I'm attaching logs from manual executions of both pvcreate and pvchange. Regards, Lukasz
On 07/30/2013 06:14 PM, Łukasz Faber wrote:
Hi Ayal,
On Mon, 2013-07-29 at 10:13 -0400, Ayal Baron wrote:>
I have found a similar issue here: https://www.redhat.com/archives/lvm-devel/2011-February/msg00127.html
After discussing this with Peter Rajnoha, it looks like the specific issue in the above thread has been resolved and your issue is probably a reincarnation of the problem. Can you manually run the pvchange with -vvvv to get more info?
Thanks.
I'm attaching logs from manual executions of both pvcreate and pvchange.
So, looking at the logs, it looks like lvmetad might be the culprit here. Is it reproducible if you use global/use_lvmetad=0 in /etc/lvm/lvm.conf? The pvcreate log: 21 #device/dev-io.c:271 /dev/mapper/3600a0b800074a36e000006e951f14e7d: size is 209715200 sectors ... 97 #format_text/format-text.c:1324 Creating metadata area on /dev/mapper/3600a0b800074a36e000006e951f14e7d at sector 8 size 264184 sectors 98 #metadata/metadata.c:4468 Setting ignored flag for mda /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 4096. 99 #format_text/format-text.c:1324 Creating metadata area on /dev/mapper/3600a0b800074a36e000006e951f14e7d at sector 209453056 size 262144 sectors 100 #metadata/metadata.c:4468 Setting ignored flag for mda /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 107239964672. The pvcreate looks OK. Now, the pvchange: <STILL OK HERE> 16 #device/dev-io.c:271 /dev/mapper/3600a0b800074a36e000006e951f14e7d: size is 209715200 sectors 27 #metadata/metadata.c:4468 Setting ignored flag for mda /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 4096. 28 #format_text/text_label.c:299 Ignoring mda on device /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 4096 29 #metadata/metadata.c:4468 Setting ignored flag for mda /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 107239964672. 30 #format_text/text_label.c:299 Ignoring mda on device /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 107239964672 <LVMETAD COMMUNICATION - UPDATE LVMETAD CACHE STATE> 32 #libdm-config.c:768 Setting response to OK 33 #libdm-config.c:768 Setting response to OK 34 #libdm-config.c:768 Setting id to wiCjbg-mYay-0NQf-r4qu-xK1Y-Lc8K-KxhmIc 35 #libdm-config.c:768 Setting format to lvm2 36 #libdm-config.c:799 Setting device to 64770 37 #libdm-config.c:799 Setting dev_size to 107374182400 38 #libdm-config.c:799 Setting label_sector to 1 39 #ioctl/libdm-iface.c:1724 dm status (253:2) OF [16384] (*1) 40 #device/dev-io.c:524 Opened /dev/mapper/3600a0b800074a36e000006e951f14e7d RO O_DIRECT 41 #device/dev-io.c:271 /dev/mapper/3600a0b800074a36e000006e951f14e7d: size is 209715200 sectors 42 #device/dev-io.c:577 Closed /dev/mapper/3600a0b800074a36e000006e951f14e7d 43 #device/dev-io.c:271 /dev/mapper/3600a0b800074a36e000006e951f14e7d: size is 209715200 sectors 44 #device/dev-io.c:524 Opened /dev/mapper/3600a0b800074a36e000006e951f14e7d RO O_DIRECT 45 #device/dev-io.c:137 /dev/mapper/3600a0b800074a36e000006e951f14e7d: block size is 4096 bytes 46 #device/dev-io.c:577 Closed /dev/mapper/3600a0b800074a36e000006e951f14e7d 47 #filters/filter-composite.c:31 Using /dev/mapper/3600a0b800074a36e000006e951f14e7d 48 #libdm-config.c:799 Setting size to 135262208 49 #libdm-config.c:799 Setting start to 4096 50 #libdm-config.c:799 Setting ignore to 1 51 #metadata/metadata.c:4468 Setting ignored flag for mda /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 4096. 52 #libdm-config.c:799 Setting size to 134217728 53 #libdm-config.c:799 Setting start to 107239964672 54 #libdm-config.c:799 Setting ignore to 1 <AND NOW IT GOES WRONG AS IT READS INFO FROM LVMETAD - offset 18446744073575333888 IS INCORRECT> 55 #metadata/metadata.c:4468 Setting ignored flag for mda /dev/mapper/3600a0b800074a36e000006e951f14e7d at offset 18446744073575333888. 156 #pvchange.c:157 Updating physical volume "/dev/mapper/3600a0b800074a36e000006e951f14e7d" 157 #format_text/format-text.c:1324 Creating metadata area on /dev/mapper/3600a0b800074a36e000006e951f14e7d at sector 8 size 264184 sectors 158 #format_text/format-text.c:1324 Creating metadata area on /dev/mapper/3600a0b800074a36e000006e951f14e7d at sector 36028797018701824 size 262144 sectors 159 #device/dev-io.c:577 Closed /dev/mapper/3600a0b800074a36e000006e951f14e7d 160 #device/dev-io.c:524 Opened /dev/mapper/3600a0b800074a36e000006e951f14e7d RW O_DIRECT 161 #device/dev-io.c:137 /dev/mapper/3600a0b800074a36e000006e951f14e7d: block size is 4096 bytes 162 #device/dev-io.c:89 /dev/mapper/3600a0b800074a36e000006e951f14e7d: lseek 18446744073575333888 failed: Invalid argument 163 #device/dev-io.c:89 /dev/mapper/3600a0b800074a36e000006e951f14e7d: lseek 18446744073575333888 failed: Invalid argument Peter
O n 07/30/2013 06:14 PM, Łukasz Faber wrote:
On Mon, 2013-07-29 at 10:13 -0400, Ayal Baron wrote:>
I have found a similar issue here: https://www.redhat.com/archives/lvm-devel/2011-February/msg00127.html
After discussing this with Peter Rajnoha, it looks like the specific issue in the above thread has been resolved and your issue is probably a reincarnation of the problem. Can you manually run the pvchange with -vvvv to get more info?
Thanks.
I'm attaching logs from manual executions of both pvcreate and pvchange.
So, looking at the logs, it looks like lvmetad might be the culprit here. Is it reproducible if you use global/use_lvmetad=0 in /etc/lvm/lvm.conf?
No. When I set use_lvmetad to 0 everything seems to work correctly with pvchange: Physical volume "/dev/mapper/3600a0b800074a36e000006e951f14e7d" changed 1 physical volume changed / 0 physical volumes not changed Log for pvchange attached. Thanks for your help! Best regards, Lukasz
On 08/06/2013 09:59 AM, Łukasz Faber wrote:
O n 07/30/2013 06:14 PM, Łukasz Faber wrote:
On Mon, 2013-07-29 at 10:13 -0400, Ayal Baron wrote:>
I have found a similar issue here: https://www.redhat.com/archives/lvm-devel/2011-February/msg00127.html
After discussing this with Peter Rajnoha, it looks like the specific issue in the above thread has been resolved and your issue is probably a reincarnation of the problem. Can you manually run the pvchange with -vvvv to get more info?
Thanks.
I'm attaching logs from manual executions of both pvcreate and pvchange.
So, looking at the logs, it looks like lvmetad might be the culprit here. Is it reproducible if you use global/use_lvmetad=0 in /etc/lvm/lvm.conf?
No. When I set use_lvmetad to 0 everything seems to work correctly with pvchange:
Physical volume "/dev/mapper/3600a0b800074a36e000006e951f14e7d" changed 1 physical volume changed / 0 physical volumes not changed
So it's definitely an lvmetad issue, now I can reproduce the problem with larger PVs. We'll try to provide a fix asap and then update Fedora 19 package immediately. Sorry for the inconvenience and thanks for the report! Peter
participants (3)
-
Ayal Baron -
Peter Rajnoha -
Łukasz Faber