Related error mesage is CheckUserLog entry was not recorded. This means checks can occur without being auditable. Immediate fix required., e.g. https://logstash.wikimedia.org/app/discover#/doc/logstash-*/logstash-mediawiki-1-7.0.0-1-2024.09.26?id=FGlwMJIBfb-ROeD6ichd. 11 of these in the last 7 days.

Looking into this error further, the query does not attempt to assign the value of the ID for the row in the query, so it should pick the auto increment ID. Therefore, it seems that the DB is trying to use an auto_increment ID that was already taken. Take https://logstash.wikimedia.org/app/dashboards#/doc/logstash-*/logstash-deploy-1-7.0.0-1-2024.09.26?id=2gZwMJIBa-PL6vFeiU7A for an example, the associated ID in that error is used for a log that has been in the table since 2009. All errors that proceed this use an auto_increment ID such that the first error starts with 1 and goes up to this log. This appears to have only started after the switchover.

I ran SHOW TABLE STATUS WHERE name LIKE 'cu_log'; on the affected wiki, and it showed the correct auto_increment value. However, when I try to connect to the DB that had the error it appears that it's been de-pooled.

This is a serious error because it prevented an audit log for running a CheckUser check. Adding DBA so that they are aware, as it appears this was the fault of the DB and not how we constructed the query.

I try to investigate ASAP.

checkin cu_log, it seems it has different auto_increments on different servers. This could happen if a schema change has been applied or the table has been rebuilt recently (or restarted). ALTERing the table just setting auto_increment to a safe value (7 as I write this lines) should fix the issue. It seems to be a db2205.codfw.wmnet specific issue only (all others have the right id).

On the bright side, this is only possible on wikis with very very low traffic, such as they barely generate any log, perform some maintenance and switch before the auto_increment can fix itself automatically.

set sql_bin_log=0; ALTER TABLE cu_log AUTO_INCREMENT=7;

on db2205 will fix the issue.

Many tables have different auto_increment value in different replicas. I saw this in ores_model and abuse_filter. I think I fixed abuse_filter but never got around to fix the rest. It's in the never ending list of stuff to fix :(

I wrote a quick script (P69464) to check which tables have different auto_increment values. The result is this: P69463 it is around 500 tables out of 50,000. Not too bad but definitely not great either. 187 of it is linter which can be replag (plus some other tables that are clearly replag, e.g. revision in wikidata) but 300 of them are serious issues, e.g. ores_model for ruwiki is 1 in one dc and 7 in another one. We need to: fix existing ones AND make sure it doesn't happen (which I think we still have faulty code in mw)

I double checked the linter drifts are not because of replag, e.g. you can check bdrwiki (s5) which is a new wiki and quite small.

In T375652#10203726, @Ladsgroup wrote:

I double checked the linter drifts are not because of replag, e.g. you can check bdrwiki (s5) which is a new wiki and quite small.

Also they don't seem to be caused by errors in the code. Nothing tries to set linter_id or insert it with value. Only used in reads or where condition.

Same for page_restrictions where it's showing difference in 163 wikis but no code actually writes to pr_id (at least not now) but since bdrwiki is a new wiki, I don't think this is an extremely old issue that's resolved by now. bdrwiki was created two months ago T371757#10045249

I fixed the dzwiki issue for right now:

cumin2024@db2205.codfw.wmnet[dzwiki]> set session sql_log_bin=0;
Query OK, 0 rows affected (0.031 sec)

cumin2024@db2205.codfw.wmnet[dzwiki]> ALTER TABLE cu_log AUTO_INCREMENT=7;
Query OK, 0 rows affected (0.034 sec)
Records: 0  Duplicates: 0  Warnings: 0

