Skip to content
  • zzak's avatar
    6bdff8b6
    Add timeout to avoid nested deadlock flakey test · 6bdff8b6
    zzak authored
    Due to the large number of times I ran the whole suite to debugging
    other flakey tests, I was able to reproduce the issue similar to #49841.
    
    That issue has still happened recently, but as we've noted (can't find
    the ticket now) that the Active Record tests sometimes run other
    adapter's tests leading to confusion that it might be specific to
    sqlite, but it's not.
    
    I can reproduce this by running the tests with mysql2 many many times,
    eventually it hangs. And when it does the last thing in `debug.log`:
    
    ```
    ActiveRecord::NestedDeadlockTest::Sample Pluck (0.1ms)  SELECT `samples`.`value` FROM `samples`
     (5.3ms)  DROP TABLE IF EXISTS `samples`
     (1.1ms)  DROP TABLE IF EXISTS `samples`
     (7.1ms)  CREATE TABLE `samples` (`id` bigint NOT NULL AUTO_INCREMENT PRIMARY KEY, `value` int)
    TRANSACTION (0.0ms)  BEGIN
    ActiveRecord::NestedDeadlockTest::Sample Create (0.2ms)  INSERT INTO `samples` (`value`) VALUES (?)  [["value", 1]]
    TRANSACTION (1.4ms)  COMMIT
    TRANSACTION (0.0ms)  BEGIN
    ActiveRecord::NestedDeadlockTest::Sample Create (0.1ms)  INSERT INTO `samples` (`value`) VALUES (?)  [["value", 2]]
    TRANSACTION (1.6ms)  COMMIT
    TRANSACTION (0.2ms)  BEGIN
    TRANSACTION (0.1ms)  BEGIN
    ActiveRecord::NestedDeadlockTest::Sample Load (0.3ms)  SELECT `samples`.* FROM `samples` LIMIT ?  [["LIMIT", 1]]
    TRANSACTION (0.0ms)  SAVEPOINT active_record_1
    ActiveRecord::NestedDeadlockTest::Sample Load (0.4ms)  SELECT `samples`.* FROM `samples` LIMIT ?  [["LIMIT", 1]]
    ActiveRecord::NestedDeadlockTest::Sample Load (0.4ms)  SELECT `samples`.* FROM `samples` WHERE `samples`.`id` = ? LIMIT ? FOR UPDATE  [["id", 2], ["LIMIT", 1]]
    TRANSACTION (0.1ms)  SAVEPOINT active_record_1
    TRANSACTION (0.0ms)  ROLLBACK TO SAVEPOINT active_record_1
    ActiveRecord::NestedDeadlockTest::Sample Load (0.3ms)  SELECT `samples`.* FROM `samples` WHERE `samples`.`id` = ? LIMIT ? FOR UPDATE  [["id", 1], ["LIMIT", 1]]
    TRANSACTION (0.4ms)  ROLLBACK
    ```
    
    I tried gdb, strace, lsof, but the logs were always on the same test
    class when it happened. I have a coredump if anyone one the team wants
    to take a look.
    6bdff8b6
    Add timeout to avoid nested deadlock flakey test
    zzak authored
    Due to the large number of times I ran the whole suite to debugging
    other flakey tests, I was able to reproduce the issue similar to #49841.
    
    That issue has still happened recently, but as we've noted (can't find
    the ticket now) that the Active Record tests sometimes run other
    adapter's tests leading to confusion that it might be specific to
    sqlite, but it's not.
    
    I can reproduce this by running the tests with mysql2 many many times,
    eventually it hangs. And when it does the last thing in `debug.log`:
    
    ```
    ActiveRecord::NestedDeadlockTest::Sample Pluck (0.1ms)  SELECT `samples`.`value` FROM `samples`
     (5.3ms)  DROP TABLE IF EXISTS `samples`
     (1.1ms)  DROP TABLE IF EXISTS `samples`
     (7.1ms)  CREATE TABLE `samples` (`id` bigint NOT NULL AUTO_INCREMENT PRIMARY KEY, `value` int)
    TRANSACTION (0.0ms)  BEGIN
    ActiveRecord::NestedDeadlockTest::Sample Create (0.2ms)  INSERT INTO `samples` (`value`) VALUES (?)  [["value", 1]]
    TRANSACTION (1.4ms)  COMMIT
    TRANSACTION (0.0ms)  BEGIN
    ActiveRecord::NestedDeadlockTest::Sample Create (0.1ms)  INSERT INTO `samples` (`value`) VALUES (?)  [["value", 2]]
    TRANSACTION (1.6ms)  COMMIT
    TRANSACTION (0.2ms)  BEGIN
    TRANSACTION (0.1ms)  BEGIN
    ActiveRecord::NestedDeadlockTest::Sample Load (0.3ms)  SELECT `samples`.* FROM `samples` LIMIT ?  [["LIMIT", 1]]
    TRANSACTION (0.0ms)  SAVEPOINT active_record_1
    ActiveRecord::NestedDeadlockTest::Sample Load (0.4ms)  SELECT `samples`.* FROM `samples` LIMIT ?  [["LIMIT", 1]]
    ActiveRecord::NestedDeadlockTest::Sample Load (0.4ms)  SELECT `samples`.* FROM `samples` WHERE `samples`.`id` = ? LIMIT ? FOR UPDATE  [["id", 2], ["LIMIT", 1]]
    TRANSACTION (0.1ms)  SAVEPOINT active_record_1
    TRANSACTION (0.0ms)  ROLLBACK TO SAVEPOINT active_record_1
    ActiveRecord::NestedDeadlockTest::Sample Load (0.3ms)  SELECT `samples`.* FROM `samples` WHERE `samples`.`id` = ? LIMIT ? FOR UPDATE  [["id", 1], ["LIMIT", 1]]
    TRANSACTION (0.4ms)  ROLLBACK
    ```
    
    I tried gdb, strace, lsof, but the logs were always on the same test
    class when it happened. I have a coredump if anyone one the team wants
    to take a look.
Loading