Bug 886989

Summary: Deleting relocated resource causes a lot of suspicious error messages in syslog
Product: Red Hat Enterprise Linux 6 Reporter: Jaroslav Kortus <jkortus>
Component: pacemakerAssignee: Andrew Beekhof <abeekhof>
Status: CLOSED ERRATA QA Contact: Cluster QE <mspqa-list>
Severity: high Docs Contact:
Priority: high    
Version: 6.4CC: cluster-maint, dvossel, mnovacek, tlavigne, uwe.knop
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: pacemaker-1.1.8-7.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-21 09:51:32 UTC Type: Bug
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: 768522    
Attachments:
Description Flags
crm_report from the time the resource actions were performed
none
crm_report for 1.1.8-5 none

Description Jaroslav Kortus 2012-12-13 18:48:05 UTC 
Description of problem:
Deleting relocated resource causes a lot of suspicious error messages in syslog.
The scary syslog snip:

Dec 13 12:40:17 marathon-03c1-node01 cib[10019]:    error: validate_cib_digest: Digest comparision failed: expected f5a12afaf9bb047635b00c036e86fc64 (/var/lib/pacemaker/cib/cib.hktXRh), calculated 27a226978c3fd64fda4ff3923ae7666f
Dec 13 12:40:17 marathon-03c1-node01 cib[10019]:    error: retrieveCib: Checksum of /var/lib/pacemaker/cib/cib.tt1iXX failed!  Configuration contents ignored!
Dec 13 12:40:17 marathon-03c1-node01 cib[10019]:    error: retrieveCib: Usually this is caused by manual changes, please refer to http://clusterlabs.org/wiki/FAQ#cib_changes_detected
Dec 13 12:40:17 marathon-03c1-node01 cib[10019]:    error: crm_abort: write_cib_contents: Triggered fatal assert at io.c:715 : cib_tmp != NULL
Dec 13 12:40:17 marathon-03c1-node01 abrt[10021]: /var/lib/pacemaker/cores//cores/core.marathon-03c1-node01.cib.10019 fd(-1) is not a regular file with link count 1: Permission denied
Dec 13 12:40:17 marathon-03c1-node01 abrt[10021]: Saved core dump of pid 10019 (/usr/libexec/pacemaker/cib) to /var/spool/abrt/ccpp-2012-12-13-12:40:17-10019 (10035200 bytes)
Dec 13 12:40:17 marathon-03c1-node01 abrtd: Directory 'ccpp-2012-12-13-12:40:17-10019' creation detected
Dec 13 12:40:17 marathon-03c1-node01 cib[9613]:   notice: cib_diskwrite_complete: Disk write process terminated with signal 6 (pid=10019, core=128)
Dec 13 12:40:17 marathon-03c1-node01 cib[9613]:    error: cib_diskwrite_complete: Disabling disk writes after write failure
Dec 13 12:40:17 marathon-03c1-node01 abrtd: Package 'pacemaker' isn't signed with proper key
Dec 13 12:40:17 marathon-03c1-node01 abrtd: 'post-create' on '/var/spool/abrt/ccpp-2012-12-13-12:40:17-10019' exited with 1
Dec 13 12:40:17 marathon-03c1-node01 abrtd: Corrupted or bad directory /var/spool/abrt/ccpp-2012-12-13-12:40:17-10019, deleting
Dec 13 12:40:17 marathon-03c1-node01 attrd[9616]:  warning: attrd_cib_callback: Update terminate=(null) failed: No such device or address
Dec 13 12:40:17 marathon-03c1-node01 cib[10024]:    error: validate_cib_digest: Digest comparision failed: expected 97256180de8e98b33104ed0e61d732d1 (/var/lib/pacemaker/cib/cib.aQpmem), calculated 433d2acd87e83bf234ef5b7eec03502a
Dec 13 12:40:17 marathon-03c1-node01 cib[10024]:    error: retrieveCib: Checksum of /var/lib/pacemaker/cib/cib.PNAcp0 failed!  Configuration contents ignored!
Dec 13 12:40:17 marathon-03c1-node01 cib[10024]:    error: retrieveCib: Usually this is caused by manual changes, please refer to http://clusterlabs.org/wiki/FAQ#cib_changes_detected
Dec 13 12:40:17 marathon-03c1-node01 cib[10024]:    error: crm_abort: write_cib_contents: Triggered fatal assert at io.c:715 : cib_tmp != NULL
Dec 13 12:40:17 marathon-03c1-node01 abrt[10025]: /var/lib/pacemaker/cores//cores/core.marathon-03c1-node01.cib.10024 fd(-1) is not a regular file with link count 1: Permission denied
Dec 13 12:40:17 marathon-03c1-node01 abrt[10025]: Not dumping repeating crash in '/usr/libexec/pacemaker/cib'
Dec 13 12:40:17 marathon-03c1-node01 cib[9613]:   notice: cib_diskwrite_complete: Disk write process terminated with signal 6 (pid=10024, core=128)
Dec 13 12:40:18 marathon-03c1-node01 crmd[9618]:  warning: decode_transition_key: Bad UUID (crm-resource-10020) in sscanf result (3) for 0:0:crm-resource-10020

