Bug 217895
Summary: | lost election results from cmirror server cause mirror activation deadlock | ||||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|---|---|
Product: | [Retired] Red Hat Cluster Suite | Reporter: | Corey Marthaler <cmarthal> | ||||||||||
Component: | cmirror | Assignee: | Jonathan Earl Brassow <jbrassow> | ||||||||||
Status: | CLOSED ERRATA | QA Contact: | Cluster QE <mspqa-list> | ||||||||||
Severity: | high | Docs Contact: | |||||||||||
Priority: | high | ||||||||||||
Version: | 4 | CC: | agk, dwysocha, mbroz, prockai | ||||||||||
Target Milestone: | --- | Keywords: | TestBlocker | ||||||||||
Target Release: | --- | ||||||||||||
Hardware: | All | ||||||||||||
OS: | Linux | ||||||||||||
Whiteboard: | |||||||||||||
Fixed In Version: | RHBA-2008-0803 | Doc Type: | Bug Fix | ||||||||||
Doc Text: | Story Points: | --- | |||||||||||
Clone Of: | Environment: | ||||||||||||
Last Closed: | 2008-07-25 19:27:59 UTC | Type: | --- | ||||||||||
Regression: | --- | Mount Type: | --- | ||||||||||
Documentation: | --- | CRM: | |||||||||||
Verified Versions: | Category: | --- | |||||||||||
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||||
Cloudforms Team: | --- | Target Upstream Version: | |||||||||||
Embargoed: | |||||||||||||
Bug Depends On: | |||||||||||||
Bug Blocks: | 227155, 362691 | ||||||||||||
Attachments: |
|
Description
Corey Marthaler
2006-11-30 17:25:57 UTC
I can't seem to reproduce this, but I'm not convinced it is gone. Requesting help in reproducing. Reproduced this issue along with bz 207132 last night doing looping create/convert/remove cmirror operations. Saw this on all the nodes in the cluster except the node which had the messages seen in bz 207132. So these two bugs are most likely related. dm-cmirror: Failed to receive election results from server: -110 I fixed a race where critical variables (restart_event_id/restart_event_type) could be overwritten by the server after a client had set them. This would cause the kcl_start_done issued by the server to fail. It would loose the ability to acknowledge the start and the cluster mirror would stall... This has all sorts of side-effects, including never being able to reach the server. I wonder if I hit one of the side effects mentioned in comment #4, I was doing different cmirror operations on different nodes in the cluster and saw that the device-mapper devices were still around for a cmirror on one of the nodes after it had been deactivated. Should this issue be opened as another bz? Mar 8 03:31:54 taft-01 qarshd[25508]: Running cmdline: lvchange -an hang/taft-01.28863 Mar 8 03:31:54 taft-01 lvm[5026]: Monitoring mirror device hang-taft--04.28866 for events Mar 8 03:32:05 taft-01 lvm[5026]: Monitoring mirror device hang-taft--03.28869 for events Mar 8 03:32:07 taft-01 kernel: dm-cmirror: Clean-up required due to new server Mar 8 03:32:07 taft-01 kernel: dm-cmirror: - Wiping clear region list Mar 8 03:32:07 taft-01 kernel: dm-cmirror: - 1 clear region requests wiped Mar 8 03:32:07 taft-01 kernel: dm-cmirror: - Resending all mark region requests Mar 8 03:32:07 taft-01 kernel: dm-cmirror: Clean-up complete Mar 8 03:32:07 taft-01 kernel: dm-cmirror: Continuing request type, 7 (LRT_COMPLETE_RESYNC_WORK) Mar 8 03:32:07 taft-01 kernel: dm-cmirror: Error while listening for server response: -110 Mar 8 03:32:07 taft-01 kernel: dm-cmirror: Clustered mirror retried requests :: 1280 of 1683741 (1%) Mar 8 03:32:07 taft-01 kernel: dm-cmirror: Too many retries, attempting to re-establish server connection. Mar 8 03:32:07 taft-01 kernel: dm-cmirror: Failed to receive election results from server: (7ta2WQra,-110) Mar 8 03:32:07 taft-01 lvm[5026]: dm_task_run failed, errno = 6, No such device or address Mar 8 03:32:07 taft-01 lvm[5026]: hang-taft--01.28863 disappeared, detaching Mar 8 03:32:08 taft-01 kernel: dm-cmirror: Clean-up required due to new server Mar 8 03:32:08 taft-01 kernel: dm-cmirror: - Wiping clear region list Mar 8 03:32:08 taft-01 kernel: dm-cmirror: - 0 clear region requests wiped Mar 8 03:32:08 taft-01 kernel: dm-cmirror: - Resending all mark region requests Mar 8 03:32:08 taft-01 kernel: dm-cmirror: Clean-up complete Mar 8 03:32:08 taft-01 kernel: dm-cmirror: Continuing request type, 6 (LRT_GET_RESYNC_WORK) Mar 8 03:32:08 taft-01 kernel: dm-cmirror: Clean-up required due to new server Mar 8 03:32:08 taft-01 kernel: dm-cmirror: - Wiping clear region list Mar 8 03:32:08 taft-01 kernel: dm-cmirror: - 1 clear region requests wiped Mar 8 03:32:08 taft-01 kernel: dm-cmirror: - Resending all mark region requests Mar 8 03:32:08 taft-01 kernel: dm-cmirror: Clean-up complete Mar 8 03:32:08 taft-01 kernel: dm-cmirror: Continuing request type, 7 (LRT_COMPLETE_RESYNC_WORK) Mar 8 03:32:08 taft-01 lvm[5026]: dm_task_run failed, errno = 6, No such device or address Mar 8 03:32:08 taft-01 lvm[5026]: hang-taft--04.28866 disappeared, detaching [root@taft-01 ~]# lvs LV VG Attr LSize Origin Snap% Move Log Copy% LogVol00 VolGroup00 -wi-ao 66.16G LogVol01 VolGroup00 -wi-ao 1.94G taft-01.28863 hang mwi--- 500.00M taft-01.28863_mlog taft-02.28860 hang mwi--- 500.00M taft-02.28860_mlog taft-03.28869 hang mwi-a- 500.00M taft-03.28869_mlog 100.00 taft-04.28866 hang mwi--- 500.00M taft-04.28866_mlog [root@taft-01 ~]# dmsetup ls hang-taft--03.28869_mlog (253, 15) hang-taft--03.28869_mimage_3 (253, 20) hang-taft--03.28869_mimage_2 (253, 19) hang-taft--02.28860_mimage_1 (253, 4) hang-taft--03.28869_mimage_1 (253, 17) hang-taft--02.28860_mimage_0 (253, 3) hang-taft--03.28869_mimage_0 (253, 16) hang-taft--04.28866_mimage_3 (253, 14) hang-taft--04.28866_mimage_2 (253, 13) hang-taft--02.28860_mlog (253, 2) hang-taft--04.28866_mimage_1 (253, 11) hang-taft--04.28866_mimage_0 (253, 10) hang-taft--01.28863_mlog (253, 6) VolGroup00-LogVol01 (253, 1) hang-taft--03.28869 (253, 22) VolGroup00-LogVol00 (253, 0) hang-taft--01.28863_mimage_1 (253, 8) hang-taft--04.28866_mlog (253, 9) hang-taft--01.28863_mimage_0 (253, 7) [root@taft-02 ~]# lvs LV VG Attr LSize Origin Snap% Move Log Copy% LogVol00 VolGroup00 -wi-ao 66.16G LogVol01 VolGroup00 -wi-ao 1.94G taft-01.28863 hang mwi--- 500.00M taft-01.28863_mlog taft-02.28860 hang mwi--- 500.00M taft-02.28860_mlog taft-03.28869 hang mwi-a- 500.00M taft-03.28869_mlog 100.00 taft-04.28866 hang mwi--- 500.00M taft-04.28866_mlog [root@taft-02 ~]# dmsetup ls hang-taft--03.28869_mlog (253, 15) hang-taft--03.28869_mimage_3 (253, 20) hang-taft--03.28869_mimage_2 (253, 19) hang-taft--03.28869_mimage_1 (253, 17) hang-taft--03.28869_mimage_0 (253, 16) VolGroup00-LogVol01 (253, 1) hang-taft--03.28869 (253, 22) VolGroup00-LogVol00 (253, 0) [root@taft-03 ~]# lvs LV VG Attr LSize Origin Snap% Move Log Copy% LogVol00 VolGroup00 -wi-ao 66.16G LogVol01 VolGroup00 -wi-ao 1.94G taft-01.28863 hang mwi--- 500.00M taft-01.28863_mlog taft-02.28860 hang mwi--- 500.00M taft-02.28860_mlog taft-03.28869 hang mwi-a- 500.00M taft-03.28869_mlog 100.00 taft-04.28866 hang mwi--- 500.00M taft-04.28866_mlog [root@taft-03 ~]# dmsetup ls hang-taft--03.28869_mlog (253, 15) hang-taft--03.28869_mimage_3 (253, 20) hang-taft--03.28869_mimage_2 (253, 19) hang-taft--03.28869_mimage_1 (253, 17) hang-taft--03.28869_mimage_0 (253, 16) VolGroup00-LogVol01 (253, 1) hang-taft--03.28869 (253, 22) VolGroup00-LogVol00 (253, 0) [root@taft-04 ~]# lvs LV VG Attr LSize Origin Snap% Move Log Copy% LogVol00 VolGroup00 -wi-ao 66.16G LogVol01 VolGroup00 -wi-ao 1.94G taft-01.28863 hang mwi--- 500.00M taft-01.28863_mlog taft-02.28860 hang mwi--- 500.00M taft-02.28860_mlog taft-03.28869 hang mwi-a- 500.00M taft-03.28869_mlog 100.00 taft-04.28866 hang mwi--- 500.00M taft-04.28866_mlog [root@taft-04 ~]# dmsetup ls hang-taft--03.28869_mlog (253, 15) hang-taft--03.28869_mimage_3 (253, 20) hang-taft--03.28869_mimage_2 (253, 19) hang-taft--03.28869_mimage_1 (253, 17) hang-taft--03.28869_mimage_0 (253, 16) VolGroup00-LogVol01 (253, 1) hang-taft--03.28869 (253, 22) VolGroup00-LogVol00 (253, 0) I was attempting to reproduce bz 231230, and ended up hitting a case similar to this problem. I had a very basic cmirror, 2 legs, 10G, no fs on top, no I/O running, and I failed the primary leg of the cmirror while the mirror was still syncing. This caused a lost of elections results and ended up causing a node in the cluster to be fenced. [...] Mar 15 07:17:09 link-02 kernel: end_request: I/O error, dev sda, sector 10165809 Mar 15 07:17:09 link-02 kernel: SCSI error : <0 0 0 1> return code = 0x10000 Mar 15 07:17:09 link-02 kernel: end_request: I/O error, dev sda, sector 10165817 Mar 15 07:17:09 link-02 kernel: device-mapper: Unable to read from primary mirror during recovery Mar 15 07:17:09 link-02 kernel: device-mapper: recovery failed on region 9911 Mar 15 07:17:27 link-02 kernel: dm-cmirror: Failed to receive election results from server: (TKbs5wES,-110) Mar 15 07:17:39 link-02 fenced[4519]: link-08 not a cluster member after 30 sec post_fail_delay Mar 15 07:17:39 link-02 fenced[4519]: fencing node "link-08" Mar 15 07:17:47 link-02 kernel: dm-cmirror: Failed to receive election results from server: (TKbs5wES,-110) Mar 15 07:17:59 link-02 fenced[4519]: fence "link-08" success Mar 15 07:18:06 link-02 kernel: dm-cmirror: A cluster mirror log member has failed. Mar 15 07:18:07 link-02 kernel: dm-cmirror: Failed to receive election results from server: (TKbs5wES,-110) A write attempt to this mirror inorder to trigger the down convert fails: [root@link-07 ~]# dd if=/dev/zero of=/dev/helter_skelter/mirror count=10 dd: writing to `/dev/helter_skelter/mirror': Input/output error 1+0 records in 0+0 records out I'll attach the clvmd debug logs Created attachment 150149 [details]
clvmd -d log from link-02
Created attachment 150150 [details]
clvmd -d log from link-04
Created attachment 150151 [details]
clvmd -d log from link-07
Created attachment 150152 [details]
clvmd -d log from link-08
We know now that the dd command used to trigger the down convert does not work because it does reads before writes. Doing real writes should trigger the convert. The issue now is, why did a node get fenced? Note: It is not a problem to recieve a few of these: dm-cmirror: Failed to receive election results It is a problem if it never recovers from it. Please reproduce so we can determine why the member got fenced. Is something else going on that might trigger that? assigned -> needinfo I think the root cause of this has been fixed since I marked it 'needinfo' needinfo -> modified I have not seen any "failed election results" messages for quite awhile, and there are other bugs to document a cmirror operations deadlock. Marking this bz verified. I may have spoken too soon. I appear to have hit this while doing IO to 4 mirrors from 4 vgs while at the same time doing disk to core log (and back) converts. The scenario in comment #15 reliably reproduces this bug. This still appears to be reproducable (that or this is a new bug). I was attempting something similar to that in comment #15 with I/O to two cmirrors each on a different vg, all while converting to and from disk log and core log. After a couple successful converts, it failed with locking errors. Error locking on node grant-03: Command timed out Error locking on node link-08: Command timed out Failed to lock mirror1 The devices in that mirror failed convert mirror are now suspended: mirror1 vg1 Mwi-so 15.00G 100.00 mirror1_mimage_0(0),mirror1_mimage_1(0) [mirror1_mimage_0] vg1 iwi-so 15.00G /dev/sdb1(0) [mirror1_mimage_1] vg1 iwi-so 15.00G /dev/sdc1(0) mirror1_mlog vg1 -wi--- 4.00M /dev/sdd1(0) On the consoles where thelocks failed (link-08 and grant-03), I'm seeing a steady stream of cmirror server messages... Nov 8 16:20:09 link-08 kernel: dm-cmirror: Too many retries, attempting to re-establish server connection. Nov 8 16:20:09 link-08 kernel: dm-cmirror: Clustered mirror retried requests :: 5223200 of 5244922 (100%) Nov 8 16:20:09 link-08 kernel: dm-cmirror: Too many retries, attempting to re-establish server connection. Nov 8 16:20:09 link-08 kernel: dm-cmirror: Clustered mirror retried requests :: 5223264 of 5244986 (100%) Nov 8 16:20:09 link-08 kernel: dm-cmirror: Too many retries, attempting to re-establish server connection. Nov 8 16:20:09 link-08 kernel: dm-cmirror: Clustered mirror retried requests :: 5223296 of 5245018 (100%) Nov 8 16:20:09 link-08 kernel: dm-cmirror: Too many retries, attempting to re-establish server connection. Nov 8 16:20:09 link-08 kernel: dm-cmirror: Clustered mirror retried requests :: 5223328 of 5245050 (100%) Nov 8 16:20:09 link-08 kernel: dm-cmirror: Too many retries, attempting to re-establish server connection Hit this bug during 4.6 regression tesing. Hit this bug during 4.6.Z regression testing. Bumping the priority and marking this as a TestBlocker, since this is stopping us from verifying other cmirror bug fixes. Looks like I've hit this in the current 4.6.Z testing. lvm2-cluster-2.02.27-2.el4_6.1 lvm2-cluster-debuginfo-2.02.27-2.el4_6.1 lvm2-debuginfo-2.02.27-2.el4_6.1 lvm2-2.02.27-2.el4_6.1 device-mapper-1.02.21-1.el4 I see many of these messages on the consoles while running [lvm_cluster_cmirror_lock_stress]: dm-cmirror: Failed to receive election results from server: (k1SECe8j/1,-110) And my tests are stuck at this point. The tests running: <herd name="lock_stress_cmirror" desc="lock_stress some mirrors" version="1"> <pan2_opts numactive="all" allstop="true" iterations="5"/> <test name="link-13_1"> <cmd timeout="450">/usr/tests/sts-rhel4.6/lvm2/bin/lock_ops -n link-13 -v lock_stress</cmd> </test> <test name="link-14_1"> <cmd timeout="450">/usr/tests/sts-rhel4.6/lvm2/bin/lock_ops -n link-14 -v lock_stress</cmd> </test> <test name="link-16_1"> <cmd timeout="450">/usr/tests/sts-rhel4.6/lvm2/bin/lock_ops -n link-16 -v lock_stress</cmd> </test> </herd> This hasn't been seen in over 6 months. Marking verified. Will re-open if seen again. 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 the 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-2008-0803.html |