[root@taft-01 ~]# lvs -a -o +devices
LV                                            VG             Attr   LSize   Origin                        Snap%  Log                                Copy%  Convert Devices
snap0                                         helter_skelter swi-a- 252.00M syncd_both_logs_2legs_2logs_1   0.00                                                   /dev/sdf1(150)
syncd_both_logs_2legs_2logs_1                 helter_skelter owi-a- 600.00M                                      syncd_both_logs_2legs_2logs_1_mlog 100.00         syncd_both_logs_2legs_2logs_1_mimage_0(0),syncd_both_logs_2legs_2logs_1_mimage_1(0)
[syncd_both_logs_2legs_2logs_1_mimage_0]      helter_skelter iwi-ao 600.00M                                                                                        /dev/sdf1(0)
[syncd_both_logs_2legs_2logs_1_mimage_1]      helter_skelter iwi-ao 600.00M                                                                                        /dev/sdd1(0)
[syncd_both_logs_2legs_2logs_1_mlog]          helter_skelter mwi-ao   4.00M                                                                         100.00         syncd_both_logs_2legs_2logs_1_mlog_mimage_0(0),syncd_both_logs_2legs_2logs_1_mlog_mimage_1(0)
[syncd_both_logs_2legs_2logs_1_mlog_mimage_0] helter_skelter iwi-ao   4.00M                                                                                        /dev/sdb1(0)
[syncd_both_logs_2legs_2logs_1_mlog_mimage_1] helter_skelter iwi-ao   4.00M                                                                                        /dev/sdg1(0)

Just a note that the mirror in comment #0 & #1 has a snapshot volume associated with it, however this issue has been reproduced without there being a snapshot involved.

Please identify test, I'm not sure which one it is:
        kill_primary_synced_2_legs
        kill_primary_synced_3_legs
        kill_primary_synced_core_log_2_legs
        kill_secondary_synced_2_legs
        kill_secondary_synced_3_legs
        kill_secondary_synced_core_log_2_legs
        kill_secondary_non_synced_2_legs
        kill_secondary_non_synced_3_legs
        kill_secondary_non_synced_core_log_2_legs
        kill_log_synced_2_legs
        kill_log_synced_3_legs
        kill_log_non_synced_2_legs
        kill_log_non_synced_3_legs
        kill_primary_synced_4_legs
        kill_primary_synced_core_log_4_legs
        kill_secondary_synced_4_legs
        kill_secondary_synced_core_log_4_legs
        kill_secondary_non_synced_4_legs
        kill_log_synced_4_legs
        kill_log_non_synced_4_legs
        kill_primary_and_log_synced_2_legs
        kill_primary_and_log_synced_3_legs
        kill_secondary_and_log_synced_2_legs
        kill_secondary_and_log_synced_4_legs
        kill_multiple_legs_synced_3_legs
        kill_multiple_legs_synced_4_legs
[jbrassow@silver sts-root]$ grep syncd_both_logs_2legs_2logs_1 -r lvm2
[jbrassow@silver sts-root]$

Created attachment 453256 [details]
Output of 'lvconvert --repair --use-policies vg/lv -vvvv'

***
[root@bp-01 ~]# devices
  LV                 Copy%  Devices
  LogVol00                  /dev/sda2(0)
  LogVol01                  /dev/sda2(4451)
  lv                 100.00 lv_mimage_0(0),lv_mimage_1(0)
  [lv_mimage_0]             /dev/sdb1(0)
  [lv_mimage_1]             /dev/sdc1(0)
  [lv_mlog]          100.00 lv_mlog_mimage_0(0),lv_mlog_mimage_1(0)
  [lv_mlog_mimage_0]        /dev/sdf1(0)
  [lv_mlog_mimage_1]        /dev/sdg1(0)
[root@bp-01 ~]# ps -C dmeventd
  PID TTY          TIME CMD
[root@bp-01 ~]# off.sh sd[fg]
Turning off sdf
Turning off sdg
[root@bp-01 ~]# dmsetup status
vg-lv: 0 10485760 mirror 2 253:5 253:6 10240/10240 1 AA 3 disk 253:4 D
vg-lv_mimage_1: 0 10485760 linear
vg-lv_mimage_0: 0 10485760 linear
vg-lv_mlog_mimage_1: 0 8192 linear
vg-lv_mlog: 0 8192 mirror 2 253:2 253:3 7/8 1 DD 1 core
vg-lv_mlog_mimage_0: 0 8192 linear
VolGroup00-LogVol01: 0 20578304 linear
VolGroup00-LogVol00: 0 291700736 linear
[root@bp-01 ~]# lvconvert --repair --use-policies vg/lv -vvvv >& output.txt
***

