Unnecessary recopies w/ChecksumDatabase (I think)

[Wil Cooley]

I've been running up against some buggery with 2.1.14 using
ChecksumDatabase in cfservd.conf.  It seems that some of my files
periodically get recopied for no apparent reason.  My cfservd.conf has
the checksum database /var/cfengine/cache.db and cfagent defaults as
usual to /var/cfengine/checksum.db.  I have a basic setup with only a
single fileserver.  I have DefaultCopyType set to checksum.

Before I post the debug output, here are a few items:
 o It's kind of a pain to debug this kind of thing, because there's not
a way to pass parameters from cfexecd to cfagent or variables to set for
cfagent to enable debugging output.  I had to just manually run cfrun
over and over while testing, which took a lot more attention than it
needed to.

 o I wanted to look at the contents of my cache.db file, but since
cfshow doesn't take parameters for -c, I ended up writing a little Perl
script to do it.  Now that I've done it and looked at the source code
enough, I could probably implement it in cfshow, but I'll probably not
get around to it.  Anyway, here's a Perl script for anyone wanting to
examine his checksum databases:

http://haus.nakedape.cc/svn/public/trunk/small-projects/cfengine-utils/cfchecksumdb.pl

You'd have to know whether your checksums are MD5 or SHA to feed its
output into md5sum or sha1sum.

 o It'd be nice if the logging about this kind of thing was more
explicit, such as including the checksums from both the local and the
server versions of the files.  I guess cfagent sends the checksum to
server, which replies with "good" or "bad", so I'd really need that
logged in the server.  Running cfservd on my main server in debug mode
doesn't sound like it would be useful; it already logs more than I can
keep up with.

 o Since I've disabled ChecksumDatabase in cfservd.conf, I haven't seen
the spontaneous re-copying I saw previously.  It's been nearly 4 hours
so far.

Here's the section the actually performs the copy; nothing especially
interesting about it:
-------------------------------------------
copy:
    ${configroot}/${site}/${host}/snmpd.local.conf
        dest=/etc/snmp/snmpd.local.conf
        server=${cfserver}
        owner=root group=root mode=0440
        define=snmpd_needs_restart,snmpd_local_conf_updated
        timestamps=preserve
        inform=true
        backup=true
        verify=true
        action=fix
-------------------------------------------

The timestamps, inform, explicit backup and verify were all added in an
attempt to debug this problem.

Here's one run where snmpd.local.conf is changed in the repository and
is supposed to be copied.  Despite the "new file ... seems to have been
corrupted in transit, aborting!" message, it does seem to actually get
copied--I verified right after I ran it. It's possible that a scheduled
run happened right after my manual run and updated it.

