Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-28731

Race condition on log checkpoint

Details

    Description

      This was found while testing MDEV-13542.

      mysqld: /data/Server/bb-10.6-MDEV-13542L/storage/innobase/buf/buf0flu.cc:175: void buf_pool_t::insert_into_flush_list(buf_block_t*, lsn_t): Assertion `((&(&log_sys.flush_order_mutex)->m_mutex)->count > 0 && pthread_equal(pthread_self(), (&(&log_sys.flush_order_mutex)->m_mutex)->thread))' failed.

      The corresponding source code is:

      void buf_pool_t::insert_into_flush_list(buf_block_t *block, lsn_t lsn)
      		 
      {
      		 
        mysql_mutex_assert_not_owner(&mutex);
      		 
        mysql_mutex_assert_owner(&log_sys.flush_order_mutex);

      The assertion fails, because log_sys.flush_order_mutex is not being held, even though it is supposed to be.

      This could lead to incorrect log checkpoints being written, that is, invalid crash recovery or backup. The fix is simple:

      diff --git a/storage/innobase/mtr/mtr0mtr.cc b/storage/innobase/mtr/mtr0mtr.cc
      		 
      index 2feb5a0583f..f13b677742b 100644
      		 
      --- a/storage/innobase/mtr/mtr0mtr.cc
      		 
      +++ b/storage/innobase/mtr/mtr0mtr.cc
      		 
      @@ -1263,4 +1263,6 @@ void mtr_t::modify(const buf_block_t &block)
      		 
         }
      		 
         iteration.functor.found->type= static_cast<mtr_memo_type_t>
      		 
           (iteration.functor.found->type | MTR_MEMO_MODIFY);
      		 
      +  if (is_block_dirtied(&block))
      		 
      +    m_made_dirty= true;
      		 
       }

      The flag mtr_t::m_made_dirty will inform mtr_t::commit() to acquire the mutex.

      Attachments

        Issue Links

          is caused by

          Task - A task that needs to be done. MDEV-12353 Efficient InnoDB redo log record format

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22107 Restore accidentally orphaned MTR_MEMO_MODIFY

          • Major - Major loss of function.
          • Closed

          Activity

            marko Marko Mäkelä added a comment -

            Even after this fix, we got a failure on FreeBSD 13.0 that I was not able to repeat:

            • In a FreeBSD 13.0 virtual machine with a CMAKE_BUILD_TYPE=RelWithDebInfo build
            • On Linux (liburing or innodb_use_native_aio=0) on ext4fs on NVMe, both CMAKE_BUILD_TYPE=Debug and CMAKE_BUILD_TYPE=RelWithDebInfo

            The failure looks like this:

            10.6 8920a6f80b91592f3bb072d0707ff21362702144

            		 
            encryption.tempfiles_encrypted 'ctr,innodb' w4 [ pass ]  20339
            		 
            worker[4] > Restart [mysqld.1 - pid: 9200, winpid: 9200] - running with different options '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --plugin-load-add=file_key_management.so --loose-file-key-management --loose-file-key-management-filename=/usr/local/share/mysql-test/std_data/keys.txt --file-key-management-encryption-algorithm=aes_cbc --skip-innodb-read-only-compressed --innodb-change-buffering=none --innodb-default-encryption-key-id=20' != '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --plugin-load-add=file_key_management.so --loose-file-key-management --loose-file-key-management-filename=/usr/local/share/mysql-test/std_data/keys.txt --file-key-management-encryption-algorithm=aes_ctr --skip-innodb-read-only-compressed --loose-sequence --loose-sequence --encrypt-tmp_files=ON'
            		 
            …
            		 
            encryption.innodb-redo-nokeys 'cbc,innodb' w4 [ fail ]  Found warnings/errors in server log file!
            		 
                    Test ended at 2022-06-02 15:22:32
            		 
            line
            		 
            2022-06-02 15:22:30 0 [ERROR] InnoDB: Missing FILE_CHECKPOINT at 1166935 between the checkpoint 51825 and the end 1232384.
            		 
            ^ Found warnings in /tmp/var/4/log/mysqld.1.err

            The test is not encrypting the log; it is testing recovery of encrypted tables when the keys are missing.

            marko Marko Mäkelä added a comment - Even after this fix, we got a failure on FreeBSD 13.0 that I was not able to repeat: In a FreeBSD 13.0 virtual machine with a CMAKE_BUILD_TYPE=RelWithDebInfo build On Linux (liburing or innodb_use_native_aio=0 ) on ext4fs on NVMe, both CMAKE_BUILD_TYPE=Debug and CMAKE_BUILD_TYPE=RelWithDebInfo The failure looks like this: 10.6 8920a6f80b91592f3bb072d0707ff21362702144 encryption.tempfiles_encrypted 'ctr,innodb' w4 [ pass ] 20339 worker[4] > Restart [mysqld.1 - pid: 9200, winpid: 9200] - running with different options '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --plugin-load-add=file_key_management.so --loose-file-key-management --loose-file-key-management-filename=/usr/local/share/mysql-test/std_data/keys.txt --file-key-management-encryption-algorithm=aes_cbc --skip-innodb-read-only-compressed --innodb-change-buffering=none --innodb-default-encryption-key-id=20' != '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --plugin-load-add=file_key_management.so --loose-file-key-management --loose-file-key-management-filename=/usr/local/share/mysql-test/std_data/keys.txt --file-key-management-encryption-algorithm=aes_ctr --skip-innodb-read-only-compressed --loose-sequence --loose-sequence --encrypt-tmp_files=ON' … encryption.innodb-redo-nokeys 'cbc,innodb' w4 [ fail ] Found warnings/errors in server log file! Test ended at 2022-06-02 15:22:32 line 2022-06-02 15:22:30 0 [ERROR] InnoDB: Missing FILE_CHECKPOINT at 1166935 between the checkpoint 51825 and the end 1232384. ^ Found warnings in /tmp/var/4/log/mysqld.1.err The test is not encrypting the log; it is testing recovery of encrypted tables when the keys are missing.

            People

              marko Marko Mäkelä
              marko Marko Mäkelä
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.