Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mysql UNIQUE_CHECKS is disabled for data manipulation while it should only be disabled for schema manipulations #32283

Closed
1 of 5 tasks
hostep opened this issue Feb 25, 2021 · 3 comments · Fixed by #32286
Closed
1 of 5 tasks
Assignees
Labels
Issue: Confirmed Gate 3 Passed. Manual verification of the issue completed. Issue is confirmed Issue: ready for confirmation Priority: P1 Once P0 defects have been fixed, a defect having this priority is the next candidate for fixing. Progress: done Reproduced on 2.4.x The issue has been reproduced on latest 2.4-develop branch Severity: S1 Affects critical data or functionality and forces users to employ a workaround.

Comments

@hostep
Copy link
Contributor

hostep commented Feb 25, 2021

Preconditions (*)

  1. A Magento installation with declarative schema (so Magento 2.2.0 and higher)
  2. Some unknown combination of a mysql version or settings or some other environmental thing, is not always reproducible, which is very strange ...

Steps to reproduce (*)

  1. Have some data patch which inserts duplicated values in a database table which would normally be prevented by a unique key
  2. Run bin/magento setup:upgrade

Expected result (*)

  1. Duplicated value insertions shouldn't work

Actual result (*)

  1. Duplicated values get inserted, resulting in a corrupt database

Discussion

This was seen on two completely different shops when upgrading them from Magento 2.1.11 and 2.1.16 to 2.3.6-p1

This UpgradeWebsiteAttributes patch (which only executes when you upgrade from Magento < 2.2.0 to 2.2.0 or higher) can add duplicated values in certain catalog_product_entity_xxx tables. The ON DUPLICATE KEY UPDATE statement is being ignored because unique_checks are disabled by the OperationsExecutor.
After talking to some Magento core devs on Slack, they said the UNIQUE_CHECKS setting is supposed to be disabled for schema changes, but not for data manipulation. However UNIQUE_CHECKS is never enabled again after being disabled.
They further explained that the connection to the mysql server and thus the temporary changes being made to UNIQUE_CHECKS (and other variables) is supposed to be closed after schema manipulation is done and a new connection should start up before manipulating the data. This unfortunately doesn't seem to be the case.

This is a pretty serious issue in my opinion, not because only a certain Patch inside core Magento can trigger it, but because many customisations can also cause something like this if they aren't very careful.
And also because this is an invisible problem. You won't notice errors anywhere, unless you dump the database and try to import it again. So there is a chance people have run against this problem and are not aware of this and now have a corrupt database.

An example

I have a specific case where I can actually debug this, it only happens on a remote server, not on my local, but at least I can reproduce it every single time by:

  1. Importing a database backup from the Magento 2.1.11 shop
  2. Using the Magento 2.3.6-p1 codebase and running bin/magento setup:upgrade

In the 2.1.11 database, these records exist:

mysql> SELECT * FROM catalog_product_entity_datetime WHERE entity_id = 1961 AND attribute_id = 79;
+----------+--------------+----------+-----------+-------+
| value_id | attribute_id | store_id | entity_id | value |
+----------+--------------+----------+-----------+-------+
|    42598 |           79 |        0 |      1961 | NULL  |
|     2024 |           79 |        1 |      1961 | NULL  |
|    13960 |           79 |        2 |      1961 | NULL  |
+----------+--------------+----------+-----------+-------+
3 rows in set (0.00 sec)

After setup:upgrade ran, it now contains:

mysql> SELECT * FROM catalog_product_entity_datetime WHERE entity_id = 1961 AND attribute_id = 79;
+----------+--------------+----------+-----------+-------+
| value_id | attribute_id | store_id | entity_id | value |
+----------+--------------+----------+-----------+-------+
|    42598 |           79 |        0 |      1961 | NULL  |
|     2024 |           79 |        1 |      1961 | NULL  |
|    56790 |           79 |        1 |      1961 | NULL  |
|    13960 |           79 |        2 |      1961 | NULL  |
|    56791 |           79 |        2 |      1961 | NULL  |
+----------+--------------+----------+-----------+-------+
5 rows in set (0.00 sec)

