CiviCRM Community Forums (archive)

*

News:

Have a question about CiviCRM?
Get it answered quickly at the new
CiviCRM Stack Exchange Q+A site
This forum was archived on 25 November 2017. Learn more.
How to get involved.
What to do if you think you've found a bug.



  • CiviCRM Community Forums (archive) »
  • Old sections (read-only, deprecated) »
  • Support »
  • Using CiviCRM »
  • Using Core CiviCRM Functions (Moderator: Yashodha Chaku) »
  • Suspected bug: logging write failure breaks transactions.
Pages: [1]

Author Topic: Suspected bug: logging write failure breaks transactions.  (Read 366 times)

sonicthoughts

  • Ask me questions
  • ****
  • Posts: 498
  • Karma: 10
Suspected bug: logging write failure breaks transactions.
February 11, 2015, 08:54:46 am
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.
Quote
(
    [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

  • Ask me questions
  • ****
  • Posts: 498
  • Karma: 10
PROPOSED SOL SOLUTION to logging write failure that breaks transactions
February 26, 2015, 11:48:37 am
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:
Quote
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:
Quote
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?
Pages: [1]
  • CiviCRM Community Forums (archive) »
  • Old sections (read-only, deprecated) »
  • Support »
  • Using CiviCRM »
  • Using Core CiviCRM Functions (Moderator: Yashodha Chaku) »
  • Suspected bug: logging write failure breaks transactions.

This forum was archived on 2017-11-26.