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

MTR worker aborts after server restart failure

    XMLWordPrintable

    Details

      Description

      When the server fails to start at the beginning of a test, the corresponding MTR worker immediately aborts, doesn't finalize the test and doesn't run any other ones.
      As a result,

      • failures aren't recorded in final results or in the buildbot database;
      • if all parallel workers abort this way, the test suite execution aborts prematurely.

      $ cat /data/bug/1.test
      select 1;
       
      $ cat /data/bug/1.cnf
      !include include/default_my.cnf
       
      [mysqld.1]
      foo
      

      $ perl ./mtr bug.1 main.1st --noreorder  --force --max-test-fail=0
      

      10.2 2df99f21 (bad)

      ==============================================================================
       
      TEST                                      RESULT   TIME (ms) or COMMENT
      --------------------------------------------------------------------------
       
      worker[1] Using MTR_BUILD_THREAD 301, with reserved ports 16020..16039
      worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 2668675, winpid: 2668675] died after mysql-test-run waited 0.2 seconds for /mnt-hd8t/bld/10.2-debug-nightly/mysql-test/var/run/mysqld.1.pid to be created.
      worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command /mnt-hd8t/bld/10.2-debug-nightly/bin/mysqld  --defaults-group-suffix=.1 --defaults-file=/mnt-hd8t/bld/10.2-debug-nightly/mysql-test/var/my.cnf --log-output=file --core-file --loose-debug-sync-timeout=300
      mysql-test-run: *** ERROR: Test suite aborted
      

      The desired result is of course that the test is marked as failed and execution of the test suite continues normally, like this:

      10.2.37 (good)

      ==============================================================================
       
      TEST                                      RESULT   TIME (ms) or COMMENT
      --------------------------------------------------------------------------
       
      worker[1] Using MTR_BUILD_THREAD 301, with reserved ports 16020..16039
      select 1;
      1
      1
      bug.2                                    [ fail ]
              Test ended at 2021-11-04 16:20:03
       
      CURRENT_TEST: bug.2
       
       
      Server [mysqld.1 - pid: 2669220, winpid: 2669220, exit: 512] failed during test run
      Server log from this test:
      ----------SERVER LOG START-----------
      2021-11-04 16:20:02 139846509990656 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld (mysqld 10.2.37-MariaDB-debug-log) starting as process 2669205 ...
      2021-11-04 16:20:02 139846509990656 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32198)
      2021-11-04 16:20:02 139846509990656 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'SEQUENCE' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'partition' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'InnoDB' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_LOCKS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_MUTEXES' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMPMEM' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'FEEDBACK' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'user_variables' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_TRX' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_METRICS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
      2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
      2021-11-04 16:20:02 139846509990656 [Warning] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--loose-pam-debug'
      2021-11-04 16:20:02 139846509990656 [Note] Server socket created on IP: '127.0.0.1'.
      2021-11-04 16:20:02 139846509990656 [Note] Reading of all Master_info entries succeeded
      2021-11-04 16:20:02 139846509990656 [Note] Added new Master_info '' to hash table
      2021-11-04 16:20:02 139846509990656 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: ready for connections.
      Version: '10.2.37-MariaDB-debug-log'  socket: '/mnt-hd8t/bld/10.2.37-asan/mysql-test/var/tmp/mysqld.1.sock'  port: 16020  Source distribution
      2021-11-04 16:20:02 139846330197760 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
      2021-11-04 16:20:02 139846330197760 [Note] Event Scheduler: Purging the queue. 0 events
      2021-11-04 16:20:02 139846330197760 [Note] Debug sync points hit:                   855
      2021-11-04 16:20:02 139846330197760 [Note] Debug sync points executed:              0
      2021-11-04 16:20:02 139846330197760 [Note] Debug sync points max active per thread: 0
      2021-11-04 16:20:02 139846330197760 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: Shutdown complete
       
      2021-11-04 16:20:03 140490684326656 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld (mysqld 10.2.37-MariaDB-debug-log) starting as process 2669221 ...
      2021-11-04 16:20:03 140490684326656 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32198)
      2021-11-04 16:20:03 140490684326656 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'SEQUENCE' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'partition' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'InnoDB' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_LOCKS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_MUTEXES' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMPMEM' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'FEEDBACK' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'user_variables' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_TRX' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_METRICS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
      2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
      2021-11-04 16:20:03 140490684326656 [Warning] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--loose-pam-debug'
      2021-11-04 16:20:03 140490684326656 [ERROR] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--foo'
      2021-11-04 16:20:03 140490684326656 [ERROR] Aborting
       
      ----------SERVER LOG END-------------
      mysqltest failed but provided no output
       
       
       - saving '/mnt-hd8t/bld/10.2.37-asan/mysql-test/var/log/bug.2/' to '/mnt-hd8t/bld/10.2.37-asan/mysql-test/var/log/bug.2/'
      ***Warnings generated in error logs during shutdown after running tests: bug.2
       
      2021-11-04 16:20:03 140490684326656 [ERROR] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--foo'
      2021-11-04 16:20:03 140490684326656 [ERROR] Aborting
       
      main.1st                                 [ pass ]      2
      --------------------------------------------------------------------------
      The servers were restarted 1 times
      Spent 0.002 of 6 seconds executing testcases
       
      Completed: Failed 1/2 tests, 50.00% were successful.
       
      Failing test(s): bug.2
       
      The log files in var/log may give you some hint of what went wrong.
       
      If you want to report this error, please read first the documentation
      at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
       
      Errors/warnings were found in logfiles during server shutdown after running the
      following sequence(s) of tests:
          bug.2
      mysql-test-run: *** ERROR: there were failing test cases
      

      It is (partially) a regression introduced by this commit

      commit feacc0aaf2860a391f0febbc11e42f1d09598705 (HEAD)
      Author: Sergei Golubchik
      Date:   Mon Jan 25 13:16:04 2021 +0100
       
          unify mtr handling of debuggers
      

      particularly by this change

      @@ -5455,11 +5120,8 @@ sub mysqld_start ($$) {
           mtr_verbose("Started $mysqld->{proc}");
         }
       
      -  if ( $wait_for_pid_file &&
      -       !sleep_until_file_created($mysqld->value('pid-file'),
      -                                $opt_start_timeout,
      -                                $mysqld->{'proc'},
      -                                 $warn_seconds))
      +  if (!sleep_until_file_created($mysqld->value('pid-file'),
      +                      $opt_start_timeout, $mysqld->{'proc'}, $warn_seconds))
         {
           my $mname= $mysqld->name();
           mtr_error("Failed to start mysqld $mname with command $exe");
      

      That's where the worker aborts.
      Before the change, $wait_for_pid_file would be true for all debuggers, but false for the "normal" (non-debugging) execution. Apparently it was a very intentional distinction.

      Later when rr was introduced, it inherited logic of debuggers, so it would abort with rr execution too, I'm not sure whether it was intentional or not.

      But now the logic is unified and the $wait_for_pid_file variable has gone away, so it always aborts, even for normal execution, hence the effects described earlier.

      I can de-unify it by introducing a flag based on the initial MTR call options, but maybe it's more consistent to do something about it in My::Debugger (to make the distinction when the execution should be aborted and when it should continue).

        Attachments

          Activity

            People

            Assignee:
            serg Sergei Golubchik
            Reporter:
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 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.