You see 2 duplicated lines in here, even though there is a unique key set on the combination of attribute_id, store_id and entity_id columns.
There is only one website on this instance with one store and two storeviews.

I've added some debug code in some files, to demonstrate what is going on.
In OperationsExecutor::startSetupForAllConnections, added some var_dumps around disabling the unique_checks

            var_dump('*** Before manipulating unique_checks', $this->resourceConnection->getConnection($resource)
                ->query('SHOW VARIABLES LIKE "UNIQUE_CHECKS"')->fetch());

                $this->resourceConnection->getConnection($resource)
                ->query('SET UNIQUE_CHECKS=0');

            var_dump('*** After manipulating unique_checks', $this->resourceConnection->getConnection($resource)
                ->query('SHOW VARIABLES LIKE "UNIQUE_CHECKS"')->fetch());

This results in the following output:

string(37) "*** Before manipulating unique_checks"
array(2) {
  ["Variable_name"]=>
  string(13) "unique_checks"
  ["Value"]=>
  string(2) "ON"
}
string(36) "*** After manipulating unique_checks"
array(2) {
  ["Variable_name"]=>
  string(13) "unique_checks"
  ["Value"]=>
  string(3) "OFF"
}

In UpgradeWebsiteAttributes::apply:

$connection = $this->moduleDataSetup->getConnection();
var_dump('*** In UpgradeWebsiteAttributes', $connection->query('SHOW VARIABLES LIKE "UNIQUE_CHECKS"')->fetch());

Resulting in:

string(31) "*** In UpgradeWebsiteAttributes"
array(2) {
  ["Variable_name"]=>
  string(13) "unique_checks"
  ["Value"]=>
  string(3) "OFF"
}

This demonstrates that the unique_checks are still disabled when this data patch executes, which is very bad!

In UpgradeWebsiteAttributes::executeInsertions, to search for insert statements which can introduce duplicated values:

        foreach ($insertions as $insertion) {
            for ($i = 0; $i < 3; ++$i) {
                $key = ':entity_id' . $i;
                if (isset($insertion[$key]) && $insertion[$key] == 1961) {
                    var_dump('+++', $rawQuery, print_r($insertions, true), '+++');
                }
            }
        }

Resulting in:

string(3) "+++"
string(288) "INSERT INTO
            catalog_product_entity_datetime(attribute_id, store_id, entity_id, `value`)
            VALUES
            (:attribute_id0,:store_id0,:entity_id0,:value0),(:attribute_id1,:store_id1,:entity_id1,:value1)
            ON duplicate KEY UPDATE `value` = VALUES(`value`)"
string(336) "Array
(
    [0] => Array
        (
            [:attribute_id0] => 79
            [:store_id0] => 1
            [:entity_id0] => 1961
            [:value0] =>
        )

    [1] => Array
        (
            [:attribute_id1] => 79
            [:store_id1] => 2
            [:entity_id1] => 1961
            [:value1] =>
        )

)
"
string(3) "+++"
string(3) "+++"
string(288) "INSERT INTO
            catalog_product_entity_datetime(attribute_id, store_id, entity_id, `value`)
            VALUES
            (:attribute_id0,:store_id0,:entity_id0,:value0),(:attribute_id1,:store_id1,:entity_id1,:value1)
            ON duplicate KEY UPDATE `value` = VALUES(`value`)"
string(336) "Array
(
    [0] => Array
        (
            [:attribute_id0] => 79
            [:store_id0] => 1
            [:entity_id0] => 1961
            [:value0] =>
        )

    [1] => Array
        (
            [:attribute_id1] => 79
            [:store_id1] => 2
            [:entity_id1] => 1961
            [:value1] =>
        )

)
"
string(3) "+++"

This demonstrates that two records get inserted with the same values.
I do wonder why the end result is then not 3 duplicated entries, because one already existed from before the upgrade was ran. Not exactly sure what's going on there ...

The end result is a corrupt database. You won't notice this at all, unless you mysqldump the database and try to import it again, only then you see the error happening:

ERROR 1062 (23000) at line 2789: Duplicate entry '1961-79-1' for key 'CATALOG_PRODUCT_ENTITY_DATETIME_ENTITY_ID_ATTRIBUTE_ID_STORE_ID'

