Published
Monday, June 27, 2016 - 16:33
Written by

For many years CiviCRM has had the capability to log all actions that take place in the database but while it mostly works well there have been a few issues. I looked into these recently and came up with some improvements, which shipped in 4.7.7 - but if you want to take advantage of them there are some actions you might need to take. This article is mostly intended for a technical audience.

 

How does CiviCRM logging work?

Turning logging on is as simple as checking the box 'Logging' on the admin page at Administer->System Settings->Misc. Once you do this a 'shadow table' for each table in your database (except for cache tables) is created. For example log_civicm_contact tracks civicrm_contact table. MySQL triggers are created that cause every update, insert or delete action to be logged in these tables. Some of the data in these tables can be viewed through the 'Log' tab on the contact record, although much more is only visible through the database itself.

 

How does logging perform?

Figuring this out was one of the key issues for me. I was working on a large dataset with high throughput and we wanted to be clear about this. I ran a script that imported contributions several times. My script processed 2000 contributions and the best throughput was the first run with 378 seconds for 2000 contributions (317 per minute). I retried after turning logging on and again after to converting to INNODB and adding indexes. My worst performance was 397 seconds for 2000 contibutions (302 per minute). I got considerable variance on these results so my best conclusion was that there was probably a small performance hit on write operations turning on logging. It did not appear to be greater for INNODB vs ARCHIVE format. The effect might be large enough to notice in large import jobs but not in day to day usage. 


Huh? what's this about ARCHIVE & INNODB?

When you turn logging on the tables are created using the ARCHIVE engine by default. The ARCHIVE engine is optimised for writing rather than reading and cannot be indexed. Without having been party to the original discussions there are 2 possible reasons why the ARCHIVE engine was chosen

1) performance - I believe it was perceived that it would perform better, although my tests did not support that perception

2) disk space  - the archive tables take up considerably less disk space. With INNODB tables the largest chunk of disk space goes on indexes so the amount of space used depends on indexing. I found that a table taking 250MB of disk space in ARCHIVE format took 2GB once I had converted it to INNODB and added indexes to the fields id, contact_id, log_conn_id & log_date

 

On the other hand ARCHIVE tables have significant disadvantages

1) slow retrieval - really slow!

2) prone to corruption - in discussion on the dev list a number of people had seen their ARCHIVE log tables corrupt - causing backups to fail and potentially losing data from them.

 

Getting data back out ... better

I came to the conclusion there were 2 things that needed to be done to improve the data retrieval from log tables

1) switch to indexed INNODB tables - I used indexes on 3-4 fields id, contact_id (if present), log_conn_id, log_date. With these indexes the log tab renders as fast as any other tab on the contact summary.

2) use a more reliable method to set the log_conn_id.

 

The log_conn_id....

The pre 4.7.7 log table format creates an integer field 13 chars long for the log_conn_id. The value stored here is the mysql CONNECTION_ID(). Unfortunately this mysql value is not actually unique. It is only unique at a given point in time. If you want to retrieve the changes made in a specific mysql transaction you need to add some time parameters - but unfortunately there is no accurate way to calculate what those time parameters should be since the transaction could be a batch transaction lasting 10 minutes or only 10 seconds. For anyone who has loaded change reports and found data missing the miscalculation of this timeframe is a likely cause.

 

My fix was to replace the calculation for log_conn_id with one based on the uniqid() php function with a few extra characters to make it more unique (I backed away from passing in a prefix in order not to blow out the field length too much). In order for this to work the log_conn_id field needs to be 17 varchar characters not 13 integer characters.

 

Swapping over

While INNODB is a better option for most sites and the changed log_conn_id methodology is better for all it wasn't a change I wanted to put in the upgrade script, for the simple reason it could take a while. Converting and altering all the log tables on a large site is likely to require a planned outage - so instead of imposing that change we settled for

1) new sites turning on logging would use the new log_conn_id format

2) new sites turning on logging could get the INNODB table format and indexes by implementing a hook. The hook is implemented in this extension https://github.com/eileenmcnaughton/nz.co.fuzion.innodbtriggers/blob/mas... and sites could opt to install that extension or add a similar hook before turning on logging if they choose

