Problems with dropbox accounts with updateCreds: Failure: 1205 Lock wait timeout exceeded; try restarting transaction

[crspybits]

When I use a dropbox account to add a user, it is doing an updateCreds and getting

Failure: 1205 Lock wait timeout exceeded; try restarting transaction
[2020-08-26T03:23:00.192Z] [ERROR] [UserRepository.swift:230 updateCreds(creds:forUser:accountManager:)] Failed updating User: executionError

So far my workaround is to make a User updateCreds not required.

I'm going to add in test cases for User updateCreds specifically.
And, hopefully, other tests as well.

[crspybits]

So far, I've added two test cases:

DatabaseTests.IntegrationDatabaseTests/testFakeAddUser-- this is intended to reproduce all of "relevant" database actions when calling the addUser endpoint with dropbox when the needToGenerateTokens returns true.

DatabaseTests.SpecificDatabaseTests_UserRepository/testUpdateCreds-- Just exercises the User updateCreds method.

and I tried commenting out the code that adds the second db connection in the server.

But no luck so far. I can't figure out why this was happening when ServerDropboxAccount had needToGenerateTokens returning true.

[crspybits]

mysql> SHOW ENGINE INNODB STATUS;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    110
Current database: *** NONE ***

| InnoDB |      | 
=====================================
2020-08-25 21:52:06 0x7000096ce000 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 43 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 77 srv_active, 0 srv_shutdown, 62771 srv_idle
srv_master_thread log flush and writes: 62848
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 388
OS WAIT ARRAY INFO: signal count 452
RW-shared spins 0, rounds 1039, OS waits 364
RW-excl spins 0, rounds 2563, OS waits 3
RW-sx spins 133, rounds 2155, OS waits 11
Spin rounds per wait: 1039.00 RW-shared, 2563.00 RW-excl, 16.20 RW-sx
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2020-08-25 21:52:00 0x700009712000  Cannot drop table `syncserver`.`sharinggroup`
because it is referenced by `syncserver`.`masterversion`
------------
TRANSACTIONS
------------
Trx id counter 2787193
Purge done for trx's n:o < 2787160 undo n:o < 0 state: running but idle
History list length 63
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 281479531479496, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479531476784, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 2787192, ACTIVE 5 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 107, OS thread handle 123145459884032, query id 1903 localhost 127.0.0.1 crspybits updating
UPDATE User SET creds=? WHERE userId=?
------- TRX HAS BEEN WAITING 5 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 211218 page no 4 n bits 72 index userId of table `syncserver`.`user` trx id 2787192 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 8000000000000001; asc         ;;
 1: len 7; hex 44726f70626f78; asc Dropbox;;
 2: len 30; hex <snip>; (total 40 bytes);

------------------
---TRANSACTION 2787191, ACTIVE 5 sec
5 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 3
MySQL thread id 109, OS thread handle 123145459605504, query id 1901 localhost 127.0.0.1 crspybits
Trx read view will not see trx with id >= 2787191, sees < 2787191
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
684 OS file reads, 8898 OS file writes, 3851 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 5.30 writes/s, 2.49 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
0.30 hash searches/s, 17.49 non-hash searches/s
---
LOG
---
Log sequence number 5690346180
Log flushed up to   5690346180
Pages flushed up to 5690346180
Last checkpoint at  5690346171
0 pending log flushes, 0 pending chkp writes
2182 log i/o's done, 1.42 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137428992
Dictionary memory allocated 161589
Buffer pool size   8192
Free buffers       6256
Database pages     1935
Old database pages 694
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 651, created 1284, written 5546
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1935, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=4232, Main thread ID=123145454219264, state: sleeping
Number of rows inserted 6644, updated 7, deleted 0, read 4358
6.16 inserts/s, 0.00 updates/s, 0.00 deletes/s, 4.02 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

[crspybits]