So there is a chance that more people already ran into this problem but never saw an error about it but now have a corrupt database.

Workaround

The workaround is to restore the unique_checks variable again in: OperationsExecutor::endSetupForAllConnections.

A PR will follow soon.

For people having to deal with this corrupt database and a way to fix it (which isn't easy nor explained very well on the world wide web), you can:

  • Run mysqldump with the --extended-insert=FALSE flag but only for the tables with problems
  • Run mysql with the -f flag to import that dump again, it will output warnings about all the duplicated entries but continues to import the other ones.

Be VERY CAREFUL HERE, triple check what you are doing here before executing this on a production environment.


Please provide Severity assessment for the Issue as Reporter. This information will help during Confirmation and Issue triage processes.

  • Severity: S0 - Affects critical data or functionality and leaves users without workaround.
  • Severity: S1 - Affects critical data or functionality and forces users to employ a workaround.
  • Severity: S2 - Affects non-critical data or functionality and forces users to employ a workaround.
  • Severity: S3 - Affects non-critical data or functionality and does not force users to employ a workaround.
  • Severity: S4 - Affects aesthetics, professional look and feel, “quality” or “usability”.
@m2-assistant
Copy link

m2-assistant bot commented Feb 25, 2021

Hi @hostep. Thank you for your report.
To help us process this issue please make sure that you provided the following information:

  • Summary of the issue
  • Information on your environment
  • Steps to reproduce
  • Expected and actual results

Please make sure that the issue is reproducible on the vanilla Magento instance following Steps to reproduce. To deploy vanilla Magento instance on our environment, please, add a comment to the issue:

@magento give me 2.4-develop instance - upcoming 2.4.x release

For more details, please, review the Magento Contributor Assistant documentation.

Please, add a comment to assign the issue: @magento I am working on this


⚠️ According to the Magento Contribution requirements, all issues must go through the Community Contributions Triage process. Community Contributions Triage is a public meeting.

🕙 You can find the schedule on the Magento Community Calendar page.

📞 The triage of issues happens in the queue order. If you want to speed up the delivery of your contribution, please join the Community Contributions Triage session to discuss the appropriate ticket.

🎥 You can find the recording of the previous Community Contributions Triage on the Magento Youtube Channel

✏️ Feel free to post questions/proposals/feedback related to the Community Contributions Triage process to the corresponding Slack Channel

@m2-community-project m2-community-project bot added this to Ready for Confirmation in Issue Confirmation and Triage Board Feb 25, 2021
@m2-community-project m2-community-project bot added Severity: S1 Affects critical data or functionality and forces users to employ a workaround. Priority: P1 Once P0 defects have been fixed, a defect having this priority is the next candidate for fixing. labels Feb 26, 2021
@hostep
Copy link
Contributor Author

hostep commented Apr 8, 2021

Looks like others bumped into this same problem before: #28326

@m2-community-project m2-community-project bot added this to Pull Request In Progress in High Priority Backlog Apr 8, 2021
@m2-community-project m2-community-project bot removed this from Ready for Confirmation in Issue Confirmation and Triage Board Apr 8, 2021
@engcom-Hotel engcom-Hotel added Issue: Confirmed Gate 3 Passed. Manual verification of the issue completed. Issue is confirmed Reproduced on 2.4.x The issue has been reproduced on latest 2.4-develop branch labels Aug 16, 2021
@magento-engcom-team
Copy link
Contributor

✅ Confirmed by @engcom-Hotel
Thank you for verifying the issue. Based on the provided information internal tickets MC-43094 were created

Issue Available: @engcom-Hotel, You will be automatically unassigned. Contributors/Maintainers can claim this issue to continue. To reclaim and continue work, reassign the ticket to yourself.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Issue: Confirmed Gate 3 Passed. Manual verification of the issue completed. Issue is confirmed Issue: ready for confirmation Priority: P1 Once P0 defects have been fixed, a defect having this priority is the next candidate for fixing. Progress: done Reproduced on 2.4.x The issue has been reproduced on latest 2.4-develop branch Severity: S1 Affects critical data or functionality and forces users to employ a workaround.
Projects
Development

Successfully merging a pull request may close this issue.

3 participants