Bug 474174 - RHEL5 cmirror tracker: copy percentage of corelog mirror can get stuck during sync attempt (creation/conversion)
RHEL5 cmirror tracker: copy percentage of corelog mirror can get stuck during...
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: cmirror (Show other bugs)
5.3
All Linux
medium Severity medium
: rc
: ---
Assigned To: Jonathan Earl Brassow
Cluster QE
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-12-02 11:44 EST by Corey Marthaler
Modified: 2010-01-11 21:09 EST (History)
9 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2009-09-02 07:05:48 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Corey Marthaler 2008-12-02 11:44:23 EST
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
Comment 1 Corey Marthaler 2009-01-30 12:23:04 EST
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
Comment 2 Jonathan Earl Brassow 2009-02-10 16:32:53 EST
commit 337f12b719cb5dfb279317d2d111954c5c5c0416
Author: Jonathan Brassow <jbrassow@redhat.com>
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).
Comment 4 Corey Marthaler 2009-06-04 15:14:45 EDT
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]
Comment 5 Corey Marthaler 2009-06-11 11:47:01 EDT
Marking this back to assigned due to comment #4.
Comment 6 Tom Coughlan 2009-06-15 20:50:29 EDT
This will be a serious issue for HA customers. It would be good to get it in 5.4 if possible. Setting exception.
Comment 10 Jonathan Earl Brassow 2009-07-15 00:00:49 EDT
commit 6cf7dbc393d206e56a14261af81b1aeeb5bb160a
Author: Jonathan Brassow <jbrassow@redhat.com>
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);
Comment 12 Corey Marthaler 2009-08-06 11:49:37 EDT
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.
Comment 14 errata-xmlrpc 2009-09-02 07:05:48 EDT
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

Note You need to log in before you can comment on or make changes to this bug.