----- Original Message -----
From: "Boyan Tabakov" <blade@alslayer.net> To: "Nir Soffer" <nsoffer@redhat.com> Cc: users@ovirt.org Sent: Wednesday, February 19, 2014 7:18:36 PM Subject: Re: [Users] SD Disk's Logical Volume not visible/activated on some nodes
Hello,
On 19.2.2014, 17:09, Nir Soffer wrote:
----- Original Message -----
From: "Boyan Tabakov" <blade@alslayer.net> To: users@ovirt.org Sent: Tuesday, February 18, 2014 3:34:49 PM Subject: [Users] SD Disk's Logical Volume not visible/activated on some nodes
Hello,
I have ovirt 3.3 installed on on FC 19 hosts with vdsm 4.13.3-2.fc19.
Which version of ovirt 3.3 is this? (3.3.2? 3.3.3?)
ovirt-engine is 3.3.2-1.fc19
One of the hosts (host1) is engine + node + SPM and the other host2 is just a node. I have an iSCSI storage domain configured and accessible from both nodes.
When creating a new disk in the SD, the underlying logical volume gets properly created (seen in vgdisplay output on host1), but doesn't seem to be automatically picked by host2.
How do you know it is not seen on host2?
It's not present in the output of vgdisplay -v nor vgs.
Consequently, when creating/booting a VM with the said disk attached, the VM fails to start on host2, because host2 can't see the LV. Similarly, if the VM is started on host1, it fails to migrate to host2. Extract from host2 log is in the end. The LV in question is 6b35673e-7062-4716-a6c8-d5bf72fe3280.
As far as I could track quickly the vdsm code, there is only call to lvs and not to lvscan or lvchange so the host2 LVM doesn't fully refresh. The only workaround so far has been to restart VDSM on host2, which makes it refresh all LVM data properly.
When is host2 supposed to pick up any newly created LVs in the SD VG? Any suggestions where the problem might be?
When you create a new lv on the shared storage, the new lv should be visible on the other host. Lets start by verifying that you do see the new lv after a disk was created.
Try this:
1. Create a new disk, and check the disk uuid in the engine ui 2. On another machine, run this command:
lvs -o vg_name,lv_name,tags
You can identify the new lv using tags, which should contain the new disk uuid.
If you don't see the new lv from the other host, please provide /var/log/messages and /var/log/sanlock.log.
Just tried that. The disk is not visible on the non-SPM node.
This means that storage is not accessible from this host.
On the SPM node (where the LV is visible in vgs output):
Feb 19 19:10:43 host1 vdsm root WARNING File: /rhev/data-center/61f15cc0-8bba-482d-8a81-cd636a581b58/3307f6fa-dd58-43db-ab23-b1fb299006c7/images/4d15543c-4c45-4c23-bbe3-f10b9084472a/3e0ce8cb-3740-49d7-908e-d025875ac9a2 already removed Feb 19 19:10:45 host1 multipathd: dm-65: remove map (uevent) Feb 19 19:10:45 host1 multipathd: dm-65: devmap not registered, can't remove Feb 19 19:10:45 host1 multipathd: dm-65: remove map (uevent) Feb 19 19:10:54 host1 kernel: [1652684.864746] dd: sending ioctl 80306d02 to a partition! Feb 19 19:10:54 host1 kernel: [1652684.963931] dd: sending ioctl 80306d02 to a partition!
No recent entries in sanlock.log on the SPM node.
On the non-SPM node (the one that doesn't show the LV in vgs output), there are no relevant entries in /var/log/messages.
Strange - sanlock errors are logged to /var/log/messages. It would be helpful if you attach this log - we may find something in it.
Here's the full sanlock.log for that host:
2014-01-30 16:28:09+0200 1324 [2335]: sanlock daemon started 2.8 host 18bd0a27-c280-4007-98f2-d2e7e73cd8b5.xenon.futu 2014-01-30 16:59:51+0200 5 [609]: sanlock daemon started 2.8 host 4a7627e2-296a-4e48-a7e2-f6bcecac07ab.xenon.futu 2014-01-31 09:51:43+0200 60717 [614]: s1 lockspace 3307f6fa-dd58-43db-ab23-b1fb299006c7:2:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids:0 2014-01-31 16:03:51+0200 83045 [613]: s1:r1 resource 3307f6fa-dd58-43db-ab23-b1fb299006c7:SDM:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/leases:1048576 for 8,16,30268 2014-01-31 16:18:01+0200 83896 [614]: s1:r2 resource 3307f6fa-dd58-43db-ab23-b1fb299006c7:SDM:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/leases:1048576 for 8,16,30268 2014-02-06 05:24:10+0200 563065 [31453]: 3307f6fa aio timeout 0 0x7fc37c0008c0:0x7fc37c0008d0:0x7fc391f5f000 ioto 10 to_count 1 2014-02-06 05:24:10+0200 563065 [31453]: s1 delta_renew read rv -202 offset 0 /dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids
Sanlock cannot write to the ids lockspace
2014-02-06 05:24:10+0200 563065 [31453]: s1 renewal error -202 delta_length 10 last_success 563034 2014-02-06 05:24:21+0200 563076 [31453]: 3307f6fa aio timeout 0 0x7fc37c000910:0x7fc37c000920:0x7fc391d5c000 ioto 10 to_count 2 2014-02-06 05:24:21+0200 563076 [31453]: s1 delta_renew read rv -202 offset 0 /dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids 2014-02-06 05:24:21+0200 563076 [31453]: s1 renewal error -202 delta_length 11 last_success 563034 2014-02-06 05:24:32+0200 563087 [31453]: 3307f6fa aio timeout 0 0x7fc37c000960:0x7fc37c000970:0x7fc391c5a000 ioto 10 to_count 3 2014-02-06 05:24:32+0200 563087 [31453]: s1 delta_renew read rv -202 offset 0 /dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids 2014-02-06 05:24:32+0200 563087 [31453]: s1 renewal error -202 delta_length 11 last_success 563034 2014-02-06 05:24:40+0200 563094 [609]: s1 check_our_lease warning 60 last_success 563034 2014-02-06 05:24:41+0200 563095 [609]: s1 check_our_lease warning 61 last_success 563034 2014-02-06 05:24:42+0200 563096 [609]: s1 check_our_lease warning 62 last_success 563034 2014-02-06 05:24:43+0200 563097 [609]: s1 check_our_lease warning 63 last_success 563034 2014-02-06 05:24:43+0200 563098 [31453]: 3307f6fa aio timeout 0 0x7fc37c0009b0:0x7fc37c0009c0:0x7fc391b58000 ioto 10 to_count 4 2014-02-06 05:24:43+0200 563098 [31453]: s1 delta_renew read rv -202 offset 0 /dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids 2014-02-06 05:24:43+0200 563098 [31453]: s1 renewal error -202 delta_length 11 last_success 563034 2014-02-06 05:24:44+0200 563098 [609]: s1 check_our_lease warning 64 last_success 563034 2014-02-06 05:24:45+0200 563099 [609]: s1 check_our_lease warning 65 last_success 563034 2014-02-06 05:24:46+0200 563100 [609]: s1 check_our_lease warning 66 last_success 563034 2014-02-06 05:24:47+0200 563101 [609]: s1 check_our_lease warning 67 last_success 563034 2014-02-06 05:24:48+0200 563102 [609]: s1 check_our_lease warning 68 last_success 563034 2014-02-06 05:24:49+0200 563103 [609]: s1 check_our_lease warning 69 last_success 563034 2014-02-06 05:24:50+0200 563104 [609]: s1 check_our_lease warning 70 last_success 563034 2014-02-06 05:24:51+0200 563105 [609]: s1 check_our_lease warning 71 last_success 563034 2014-02-06 05:24:52+0200 563106 [609]: s1 check_our_lease warning 72 last_success 563034 2014-02-06 05:24:53+0200 563107 [609]: s1 check_our_lease warning 73 last_success 563034 2014-02-06 05:24:54+0200 563108 [609]: s1 check_our_lease warning 74 last_success 563034 2014-02-06 05:24:54+0200 563109 [31453]: s1 delta_renew read rv -2 offset 0 /dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids 2014-02-06 05:24:54+0200 563109 [31453]: s1 renewal error -2 delta_length 11 last_success 563034 2014-02-06 05:24:55+0200 563109 [609]: s1 check_our_lease warning 75 last_success 563034 2014-02-06 05:24:56+0200 563110 [609]: s1 check_our_lease warning 76 last_success 563034 2014-02-06 05:24:57+0200 563111 [609]: s1 check_our_lease warning 77 last_success 563034 2014-02-06 05:24:58+0200 563112 [609]: s1 check_our_lease warning 78 last_success 563034 2014-02-06 05:24:59+0200 563113 [609]: s1 check_our_lease warning 79 last_success 563034 2014-02-06 05:25:00+0200 563114 [609]: s1 check_our_lease failed 80 2014-02-06 05:25:00+0200 563114 [609]: s1 all pids clear 2014-02-06 05:25:05+0200 563119 [31453]: s1 delta_renew read rv -2 offset 0 /dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids 2014-02-06 05:25:05+0200 563119 [31453]: s1 renewal error -2 delta_length 10 last_success 563034 2014-02-06 05:25:15+0200 563129 [31453]: 3307f6fa close_task_aio 0 0x7fc37c0008c0 busy 2014-02-06 05:25:15+0200 563129 [31453]: 3307f6fa close_task_aio 1 0x7fc37c000910 busy 2014-02-06 05:25:15+0200 563129 [31453]: 3307f6fa close_task_aio 2 0x7fc37c000960 busy 2014-02-06 05:25:15+0200 563129 [31453]: 3307f6fa close_task_aio 3 0x7fc37c0009b0 busy 2014-02-06 05:25:25+0200 563139 [31453]: 3307f6fa close_task_aio 0 0x7fc37c0008c0 busy 2014-02-06 05:25:25+0200 563139 [31453]: 3307f6fa close_task_aio 1 0x7fc37c000910 busy 2014-02-06 05:25:25+0200 563139 [31453]: 3307f6fa close_task_aio 2 0x7fc37c000960 busy 2014-02-06 05:25:25+0200 563139 [31453]: 3307f6fa close_task_aio 3 0x7fc37c0009b0 busy 2014-02-06 05:25:35+0200 563149 [31453]: 3307f6fa close_task_aio 0 0x7fc37c0008c0 busy 2014-02-06 05:25:35+0200 563149 [31453]: 3307f6fa close_task_aio 1 0x7fc37c000910 busy 2014-02-06 05:25:35+0200 563149 [31453]: 3307f6fa close_task_aio 2 0x7fc37c000960 busy 2014-02-06 05:25:35+0200 563149 [31453]: 3307f6fa close_task_aio 3 0x7fc37c0009b0 busy 2014-02-06 05:25:45+0200 563159 [31453]: 3307f6fa close_task_aio 0 0x7fc37c0008c0 busy 2014-02-06 05:25:45+0200 563159 [31453]: 3307f6fa close_task_aio 1 0x7fc37c000910 busy 2014-02-06 05:25:45+0200 563159 [31453]: 3307f6fa close_task_aio 2 0x7fc37c000960 busy 2014-02-06 05:25:45+0200 563159 [31453]: 3307f6fa close_task_aio 3 0x7fc37c0009b0 busy 2014-02-06 05:25:55+0200 563169 [31453]: 3307f6fa close_task_aio 0 0x7fc37c0008c0 busy 2014-02-06 05:25:55+0200 563169 [31453]: 3307f6fa close_task_aio 1 0x7fc37c000910 busy 2014-02-06 05:25:55+0200 563169 [31453]: 3307f6fa close_task_aio 2 0x7fc37c000960 busy 2014-02-06 05:25:55+0200 563169 [31453]: 3307f6fa close_task_aio 3 0x7fc37c0009b0 busy 2014-02-06 05:25:59+0200 563173 [31453]: 3307f6fa aio collect 0x7fc37c0008c0:0x7fc37c0008d0:0x7fc391f5f000 result 1048576:0 close free 2014-02-06 05:25:59+0200 563173 [31453]: 3307f6fa aio collect 0x7fc37c000910:0x7fc37c000920:0x7fc391d5c000 result 1048576:0 close free 2014-02-06 05:25:59+0200 563173 [31453]: 3307f6fa aio collect 0x7fc37c000960:0x7fc37c000970:0x7fc391c5a000 result 1048576:0 close free 2014-02-06 05:25:59+0200 563173 [31453]: 3307f6fa aio collect 0x7fc37c0009b0:0x7fc37c0009c0:0x7fc391b58000 result 1048576:0 close free 2014-02-06 05:26:09+0200 563183 [614]: s2 lockspace 3307f6fa-dd58-43db-ab23-b1fb299006c7:2:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids:0
Sanlock can access the storage again - did you change something around this time?
2014-02-18 14:22:16+0200 1632150 [614]: s3 lockspace 3307f6fa-dd58-43db-ab23-b1fb299006c7:2:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids:0 2014-02-18 14:38:16+0200 1633111 [614]: s4 lockspace 3307f6fa-dd58-43db-ab23-b1fb299006c7:2:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids:0 2014-02-18 16:13:07+0200 1638801 [613]: s5 lockspace 3307f6fa-dd58-43db-ab23-b1fb299006c7:2:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids:0 2014-02-18 19:28:09+0200 1650504 [614]: s6 lockspace 3307f6fa-dd58-43db-ab23-b1fb299006c7:2:/dev/3307f6fa-dd58-43db-ab23-b1fb299006c7/ids:0
Last entry is from yesterday, while I just created a new disk.
What was the status of this host in the engine from 2014-02-06 05:24:10+0200 to 2014-02-18 14:22:16? vdsm.log and engine.log for this time frame will make it more clear. Nir