While investigating database errors logged in my application, I noticed that some records that reference a different table with an ON DELETE CASCADE constraint had not been deleted. This constraint normally works, this is the first time I've spotted stale rows.
The queries below show stale rows in matchmaking_group_users and matchmaking_group_maps. They both have a matchmaking_group_id that references the column id in the table matchmaking_groups.
MariaDB [esportal]> select * from matchmaking_group_users where matchmaking_group_id not in (select id from matchmaking_groups);
|
+----------------------+-----------+------------+
|
| matchmaking_group_id | user_id | microphone |
|
+----------------------+-----------+------------+
|
| 278066 | 182715729 | 1 |
|
+----------------------+-----------+------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [esportal]> select * from matchmaking_group_maps where matchmaking_group_id not in (select id from matchmaking_groups);
|
+----------------------+--------+----------+
|
| matchmaking_group_id | map_id | priority |
|
+----------------------+--------+----------+
|
| 278066 | 1 | 4 |
|
| 278066 | 2 | 2 |
|
| 278066 | 5 | 1 |
|
| 278066 | 6 | 3 |
|
| 278066 | 7 | 6 |
|
| 278066 | 8 | 5 |
|
+----------------------+--------+----------+
|
6 rows in set (0.00 sec)
|
|
MariaDB [esportal]> show create table matchmaking_group_users;
|
+-------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|
| Table | Create Table |
|
+-------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|
| matchmaking_group_users | CREATE TABLE `matchmaking_group_users` (
|
`matchmaking_group_id` bigint(20) unsigned NOT NULL,
|
`user_id` int(10) unsigned NOT NULL,
|
`microphone` tinyint(1) unsigned NOT NULL,
|
PRIMARY KEY (`matchmaking_group_id`,`user_id`),
|
UNIQUE KEY `user_id` (`user_id`),
|
CONSTRAINT `matchmaking_group_users_ibfk_1` FOREIGN KEY (`matchmaking_group_id`) REFERENCES `matchmaking_groups` (`id`) ON DELETE CASCADE ON UPDATE CASCADE,
|
CONSTRAINT `matchmaking_group_users_ibfk_2` FOREIGN KEY (`user_id`) REFERENCES `users` (`id`) ON DELETE CASCADE ON UPDATE CASCADE
|
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
|
+-------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|
1 row in set (0.00 sec)
|
|
MariaDB [esportal]> show create table matchmaking_group_maps;
|
+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|
| Table | Create Table |
|
+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|
| matchmaking_group_maps | CREATE TABLE `matchmaking_group_maps` (
|
`matchmaking_group_id` bigint(20) unsigned NOT NULL,
|
`map_id` tinyint(2) unsigned NOT NULL,
|
`priority` tinyint(2) unsigned NOT NULL,
|
PRIMARY KEY (`matchmaking_group_id`,`map_id`),
|
CONSTRAINT `matchmaking_group_maps_ibfk_1` FOREIGN KEY (`matchmaking_group_id`) REFERENCES `matchmaking_groups` (`id`) ON DELETE CASCADE ON UPDATE CASCADE
|
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
|
+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|
1 row in set (0.00 sec)
|
I'm running the latest stable version on Debian Stretch:
I did spot these errors in /var/log/daemon.log, but I'm not sure if they're relevant.
Jul 3 22:04:58 esportal mysqld[1772]: 2017-07-03 22:04:58 140365854455552 [ERROR] InnoDB: WSREP: referenced FK check fail: 15 index user_id table esportal/match_rematch_votes
|
Jul 4 17:40:59 esportal mysqld[1772]: 2017-07-04 17:40:59 140365548082944 [ERROR] InnoDB: WSREP: referenced FK check fail: 15 index host_user_id table esportal/matchmaking_groups
|
{"report":{"fcp":1564.2999997138977,"ttfb":436.7999997138977,"pageVisibility":"visible","entityId":62162,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"e37bc178-d732-4eb2-abf1-92b89203c559","navigationType":0,"readyForUser":1667.2999997138977,"redirectCount":0,"resourceLoadedEnd":1902.7999997138977,"resourceLoadedStart":443.09999990463257,"resourceTiming":[{"duration":557.5999999046326,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":443.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":443.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1000.6999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":557.6000003814697,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":443.3999996185303,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":443.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1001,"responseStart":0,"secureConnectionStart":0},{"duration":576.3999996185303,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":443.5,"connectEnd":443.5,"connectStart":443.5,"domainLookupEnd":443.5,"domainLookupStart":443.5,"fetchStart":443.5,"redirectEnd":0,"redirectStart":0,"requestStart":443.5,"responseEnd":1019.8999996185303,"responseStart":1019.8999996185303,"secureConnectionStart":443.5},{"duration":648.8000001907349,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":443.69999980926514,"connectEnd":443.69999980926514,"connectStart":443.69999980926514,"domainLookupEnd":443.69999980926514,"domainLookupStart":443.69999980926514,"fetchStart":443.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":443.69999980926514,"responseEnd":1092.5,"responseStart":1092.5,"secureConnectionStart":443.69999980926514},{"duration":653.2999997138977,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":444,"connectEnd":444,"connectStart":444,"domainLookupEnd":444,"domainLookupStart":444,"fetchStart":444,"redirectEnd":0,"redirectStart":0,"requestStart":444,"responseEnd":1097.2999997138977,"responseStart":1097.2999997138977,"secureConnectionStart":444},{"duration":653.5999999046326,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":444.09999990463257,"connectEnd":444.09999990463257,"connectStart":444.09999990463257,"domainLookupEnd":444.09999990463257,"domainLookupStart":444.09999990463257,"fetchStart":444.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":444.09999990463257,"responseEnd":1097.6999998092651,"responseStart":1097.6999998092651,"secureConnectionStart":444.09999990463257},{"duration":653.7000002861023,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":444.3999996185303,"connectEnd":444.3999996185303,"connectStart":444.3999996185303,"domainLookupEnd":444.3999996185303,"domainLookupStart":444.3999996185303,"fetchStart":444.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":444.3999996185303,"responseEnd":1098.0999999046326,"responseStart":1098.0999999046326,"secureConnectionStart":444.3999996185303},{"duration":723.1999998092651,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":444.59999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":444.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1167.7999997138977,"responseStart":0,"secureConnectionStart":0},{"duration":653.8000001907349,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":444.69999980926514,"connectEnd":444.69999980926514,"connectStart":444.69999980926514,"domainLookupEnd":444.69999980926514,"domainLookupStart":444.69999980926514,"fetchStart":444.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":444.69999980926514,"responseEnd":1098.5,"responseStart":1098.5,"secureConnectionStart":444.69999980926514},{"duration":723.1000003814697,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":444.8999996185303,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":444.8999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1168,"responseStart":0,"secureConnectionStart":0},{"duration":654.0999999046326,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":445.09999990463257,"connectEnd":445.09999990463257,"connectStart":445.09999990463257,"domainLookupEnd":445.09999990463257,"domainLookupStart":445.09999990463257,"fetchStart":445.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":445.09999990463257,"responseEnd":1099.1999998092651,"responseStart":1099.1999998092651,"secureConnectionStart":445.09999990463257},{"duration":829.4000000953674,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":452.2999997138977,"connectEnd":452.2999997138977,"connectStart":452.2999997138977,"domainLookupEnd":452.2999997138977,"domainLookupStart":452.2999997138977,"fetchStart":452.2999997138977,"redirectEnd":0,"redirectStart":0,"requestStart":452.2999997138977,"responseEnd":1281.6999998092651,"responseStart":1281.6999998092651,"secureConnectionStart":452.2999997138977},{"duration":1363.7999997138977,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":480.59999990463257,"connectEnd":480.59999990463257,"connectStart":480.59999990463257,"domainLookupEnd":480.59999990463257,"domainLookupStart":480.59999990463257,"fetchStart":480.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":480.59999990463257,"responseEnd":1844.3999996185303,"responseStart":1844.3999996185303,"secureConnectionStart":480.59999990463257},{"duration":107.2000002861023,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":1178.8999996185303,"connectEnd":1178.8999996185303,"connectStart":1178.8999996185303,"domainLookupEnd":1178.8999996185303,"domainLookupStart":1178.8999996185303,"fetchStart":1178.8999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":1178.8999996185303,"responseEnd":1286.0999999046326,"responseStart":1286.0999999046326,"secureConnectionStart":1178.8999996185303},{"duration":412.09999990463257,"initiatorType":"link","name":"https://jira.mariadb.org/s/d5715adaadd168a9002b108b2b039b50-CDN/lu2cib/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/css/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":1490.6999998092651,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1490.6999998092651,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1902.7999997138977,"responseStart":0,"secureConnectionStart":0},{"duration":381.69999980926514,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/e65b778d185daf5aee24936755b43da6/_/download/contextbatch/js/browser-metrics-plugin.contrib,-_super,-project.issue.navigator,-jira.view.issue,-atl.general/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":1492,"connectEnd":1492,"connectStart":1492,"domainLookupEnd":1492,"domainLookupStart":1492,"fetchStart":1492,"redirectEnd":0,"redirectStart":0,"requestStart":1492,"responseEnd":1873.6999998092651,"responseStart":1873.6999998092651,"secureConnectionStart":1492},{"duration":388.2000002861023,"initiatorType":"script","name":"https://jira.mariadb.org/s/097ae97cb8fbec7d6ea4bbb1f26955b9-CDN/lu2cib/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/js/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":1492.3999996185303,"connectEnd":1492.3999996185303,"connectStart":1492.3999996185303,"domainLookupEnd":1492.3999996185303,"domainLookupStart":1492.3999996185303,"fetchStart":1492.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":1492.3999996185303,"responseEnd":1880.5999999046326,"responseStart":1880.5999999046326,"secureConnectionStart":1492.3999996185303},{"duration":383.40000009536743,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":1540.3999996185303,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1540.3999996185303,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1923.7999997138977,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":227,"responseStart":437,"responseEnd":481,"domLoading":441,"domInteractive":1931,"domContentLoadedEventStart":1931,"domContentLoadedEventEnd":2010,"domComplete":2683,"loadEventStart":2683,"loadEventEnd":2684,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1846},{"name":"bigPipe.sidebar-id.end","time":1846.8999996185303},{"name":"bigPipe.activity-panel-pipe-id.start","time":1847.0999999046326},{"name":"bigPipe.activity-panel-pipe-id.end","time":1858.5999999046326},{"name":"activityTabFullyLoaded","time":2034.1999998092651}],"measures":[],"correlationId":"37a05dc5dc67cf","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":134,"dbReadsTimeInMs":14,"dbConnsTimeInMs":23,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
marko, I will amend the test, it's clear why it fails; but first let's make sure that the code actually works as expected now, I'm not sure about that.
The relevant part of the test does the following:
1. Connection 1 starts transaction and updates a row X in table 1;
2. Connection 2 deletes a row from table 2, which references table 1, and the operation should cascade-delete row X from the table 1.
Without the fix (apart from the assertion failure, e.g. on a release build, or on 10.1), the DELETE query in connection 2 starts waiting, the process list says
10 root localhost test Query 1 updating DELETE FROM `matchmaking_groups` WHERE id = 10
and information_schema.innodb_trx says
1299 LOCK WAIT 2017-08-14 17:22:05 1299:4:3:2 2017-08-14 17:22:05 15 10 DELETE FROM `matchmaking_groups` WHERE id = 10 updating or deleting 36 14 1136 8 1 0 REPEATABLE READ 1 1 NULL 0 0 0
which is what the test waits for.
After the fix, the DELETE query succeeds immediately – no waiting, no transaction waiting for a lock.
It seems strange. Is it expected?