Surprisingly the resource is deleted, can be recreated and everything seems working well.

These errors then re-appear also each time pacemaker is restarted.

I have also noticed the last line (Bad UUID) appearing when resources are removed. 

Version-Release number of selected component (if applicable):
pacemaker-1.1.8-4.el6.x86_64

How reproducible:
always

Steps to Reproduce:
1. setup 2-node cluster (cman+pacemaker)
2. create a resource (pcs resource create ClusterIP ocf:heartbeat:IPaddr2 params ip=192.168.101.101 cidr_netmask=32 op monitor interval=30s)
3. wait for it to start, then move it (pcs resource move ClusterIP)
4. wait for it to start on the other node, stop it (pcs resource stop ClusterIP)
5. remove the resource (pcs resource delete ClusterIP)
  
Actual results:
scary logging

Expected results:
no scary logging, it should behave as in the case where resource was not moved

Additional info:
Comment 1 Jaroslav Kortus 2012-12-13 18:49:42 UTC 
Created attachment 663115 [details]
crm_report from the time the resource actions were performed
Comment 3 David Vossel 2012-12-14 17:02:56 UTC 
Created attachment 663661 [details]
crm_report for 1.1.8-5

I updated the cluster to the new 1.1.8-5 build to see if this still occurred.  It definitely does.  I've uploaded a crm_report for 1.1.8-5.

-- Vossel
Comment 5 David Vossel 2012-12-14 18:46:10 UTC 
It appears that the 'pcs resource delete ClusterIP' performs two operations on the cib using cibadmin back to back.

cibadmin -c -R --xml-text "<constraints>"
cibadmin -o resources -D --xpath "//primitive[@id='ClusterIP']"


If I manually execute those two commands with a 2 second sleep between them instead of doing 'pcs resource delete ClusterIP', I do not see the digest error.  That seems to indicate that this is some sort of race condition.

-- Vossel
Comment 6 David Vossel 2012-12-17 23:27:04 UTC 
This isn't a race condition. Ignore my previous post.

We are allowing text nodes into the cib because of how pcs is deleting the constraint.  That causes validation problems later on.

A patch has been committed upstream for this.

https://github.com/ClusterLabs/pacemaker/commit/c2550cbd33a3b2ab7efcd6ef516ba124fbae9a81
Comment 8 Jaroslav Kortus 2013-01-22 15:57:50 UTC 
The scary logging is gone, everything in the reproducer works as expected, marking as verified with pacemaker-1.1.8-7.el6.x86_64.
Comment 10 errata-xmlrpc 2013-02-21 09:51:32 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2013-0375.html