cumin2024@db2205.codfw.wmnet[dzwiki]> show create table cu_log;
+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------->
| Table  | Create Table                                                                                                                                                                                           >
+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------->
| cu_log | CREATE TABLE `cu_log` (
  `cul_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `cul_timestamp` varbinary(14) NOT NULL DEFAULT '',
  `cul_type` varbinary(30) NOT NULL DEFAULT '',
  `cul_target_id` int(10) unsigned NOT NULL DEFAULT 0,
  `cul_target_text` blob NOT NULL,
  `cul_target_hex` varbinary(255) NOT NULL DEFAULT '',
  `cul_range_start` varbinary(255) NOT NULL DEFAULT '',
  `cul_range_end` varbinary(255) NOT NULL DEFAULT '',
  `cul_actor` bigint(20) unsigned NOT NULL,
  `cul_reason_id` bigint(20) unsigned NOT NULL,
  `cul_reason_plaintext_id` bigint(20) unsigned NOT NULL,
  `cul_result_id` bigint(20) unsigned NOT NULL DEFAULT 0,
  `cul_result_plaintext_id` bigint(20) unsigned NOT NULL DEFAULT 0,
  PRIMARY KEY (`cul_id`),
  KEY `cul_timestamp` (`cul_timestamp`),
  KEY `cul_type_target` (`cul_type`,`cul_target_id`,`cul_timestamp`),
  KEY `cul_target_hex` (`cul_target_hex`,`cul_timestamp`),
  KEY `cul_range_start` (`cul_range_start`,`cul_timestamp`),
  KEY `cul_actor_time` (`cul_actor`,`cul_timestamp`)
) ENGINE=InnoDB AUTO_INCREMENT=7 DEFAULT CHARSET=binary ROW_FORMAT=COMPRESSED |
+--------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------->
1 row in set (0.032 sec)

Trying to see what mess we are dealing with regarding other 500 tables.

I wrote a script to go through the 500 cases and compare each database for that value. A nice pattern emerged, out of ~500 cases, 250 cases were ['db2205 (codfw master)', 'db2227', 'db1223', 'db1212', 'db1157'] having a different value than the rest of s3 (['db1189 (eqiad master)', 'db2149', 'db2209', 'db2194', 'db2190', 'db2156', 'db2177', 'db1198', 'db1166', 'db1175']) this clearly shows a split brain and/or skipped transactions and in all that I checked, the value of the first group were lower than values of the second group. Note that this is a not dc split brain, there are hosts from both dcs in both groups.

Suggested course of action:

• Reclone 'db2227', 'db1223', 'db1212', 'db1157' from other replicas.
• Switchover codfw master, reclone the old master from other ones
• Run the check again, this time include all other replicas (backup sources, etc.)
• Fix any other that's left from s3.
• Profit?

The other 250 cases seems to be different issues (replag for example).

Does that sound good to you @jcrespo ?

Forgot to link the result of the check:

No concerns. Look, if you can, if there is any pattern common to the issues both corrected T375507#10175248 & pending at T375507#10175251

Thanks. I don't have access to the pastes:

But those look like s7 issues. This is s3. Likely something similar as well but I need to investigate that separately :(

In T375652#10214455, @Ladsgroup wrote:

Thanks. I don't have access to the pastes:

I have added you to the SRE team, you should be able to see them now.

Thanks. There are a lot of s3 issues there indeed, let's run it again once the clean up is done and see what's left.

Mentioned in SAL (#wikimedia-operations) [2024-10-09T14:24:04Z] <ladsgroup@cumin1002> dbctl commit (dc=all): 'Depooling for reclone (T375652)', diff saved to https://phabricator.wikimedia.org/P69520 and previous config saved to /var/cache/conftool/dbconfig/20241009-142404-ladsgroup.json

Mentioned in SAL (#wikimedia-operations) [2024-10-09T18:26:32Z] <ladsgroup@cumin1002> dbctl commit (dc=all): 'Depool for reclone (T375652)', diff saved to https://phabricator.wikimedia.org/P69527 and previous config saved to /var/cache/conftool/dbconfig/20241009-182632-ladsgroup.json

Mentioned in SAL (#wikimedia-operations) [2024-10-09T22:50:55Z] <ladsgroup@cumin1002> dbctl commit (dc=all): 'Depool for reclone (T375652)', diff saved to https://phabricator.wikimedia.org/P69532 and previous config saved to /var/cache/conftool/dbconfig/20241009-225055-ladsgroup.json

So the eqiad ones have been recloned from db1198 and are pooled back. Next is codfw and specially its master. I will be out until Monday, I will take care of it then.

Mentioned in SAL (#wikimedia-operations) [2024-10-14T10:12:47Z] <ladsgroup@cumin1002> dbctl commit (dc=all): 'Depooling for reclone (T375652)', diff saved to https://phabricator.wikimedia.org/P69770 and previous config saved to /var/cache/conftool/dbconfig/20241014-101246-ladsgroup.json

Mentioned in SAL (#wikimedia-operations) [2024-10-14T10:13:55Z] <ladsgroup@cumin1002> dbctl commit (dc=all): 'Depooling for reclone (T375652)', diff saved to https://phabricator.wikimedia.org/P69771 and previous config saved to /var/cache/conftool/dbconfig/20241014-101354-ladsgroup.json

Mentioned in SAL (#wikimedia-operations) [2024-10-15T16:20:01Z] <ladsgroup@cumin1002> dbctl commit (dc=all): 'Depool for reclone (T375652)', diff saved to https://phabricator.wikimedia.org/P70002 and previous config saved to /var/cache/conftool/dbconfig/20241015-161934-ladsgroup.json

After the cloning, the total number of mismatch in auto_increment value reported is now around 300. In almost all cases that I have checked, it's very very likely caused by replag and nothing to worry about. These stood out (via checking on cases that master has lower value than replicas):

eowikivoyage geo_tags {1: ['db2123 (codfw master)', 'db2178', 'db2192', 'db2213', 'db1213', 'db1200', 'db1230', 'db1185'], 5305: ['db1183 (eqiad master)', 'db2211', 'db2157', 'db2171', 'db2128', 'db1161', 'db1210']}
frwiki cur {1: ['db2214 (codfw master)', 'db2229', 'db2224'], 310635: ['db1201 (eqiad master)', 'db2217', 'db2193', 'db2158', 'db2169', 'db2180', 'db2151', 'db1165', 'db1180', 'db1187', 'db1168', 'db1231', 'db1173']}
frwiki ores_model {1: ['db2214 (codfw master)', 'db2229', 'db2224'], 12: ['db1201 (eqiad master)', 'db2217', 'db2193', 'db2158', 'db2169', 'db2180', 'db2151', 'db1165', 'db1180', 'db1187', 'db1168', 'db1231', 'db1173']}
gorwiktionary linter {19823: ['db2123 (codfw master)'], 19359: ['db1183 (eqiad master)', 'db2211', 'db2178', 'db2157', 'db2192', 'db2171', 'db2213', 'db2128'], 19879: ['db1213', 'db1200', 'db1230', 'db1161', 'db1210', 'db1185']}
jawiki cur {1: ['db2214 (codfw master)', 'db2229', 'db2224'], 283002: ['db1201 (eqiad master)', 'db2217', 'db2193', 'db2158', 'db2169', 'db2180', 'db2151', 'db1165', 'db1180', 'db1187', 'db1168', 'db1231', 'db1173']}
kabwiki linter {94756: ['db2209 (codfw master)'], 94729: ['db1189 (eqiad master)', 'db2190', 'db2149', 'db2177', 'db2227', 'db2156', 'db1157', 'db1166', 'db1223', 'db1212', 'db1198', 'db1175'], 94773: ['db2194']}
mniwiktionary linter {3354: ['db2123 (codfw master)', 'db2211', 'db2178', 'db2157', 'db2192', 'db2171', 'db2213', 'db2128'], 3364: ['db1183 (eqiad master)'], 3926: ['db1213', 'db1200', 'db1230', 'db1161', 'db1210', 'db1185']}
ptwiki ores_model {2220: ['db2204 (codfw master)'], 2326: ['db1222 (eqiad master)', 'db1233', 'db1246', 'db1182', 'db1156', 'db1229', 'db1188', 'db1197', 'db1162'], 2218: ['db2207'], 1994: ['db2189'], 2256: ['db2148'], 2144: ['db2126'], 2298: ['db2238'], 2158: ['db2175'], 2278: ['db2225']}
ruwiki cur {1: ['db2214 (codfw master)', 'db2229', 'db2224'], 57403: ['db1201 (eqiad master)', 'db2217', 'db2193', 'db2158', 'db2169', 'db2180', 'db2151', 'db1165', 'db1180', 'db1187', 'db1168', 'db1231', 'db1173']}
ruwiki ores_model {1: ['db2214 (codfw master)', 'db2229', 'db2224'], 17: ['db1201 (eqiad master)', 'db2217', 'db2193', 'db2158', 'db2169', 'db2180', 'db2151', 'db1165', 'db1180', 'db1187', 'db1168', 'db1231', 'db1173']}

@Ladsgroup Did you add the backup sources into your checks? If not, could you do it (assuming it won't take much effort)? I would like to make sure backups are generated fine on both dcs before archiving them for the other ticket.

I forgot. I do it right after lunch.

I made some modifications and ran it again. I confirm that these hosts seems to have a different value and probably need to be recloned:

aawiki.page_restrictions {7: ['db1150.eqiad.wmnet:3313', 'db1154.eqiad.wmnet:3313', 'db1240.eqiad.wmnet:3313', 'db2139.codfw.wmnet:3313'], 8: ['db1157.eqiad.wmnet:3306', 'db1166.eqiad.wmnet:3306', 'db1175.eqiad.wmnet:3306', 'db1189.eqiad.wmnet:3306', 'db1198.eqiad.wmnet:3306', 'db1212.eqiad.wmnet:3306', 'db1223.eqiad.wmnet:3306', 'db2149.codfw.wmnet:3306', 'db2156.codfw.wmnet:3306', 'db2177.codfw.wmnet:3306', 'db2186.codfw.wmnet:3313', 'db2190.codfw.wmnet:3306', 'db2194.codfw.wmnet:3306', 'db2205.codfw.wmnet:3306', 'db2209.codfw.wmnet:3306', 'db2227.codfw.wmnet:3306', 'dbstore1007.eqiad.wmnet:3313']}

But I found something more concerning, many many tables. Almost all. Have auto increment value set to 1 in ['db2205.codfw.wmnet:3306', 'db2227.codfw.wmnet:3306']. db2205 just got reimaged and recloned today by @ABran-WMF.
I put some examples here:

aawikibooks.cur {935: ['db1150.eqiad.wmnet:3313', 'db1157.eqiad.wmnet:3306', 'db1166.eqiad.wmnet:3306', 'db1175.eqiad.wmnet:3306', 'db1189.eqiad.wmnet:3306', 'db1198.eqiad.wmnet:3306', 'db1212.eqiad.wmnet:3306', 'db1223.eqiad.wmnet:3306', 'db1240.eqiad.wmnet:3313', 'db2139.codfw.wmnet:3313', 'db2149.codfw.wmnet:3306', 'db2156.codfw.wmnet:3306', 'db2177.codfw.wmnet:3306', 'db2190.codfw.wmnet:3306', 'db2194.codfw.wmnet:3306', 'db2209.codfw.wmnet:3306', 'dbstore1007.eqiad.wmnet:3313'], 1: ['db2205.codfw.wmnet:3306', 'db2227.codfw.wmnet:3306']}
aawiki.cur {1106: ['db1150.eqiad.wmnet:3313', 'db1157.eqiad.wmnet:3306', 'db1166.eqiad.wmnet:3306', 'db1175.eqiad.wmnet:3306', 'db1189.eqiad.wmnet:3306', 'db1198.eqiad.wmnet:3306', 'db1212.eqiad.wmnet:3306', 'db1223.eqiad.wmnet:3306', 'db1240.eqiad.wmnet:3313', 'db2139.codfw.wmnet:3313', 'db2149.codfw.wmnet:3306', 'db2156.codfw.wmnet:3306', 'db2177.codfw.wmnet:3306', 'db2190.codfw.wmnet:3306', 'db2194.codfw.wmnet:3306', 'db2209.codfw.wmnet:3306', 'dbstore1007.eqiad.wmnet:3313'], 1: ['db2205.codfw.wmnet:3306', 'db2227.codfw.wmnet:3306']}
aawiki.cu_log {5: ['db1150.eqiad.wmnet:3313', 'db1157.eqiad.wmnet:3306', 'db1166.eqiad.wmnet:3306', 'db1175.eqiad.wmnet:3306', 'db1189.eqiad.wmnet:3306', 'db1198.eqiad.wmnet:3306', 'db1212.eqiad.wmnet:3306', 'db1223.eqiad.wmnet:3306', 'db1240.eqiad.wmnet:3313', 'db2139.codfw.wmnet:3313', 'db2149.codfw.wmnet:3306', 'db2156.codfw.wmnet:3306', 'db2177.codfw.wmnet:3306', 'db2190.codfw.wmnet:3306', 'db2194.codfw.wmnet:3306', 'db2209.codfw.wmnet:3306', 'dbstore1007.eqiad.wmnet:3313'], 1: ['db2205.codfw.wmnet:3306', 'db2227.codfw.wmnet:3306']}

And many many more, I haven't even got to end of aawikis yet.

But I found something more concerning, many many tables. Almost all. Have auto increment value set to 1 in ['db2205.codfw.wmnet:3306', 'db2227.codfw.wmnet:3306']. db2205 just got reimaged and recloned today by @ABran-WMF.

Update: After downgrading mariadb, this didn't happen again.

I did a new run of the script yesterday. The list of drifts in auto_increment value is in /home/ladsgroup/compreshensive_list_of_drifts_Nov_4 in cumin1002

I have not been able to reproduce the AUTO_INCREMENT bug (as I really want to report it to MariaDB).
{P70924}