mysql> show processlist;
+-----+-----------+-----------------+------------+---------+------+----------+----------------
------------------------+
| Id  | User      | Host            | db         | Command | Time | State    | Info                                   |
+-----+-----------+-----------------+------------+---------+------+----------+----------------------------------------+
| 110 | crspybits | localhost       | syncserver | Query   |    0 | starting | show processlist                       |
| 119 | crspybits | localhost:59061 | syncserver | Sleep   |    4 |          | NULL                                   |
| 120 | crspybits | localhost:59063 | syncserver | Execute |    3 | updating | UPDATE User SET creds=? WHERE userId=? |
| 121 | crspybits | localhost:59064 | syncserver | Sleep   |    3 |          | NULL                                   |
| 122 | crspybits | localhost:59066 | syncserver | Sleep   |    3 |          | NULL                                   |
+-----+-----------+-----------------+------------+---------+------+----------+----------------------------------------+
5 rows in set (0.00 sec)

[crspybits]

mysql> show open tables where In_Use > 0 ;
+------------+-------+--------+-------------+
| Database   | Table | In_use | Name_locked |
+------------+-------+--------+-------------+
| syncserver | user  |      1 |           0 |
+------------+-------+--------+-------------+
1 row in set (0.00 sec)

[crspybits]

mysql> USE INFORMATION_SCHEMA;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

mysql> SELECT * FROM INNODB_LOCKS;
+--------------------+-------------+-----------+-----------+---------------------+------------+------------+-----------+----------+-----------+
| lock_id            | lock_trx_id | lock_mode | lock_type | lock_table          | lock_index | lock_space | lock_page | lock_rec | lock_data |
+--------------------+-------------+-----------+-----------+---------------------+------------+------------+-----------+----------+-----------+
| 2787720:211265:4:2 | 2787720     | X         | RECORD    | `syncserver`.`user` | userId     |     211265 |         4 |        2 | 1         |
| 2787719:211265:4:2 | 2787719     | X         | RECORD    | `syncserver`.`user` | userId     |     211265 |         4 |        2 | 1         |
+--------------------+-------------+-----------+-----------+---------------------+------------+------------+-----------+----------+-----------+
2 rows in set, 1 warning (0.00 sec)

[crspybits]

https://stackoverflow.com/questions/13148630/how-do-i-find-which-transaction-is-causing-a-waiting-for-table-metadata-lock-s/23757255

[crspybits]

Things to try:

1. Try a different mySQL instance-- e.g., on AWS RDS to see if something has corrupted in my existing mySQL instance.
2. Get a baseline version of the SHOW ENGINE INNODB STATUS; results-- with the server "at rest" to see if there is a lock held, with the User table, by default.
3. Try creating a Google user with my old iOS client and the new server. The ServerGoogleAccount has needToGenerateTokens returning true. See if this causes the same problem.

[crspybits]

Baseline-- with server up but not running requests currently.

| InnoDB |      | 
=====================================
2020-08-26 20:53:42 0x7000096ce000 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 0 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2009 srv_active, 0 srv_shutdown, 129907 srv_idle
srv_master_thread log flush and writes: 131916
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 5738
OS WAIT ARRAY INFO: signal count 6233
RW-shared spins 0, rounds 17328, OS waits 5493
RW-excl spins 0, rounds 26876, OS waits 13
RW-sx spins 1037, rounds 17523, OS waits 46
Spin rounds per wait: 17328.00 RW-shared, 26876.00 RW-excl, 16.90 RW-sx
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2020-08-25 22:42:24 0x7000096ce000  Cannot drop table `syncserver`.`sharinggroup`
because it is referenced by `syncserver`.`sharinginvitation`
------------
TRANSACTIONS
------------
Trx id counter 2823520
Purge done for trx's n:o < 2823519 undo n:o < 0 state: running but idle
History list length 26
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 281479531477688, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281479531476784, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
741 OS file reads, 114381 OS file writes, 57729 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
0.00 hash searches/s, 2000.00 non-hash searches/s
---
LOG
---
Log sequence number 5774137019
Log flushed up to   5774137019
Pages flushed up to 5774137019
Last checkpoint at  5774137010
0 pending log flushes, 0 pending chkp writes
33263 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137428992
Dictionary memory allocated 166089
Buffer pool size   8192
Free buffers       1024
Database pages     7167
Old database pages 2625
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 406, not young 2202
0.00 youngs/s, 0.00 non-youngs/s
Pages read 700, created 17401, written 64493
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 7167, unzip_LRU len: 0
I/O sum[65]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=4232, Main thread ID=123145454219264, state: sleeping
Number of rows inserted 245379, updated 344, deleted 467, read 166142
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
 |