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

Print server version to error log instead of stderr during startup process

    XMLWordPrintable

Details

    • Bug
    • Status: Open (View Workflow)
    • Major
    • Resolution: Unresolved
    • 10.2.29, 10.3.20, 10.4.10
    • 10.4
    • Server
    • None

    Description

      It would be great if MariaDB printed the server version to the error log earlier during the startup process than it currently does.

      The server does print the server version immediately during the startup process at this line of code:

      https://github.com/MariaDB/server/blob/mariadb-10.2.29/sql/mysqld.cc#L4326

      However, this output does not go to the error log. Instead, this output is printed to stderr before stderr is redirected to the error log. For example, we can see this happening if we check with strace:

      write(2, "2019-11-14  0:09:55 0 [Note] mysqld (mysqld 10.3.18-MariaDB-log) starting as process 24975 ...\n", 95) = 95
      ...
      open("/var/log/mysql/mariadb.err", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
      lseek(3, 0, SEEK_END)                   = 2873034
      dup3(3, 1, 0)                           = 1
      close(3)                                = 0
      open("/var/log/mysql/mariadb.err", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
      lseek(3, 0, SEEK_END)                   = 2873034
      dup3(3, 2, 0)                           = 2
      close(3)                                = 0
      

      This means that if the server is started with systemd (which is the most common startup method now), then the output goes to the systemd journal. For example:

      $ sudo journalctl -u mariadb | grep "starting as process"
      Nov 08 19:38:27 ip-172-30-0-105.us-west-2.compute.internal mysqld[4264]: 2019-11-08 19:38:27 0 [Note] /usr/sbin/mysqld (mysqld 10.3.18-MariaDB-log) starting as process 4264 ...
      Nov 08 19:42:22 ip-172-30-0-105.us-west-2.compute.internal mysqld[4478]: 2019-11-08 19:42:22 0 [Note] /usr/sbin/mysqld (mysqld 10.3.18-MariaDB-log) starting as process 4478 ...
      Nov 13 19:06:21 ip-172-30-0-105.us-west-2.compute.internal mysqld[24125]: 2019-11-13 19:06:21 0 [Note] /usr/sbin/mysqld (mysqld 10.3.18-MariaDB-log) starting as process 24125 ...
      

      We should probably fix this code, so that the output properly goes to the error log. We may also want to modify the message, so that it includes the information requested in MDEV-17093.

      Currently, MariaDB only prints the server version to the error log after it has been completely initialized, and it is ready for connections. For example:

      2019-11-13 19:06:22 0 [Note] InnoDB: Using Linux native AIO
      2019-11-13 19:06:22 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2019-11-13 19:06:22 0 [Note] InnoDB: Uses event mutexes
      2019-11-13 19:06:22 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2019-11-13 19:06:22 0 [Note] InnoDB: Number of pools: 1
      2019-11-13 19:06:22 0 [Note] InnoDB: Using SSE2 crc32 instructions
      ...
      2019-11-13 19:06:22 0 [Note] /usr/sbin/mysqld: ready for connections.
      Version: '10.3.18-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
      

      However, if the server has to go through crash recovery, or if the server is using Galera and it has to perform an SST or IST, then the user may have to wait a long time to see this message get printed in the error log. I don't think this is sufficient.

      Attachments

        Issue Links

          Activity

            People

              serg Sergei Golubchik
              GeoffMontee Geoff Montee (Inactive)
              Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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