false error messages when merging

false error messages when merging

[Mikulas Patocka]

Hi

LVM2.2.02.60 writes false error messages about tree node not found when 
activating delayed merging. But it starts merging anyway.

Mikulas

---

[slunicko:~]# lvs
  LV   VG   Attr   LSize  Origin Snap%  Move Log Copy%  Convert
  m    vg1  -wi-a- 16.00m
[slunicko:~]# lvcreate -s -n s -c 4k -L 24M vg1/m
  Logical volume "s" created
[slunicko:~]# mount -t ext2 /dev/vg1/s /mnt/test
[slunicko:~]# lvconvert --merge /dev/vg1/s
  Can't merge when snapshot is open
  Merging of snapshot s will start next activation.
[slunicko:~]# umount /mnt/test
[slunicko:~]# lvchange -an vg1/m
[slunicko:~]# lvchange -ay vg1/m
  failed to find tree node for m
  failed to find tree node for s
[slunicko:~]#
... the merging starts on backgound fine

false error messages when merging

[Mike Snitzer]

On Mon, Feb 08 2010 at  3:49pm -0500,
Mikulas Patocka <mpatocka@redhat.com> wrote:

> Hi
> 
> LVM2.2.02.60 writes false error messages about tree node not found when 
> activating delayed merging. But it starts merging anyway.
> 
> [slunicko:~]# lvs
>   LV   VG   Attr   LSize  Origin Snap%  Move Log Copy%  Convert
>   m    vg1  -wi-a- 16.00m
> [slunicko:~]# lvcreate -s -n s -c 4k -L 24M vg1/m
>   Logical volume "s" created
> [slunicko:~]# mount -t ext2 /dev/vg1/s /mnt/test
> [slunicko:~]# lvconvert --merge /dev/vg1/s
>   Can't merge when snapshot is open
>   Merging of snapshot s will start next activation.
> [slunicko:~]# umount /mnt/test
> [slunicko:~]# lvchange -an vg1/m
> [slunicko:~]# lvchange -ay vg1/m
>   failed to find tree node for m
>   failed to find tree node for s
> [slunicko:~]#
> ... the merging starts on backgound fine

I can reproduce your "failed to find tree node for" scenario using
the steps you provided.

I'm auditing the deptree code now while working to fix snapshot-merge
for use with Milan's "query info by uuid rather than name" support.  So
something may turn up.

I also saw "failed to find tree node for" messages late last week when I
was developing the 'lvconvert --merge @tag" support that iterated over a
single VG with two LVs that had pending snapshot merges.

