Who did what when?

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/master/innodbtriggers.php 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')));