Magento2: Deadlock occurs using REST API & OAuth 1.0a under high concurrency

[careys7]

Preconditions

1. Magento 2.1.7

Steps to reproduce

1. Create thousands of OAuth 1.0a requests to REST API (eg concurrency of 5 / sec)

Expected result

1. Requests complete successfully

Actual result

1. 401 Unauthorized response:
   {"message":"An error occurred validating the nonce"}

It appears this is caused by a deadlock where Magento is trying to clear out old consumer nonces:

LATEST DETECTED DEADLOCK
------------------------
2017-07-27 05:38:31 2b268f8e2700
*** (1) TRANSACTION:
TRANSACTION 801608608, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 1
MySQL thread id 8441440, OS thread handle 0x2b2664f4f700, query id 824710525 10.128.83.103 windsor updating
DELETE FROM `oauth_nonce` WHERE (timestamp <= 1501126711)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 125222 page no 25 n bits 344 index `OAUTH_NONCE_NONCE_CONSUMER_ID` of table `windsor`.`oauth_nonce` trx id 801608608 lock_mode X waiting
Record lock, heap no 269 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 30; hex 303030313365666139353038323531373365383139336335623831666432; asc 00013efa950825173e8193c5b81fd2; (total 32 bytes);
 1: len 4; hex 00000002; asc     ;;
 2: len 6; hex 00002f97b46a; asc   /  j;;
 3: len 7; hex b9000001640110; asc     d  ;;
 4: len 4; hex 597975c2; asc Yyu ;;

We had 48460 recent nonces in our table at the time:

mysql> select count(*) from oauth_nonce;
+----------+
| count(*) |
+----------+
|    48460 |
+----------+

The deadlock was caused by the following SQL run by Magento:

DELETE FROM `oauth_nonce` WHERE (timestamp <= 1501126711)

The above doesn't contain a limit (which extends execution time) and also is filtering based on timestamp which doesn't have an index:

mysql> show create table oauth_nonce;
+-------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table       | Create Table                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               |
+-------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| oauth_nonce | CREATE TABLE `oauth_nonce` (
  `nonce` varchar(32) NOT NULL COMMENT 'Nonce String',
  `timestamp` int(10) unsigned NOT NULL COMMENT 'Nonce Timestamp',
  `consumer_id` int(10) unsigned NOT NULL COMMENT 'Consumer ID',
  UNIQUE KEY `OAUTH_NONCE_NONCE_CONSUMER_ID` (`nonce`,`consumer_id`),
  KEY `OAUTH_NONCE_CONSUMER_ID_OAUTH_CONSUMER_ENTITY_ID` (`consumer_id`),
  CONSTRAINT `OAUTH_NONCE_CONSUMER_ID_OAUTH_CONSUMER_ENTITY_ID` FOREIGN KEY (`consumer_id`) REFERENCES `oauth_consumer` (`entity_id`) ON DELETE CASCADE
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='OAuth Nonce' |
+-------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

[orlangur]

Is it enough to add index on timestamp field to avoid deadlock?

[careys7]

That would definitely help (and is what we have done), I think it's best to delete this in increments, including an ORDER BY (for replication) and LIMIT to reduce the overall query time for a large DELETE operation.

[orlangur]

Thanks for the details! Would be great if you prepare a pull request including suggested changes. But if not, I believe core team received enough information to elaborate a fix.

[KarlDeux]

@magento-engcom-team does it make sense to use int(x) with order + limit + indexes instead of timestamp? Are we using or plan to use timestamp in the future for oauth nonces?

[vrann]

@KarlDeux timestamp is currently int(10), what exactly are you proposing? Thanks!

[KarlDeux]

@vrann I guess I had brain lag lol... checking this now.

[KarlDeux]

Adding the index allowed me to pass the given scenario. See referenced PR

[TomashKhamlai]

Hello, @careys7!
Could you help me to reproduce this issue? Here is what I tried:

1. Copy and modify the samples from devdocs
2. Create and activate the integration.
3. Generate the PHP-cURL with Postman
4. Copy the generated to the while-loop that will go through 70 000 loops
5. Run php bin/magento indexer:reindex

No deadlock. Can you give more details about the tool that was used when you experienced this issue?

[careys7]

Hey @TomashKhamlai we had about 18 requests / sec to the WebAPI at the same time that the cron was trying to clear the nonces out.

See Magento\Integration\Cron\CleanExpiredTokens. I don't know of any issues with the Magento indexes

[KarlDeux]

@TomashKhamlai @careys7,

That is exactly what I did, basically created a siege against the W.API with 20 r/s while the cron was cleaning and had a deadlock. After the indexes didn't get one.

Maybe under a higher load it might encounter a deadlock again but I feel like 20 r/s are fairly good.

[magento-engcom-team]

Hi @careys7. Thank you for your report.
The issue has been fixed in magento/magento2#13328 by @KarlDeux in 2.2-develop branch
Related commit(s):

• 521d11bb39bcddda5d9554240ec3c2d5ea653232

The fix will be available with the upcoming 2.2.6 release.

[magento-engcom-team]

Hi @careys7. Thank you for your report.
The issue has been fixed in magento/magento2#16715 by @rogyar in 2.3-develop branch
Related commit(s):

• a27fc6e23abc1dae1a52f8dc8d7489d0219347d6

The fix will be available with the upcoming 2.3.0 release.