I'd merge the 2 snapshots and in the process stale metadata would get
written to disk (at the start of merging the 2nd snapshot, because the
VG instance in process_each_lv() wasn't refreshed after each iteration).

Both merges completed but LVM thought a merge was still in progress
(because the metadata was stale).  I finally got the "failed to find
tree node" when I used "lvchange --refresh <vg/lv>" to eliminate the LVM
inconsistency (effectively the equivalent of your lvchange -an +
lvchange -ay).

Once I eliminated the source of the stale metadata (by refreshing the VG
instance between each process_each_lv iteration) these messages went
away.

All this being said, I'm not sure what's going on with your scenario but
I'll get to the bottom of it.

Mike

false error messages when merging

[Mike Snitzer]

On Mon, Feb 08 2010 at  4:29pm -0500,
Mike Snitzer <snitzer@redhat.com> wrote:

> On Mon, Feb 08 2010 at  3:49pm -0500,
> Mikulas Patocka <mpatocka@redhat.com> wrote:
> 
> > Hi
> > 
> > LVM2.2.02.60 writes false error messages about tree node not found when 
> > activating delayed merging. But it starts merging anyway.
> > 
> > [slunicko:~]# lvs
> >   LV   VG   Attr   LSize  Origin Snap%  Move Log Copy%  Convert
> >   m    vg1  -wi-a- 16.00m
> > [slunicko:~]# lvcreate -s -n s -c 4k -L 24M vg1/m
> >   Logical volume "s" created
> > [slunicko:~]# mount -t ext2 /dev/vg1/s /mnt/test
> > [slunicko:~]# lvconvert --merge /dev/vg1/s
> >   Can't merge when snapshot is open
> >   Merging of snapshot s will start next activation.
> > [slunicko:~]# umount /mnt/test
> > [slunicko:~]# lvchange -an vg1/m
> > [slunicko:~]# lvchange -ay vg1/m
> >   failed to find tree node for m
> >   failed to find tree node for s
> > [slunicko:~]#
> > ... the merging starts on backgound fine
> 
> I can reproduce your "failed to find tree node for" scenario using
> the steps you provided.
...
> All this being said, I'm not sure what's going on with your scenario but
> I'll get to the bottom of it.

So this "failed to find tree node for" message was introduced with my
optimization for not issuing more ioctls than is needed for checking
open_count: http://sources.redhat.com/git/?p=lvm2.git;a=commit;h=1199b48c

I'll dig deeper to see what I can do about the noise.

false error messages when merging

[Mike Snitzer]

On Mon, Feb 08 2010 at  5:03pm -0500,
Mike Snitzer <snitzer@redhat.com> wrote:

> On Mon, Feb 08 2010 at  4:29pm -0500,
> Mike Snitzer <snitzer@redhat.com> wrote:
> 
> > On Mon, Feb 08 2010 at  3:49pm -0500,
> > Mikulas Patocka <mpatocka@redhat.com> wrote:
> > 
> > > Hi
> > > 
> > > LVM2.2.02.60 writes false error messages about tree node not found when 
> > > activating delayed merging. But it starts merging anyway.
> > > 
> > > [slunicko:~]# lvs
> > >   LV   VG   Attr   LSize  Origin Snap%  Move Log Copy%  Convert
> > >   m    vg1  -wi-a- 16.00m
> > > [slunicko:~]# lvcreate -s -n s -c 4k -L 24M vg1/m
> > >   Logical volume "s" created
> > > [slunicko:~]# mount -t ext2 /dev/vg1/s /mnt/test
> > > [slunicko:~]# lvconvert --merge /dev/vg1/s
> > >   Can't merge when snapshot is open
> > >   Merging of snapshot s will start next activation.
> > > [slunicko:~]# umount /mnt/test
> > > [slunicko:~]# lvchange -an vg1/m
> > > [slunicko:~]# lvchange -ay vg1/m
> > >   failed to find tree node for m
> > >   failed to find tree node for s
> > > [slunicko:~]#
> > > ... the merging starts on backgound fine
> > 
> > I can reproduce your "failed to find tree node for" scenario using
> > the steps you provided.
> ...
> > All this being said, I'm not sure what's going on with your scenario but
> > I'll get to the bottom of it.
> 
> So this "failed to find tree node for" message was introduced with my
> optimization for not issuing more ioctls than is needed for checking
> open_count: http://sources.redhat.com/git/?p=lvm2.git;a=commit;h=1199b48c
> 
> I'll dig deeper to see what I can do about the noise.

The following patch eliminates the false error entirely.  I'm leaning
toward removing the message (rather than switch to log_debug()) because
it is valid (and expected) to not have a node in the tree (for both the
merging origin and the merging snapshot) in the case of when we're
activating a merging origin.

diff --git a/lib/activate/dev_manager.c b/lib/activate/dev_manager.c
index 6023574..6fbc392 100644
--- a/lib/activate/dev_manager.c
+++ b/lib/activate/dev_manager.c
@@ -264,10 +264,9 @@ static const struct dm_info *_cached_info(struct dm_pool *mem,
 		return NULL;
 	}
 
-	if (!(dnode = dm_tree_find_node_by_uuid(dtree, dlid))) {
-		log_error("failed to find tree node for %s", lv->name);
+	/* An activating merging origin won't have a node in the tree yet */
+	if (!(dnode = dm_tree_find_node_by_uuid(dtree, dlid)))
 		return NULL;
-	}
 
 	if (!(dinfo = dm_tree_node_get_info(dnode))) {
 		log_error("failed to get info from tree node for %s", lv->name);

false error messages when merging

[Mikulas Patocka]

On Mon, 8 Feb 2010, Mike Snitzer wrote:

> On Mon, Feb 08 2010 at  5:03pm -0500,
> Mike Snitzer <snitzer@redhat.com> wrote:
> 
> > On Mon, Feb 08 2010 at  4:29pm -0500,
> > Mike Snitzer <snitzer@redhat.com> wrote:
> > 
> > > On Mon, Feb 08 2010 at  3:49pm -0500,
> > > Mikulas Patocka <mpatocka@redhat.com> wrote:
> > > 
> > > > Hi
> > > > 
> > > > LVM2.2.02.60 writes false error messages about tree node not found when 
> > > > activating delayed merging. But it starts merging anyway.
> > > > 
> > > > [slunicko:~]# lvs
> > > >   LV   VG   Attr   LSize  Origin Snap%  Move Log Copy%  Convert
> > > >   m    vg1  -wi-a- 16.00m
> > > > [slunicko:~]# lvcreate -s -n s -c 4k -L 24M vg1/m
> > > >   Logical volume "s" created
> > > > [slunicko:~]# mount -t ext2 /dev/vg1/s /mnt/test
> > > > [slunicko:~]# lvconvert --merge /dev/vg1/s
> > > >   Can't merge when snapshot is open
> > > >   Merging of snapshot s will start next activation.
> > > > [slunicko:~]# umount /mnt/test
> > > > [slunicko:~]# lvchange -an vg1/m
> > > > [slunicko:~]# lvchange -ay vg1/m
> > > >   failed to find tree node for m
> > > >   failed to find tree node for s
> > > > [slunicko:~]#
> > > > ... the merging starts on backgound fine
> > > 
> > > I can reproduce your "failed to find tree node for" scenario using
> > > the steps you provided.
> > ...
> > > All this being said, I'm not sure what's going on with your scenario but
> > > I'll get to the bottom of it.
> > 
> > So this "failed to find tree node for" message was introduced with my
> > optimization for not issuing more ioctls than is needed for checking
> > open_count: http://sources.redhat.com/git/?p=lvm2.git;a=commit;h=1199b48c
> > 
> > I'll dig deeper to see what I can do about the noise.
> 
> The following patch eliminates the false error entirely.  I'm leaning
> toward removing the message (rather than switch to log_debug()) because
> it is valid (and expected) to not have a node in the tree (for both the
> merging origin and the merging snapshot) in the case of when we're
> activating a merging origin.
> 
> diff --git a/lib/activate/dev_manager.c b/lib/activate/dev_manager.c
> index 6023574..6fbc392 100644
> --- a/lib/activate/dev_manager.c
> +++ b/lib/activate/dev_manager.c
> @@ -264,10 +264,9 @@ static const struct dm_info *_cached_info(struct dm_pool *mem,
>  		return NULL;
>  	}
>  
> -	if (!(dnode = dm_tree_find_node_by_uuid(dtree, dlid))) {
> -		log_error("failed to find tree node for %s", lv->name);
> +	/* An activating merging origin won't have a node in the tree yet */
> +	if (!(dnode = dm_tree_find_node_by_uuid(dtree, dlid)))
>  		return NULL;
> -	}
>  
>  	if (!(dinfo = dm_tree_node_get_info(dnode))) {
>  		log_error("failed to get info from tree node for %s", lv->name);
> 

OK.

Reviewed-by: Mikulas Patocka <mpatocka@redhat.com>

Mikulas