lvconvert seems to be trying to suspend vg/lv - which will fail because the kernel target is blocking I/O (because it's log has failed).  I thought we had this logic right.  Did something go missing in the rebase?

In '_lvconvert_mirrors_repair', after removing the entire log, I pause (in gdb) before going on to attempt re-adding the mirrored log and I see the following:

[root@bp-01 ~]# dmsetup table
vg-lv: 0 10485760 mirror core 3 1024 nosync block_on_error 2 253:5 0 253:6 0
vg-lv_mimage_1: 0 10485760 linear 8:33 2048
vg-lv_mimage_0: 0 10485760 linear 8:17 2048
vg-lv_mlog_mimage_1-missing_0_0: 0 8192 error
vg-lv_mlog_mimage_1: 0 8192 linear 253:8 0
vg-lv_mlog_mimage_0: 0 8192 linear 253:9 0
vg-lv_mlog_mimage_0-missing_0_0: 0 8192 error

The devices there seem to prevent us from adding the mirror log.  Allowed to continue, we see the log is replace; but it is a linear (not mirrored) log:

[root@bp-01 ~]# devices
  /dev/sdf1: open failed: No such device or address
  /dev/sdg1: open failed: No such device or address
  LV            Copy%  Devices
  LogVol00             /dev/sda2(0)
  LogVol01             /dev/sda2(4451)
  lv            100.00 lv_mimage_0(0),lv_mimage_1(0)
  [lv_mimage_0]        /dev/sdb1(0)
  [lv_mimage_1]        /dev/sdc1(0)
  [lv_mlog]            /dev/sde1(0)
[root@bp-01 ~]# dmsetup ls
vg-lv   (253, 7)
vg-lv_mimage_1  (253, 6)
vg-lv_mimage_0  (253, 5)
vg-lv_mlog_mimage_1-missing_0_0 (253, 8)
vg-lv_mlog_mimage_1     (253, 3)
vg-lv_mlog      (253, 4)
vg-lv_mlog_mimage_0     (253, 2)
vg-lv_mlog_mimage_0-missing_0_0 (253, 9)
VolGroup00-LogVol01     (253, 1)
VolGroup00-LogVol00     (253, 0)

... and we still have the old mlog devices left around.

This seems to be just one possible outcome.  There seem to be other ways of failing.  I'm not sure if they are all related to DM devices that are not being removed.

gdb is bouncing all over the place... I can correlate the line numbers, but it isn't doing them in the proper sequence:

(gdb) n
703             if (!log_count)
(gdb)
1250            if (!(lp->failed_pvs = _failed_pv_list(lv->vg)))
(gdb)
703             if (!log_count)
(gdb)
1250            if (!(lp->failed_pvs = _failed_pv_list(lv->vg)))
(gdb)
703             if (!log_count)
(gdb)
1265            if (failed_mirrors) {
(gdb)
1262            if (lp->mirrors == 1)
(gdb)
1265            if (failed_mirrors) {
(gdb)
1272            if (!_lv_update_log_type(cmd, lp, lv, lp->failed_pvs,

The _lv_update_log_type at 1272 is already too late... it skips over the one at 1259.  Probably have to compile w/o optimization.

After attempting to remove the mirrored log
_lvconvert_mirrors_repair 
-> _lv_update_log_type
-> remove_mirror_log
-> _remove_mirror_images
-> replace_lv_with_error_segment - followed by suspend

Why is there no new table loaded for the _mlog, which should be an error target?
[from dmsetup ls]
vg-lv_mlog_mimage_1     (253, 3)
vg-lv_mlog      (253, 4)
vg-lv_mlog_mimage_0     (253, 2)

[from dmsetup info]
Name:              vg-lv_mlog
State:             SUSPENDED
Read Ahead:        256
Tables present:    LIVE

And after the resume, why do I have -missing_ devices?  What possible good are they?  Especially since they aren't used?
[from dmsetup ls]
vg-lv_mlog_mimage_1-missing_0_0 (253, 8)
vg-lv_mlog_mimage_1     (253, 3)
vg-lv_mlog      (253, 4)
vg-lv_mlog_mimage_0     (253, 2)
vg-lv_mlog_mimage_0-missing_0_0 (253, 9)

[from dmsetup table]
vg-lv_mlog_mimage_1-missing_0_0: 0 8192 error
vg-lv_mlog_mimage_1: 0 8192 linear 253:8 0
vg-lv_mlog: 0 8192 mirror core 3 1024 nosync block_on_error 2 253:2 0 253:3 0
vg-lv_mlog_mimage_0: 0 8192 linear 253:9 0
vg-lv_mlog_mimage_0-missing_0_0: 0 8192 error

Where did this behavior come from?

Jon, about gdb jumping around: you need to compile with -O0 instead of -O2 to get the runs straight. Optimized code does not usually follow the control flow of the program straightforwardly.

I will have a look at replace_lv_with_error_segment. Since you can reproduce this problem, do you think it would be possible to script this down as a regression test? It would be very valuable, both for hunting this down and for making sure it does not regress in the future... It seems you don't even need dmeventd to reproduce the problem, is that right?

Jon, what version are you using here? I can kill a mirrored log and have lvconvert --repair clean it up (and even replace the legs) here, without hitting any bugs. That is with the current CVS, although nothing has changed recently in this respect. The ...-missing_0_0 mappings do not appear (they may appear during the repair temporarily, but after it is done, there's no debris left).

I know about gdb (it's why I mentioned recompiling), but I'm trying to stick with the rpms.  I'll abandon the RPMs soon in favor of CVS head.

Versions:
lvm2-2.02.73-2.el5
lvm2-cluster-2.02.73-2.el5
device-mapper-multipath-0.4.7-39.el5
device-mapper-1.02.54-2.el5
device-mapper-event-1.02.54-2.el5

The components necessary to reproduce are:
1) mirror with a mirrored log [from comment #11 you have this]
2) I/O must be occurring at time of failure [I mount and do loops of kernel untars]
3) kill both devices containing the mirrored log

I know you are doing 1 & 3 - perhaps not 2?

Ok, I won't worry about the -missing_* mappings for now.  Even w/o that, there is still no new table for _mlog - which should be error after the above mentioned suspend.

Yes, the bug can be hit without going through dmeventd.  I move dmeventd so I can run 'lvconvert --repair' directly.

I should mention too that if you are going to run 'lvconvert --repair', I typically wait for 'dmsetup status' to show that the devices have failed before running the command (note the 'D's):
[root@bp-01 ~]# dmsetup status
vg-lv: 0 10485760 mirror 2 253:5 253:6 10240/10240 1 AA 3 disk 253:4 D
vg-lv_mimage_1: 0 10485760 linear
vg-lv_mimage_0: 0 10485760 linear
vg-lv_mlog_mimage_1-missing_0_0: 0 8192 error
vg-lv_mlog_mimage_1: 0 8192 linear
vg-lv_mlog: 0 8192 mirror 2 253:2 253:3 7/8 1 DD 1 core
vg-lv_mlog_mimage_0: 0 8192 linear
vg-lv_mlog_mimage_0-missing_0_0: 0 8192 error

The following change fixes the problem:

--- old-upstream/lib/metadata/mirror.c  2010-10-14 18:38:37.000000000 +0200
+++ new-upstream/lib/metadata/mirror.c  2010-10-14 18:38:37.000000000 +0200
@@ -905,6 +905,11 @@ static int _remove_mirror_images(struct 
                        return 0;
                }
 
+               if (!vg_write(detached_log_lv->vg)) {
+                       log_error("intermediate VG write failed.");
+                       return 0;
+               }
+
                /*
                 * Flush all I/Os held by mirrored log.
                 */
@@ -915,6 +920,12 @@ static int _remove_mirror_images(struct 
                        return 0;
                }
 
+               if (!vg_commit(detached_log_lv->vg)) {
+                       if (!resume_lv(detached_log_lv->vg->cmd, detached_log_lv))
+                               stack;
+                       return_0;
+               }
+
                if (!resume_lv(detached_log_lv->vg->cmd,
                               detached_log_lv)) {
                        log_error("Failed to resume %s",

Jon,

The H_S test case is "kill_both_logs_2_legs_2_logs". It doesn't show up because it's been commented out in lvm2/lib/helter_skelter/HS_Scenarios.pm due to this issue.

New patch created, tested, and sent to lvm-devel

Created attachment 453534 [details]
Patch that was sent to lvm-devel

Fix in lvm2-2.02.74-1.el5.

Fix verified in lvm2-2.02.74-1.el5.

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2011-0052.html