Bug 623790 - cmirrord: Failed to open checkpoint: SA_AIS_ERR_NOT_EXIST
cmirrord: Failed to open checkpoint: SA_AIS_ERR_NOT_EXIST
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: corosync (Show other bugs)
6.0
All Linux
urgent Severity urgent
: rc
: ---
Assigned To: Steven Dake
Cluster QE
: Regression, TestBlocker
: 627297 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2010-08-12 15:05 EDT by Corey Marthaler
Modified: 2016-04-26 11:58 EDT (History)
13 users (show)

See Also:
Fixed In Version: corosync-1.2.3-20.el6
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2010-11-10 17:07:28 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
log from hayes-01 (96.23 KB, text/plain)
2010-08-12 15:11 EDT, Corey Marthaler
no flags Details
corosync-blackbox from grant-01.lab (2.10 MB, text/plain)
2010-08-16 19:10 EDT, Jonathan Earl Brassow
no flags Details
corosync-blackbox from grant-02.lab (2.13 MB, text/plain)
2010-08-16 19:11 EDT, Jonathan Earl Brassow
no flags Details
coro (2.12 MB, text/plain)
2010-08-16 19:11 EDT, Jonathan Earl Brassow
no flags Details
test case which may represent problem (4.27 KB, text/plain)
2010-08-16 21:19 EDT, Steven Dake
no flags Details
patch to fix problem (4.35 KB, patch)
2010-08-16 21:40 EDT, Steven Dake
no flags Details | Diff

  None (edit)
Description Corey Marthaler 2010-08-12 15:05:46 EDT
Description of problem:
This looks similar to the RHEL5 bug 566799.

./centipede -l /home/msp/cmarthal/work/rhel5/sts-root -r /usr/tests/sts-rhel6.0 -R ../../var/share/resource_files/hayes.xml
[...]
---------------------------------------------
TEST CASE=9
 base legs 2; convert to 2 legs;
 base log core; convert to core log;
 active 0; sync=0; pvs=sufficient
---------------------------------------------
creating a base mirror on hayes-01
  Error locking on node hayes-03: Command timed out
  Error locking on node hayes-01: Command timed out
  Aborting. Failed to activate new LV to wipe the start of it.
  Error locking on node hayes-03: Command timed out
  Error locking on node hayes-01: Command timed out
  Unable to deactivate failed new LV. Manual intervention required.

LOG:
Aug 12 10:44:13 hayes-01 qarshd[4453]: Running cmdline: lvcreate -n centi_base --mirrorlog core -m 2 -L 700M centipede
Aug 12 10:44:16 hayes-01 cmirrord[2202]: [nPg6x3kz] Failed to open checkpoint: SA_AIS_ERR_NOT_EXIST
Aug 12 10:44:16 hayes-01 cmirrord[2202]: [nPg6x3kz] Failed to import checkpoint from 2
Aug 12 10:44:16 hayes-01 cmirrord[2202]:
Aug 12 10:44:16 hayes-01 cmirrord[2202]: LOG COMPONENT DEBUGGING::
Aug 12 10:44:16 hayes-01 cmirrord[2202]: Official log list:
Aug 12 10:44:16 hayes-01 cmirrord[2202]: Pending log list:
Aug 12 10:44:16 hayes-01 cmirrord[2202]: LVM-r6lPqIa5zQ9v1CeOkjYoAen2GMz3g0iAPN6ijCK6SRedqtVioRvNZ1aTnPg6x3kz
Aug 12 10:44:16 hayes-01 cmirrord[2202]:   recoverer        : 0
Aug 12 10:44:16 hayes-01 cmirrord[2202]:   recovering_region: 18446744073709551615
Aug 12 10:44:16 hayes-01 cmirrord[2202]:   recovery_halted  : NO

I'll attach the rest of the logs...

Version-Release number of selected component (if applicable):
2.6.32-59.1.el6.x86_64

lvm2-2.02.72-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
lvm2-libs-2.02.72-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
lvm2-cluster-2.02.72-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
udev-147-2.22.el6    BUILT: Fri Jul 23 07:21:33 CDT 2010
device-mapper-1.02.53-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
device-mapper-libs-1.02.53-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
device-mapper-event-1.02.53-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
device-mapper-event-libs-1.02.53-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
cmirror-2.02.72-7.el6    BUILT: Wed Aug 11 17:12:24 CDT 2010
Comment 1 Corey Marthaler 2010-08-12 15:11:09 EDT
Created attachment 438509 [details]
log from hayes-01
Comment 2 Corey Marthaler 2010-08-12 15:14:46 EDT
I hit this on another cluster when attempting to start the clvmd init scripts with an existing mirror.

Aug 12 10:20:59 grant-03 lvm[2203]: Monitoring mirror device centipede-centi_base for events.
Aug 12 10:21:03 grant-03 cmirrord[2141]: [TGcIbDFm] Failed to open checkpoint for 2: SA_AIS_ERR_NOT_EXIST
Aug 12 10:21:03 grant-03 cmirrord[2141]: [TGcIbDFm] Failed to export checkpoint for 2
Aug 12 10:21:18 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/221] - retrying
Aug 12 10:21:33 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/224] - retrying
Aug 12 10:21:48 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/225] - retrying
Aug 12 10:22:03 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/226] - retrying
Aug 12 10:22:06 grant-03 cmirrord[2141]: Sync checkpoint section creation failed: SA_AIS_ERR_NOT_EXIST
Aug 12 10:22:06 grant-03 cmirrord[2141]: [TGcIbDFm] Failed to export checkpoint for 1
Aug 12 10:22:18 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/227] - retrying
Aug 12 10:22:33 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/228] - retrying
Aug 12 10:22:48 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/229] - retrying
Aug 12 10:23:03 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/230] - retrying
Aug 12 10:23:18 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/231] - retrying
Aug 12 10:23:33 grant-03 kernel: device-mapper: dm-log-userspace: [TGcIbDFm] Request timed out: [9/232] - retrying
Comment 3 Jonathan Earl Brassow 2010-08-13 11:43:55 EDT
This seems like an issue that would be related to when cmirror/clvmd scripts are started WRT each other, and how they are re-cycled.

