Description of problem: This is very similar to bug 464550, but to my knowledge, this bz only affects corelog mirrors and unlike the sync hang in bug 464550, a simple write to the mirror will *not* start the sync back up. There doesn't not appear to be a hack around this sync hang. ================================================================================ Iteration 28.1 started at Mon Dec 1 18:57:32 CST 2008 ================================================================================ Scenario: Kill primary leg of synced core log 2 leg mirror(s) ****** Mirror hash info for this scenario ****** * name: syncd_primary_core_2legs * sync: 1 * num mirrors: 2 * disklog: 0 * failpv: /dev/sde1 * leg devices: /dev/sde1 /dev/sdf1 ************************************************ Creating mirror(s) on a2... a2: lvcreate --corelog -m 1 -n syncd_primary_core_2legs_1 -L 600M helter_skelter /dev/sde1:0-1000 /dev/sdf1:0-1000 Error locking on node a2: /dev/sdf1: open failed: No such device or address a2: lvcreate --corelog -m 1 -n syncd_primary_core_2legs_2 -L 600M helter_skelter /dev/sde1:0-1000 /dev/sdf1:0-1000 Error locking on node a2: /dev/sdf1: open failed: No such device or address Waiting until all mirrors become fully syncd... 0/2 mirror(s) are fully synced: ( 1=21.08% 2=0.08% ) 0/2 mirror(s) are fully synced: ( 1=99.33% 2=0.08% ) 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) After 10 minutes the mirror(s) are still not in sync HACKING AROUND BZ 464550 by dd'ing to each mirror in order to restart the stuck sync 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) 1/2 mirror(s) are fully synced: ( 1=100.00% 2=0.08% ) After 15 minutes the mirror(s) are still not in sync From the log: Dec 1 18:43:34 a1 qarshd[21355]: Running cmdline: lvcreate --corelog -m 1 -n syncd_primary_core_2legs_1 -L 600M helter_skelter /dev/sdd1:0-1000 /dev/sdf1:0-1000 Dec 1 18:43:34 a1 [27917]: Monitoring mirror device helter_skelter-syncd_primary_core_2legs_1 for events Dec 1 18:43:35 a1 xinetd[27083]: EXIT: qarsh status=0 pid=21355 duration=1(sec) Dec 1 18:43:35 a1 xinetd[27083]: START: qarsh pid=21423 from=10.15.80.47 Dec 1 18:43:35 a1 qarshd[21423]: Talking to peer 10.15.80.47:40895 Dec 1 18:43:35 a1 qarshd[21423]: Running cmdline: lvcreate --corelog -m 1 -n syncd_primary_core_2legs_2 -L 600M helter_skelter /dev/sdd1:0-1000 /dev/sdf1:0-1000 Dec 1 18:43:35 a1 kernel: clogd(27803): unaligned access to 0x6000000000003f14, ip=0x40000000000490d0 Dec 1 18:43:35 a1 kernel: clogd(27803): unaligned access to 0x6000000000003f14, ip=0x400000000004d2f1 Dec 1 18:43:35 a1 kernel: clogd(27803): unaligned access to 0x6000000000003f14, ip=0x400000000004d2f1 Dec 1 18:43:35 a1 kernel: clogd(27803): unaligned access to 0x6000000000003f14, ip=0x40000000000490d0 Dec 1 18:43:35 a1 kernel: clogd(27803): unaligned access to 0x6000000000003f14, ip=0x40000000000490d0 Dec 1 18:43:36 a1 lvm[27917]: Monitoring mirror device helter_skelter-syncd_primary_core_2legs_2 for events That said, I don't see this issue very often so this can be fixed in rhel5.4. Version-Release number of selected component (if applicable): 2.6.18-123.el5 lvm2-2.02.40-6.el5 BUILT: Fri Oct 24 07:40:11 CDT 2008 lvm2-cluster-2.02.40-6.el5 BUILT: Fri Oct 24 07:40:09 CDT 2008 device-mapper-1.02.28-2.el5 BUILT: Fri Sep 19 02:51:51 CDT 2008 cmirror-1.1.34-5.el5 BUILT: Thu Nov 6 15:11:03 CST 2008 kmod-cmirror-0.1.21-2.el5 BUILT: Thu Nov 6 14:12:57 CST 2008 How reproducible: every so often
Appear to have reproduced this issue with the latest binaries that Jon gave me. aiting until all mirrors become fully syncd... 0/3 mirror(s) are fully synced: ( 1=0.17% 2=6.75% 3=6.00% ) 0/3 mirror(s) are fully synced: ( 1=0.17% 2=26.00% 3=26.50% ) 0/3 mirror(s) are fully synced: ( 1=0.17% 2=46.33% 3=49.92% ) 0/3 mirror(s) are fully synced: ( 1=0.17% 2=67.42% 3=71.17% ) 0/3 mirror(s) are fully synced: ( 1=0.17% 2=86.25% 3=89.17% ) 2/3 mirror(s) are fully synced: ( 1=0.17% 2=100.00% 3=100.00% ) 2/3 mirror(s) are fully synced: ( 1=0.17% 2=100.00% 3=100.00% ) 2/3 mirror(s) are fully synced: ( 1=0.17% 2=100.00% 3=100.00% ) After 10 minutes the mirror(s) are still not in sync HACK AROUND BZ 464550 by dd'ing to the stuck mirrors in order to restart the sync process 2/3 mirror(s) are fully synced: ( 1=0.17% 2=100.00% 3=100.00% ) 2/3 mirror(s) are fully synced: ( 1=0.17% 2=100.00% 3=100.00% ) 2/3 mirror(s) are fully synced: ( 1=0.17% 2=100.00% 3=100.00% ) After 15 minutes the mirror(s) are still not in sync ADDITIONAL HACK AROUND BZ 474174 by suspending/resuming the dm devices in order to restart the sync process dmsetup suspend helter_skelter-syncd_primary_core_2legs_1 [root@taft-01 ~]# dmsetup status helter_skelter-syncd_primary_core_2legs_1: 0 1228800 mirror 2 253:2 253:3 2/1200 1 AA 1 clustered_core helter_skelter-syncd_primary_core_2legs_3_mimage_1: 0 1228800 linear helter_skelter-syncd_primary_core_2legs_3_mimage_0: 0 1228800 linear helter_skelter-syncd_primary_core_2legs_2_mimage_1: 0 1228800 linear helter_skelter-syncd_primary_core_2legs_2_mimage_0: 0 1228800 linear helter_skelter-syncd_primary_core_2legs_1_mimage_1: 0 1228800 linear helter_skelter-syncd_primary_core_2legs_1_mimage_0: 0 1228800 linear VolGroup00-LogVol01: 0 20447232 linear VolGroup00-LogVol00: 0 122421248 linear helter_skelter-syncd_primary_core_2legs_3: 0 1228800 mirror 2 253:8 253:9 1200/1200 1 AA 1 clustered_core helter_skelter-syncd_primary_core_2legs_2: 0 1228800 mirror 2 253:5 253:6 1200/1200 1 AA 1 clustered_core [root@taft-01 ~]# dmsetup info Name: helter_skelter-syncd_primary_core_2legs_1 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 1 Major, minor: 253, 4 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVUUb1JtqodWz1JJGs1POpcFpG1XNXiehK Name: helter_skelter-syncd_primary_core_2legs_3_mimage_1 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 9 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVJRKzZ2QRO7eBPljrs9tfW0XyCtr3ehop Name: helter_skelter-syncd_primary_core_2legs_3_mimage_0 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 8 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVpXxCEOf5GoCLpp3STimpygy5x0hmciM0 Name: helter_skelter-syncd_primary_core_2legs_2_mimage_1 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 6 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVVmyxPJV8a66Hezem3mdsMLsbN7R7brO0 Name: helter_skelter-syncd_primary_core_2legs_2_mimage_0 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 5 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVbUetUBrsRmkrz0Q7wRufJSrt5dhP3IkZ Name: helter_skelter-syncd_primary_core_2legs_1_mimage_1 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 3 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVu4Zu38U7EIAGAQ5AeeRdO7hXxkEvsMyj Name: helter_skelter-syncd_primary_core_2legs_1_mimage_0 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 2 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVNOD83CiR7YTKu6f5l12cjxyF22kvoLlx Name: VolGroup00-LogVol01 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 1 Number of targets: 1 UUID: LVM-FcjofzveOLp9CZfnSwCzJ2IKGFKI9LMO3g4feOuuBwdasmvBQedG1WPIf2W09T2L Name: VolGroup00-LogVol00 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 0 Major, minor: 253, 0 Number of targets: 1 UUID: LVM-FcjofzveOLp9CZfnSwCzJ2IKGFKI9LMOq1rsKQzclBBVUQWmCzY2pPMg8N7yr7QJ Name: helter_skelter-syncd_primary_core_2legs_3 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 2 Major, minor: 253, 10 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVNKlF4dMzM5L3Tb0HluuPyuM9rRcyRcqW Name: helter_skelter-syncd_primary_core_2legs_2 State: ACTIVE Read Ahead: 256 Tables present: LIVE Open count: 1 Event number: 2 Major, minor: 253, 7 Number of targets: 1 UUID: LVM-FNDAfHLfBFrbcOtEjwAkESZfDF3WUfTVJn1DV4XyTdVhSEqwT9eYayWs7Krfv7t1
commit 337f12b719cb5dfb279317d2d111954c5c5c0416 Author: Jonathan Brassow <jbrassow> Date: Tue Feb 10 15:27:59 2009 -0600 clogd: Fix bug 474174 - copy percentage of corelog mirror can get stuck Upon resuming, it was possible for the first resuming cluster node to send out checkpoints with state from a previous session before getting around to resetting its log state for the current session. This would cause the nodes in the cluster to disagree on what recovery work needed to be done. It could also result in some nodes reporting erroneous sync percentage ratios. The fix is to not send out checkpoints until the log has been properly initialized (now done through an explicit check).
I'm not certain if it's this bug or bug 491340 that I'm seeing, but there are still issues with core log mirrors not syncing properly. Scenario: Kill secondary leg of synced core log 4 leg mirror(s) ****** Mirror hash info for this scenario ****** * name: syncd_secondary_core_4legs * sync: 1 * num mirrors: 1 * disklog: 0 * failpv(s): /dev/sde1 * leg devices: /dev/sdf1 /dev/sde1 /dev/sdg1 /dev/sdd1 ************************************************ Creating mirror(s) on taft-04... taft-04: lvcreate --corelog -m 3 -n syncd_secondary_core_4legs_1 -L 600M helter_skelter /dev/sdf1:0-1000 /dev/sde1:0-1000 /dev/sdg1:0-1000 /dev/sdd1:0-1000 Waiting until all mirrors become fully syncd... 0/1 mirror(s) are fully synced: ( 1=1.42% ) 0/1 mirror(s) are fully synced: ( 1=27.58% ) 0/1 mirror(s) are fully synced: ( 1=48.42% ) 0/1 mirror(s) are fully synced: ( 1=79.08% ) 1/1 mirror(s) are fully synced: ( 1=100.00% ) Creating gfs on top of mirror(s) on taft-01... Mounting mirrored gfs filesystems on taft-01... Mounting mirrored gfs filesystems on taft-02... Mounting mirrored gfs filesystems on taft-03... Mounting mirrored gfs filesystems on taft-04... Writing verification files (checkit) to mirror(s) on... ---- taft-01 ---- ---- taft-02 ---- ---- taft-03 ---- ---- taft-04 ---- Sleeping 10 seconds to get some outsanding GFS I/O locks before the failure Verifying files (checkit) on mirror(s) on... ---- taft-01 ---- ---- taft-02 ---- ---- taft-03 ---- ---- taft-04 ---- Disabling device sde on taft-01 Disabling device sde on taft-02 Disabling device sde on taft-03 Disabling device sde on taft-04 Attempting I/O to cause mirror down conversion(s) on taft-04 10+0 records in 10+0 records out 41943040 bytes (42 MB) copied, 27.4864 seconds, 1.5 MB/s Verifying the down conversion of the failed mirror(s) /dev/sde1: open failed: No such device or address Verifying FAILED device /dev/sde1 is *NOT* in the volume(s) /dev/sde1: open failed: No such device or address Verifying LEG device /dev/sdf1 *IS* in the volume(s) /dev/sde1: open failed: No such device or address Verifying LEG device /dev/sdg1 *IS* in the volume(s) /dev/sde1: open failed: No such device or address Verifying LEG device /dev/sdd1 *IS* in the volume(s) /dev/sde1: open failed: No such device or address Verify the dm devices associated with /dev/sde1 are no longer present Verify that the mirror image order remains the same after the down conversion /dev/sde1: open failed: No such device or address /dev/sde1: open failed: No such device or address /dev/sde1: open failed: No such device or address /dev/sde1: open failed: No such device or address Verifying files (checkit) on mirror(s) on... ---- taft-01 ---- ---- taft-02 ---- ---- taft-03 ---- ---- taft-04 ---- Enabling device sde on taft-01 Enabling device sde on taft-02 Enabling device sde on taft-03 Enabling device sde on taft-04 Recreating PVs /dev/sde1 WARNING: Volume group helter_skelter is not consistent WARNING: Volume Group helter_skelter is not consistent WARNING: Volume group helter_skelter is not consistent Extending the recreated PVs back into VG helter_skelter Up converting linear(s) back to mirror(s) on taft-04... taft-04: lvconvert --corelog -m 3 -b helter_skelter/syncd_secondary_core_4legs_1 /dev/sdf1:0-1000 /dev/sde1:0-1000 /dev/sdg1:0-1000 /dev/sdd1:0-1000 Verifying the up conversion from linear(s) to mirror(s) Verifying device /dev/sdf1 *IS* one of the legs in the mirror(s) Verifying device /dev/sde1 *IS* one of the legs in the mirror(s) Verifying device /dev/sdg1 *IS* one of the legs in the mirror(s) Verifying device /dev/sdd1 *IS* one of the legs in the mirror(s) Verifying LOG device 0 *IS* in the mirror(s) Waiting until all mirrors become fully syncd... 0/1 mirror(s) are fully synced: ( 1=0.08% ) 0/1 mirror(s) are fully synced: ( 1=0.08% ) 0/1 mirror(s) are fully synced: ( 1=0.08% ) 0/1 mirror(s) are fully synced: ( 1=0.08% ) 0/1 mirror(s) are fully synced: ( 1=0.08% ) [stuck]
Marking this back to assigned due to comment #4.
This will be a serious issue for HA customers. It would be good to get it in 5.4 if possible. Setting exception.
commit 6cf7dbc393d206e56a14261af81b1aeeb5bb160a Author: Jonathan Brassow <jbrassow> Date: Wed Jul 8 17:16:19 2009 -0500 clogd: Fix for bugs 474174 and 491340 Whether to continue mirror recovery or not was being queued off of a variable that was set by doing (x - 1). However, when 'x' was 0 the result was a very large number (unsigned). When this large number was compared against the number of total regions in the mirror, it was determined that recovery was finished. The fix is simply to do: y = x ? (x - 1) : 0; instead of: y = (x - 1);
Have not seen this bug with the latest build (though we've seen plenty of other bugs that it could still potentially be hiding behind). Marking verified in cmirror-1.1.39-2.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/RHEA-2009-1340.html