5 Replies - 332 Views - Last Post: 17 August 2017 - 11:34 AM

#1 ArtificialSoldier  Icon User is offline

  • D.I.C Lover
  • member icon

Reputation: 1836
  • View blog
  • Posts: 5,784
  • Joined: 15-January 14

Got demons in mah DB

Posted 16 August 2017 - 06:02 PM

I've got 2 tables, one of them holds "the main record" and the other one holds all of the historical records. It may not be the best design, but there it is. When launching a certain type of content which supports historical records, part of the process is to copy the current record into the history table, then delete the current record, then insert a new record so that it gets a new auto-increment ID. Both tables have identical structure, and both of them have the ID as a primary key (so the two tables can't share the same IDs even, or the copy will fail).

One client found a fun problem where trying to launch the same content twice in a row fails the second time, and the reason is because it finds a duplicate ID in the history table. I think this is a bug, because I've been looking at it all day and am about to go home and hit the bottle.

Here's the sequence of events. We look up the current record:

SELECT * FROM content_session WHERE uid=3 AND cid=940

Do some checks, then copy it to the history table:
INSERT INTO content_session_history SELECT * FROM content_session WHERE uid=3 AND cid=940

content_session also has a unique key on (uid, cid), so that's only going to be 1 record. Next, we delete the record that just got copied:
DELETE FROM content_session WHERE uid=3 AND cid=940

And add a new one:
INSERT INTO `content_session` (`uid`,`cid`,`field1`,`field2`,`field3`,`field4`,`field5`,`field6`,`field7`,`field8`,`field9`,`field10`,`field11`,`field12`,`field13`,`field14`,`field15`,`field16`,`field17`,`field18`,`field19`,`field20`,`field21`,`field22`,`field23`,`field24`,`field25`,`field26`,`field27`,`field28`,`field29`,`field30`,`counter`,`start_date`,`complete_date`,`time_taken`,`archive`,`score`,`completed`) VALUES ('3','940','','','','','','','','','','','','','','','','','','','','','','','','','','','','','','','5','1502829936','1502922493','1','0','100','1')

That makes a new primary key ID in content_session.

But wait, there's more.

Let's say that initial content_session record had an ID of 100. I can verify before these queries that content_session_history only goes up to 99, for example. So we copy record 100 from content_session to content_session_history, then delete record 100 from content_session, then insert a new record to content_session, record 101. But immediately after that I can look up a record in content_session_history with ID 101 and it will find one. So adding that new record to content_session somehow causes one of the records in content_session_history to get the same ID, so the next time this runs and tries to copy record 101 to content_session_history, there already is one. It's not the same uid and cid either, it's a completely old record that for whatever reason gets the new ID of the record in content_session. I enabled global logging for MySQL, and I can verify that between the above process, or after it, there is no additional query to update or insert on content_session_history.

What's that, you say? It sounds like a trigger? Yes it does! But there are no triggers defined on the entire database, so where's your god now?

Here's the table structures:

Spoiler


As far as I can tell no other client is experiencing this, and after messing around with it all day I can't figure out why it's doing this.

Is This A Good Question/Topic? 0
  • +

Replies To: Got demons in mah DB

#2 andrewsw  Icon User is offline

  • say what now
  • member icon

Reputation: 6408
  • View blog
  • Posts: 25,889
  • Joined: 12-December 12

Re: Got demons in mah DB

Posted 16 August 2017 - 11:19 PM

My suspicion would be the behaviour of "NO_AUTO_VALUE_ON_ZERO". I'm going to guess that there's a 0 somewhere and when the record is first copied between tables this 0 turns into 101. This would mean that the 101 is present before this number is generated in the first table.

I've only recently woken up, though :online2long:. With that setting the 0 should remain unaltered?! But I'll leave my comments here, though, as they might inspire you to discover the issue.
Was This Post Helpful? 0
  • +
  • -

#3 ArtificialSoldier  Icon User is offline

  • D.I.C Lover
  • member icon

Reputation: 1836
  • View blog
  • Posts: 5,784
  • Joined: 15-January 14

Re: Got demons in mah DB

Posted 17 August 2017 - 10:12 AM

