Suspected bug: logging write failure breaks transactions.

[sonicthoughts]

When logging enabled and log write fails  the transaction fails.
For some reason, mysql is generating a log write error during event registration (not sure why this keeps happening ...), but the real issues is that the transaction fails. 
failing at [nativecode=1194 ** Table 'log_civicrm_phone' is marked as crashed and should be repaired]"]

Give me the OK and I'll log in JIRA.

(
    [callback] => Array
        (
           

• => CRM_Core_Error
[1] => handle
        )

   

Code: [Select]

=> -1
    [message] => DB Error: unknown error
    [mode] => 16
    [debug_info] => INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_billing , phone , phone_type_id ) VALUES ( 16447 ,  1 ,  1 ,  0 , '0547177588' ,  1 )  [nativecode=1194 ** Table 'log_civicrm_phone' is marked as crashed and should be repaired]
    [type] => DB_Error
    [user_info] => INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_billing , phone , phone_type_id ) VALUES ( 16447 ,  1 ,  1 ,  0 , '0547177588' ,  1 )  [nativecode=1194 ** Table 'log_civicrm_phone' is marked as crashed and should be repaired]
    [to_string] => [db_error: message="DB Error: unknown error" code=-1 mode=callback callback=CRM_Core_Error::handle prefix="" info="INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_billing , phone , phone_type_id ) VALUES ( 16447 ,  1 ,  1 ,  0 , '0547177588' ,  1 )  [nativecode=1194 ** Table 'log_civicrm_phone' is marked as crashed and should be repaired]"]
)


Feb 10 07:08:51  [info] $backTrace = #0 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/Error.php(239): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 [internal function](): CRM_Core_Error::handle(Object(DB_Error))
#2 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/PEAR.php(931): call_user_func((Array:2), Object(DB_Error))
#3 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/DB.php(975): PEAR_Error->PEAR_Error("DB Error: unknown error", -1, 16, (Array:2), "INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_bi...")
#4 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/PEAR.php(564): DB_Error->DB_Error(-1, 16, (Array:2), "INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_bi...")
#5 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/DB/common.php(1905): PEAR->raiseError(NULL, -1, NULL, NULL, "INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_bi...", "DB_Error", TRUE)
#6 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/DB/mysql.php(899): DB_common->raiseError(-1, NULL, NULL, NULL, "1194 ** Table 'log_civicrm_phone' is marked as crashed and should be repaired")
#7 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/DB/mysql.php(328): DB_mysql->mysqlRaiseError()
#8 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/DB/common.php(1216): DB_mysql->simpleQuery("INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_bi...")
#9 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/DB/DataObject.php(2442): DB_common->query("INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_bi...")
#10 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/DB/DataObject.php(1060): DB_DataObject->_query("INSERT INTO civicrm_phone (contact_id , location_type_id , is_primary , is_bi...")
#11 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/DAO.php(455): DB_DataObject->insert()
#12 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/BAO/Phone.php(86): CRM_Core_DAO->save()
#13 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/BAO/Block.php(379): CRM_Core_BAO_Phone::add((Array:6))
#14 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/BAO/Location.php(68): CRM_Core_BAO_Block::create("phone", (Array:52), NULL)
#15 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Contact/BAO/Contact.php(358): CRM_Core_BAO_Location::create((Array:52), TRUE)
#16 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Contact/BAO/Contact.php(1849): CRM_Contact_BAO_Contact::create((Array:52))
#17 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Event/Form/Registration/Confirm.php(1068): CRM_Contact_BAO_Contact::createProfileContact((Array:64), (Array:20), NULL, (Array:1), NULL, NULL, TRUE)
#18 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Event/Form/Registration/Confirm.php(482): CRM_Event_Form_Registration_Confirm::updateContactFields(NULL, (Array:61), (Array:20), Object(CRM_Event_Form_Registration_Confirm))
#19 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/Form.php(328): CRM_Event_Form_Registration_Confirm->postProcess()
#20 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/StateMachine.php(162): CRM_Core_Form->mainProcess()
#21 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/QuickForm/Action/Next.php(60): CRM_Core_StateMachine->perform(Object(CRM_Event_Form_Registration_Confirm), "next", "Next")
#22 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/HTML/QuickForm/Controller.php(203): CRM_Core_QuickForm_Action_Next->perform(Object(CRM_Event_Form_Registration_Confirm), "next")
#23 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/packages/HTML/QuickForm/Page.php(103): HTML_QuickForm_Controller->handle(Object(CRM_Event_Form_Registration_Confirm), "next")
#24 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/Controller.php(356): HTML_QuickForm_Page->handle("next")
#25 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/Invoke.php(331): CRM_Core_Controller->run((Array:3), NULL)
#26 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/Invoke.php(75): CRM_Core_Invoke::runItem((Array:15))
#27 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/CRM/Core/Invoke.php(52): CRM_Core_Invoke::_invoke((Array:3))
#28 /home/xxxxx/public_html/drupal/sites/all/modules/civicrm/drupal/civicrm.module(457): CRM_Core_Invoke::invoke((Array:3))
#29 [internal function](): civicrm_invoke("event", "register")
#30 /home/xxxxx/public_html/drupal/includes/menu.inc(517): call_user_func_array("civicrm_invoke", (Array:2))
#31 /home/xxxxx/public_html/drupal/index.php(21): menu_execute_active_handler()
#32 {main}
[/quote]