Is there a simple reproducer?  How often does it happen?  The consequences of the bug seem pretty severe, but I'd like more info to gauge the urgency of the issue.
Comment 4 Corey Marthaler 2010-08-13 13:22:07 EDT
Hmmm, just hit this again on test case #9, must be something special with this conversion/creation.

---------------------------------------------
TEST CASE=9
 base legs 2; convert to 2 legs;
 base log disk; convert to disk log;
 active 0; sync=1; pvs=sufficient
---------------------------------------------
creating a base mirror on hayes-02
  Error locking on node hayes-02: Command timed out
  Aborting. Failed to activate new LV to wipe the start of it.
  Error locking on node hayes-03: Command timed out
  Error locking on node hayes-02: Command timed out
  Unable to deactivate failed new LV. Manual intervention required.
Comment 5 Corey Marthaler 2010-08-13 18:11:19 EDT
This appears to be a fairly major regression from the previous build. I went back to the 2.02.72-6 build and verified that this test case worked there.

This bug need the 6.0 and blocker flag set.
Comment 8 Corey Marthaler 2010-08-16 18:57:19 EDT
I said 'similar to the RHEL5 bug 566799'. :) 

I'm not positive that's it the same, in fact I'd bet that it's not. This issues didn't appear to exist until the very last build, at which point tests that had previous been working started failing quite easily.
Comment 10 Jonathan Earl Brassow 2010-08-16 19:10:28 EDT
Created attachment 439026 [details]
corosync-blackbox from grant-01.lab
Comment 11 Jonathan Earl Brassow 2010-08-16 19:11:17 EDT
Created attachment 439027 [details]
corosync-blackbox from grant-02.lab
Comment 12 Jonathan Earl Brassow 2010-08-16 19:11:41 EDT
Created attachment 439028 [details]
coro
Comment 13 Jonathan Earl Brassow 2010-08-16 19:15:34 EDT
grant-01 was the machine that incurred the following errors:
Aug 16 17:04:44 grant-01 cmirrord[13915]: Clean checkpoint section creation failed: SA_AIS_ERR_LIBRARY
Aug 16 17:04:45 grant-01 cmirrord[13915]: [vXeHaaML] Failed to export checkpoint for 2
Aug 16 17:04:45 grant-01 cmirrord[13915]: Sync checkpoint section creation failed: SA_AIS_ERR_NOT_EXIST
Aug 16 17:04:45 grant-01 cmirrord[13915]: [vXeHaaML] Failed to export checkpoint for 3
Comment 14 Steven Dake 2010-08-16 21:19:14 EDT
Created attachment 439039 [details]
test case which may represent problem
Comment 15 Steven Dake 2010-08-16 21:27:57 EDT
After speaking with Jon, it appears he is getting a CPG_ERR_LIBRARY return code first and then bad things happen.

The test case in attachment #14 [details] is meant to be run as follows:
run cluster on 2 nodes in foreground (aisexec -f)
start ckptbench.c (compiled into openais tree)
it will sleep for 5 seconds.  while it is sleeping, press ctrl-z (to background the corosync process).  (ctrl-c will gracefully exit)

This triggers a 10 second configuration change where ipc is blocked.

Then the test case tries to do a sectioncreate which returns ERR_LIBRARY.

The root of the problem is that openais follows a design pattern where ipc messages are not responded to during configuration changes to enable correctness.

Our ipc system uses a semaphore timeout operation.  This is to allow ipc clients to detect that the server has failed in some way and return an error.
Comment 17 Steven Dake 2010-08-16 21:40:53 EDT
Created attachment 439045 [details]
patch to fix problem
Comment 21 Steven Dake 2010-08-18 15:40:09 EDT
missing %patch from spec file caused qa failure on -19.
Comment 22 Corey Marthaler 2010-08-18 18:00:26 EDT
This bug appears to be fixed in the latest build, however I'm going to let the tests run all night be for marking verified.
Comment 23 Corey Marthaler 2010-08-19 12:13:12 EDT
Tests ran all night (albeit rather slowly). Marking verified in the latest rpms.

2.6.32-59.1.el6.x86_64

corosync-1.2.3-20.el6.x86_64

lvm2-2.02.72-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
lvm2-libs-2.02.72-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
lvm2-cluster-2.02.72-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
udev-147-2.22.el6    BUILT: Fri Jul 23 07:21:33 CDT 2010
device-mapper-1.02.53-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
device-mapper-libs-1.02.53-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
device-mapper-event-1.02.53-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
device-mapper-event-libs-1.02.53-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
cmirror-2.02.72-8.el6    BUILT: Wed Aug 18 10:41:52 CDT 2010
Comment 24 Nate Straz 2010-08-25 15:27:58 EDT
*** Bug 627297 has been marked as a duplicate of this bug. ***
Comment 25 releng-rhel@redhat.com 2010-11-10 17:07:28 EST
Red Hat Enterprise Linux 6.0 is now available and should resolve
the problem described in this bug report. This report is therefore being closed
with a resolution of CURRENTRELEASE. You may reopen this bug report if the
solution does not work for you.
Comment 26 Nate Straz 2011-06-02 11:16:34 EDT
*** Bug 627297 has been marked as a duplicate of this bug. ***

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