-------------------------------------------
ExpandVarstring(cfserver.example.com)
ExpandVarstring(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
ExpandVarstring(/etc/snmp/snmpd.local.conf)
Checking copy from 
cfserver.example.com:/srv/hostconfig/internal/cfclient/snmpd.local.conf to 
/etc/snmp/snmpd.local.conf
ExpandVarstring(cfserver.example.com)
Server connection to cfserver.example.com already open on 4
Authentic connection verified
cf_rstat(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
GetCachedStatData(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
Did not find in cache
Transaction Send[t 67][Packed text]
Attempting to send 75 bytes
SendSocketStream, sent 75
RecvSocketStream(8)
    (Concatenated 8 from stream)
Transaction Receive [t 71][]
RecvSocketStream(71)
    (Concatenated 71 from stream)
Mode = 436,0
OK: type=0
 mode=664
 lmode=0
 uid=109
 gid=109
 size=94
 atime=1121199793
 mtime=1121198839 ino=26705 nlnk=1, dev=14848
RecvSocketStream(8)
    (Concatenated 8 from stream)
Transaction Receive [t 3][]
RecvSocketStream(3)
    (Concatenated 3 from stream)
Linkbuffer: OK:
GetLock(copy,_srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com,time=1121200728),
 ExpireAfter=120, IfElapsed=1
GetLastLock()
CheckOldLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
Unable to find lock data 
lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923
SetLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
PutLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
Found no lock 
[lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923]:
 DB_NOTFOUND: No matching key/data pair found
Directory for /etc/snmp/snmpd.local.conf exists. Okay
CheckImage (source=/srv/hostconfig/internal/cfclient/snmpd.local.conf 
destination=/etc/snmp/snmpd.local.conf)
cf_rstat(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
GetCachedStatData(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
Found in cache
ImageCopy(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf,+440,-7337)
ExpandVarstring(cfserver.example.com)
IgnoredOrExcluded(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
file /etc/snmp/snmpd.local.conf class any was not excluded
Destination file /etc/snmp/snmpd.local.conf exists
CompareCheckSums(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf)
File sizes differ, no need to compute checksum
lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923:cfengine:cfclient:
 Update of image /etc/snmp/snmpd.local.conf from master 
/srv/hostconfig/internal/cfclient/snmpd.local.conf on cfserver.example.com
AddMultipleClasses(snmpd_needs_restart,snmpd_local_conf_updated)
AddClassToHeap(snmpd_needs_restart)
Appending [snmpd_needs_restart]
AddClassToHeap(snmpd_local_conf_updated)
Appending [snmpd_local_conf_updated]
CopyReg(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf)
This is a remote copy from server: cfserver.example.com
Transaction Send[t 54][Packed text]
Attempting to send 62 bytes
SendSocketStream, sent 62
RecvSocketStream(94)
    (Concatenated 94 from stream)
End of CopyNetReg
CopyReg succeeded in copying to 
/srv/hostconfig/internal/cfclient/snmpd.local.conf to 
/etc/snmp/snmpd.local.conf.cfnew
Final verification of transmission.
CompareCheckSums(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf.cfnew)
Compare checksums on 
cfserver.example.com:/srv/hostconfig/internal/cfclient/snmpd.local.conf & 
/etc/snmp/snmpd.local.conf.cfnew
ChecksumFile(m,/etc/snmp/snmpd.local.conf.cfnew)
Send digest of /etc/snmp/snmpd.local.conf.cfnew to server, 
MD5=a2a165652b9489d628ae526e496d6bc8
Transaction Send[t 67][Packed text]
Attempting to send 75 bytes
SendSocketStream, sent 75
RecvSocketStream(8)
    (Concatenated 8 from stream)
Transaction Receive [t 8][]
RecvSocketStream(8)
    (Concatenated 8 from stream)
MD5 mismatch: (reply - CFD_TRUE)
lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923:cfengine:cfclient:
 WARNING: new file /etc/snmp/snmpd.local.conf.cfnew seems to have been 
corrupted in transit, aborting!
ReleaseCurrentLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
PutLock(last.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
LockLog(Lock removed normally )
-------------------------------------------

Here's where the copy happens for no discernable reason; the checksum on
the local file in place was the same as the file in the repository.
You'll notice that it even matches the checksum above.

-------------------------------------------
ExpandVarstring(cfserver.example.com)
ExpandVarstring(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
ExpandVarstring(/etc/snmp/snmpd.local.conf)
Checking copy from 
cfserver.example.com:/srv/hostconfig/internal/cfclient/snmpd.local.conf to 
/etc/snmp/snmpd.local.conf
ExpandVarstring(cfserver.example.com)
Server connection to cfserver.example.com already open on 4
Authentic connection verified
cf_rstat(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
GetCachedStatData(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
Did not find in cache
Transaction Send[t 67][Packed text]
Attempting to send 75 bytes
SendSocketStream, sent 75
RecvSocketStream(8)
    (Concatenated 8 from stream)
Transaction Receive [t 71][]
RecvSocketStream(71)
    (Concatenated 71 from stream)
Mode = 436,0
OK: type=0
 mode=664
 lmode=0
 uid=109
 gid=109
 size=94
 atime=1121201186
 mtime=1121198839 ino=26705 nlnk=1, dev=14848
RecvSocketStream(8)
    (Concatenated 8 from stream)
Transaction Receive [t 3][]
RecvSocketStream(3)
    (Concatenated 3 from stream)
Linkbuffer: OK:
GetLock(copy,_srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com,time=1121202131),
 ExpireAfter=120, IfElapsed=1
GetLastLock()
CheckOldLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
Unable to find lock data 
lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923
SetLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
PutLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
Found no lock 
[lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923]:
 DB_NOTFOUND: No matching key/data pair found
Directory for /etc/snmp/snmpd.local.conf exists. Okay
CheckImage (source=/srv/hostconfig/internal/cfclient/snmpd.local.conf 
destination=/etc/snmp/snmpd.local.conf)
cf_rstat(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
GetCachedStatData(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
Found in cache
ImageCopy(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf,+440,-7337)
ExpandVarstring(cfserver.example.com)
IgnoredOrExcluded(/srv/hostconfig/internal/cfclient/snmpd.local.conf)
file /etc/snmp/snmpd.local.conf class any was not excluded
Destination file /etc/snmp/snmpd.local.conf exists
CompareCheckSums(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf)
Compare checksums on 
cfserver.example.com:/srv/hostconfig/internal/cfclient/snmpd.local.conf & 
/etc/snmp/snmpd.local.conf
ChecksumFile(m,/etc/snmp/snmpd.local.conf)
Send digest of /etc/snmp/snmpd.local.conf to server, 
MD5=a2a165652b9489d628ae526e496d6bc8
Transaction Send[t 67][Packed text]
Attempting to send 75 bytes
SendSocketStream, sent 75
RecvSocketStream(8)
    (Concatenated 8 from stream)
Transaction Receive [t 8][]
RecvSocketStream(8)
    (Concatenated 8 from stream)
MD5 mismatch: (reply - CFD_TRUE)
lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923:cfengine:cfclient:
 Update of image /etc/snmp/snmpd.local.conf from master 
/srv/hostconfig/internal/cfclient/snmpd.local.conf on cfserver.example.com
AddMultipleClasses(snmpd_needs_restart,snmpd_local_conf_updated)
AddClassToHeap(snmpd_needs_restart)
Appending [snmpd_needs_restart]
AddClassToHeap(snmpd_local_conf_updated)
Appending [snmpd_local_conf_updated]
CopyReg(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf)
This is a remote copy from server: cfserver.example.com
Transaction Send[t 54][Packed text]
Attempting to send 62 bytes
SendSocketStream, sent 62
RecvSocketStream(94)
    (Concatenated 94 from stream)
End of CopyNetReg
CopyReg succeeded in copying to 
/srv/hostconfig/internal/cfclient/snmpd.local.conf to 
/etc/snmp/snmpd.local.conf.cfnew
Final verification of transmission.
CompareCheckSums(/srv/hostconfig/internal/cfclient/snmpd.local.conf,/etc/snmp/snmpd.local.conf.cfnew)
Compare checksums on 
cfserver.example.com:/srv/hostconfig/internal/cfclient/snmpd.local.conf & 
/etc/snmp/snmpd.local.conf.cfnew
ChecksumFile(m,/etc/snmp/snmpd.local.conf.cfnew)
Send digest of /etc/snmp/snmpd.local.conf.cfnew to server, 
MD5=a2a165652b9489d628ae526e496d6bc8
Transaction Send[t 67][Packed text]
Attempting to send 75 bytes
SendSocketStream, sent 75
RecvSocketStream(8)
    (Concatenated 8 from stream)
Transaction Receive [t 9][]
RecvSocketStream(9)
    (Concatenated 9 from stream)
MD5 matched ok: (reply - CFD_FALSE)
Prepending [/etc/snmp/snmpd.local.conf.cfsaved]
CheckCopiedFile(/etc/snmp/snmpd.local.conf,+440,-7337)
CheckExistingFile(/etc/snmp/snmpd.local.conf)
cfengine:cfclient: Checking fs-object /etc/snmp/snmpd.local.conf
CheckExistingFile(+664,-7337)
CheckOwner: 0
 uid 0
Trying to fix mode...
lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923:cfengine:cfclient:
 Object /etc/snmp/snmpd.local.conf had permission 600, changed it to 440
CheckExistingFile(Done)
Appending [/etc/snmp/snmpd.local.conf]
ReleaseCurrentLock(lock.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
PutLock(last.cfagent_conf.cfclient.copy._srv_hostconfig_internal_cfclient_snmpd_local_conf__etc_snmp_snmpd_local_conf_cfserver_example_com_923)
LockLog(Lock removed normally )
-------------------------------------------


Wil
-- 
Wil Cooley <wcooley@nakedape.cc>
Naked Ape Consulting, Ltd. <http://nakedape.cc>