Bug #72162 Insert fail caused by trigger
Submitted: 29 Mar 2014 20:02 Modified: 29 Apr 2014 20:07
Reporter: Peeter Pirn Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Stored Routines Severity:S2 (Serious)
Version:5.5.35-0ubuntu0.12.04.2 (Ubuntu) OS:Linux (Linux 3.2.0-60-generic-pae i686)
Assigned to: CPU Architecture:Any
Tags: insert, trigger

[29 Mar 2014 20:02] Peeter Pirn
Description:
This is the schema for the tables that seem to be involved with the bug. There are many more tables in the database. I have not included the SQL to populate the tables.

CREATE TABLE `WhatHappened?` (
  `Event` varchar(50) NOT NULL COMMENT 'Each event type must be unique.',
  `ID` tinyint(3) unsigned NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`ID`),
  UNIQUE KEY `Event` (`Event`)
) ENGINE=InnoDB AUTO_INCREMENT=0 DEFAULT CHARSET=utf8;

CREATE TABLE `Log` (
  `TimeStamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `Date` date DEFAULT NULL,
  `StartTime` time DEFAULT NULL,
  `EndTime` time DEFAULT NULL,
  `ApproximateTimes?` tinyint(1) DEFAULT NULL,
  `LogEntry` text,
  `WhatHappened?` tinyint(3) unsigned DEFAULT NULL,
  `ID` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`ID`),
  KEY `fk_whathappened01` (`WhatHappened?`),
  CONSTRAINT `fk_whathappened01` FOREIGN KEY (`WhatHappened?`) REFERENCES `WhatHappened?` (`ID`)
) ENGINE=InnoDB AUTO_INCREMENT=0 DEFAULT CHARSET=utf8;

DELIMITER ;;
/*!50003 CREATE*/ /*!50017 DEFINER=`peeter`@`localhost`*/ /*!50003 trigger `ai_log`
after insert on `Log` for each row
begin
if new.`WhatHappened?` = 58 then
insert into `PrayResolve` values(new.`ID`, 458);
end if;
if new.`WhatHappened?` = 53 then
insert into `TodoDone` values(new.`ID`, 458);
end if;
end */;;
DELIMITER ;

CREATE TABLE `PrayResolve` (
  `PrayID` bigint(20) unsigned NOT NULL COMMENT 'This should be a log entry with `WhatHappened?` set to "PRAYER REQUEST."',
  `ResolveID` bigint(20) unsigned NOT NULL DEFAULT '458' COMMENT '458 is a dummy log entry that indicates that the prayer request described in `PrayID` has not been resolved. If the prayer is resolved, `ResolveID` is set to the log entry that signals the resolution of the prayer.',
  `Notes` text,
  PRIMARY KEY (`PrayID`,`ResolveID`),
  KEY `fk_prayid01` (`PrayID`),
  KEY `fk_resolveid01` (`ResolveID`),
  CONSTRAINT `fk_prayid01` FOREIGN KEY (`PrayID`) REFERENCES `Log` (`ID`),
  CONSTRAINT `fk_resolveid01` FOREIGN KEY (`ResolveID`) REFERENCES `Log` (`ID`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

CREATE TABLE `TodoDone` (
  `TodoID` bigint(20) unsigned NOT NULL COMMENT 'This should be a log entry with `WhatHappened?` set to "TO DO."',
  `DoneID` bigint(20) unsigned NOT NULL DEFAULT '458' COMMENT '458 is a dummy log entry that indicates that the task described in `TodoID` is not finished. If the task is finished, `DoneID` is set to the log entry that signals the completion of the task.',
  `Notes` text,
  PRIMARY KEY (`TodoID`,`DoneID`),
  KEY `fk_todoid01` (`TodoID`),
  KEY `fk_doneid01` (`DoneID`),
  CONSTRAINT `fk_doneid01` FOREIGN KEY (`DoneID`) REFERENCES `Log` (`ID`),
  CONSTRAINT `fk_todoid01` FOREIGN KEY (`TodoID`) REFERENCES `Log` (`ID`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

DELIMITER ;;
CREATE DEFINER=`peeter`@`localhost` PROCEDURE `add_log`(s_date char(10), s_stime char(5), s_etime char(5), approx_t int, s_entry text, event int)
begin
insert into `Log` (`Date`, `StartTime`, `EndTime`, `ApproximateTimes?`, `LogEntry`, `WhatHappened?`) values (s_date, s_stime, s_etime, approx_t, s_entry, event);
end ;;
DELIMITER ;

The database runs well for months, but then:

mysql> call add_log('2014-03-29', '05:06', null, 0, 'Teach youth to sing "Someone Special" p80 in "My First Hymnal"', 53);
ERROR 1136 (21S01): Column count doesn't match value count at row 1
mysql> insert into `Log` (`Date`, `StartTime`, `EndTime`, `ApproximateTimes?`, `LogEntry`, `WhatHappened?`) values('2014-03-29', '05:06', null, 0, 'Teach youth to sing "Someone Special" p80 in "My First Hymnal"', 53);
ERROR 1136 (21S01): Column count doesn't match value count at row 1
mysql> drop trigger ai_log;
Query OK, 0 rows affected (0.26 sec)

mysql> call add_log('2014-03-29', '05:06', null, 0, 'Teach youth to sing "Someone Special" p80 in "My First Hymnal"', 53);
Query OK, 1 row affected (0.48 sec)

mysql> delimiter //
mysql> create trigger `ai_log`
    -> after insert on `Log` for each row
    -> begin
    -> if new.`WhatHappened?` = 58 then
    -> insert into `PrayResolve` values(new.`ID`, 458);
    -> end if;
    -> if new.`WhatHappened?` = 53 then
    -> insert into `TodoDone` values(new.`ID`, 458);
    -> end if;
    -> end//
Query OK, 0 rows affected (0.10 sec)

mysql> delimiter ;

(Normal performance of the database after re-installing the trigger:)

mysql> call add_log('2014-03-27', '17:39', '18:39', 0, 'Confirmation class wid Deli es Brian. Lbh due today Lk 15:7; assigned "What is the Office of the Keys?"', 15);
Query OK, 1 row affected (1.07 sec)

How to repeat:
I cannot create a reproducible test case. Not yet. I had no problem with the trigger `ai_log` for months after installing it. Then, unexpectedly, the inserts on the `Log` table failed. Dropping the trigger fixed the problem; after reinstalling the trigger, everything still works.

I expect there will be no problem again for months.
[29 Mar 2014 20:27] Peeter Pirn
Actually, after the trigger is reinstalled, I can repeat the bug with this:
mysql> call add_log('2014-03-29', '16:25', null, 0, 'Make sure Joyce Russo\'s vase is installed.', 53);
ERROR 1136 (21S01): Column count doesn't match value count at row 1
[29 Mar 2014 21:07] MySQL Verification Team
Hi Peeter,

These two lines seem wrong to me.  The tables have more than two columns:

insert into `PrayResolve` values(new.`ID`, 458);
insert into `TodoDone` values(new.`ID`, 458);
[29 Apr 2014 20:07] Peeter Pirn
Thank you, Shane! That was a bug in my code, not in MySQL.