[sonicthoughts]

Ok, I think I have tracked down the issue and it may affect others.

When logging is enabled, a trigger is set on all tables during update, insert, delete, etc.
The trigger is very simple: it writes the transaction to a log file for the table being affected.
The log file uses in my case uses the Mysql Archive Engine which is very efficient for writing/storage space and does not support an index.

Since the archive engine is designed for logging, it is not very good at handling mysql crashes.  In my case, not even graceful shutdowns (not sure why ...)

The linux server can get taxed and overallocate memory.  The Linux out of memory killer takes care of this: http://www.oracle.com/technetwork/articles/servers-storage-dev/oom-killer-1911807.html and kills mysqld.  Innodb tables can handle that but on my server the Archive tables do not recover nicely.

Now if a transaction was occuring, the trigger associated with a table that was being updated gets very unhappy and fails.
Unfortunately, this means the entire transaction (registration, contribution, profile update, etc.) will also fail.  That is a big issue in many cases.

I know the logging is considered "experimental" but it has been extremely useful and likely it is pervasive. 

Some possible solutions:

• Modify the database calls in civicrm to check the result code (not sure exactly how to do this - pass a variable somehow?)
• change the table type to innodb (poor performance)
• modify the logging trigger to ignore errors (hackish, but likely the intended behavior)
• yes, add more memory - already did that but lot's of lost transactions in the meantime ...

The triggers all (Not Verified) us code like this:

BEGIN  IF ( @civicrm_disable_logging IS NULL OR @civicrm_disable_logging = 0 ) THEN INSERT INTO log_civicrm_mail_settings (id, domain_id, name, is_default, domain, localpart, return_path, protocol, server, port, username, password, is_ssl, source, log_conn_id, log_user_id, log_action) VALUES ( NEW.id, NEW.domain_id, NEW.name, NEW.is_default, NEW.domain, NEW.localpart, NEW.return_path, NEW.protocol, NEW.server, NEW.port, NEW.username, NEW.password, NEW.is_ssl, NEW.source, CONNECTION_ID(), @civicrm_user_id, 'insert');END IF; END

Mysql allows support of a handler that can be used in a trigger: http://dev.mysql.com/doc/refman/5.6/en/declare-handler.html
Perhaps we can simply add something like:

DECLARE CONTINUE HANDLER FOR SQLEXCEPTION BEGIN END;

at the top of each log entry.  I assume that the handler scope is for the trigger only....
Thoughts?