I have a script to fix the IDs, but even after running that before testing there isn't a record in content_session_history with an ID of 0. When the record gets copied over it comes with its ID from content_session also. I forgot to mention that I also tried all of those queries wrapped in a transaction, because why not, and that didn't have any effect. It's just really frustrating because I can even log every query that MySQL does, and there are no additional insert or update queries on content_session_history. It misses the query to change the ID in content_session_history, which makes me think we've ran into another MySQL bug. This is the part of the log which shows activity from connection to quit for this case, after that first insert into content_session then content_session_history will have the changed ID. The second block is when I try to launch the same content again, and it quits after trying to copy the record because there was the primary key error.

    5048967 Connect [email protected] on test_lms
    5048967 Query SET NAMES utf8
    5048967 Query SET NAMES 'utf8'
    5048967 Query SELECT type, track_type, url, media_use, launch_limit, instacomplete, exact_url, pw_required, password,
     title, lock_completion_records, lock_completion_status, parent_id, bypass_wrapper, active, auto_archive
  FROM content WHERE id = 940
    5048967 Query SELECT * FROM config ORDER BY `name` ASC
    5048967 Query SELECT * FROM content_session WHERE uid=3 AND cid=940
    5048967 Query SELECT * FROM users WHERE id=3
    5048967 Query INSERT INTO content_session_history SELECT * FROM content_session WHERE uid=3 AND cid=940
    5048967 Query DELETE FROM content_session WHERE uid=3 AND cid=940
    5048967 Query INSERT INTO `content_session` (`uid`,`cid`,`field1`,`field2`,`field3`,`field4`,`field5`,`field6`,`field7`,`field8`,`field9`,`field10`,`field11`,`field12`,`field13`,`field14`,`field15`,`field16`,`field17`,`field18`,`field19`,`field20`,`field21`,`field22`,`field23`,`field24`,`field25`,`field26`,`field27`,`field28`,`field29`,`field30`,`counter`,`start_date`,`complete_date`,`time_taken`,`archive`,`score`,`completed`) VALUES ('3','940','','','','','','','','','','','','','','','','','','','','','','','','','','','','','','','5','1502829936','1502922493','1','0','100','1')
    5048967 Query SELECT * FROM all_strings WHERE id='log_launch_content'
    5048967 Query INSERT INTO `user_change_log` (`uid`,`changes`,`date_changed`) VALUES ('3','User launched content Helpdesk Test','1502925839')
    5048967 Query SELECT * FROM content_session WHERE uid=3 AND cid=940
    5048967 Query UPDATE content_session SET counter='6',last_entered='1502925839',last_platform='Mozilla/5.0 (Windows NT 10.0; WOW64; rv:55.0) Gecko/20100101 Firefox/55.0',last_ip='127.0.0.1',field1='',field2='',field3='',field4='',field5='',field6='',field7='',field8='',field9='',field10='',field11='',field12='',field13='',field14='',field15='',field16='',field17='',field18='',field19='',field20='',field21='',field22='',field23='',field24='',field25='',field26='',field27='',field28='',field29='',field30='',completed='1'  WHERE id=23378
    5048967 Query SELECT parent_id FROM `content` WHERE id = 940 LIMIT 1
    5048967 Query SELECT * FROM all_strings WHERE id='log_training_update'
    5048967 Query INSERT INTO `user_change_log` (`uid`,`changes`,`date_changed`) VALUES ('3','Training records updated after user launched content Helpdesk Test','1502925839')
    5048967 Query SELECT cid, complete_date FROM content_session WHERE uid=3 AND completed = 1
    5048967 Query SELECT mark_cids_complete FROM content WHERE id = 2
    5048967 Query SELECT mark_cids_complete FROM content WHERE id = 630
    5048967 Query SELECT mark_cids_complete FROM content WHERE id = 709
    5048967 Query SELECT mark_cids_complete FROM content WHERE id = 730
    5048967 Query SELECT mark_cids_complete FROM content WHERE id = 940 
    5048967 Quit  



    5049034 Connect [email protected] on test_lms
    5049034 Query SET NAMES utf8
    5049034 Query SET NAMES 'utf8'
    5049034 Query SELECT type, track_type, url, media_use, launch_limit, instacomplete, exact_url, pw_required, password,
     title, lock_completion_records, lock_completion_status, parent_id, bypass_wrapper, active, auto_archive
  FROM content WHERE id = 940
    5049034 Query SELECT * FROM config ORDER BY `name` ASC
    5049034 Query SELECT * FROM content_session WHERE uid=3 AND cid=940
    5049034 Query SELECT * FROM users WHERE id=3
    5049034 Query INSERT INTO content_session_history SELECT * FROM content_session WHERE uid=3 AND cid=940
    5049034 Quit  

It's just super frustrating, my experience programming has taught me that 99.9% of bugs are because someone messed up in the code somewhere, and every time I can track that down, figure out why it's doing that, what the fix is, and fix it, but this might be the second time where I've actually seen a MySQL bug. If that's the case then I guess the next step is to try to get an example test case. I even tried to export each of those tables, suspended foreign keys and deleted and added the tables back, and that also had no effect.

I'm having a hard time even thinking about what to search for to try to find a bug report on this.
Was This Post Helpful? 0
  • +
  • -

#4 ArtificialSoldier  Icon User is offline

  • D.I.C Lover
  • member icon

Reputation: 1836
  • View blog
  • Posts: 5,784
  • Joined: 15-January 14

Re: Got demons in mah DB

Posted 17 August 2017 - 10:30 AM


I might be an idiot.
Was This Post Helpful? 0
  • +
  • -

#5 ArtificialSoldier  Icon User is offline

  • D.I.C Lover
  • member icon

Reputation: 1836
  • View blog
  • Posts: 5,784
  • Joined: 15-January 14

Re: Got demons in mah DB

Posted 17 August 2017 - 10:47 AM

Can confirm. Am idiot. My script to "fix" the problem, by going through content_session_history and renumbering any ID that already existed in either content_session or content_session_history (someone once decided it was a good idea to drop the primary key constraint on content_session_history and we ended up with records with duplicate IDs), after it renumbered the conflicting records it didn't bother to look up the current auto_increment value on content_session to make sure that the next ID also didn't already exist. I updated that script to see if the highest ID that it just reset things to is higher than the auto_increment on content_session, and reset it if so. So it didn't have anything to do with the above queries, when I ran the script to fix the issue it made it so that content_session_history had records with IDs higher than the auto_increment for content_session, so the next new record was bound to conflict. I only bothered to look for a conflicting record after inserting the new one into content_session, if I had checked before to see if a record already existed with the next auto_increment ID I would have seen one (a couple thousand, actually).
Was This Post Helpful? 0
  • +
  • -

#6 modi123_1  Icon User is offline

  • Suitor #2
  • member icon



Reputation: 13554
  • View blog
  • Posts: 54,090
  • Joined: 12-June 08

Re: Got demons in mah DB

Posted 17 August 2017 - 11:34 AM

I just have to say I love this thread's title and I cannot wait to yell it out at work when I have DB issues next.
Was This Post Helpful? 0
  • +
  • -

Page 1 of 1