3) existing sites can migrate to the new log_conn_id by running an api function (probably by drush or similar) civicrm_api3('System', 'updatelogtables', array());

4) existing sites can do a one way conversion to INNODB format by adding a hook per above prior to running that command. 

5) sites that wish to revert to ARCHIVE would need to do that through mysql - there is no process for this & it seems unlikely to be a good idea.

 

MYSQL permissions

There is an edge case scenario in a mysql replicated environment where the web user does not get the mysql SUPER (CREATE TRIGGER) permission and the site admin chooses to manage the deletion & creation of triggers as a sysadmin task - there is a setting that permits this now logging_no_trigger_permission - but that is deliberately not exposed through the UI and means that new custom fields will require sysadmin intervention in order to create triggers.

 

Reverting changes

Reverting changes has always been possible from the change log. If you merge 2 contacts you will now see that activity in the change log has a link to reverse that merge. That link gives you the opportunity to reverse the entire transaction. It's worth noting that if it is part of a batch transaction there may be multiple merge actions in that one transaction.

 

I am dealing with the situation where we want merge actions done as part of a batch process to be individually reversible and have added this hook so that the log_conn_id changes for each merge pair.

function hook_wmf_civicrm_civicrm_merge($type, &$refs, $mainID, $otherID, $tables) {
    switch ( $type ) {
      case 'batch' :
        CRM_Core_DAO::executeQuery('SET @uniqueID = %1', array(1 => array(uniqid() . CRM_Utils_String::createRandom(CRM_Utils_String::ALPHANUMERIC, 4), 'String')));
Filed under

Comments

Thanks for the write-up. It would be useful to hear a little more about how the logging actually works, in terms of how revisions are stored (ie: only changes are captured). This might also help answer questions like this: http://civicrm.stackexchange.com/questions/10239/can-i-safely-trim-civic...

Basically every change a new row is added to the relevant log_ table with the new data + the contact_id of the changer, the timestamp, the connection id & the type of change

Thanks for writing this up, and for all the work to eliminate issues with ARCHIVE tables. I feel like "Logging" is a much overloaded term in CiviCRM! I've seen people use it to mean -

Which is what when might be obvious to those of us who work with CiviCRM often, but using clear/distinctive terminology for these might help make things less confusing for a wider base of CiviCRM users.

Could "shadow table logging" from your description above, then be a better name to use for the logging described here? Or or "log table logging" or "trigger logging" (which describes the method, not the functionality, but probably makes sense to most CiviCRM developers)?

Another advantage of moving from the Archive table format to InnoDB is that the backup options with InnoDB are considerably better.  With InnoDB you can run mysqldump with `--single-transaction --skip-lock-tables`, which means your tables don't have to get locked while the dump gets taken. 

I'm currently looking at this area because of issues with the daily outage caused by the mysql backups.  I'm looking at setting up a replicated slave database for backups, but much the same issue arises - MyISAM and Archive tables also require a significant outage to get replication set up.

I wonder if the locking problem gets worse with the size of the log tables - I'm thinking it's likely to block updates to the table being logged, because the trigger would hang on the lock while mysqldump runs?

I note Eileen that you've commented elsewhere that sometimes it can be a benefit to be using a non-transational table format for logging, since those tables don't get logged back.  IT would leave the history in a messy state, but also hang onto data that might otherwise be lost.  You mentioned financial data of donors who were affected by site problems.

Re the financial transactions data - we have currently got a site where for unknown reasons some transactions are disappearing. We converted the table back to ARCHIVE and it helped us to pin point a problem in a post hook causing rollback, and retrieve lost data. We now have a second! problem on the same site with missing transactions. As the tables are still in archive format I know the problem is not the transactions being rolled back, but they are never being recorded. This is helpful forensically, although it also tells me that upgrading the site to 4.7 would mean they were recorded since in 4.7 the pending contribution is recorded before interacting with the payment processor, and means my recommendation is 'first upgrade to 4.7'.

 

So, it can be helpful - in edge forensic cases where there is a problem you can't pin down. In the end in this case  however, I found queryin Authorize.net for the rolled back data to be better than retrieving it from the log.tables. (I've added the ability to query Authorize.net to the Omnipay extension but it needs me to do another round of review on it before I encourage people to use it)

 

Merry Xmas!