Description of problem: Seems a bit odd that the process is reported twice for the one extension/one volume. [root@taft-01 ~]# lvs -a -o +devices LV VG Attr LSize Origin Snap% Devices origin snapper owi-a- 300.00M /dev/sdh1(0) snap1 snapper swi-a- 100.00M origin 0.01 /dev/sdh1(75) [root@taft-01 ~]# dd if=/dev/zero of=/dev/snapper/snap1 count=170000 170000+0 records in 170000+0 records out 87040000 bytes (87 MB) copied, 6.06972 seconds, 14.3 MB/s [root@taft-01 ~]# lvs -a -o +devices LV VG Attr LSize Origin Snap% Devices origin snapper owi-a- 300.00M /dev/sdh1(0) snap1 snapper swi-a- 120.00M origin 69.45 /dev/sdh1(75) May 23 15:18:59 taft-01 lvm[29414]: Snapshot snapper-snap1 is now 83% full. May 23 15:18:59 taft-01 lvm[29414]: Extending logical volume snap1 to 120.00 MB May 23 15:18:59 taft-01 lvm[29414]: Monitoring snapshot snapper-snap1 May 23 15:18:59 taft-01 lvm[29414]: Logical volume snap1 successfully resized May 23 15:18:59 taft-01 lvm[29414]: Extension of snapshot snapper/snap1 finished successfully. May 23 15:19:01 taft-01 lvm[29414]: No longer monitoring snapshot snapper-snap1 May 23 15:19:09 taft-01 lvm[29414]: Extension of snapshot snapper/snap1 finished successfully. Version-Release number of selected component (if applicable): 2.6.18-261.el5 lvm2-2.02.84-3.el5 BUILT: Wed Apr 27 03:42:24 CDT 2011 lvm2-cluster-2.02.84-3.el5 BUILT: Wed Apr 27 03:42:43 CDT 2011 device-mapper-1.02.63-3.el5 BUILT: Thu May 19 08:09:22 CDT 2011 device-mapper-event-1.02.63-3.el5 BUILT: Thu May 19 08:09:22 CDT 2011 cmirror-1.1.39-10.el5 BUILT: Wed Sep 8 16:32:05 CDT 2010 kmod-cmirror-0.1.22-3.el5 BUILT: Tue Dec 22 13:39:47 CST 2009 How reproducible: Everytime
It's also a bit weird that it reports "No longer monitoring snapshot snapper-snap1 " since isn't it constantly monitoring that volume?
This is indeed a bit suspicious. I'll look into it.
I have two observations: 1) I cannot reproduce this issue with snapshots, but it *might* be timing-dependent. Does it happen every time? 2) A similar symptom happens with mirrors (the "No longer monitoring" messages are frequent, and annoying). The following patch fixes the situation for mirrors (and, I would expect, also with snapshots, since it applies to common code): Index: daemons/dmeventd/plugins/lvm2/dmeventd_lvm.c =================================================================== RCS file: /cvs/lvm2/LVM2/daemons/dmeventd/plugins/lvm2/dmeventd_lvm.c,v retrieving revision 1.5 diff -u -p -r1.5 dmeventd_lvm.c --- daemons/dmeventd/plugins/lvm2/dmeventd_lvm.c 30 Sep 2010 11:40:14 -0000 1.5 +++ daemons/dmeventd/plugins/lvm2/dmeventd_lvm.c 29 Aug 2011 18:42:47 -0000 @@ -114,7 +114,7 @@ int dmeventd_lvm2_init(void) goto out; } /* FIXME Temporary: move to dmeventd core */ - lvm2_run(_lvm_handle, "_memlock_inc"); + lvm2_run(_lvm_handle, "_dmeventd_enter"); } _register_count++; @@ -130,7 +130,7 @@ void dmeventd_lvm2_exit(void) pthread_mutex_lock(&_register_mutex); if (!--_register_count) { - lvm2_run(_lvm_handle, "_memlock_dec"); + lvm2_run(_lvm_handle, "_dmeventd_leave"); dm_pool_destroy(_mem_pool); _mem_pool = NULL; lvm2_exit(_lvm_handle); Index: tools/lvmcmdlib.c =================================================================== RCS file: /cvs/lvm2/LVM2/tools/lvmcmdlib.c,v retrieving revision 1.12 diff -u -p -r1.12 lvmcmdlib.c --- tools/lvmcmdlib.c 5 Mar 2010 14:48:34 -0000 1.12 +++ tools/lvmcmdlib.c 29 Aug 2011 18:42:57 -0000 @@ -81,9 +81,12 @@ int lvm2_run(void *handle, const char *c /* FIXME Temporary - move to libdevmapper */ ret = ECMD_PROCESSED; - if (!strcmp(cmdline, "_memlock_inc")) + if (!strcmp(cmdline, "_dmeventd_enter")) { memlock_inc_daemon(cmd); - else if (!strcmp(cmdline, "_memlock_dec")) + init_dmeventd_monitor(DMEVENTD_MONITOR_IGNORE); + } else if (!strcmp(cmdline, "_memlock_inc")) + memlock_inc_daemon(cmd); + else if (!strcmp(cmdline, "_memlock_dec") || !strcmp(cmdline, "_dmeventd_leave")) memlock_dec_daemon(cmd); else ret = lvm_run_command(cmd, argc, argv);
New patch is waiting for review, see http://www.redhat.com/archives/lvm-devel/2011-October/msg00058.html
Fixed in lvm2-2.02.88-2.el5.
"Extension of snapshot $snap finished successfully" messages are no longer reported at all, even when threshold is turned on. Marking verified. Nov 17 16:16:08 hayes-01 lvm[7344]: Monitoring snapshot snapper-auto_extension Nov 17 16:16:18 hayes-01 lvm[7344]: Extending logical volume auto_extension to 120.00 MB Nov 17 16:16:18 hayes-01 lvm[7344]: Logical volume auto_extension successfully resized Nov 17 16:23:33 hayes-01 lvm[7344]: No longer monitoring snapshot snapper-auto_extension Nov 17 16:25:02 hayes-01 lvm[7344]: Monitoring snapshot snapper-auto_extension Nov 17 16:25:12 hayes-01 lvm[7344]: Extending logical volume auto_extension to 120.00 MB Nov 17 16:25:12 hayes-01 lvm[7344]: Logical volume auto_extension successfully resized Nov 17 16:25:20 hayes-01 lvm[7344]: No longer monitoring snapshot snapper-auto_extension 2.6.18-274.el5 lvm2-2.02.88-4.el5 BUILT: Wed Nov 16 09:40:55 CST 2011 lvm2-cluster-2.02.88-4.el5 BUILT: Wed Nov 16 09:46:51 CST 2011 device-mapper-1.02.67-2.el5 BUILT: Mon Oct 17 08:31:56 CDT 2011 device-mapper-event-1.02.67-2.el5 BUILT: Mon Oct 17 08:31:56 CDT 2011 cmirror-1.1.39-10.el5 BUILT: Wed Sep 8 16:32:05 CDT 2010 kmod-cmirror-0.1.22-3.el5 BUILT: Tue Dec 22 13:39:47 CST 2009
Technical note added. If any revisions are required, please edit the "Technical Notes" field accordingly. All revisions will be proofread by the Engineering Content Services team. New Contents: Automatic snapshot resize now doesn't report redundant information to syslog after successful operation.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. http://rhn.redhat.com/errata/RHBA-2012-0161.html