Wednesday, August 05, 2015

In search of cleanliness : the elusive quiet installation



UPDATE: Almost solved! See at the end.

A clean installation of a database server is one where everything goes according to the expectations. It used to be easy: you only had to do what the manual says, and, presto! you would see your database server installed and ready to use. If something went wrong, you got one or more error messages that informed you of what needs to be fixed.

Sometimes, rarely, it happened that you got also a warning message, telling you that while the installation was successful, you could improve it by fine tuning this and that. No big deal.

Gone are those times. A clean installation nowadays is a much harder exercise, if not impossible. Let’s give it a try using MySQL 5.7.7.



Attempt #1 using mysql_install_db


The first error you could do when using a new version of MySQL is assuming that basic operations are unchanged and trying to do what you did before.

tar -xzf mysql-5.7.7-rc-linux-glibc2.5-x86_64.tar.gz  
cd mysql-5.7.7-rc-linux-glibc2.5-x86_64  
./bin/mysql_install_db --no-defaults --basedir=$PWD --datadir=$PWD/data  
2015-07-24 10:38:02 [WARNING] mysql_install_db is deprecated. Please consider switching to mysqld --initialize  
2015-07-24 10:38:04 [WARNING] The bootstrap log isn't empty:  
2015-07-24 10:38:04 [WARNING] mysqld: [Warning] --bootstrap is deprecated. Please consider using --initialize instead

OpenSSL 1.0.1 14 Mar 2012  
server-cert.pem: OK  
client-cert.pem: OK

Alright. So mysql_install_db is deprecated. If I had had a look at the instructions, I would have realized that. And, unrelated to the topic of this post, I also see something new. The server is generating SSL certificates for me: that's handy!

Let’s scrap it and try with the recommended method: mysqld --initialize.

Attempt #2 the naive mysqld --initialize


This should be simple. We use mysqld with the same options that we had for mysql_install_db, with --initialize.

./bin/mysqld --no-defaults --basedir=$PWD --datadir=$PWD/data  --initialize  
2015-07-24T08:43:47.348470Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).  
2015-07-24T08:43:47.352077Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.  
2015-07-24T08:43:47.352103Z 0 [ERROR] Aborting

Not good. mysql_install_db can overwrite an existing data directory, but apparently mysqld --initialize cannot.

Let’s try again.

rm -rf data  
./bin/mysqld --no-defaults --basedir=$PWD --datadir=$PWD/data  --initialize  
2015-07-24T08:47:54.779119Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).  
2015-07-24T08:47:54.949565Z 0 [Warning] InnoDB: New log files created, LSN=45790  
2015-07-24T08:47:54.990050Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.  
2015-07-24T08:47:55.049038Z 0 [Warning] Failed to setup SSL  
2015-07-24T08:47:55.049072Z 0 [Warning] SSL error: SSL context is not usable without certificate and private key  
2015-07-24T08:47:55.049959Z 1 [Warning] A temporary password is generated for root@localhost: !u(;R<h-j7g,

Here we have several warnings, none of which have a good explanation.

  • “TIMESTAMP with implicit DEFAULT value” is not my fault. It’s generated by the very command that I have executed after looking at the manual. If this behavior is deprecated, the server should generate correct SQL statements.
  • InnoDB new log file and foreign key system tables. I am glad they were created, but why is it important to tell me this? The server has created much more than this, and yet it does not tell me (thankfully, as I have already seen what happens when the server says too much). But the main question is : why is this a warning?
  • “Failed to setup SSL” and “SSL error”. This is language that is usually related to a failure, i.e. it’s used when an operation does not succeed. However, here the operation succeeds, but I am informed that something could not complete. I notice, also, that the deprecated mysql_install_db does create the required certificates, but its replacement doesn’t. I also notice that I should not need ssl when initializing a database. If this message means that it could not generate the certificates like mysql_install_db does, then ok, but tis wording mean that there was a failure when enabling SSL. Either it's bad wording or a bug.
  • Finally, there is a warning telling me what I knew was coming (my temporary password.) I expected an [Info] on stdout but I get a [Warning] on stderr.

Attempt #3 : trying to reduce the noise


So, rather than waiting for a fix that may one day come, let’s try to play by the rules, and add options that should quench at least some of the warnings:

  • There is an option that skips ssl. While there should not be a need for this, since the server does not seem to be generating certificates like it does with mysql_install_db, at least it should keep the warning out. To create the certificates, we can later use the new utility bin/mysql_ssl_rsa_setup.
  • There is also an option that prevents the password generation (--initialize-insecure.) This should remove the warning that tells me the random password.
  • And there is an option that makes the server use the right default for timestamps.

Let’s try:

./bin/mysqld --no-defaults --basedir=$PWD \  
    --datadir=$PWD/data --initialize-insecure \  
    --skip-ssl --explicit-defaults-for-timestamp  
2015-07-24T09:13:44.249379Z 0 [Warning] InnoDB: New log files created, LSN=45790  
2015-07-24T09:13:44.285713Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.  
2015-07-24T09:13:44.345453Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.

Ugh! One way or another, we get unnecessary warnings. If I play secure, I get a warning containing the password. If I play insecure, I get a warning reminding me to play secure.

And I have no idea how I could avoid the InnoDB warnings, if it is at all possible.

Attempt #4 : repeating the noise reduction with a new version


Here comes version 5.7.8. So I try my newly learned reduction skills with this one.

./bin/mysqld --no-defaults --basedir=$PWD \  
    --datadir=$PWD/data --initialize-insecure \  
    --skip-ssl --explicit-defaults-for-timestamp  
2015-07-25T12:37:06.515886Z 0 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)  
2015-07-25T12:37:06.515990Z 0 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)  
2015-07-25T12:37:07.025017Z 0 [Warning] InnoDB: New log files created, LSN=45790  
2015-07-25T12:37:07.130484Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.  
2015-07-25T12:37:07.199374Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: dc63870e-32c9-11e5-9c1c-b8aeed737fc8.  
2015-07-25T12:37:07.202405Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.  
2015-07-25T12:37:07.203320Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.

Whoa! New warnings! Let’s see what we understand:

  • The “changed limits” warnings seem to be legitimate. They say that the defaults are higher than before and I should set better ones. OK. we can do that using --open-files-limits and --table-open-cache.
  • “No existing UUID has been found, so we assume this is the first time.” This warning looks like it was not planned very accurately: I am using --initialize, and the server does not allow overwriting an existing data directory. Thus, it is the first time. Why is there a warning for this?
  • “Gtid table is not ready to be used.” This seems another useless warning. We are initializing the system, and that table is probably being tried before it is created. This should be an error if we were trying to use GTIDs, which are disabled by default. As it is, it looks like an unnecessary warning.

Let’s try once more to reduce the noise

./bin/mysqld --no-defaults --basedir=$PWD \  
    --datadir=$PWD/data --initialize-insecure \  
    --skip-ssl --explicit-defaults-for-timestamp \  
    --open-files-limit=1024 --table_open_cache=400 \  
    --gtid-mode=on --enforce-gtid-consistency --server-id=100  
2015-07-25T12:52:44.887476Z 0 [Warning] InnoDB: New log files created, LSN=45790  
2015-07-25T12:52:44.956578Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.  
2015-07-25T12:52:44.969297Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 0b57dc9f-32cc-11e5-b908-b8aeed737fc8.  
2015-07-25T12:52:44.971661Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.  
2015-07-25T12:52:44.972187Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.

No way. My honest attempts at installing without warnings have failed. I hope it is because I have omitted to do something that is easy to add to the installation but not documented adequately. If so, probably someone will show the right solution as a comment to this article. If not, let’s wait for someone who is more usability oriented than the current implementer and can trigger a fix from the inside.

UPDATE: Then, just by chance, I found this option: --log-error-verbosity

./bin/mysqld --no-defaults --basedir=$PWD \  
    --datadir=$PWD/data --initialize-insecure \  
    --skip-ssl --explicit-defaults-for-timestamp \  
    --open-files-limit=1024 --table_open_cache=400 \  
    --gtid-mode=on --enforce-gtid-consistency --server-id=100 \
    --log-error-verbosity=1

And ... No warnings!
However, this variable suppresses ALL the warning, either necessary or not. So, my point, that there are still warnings that should not be such, still stands. I don't mind getting a true warning about some changed default that help me get the setting right. But a warning like "a new file was created" really should not be there.

5 comments:

Simon J Mudd said...

Agreed. Output should be clearly split to indicate successful progress, stuff which may need attention and/or errors. The output does seem somewhat arbitrary and hard for provisioning applications to parse to check for success. I don't normally see this as most systems I build are clones of existing ones but it would be helpful if this output were generated more consistently.

Simon J Mudd said...

Agreed. Output should be clearly split to indicate successful progress, stuff which may need attention and/or errors. The output does seem somewhat arbitrary and hard for provisioning applications to parse to check for success. I don't normally see this as most systems I build are clones of existing ones but it would be helpful if this output were generated more consistently.

Daniƫl van Eeden said...

Note for the "changed limits" it means that MySQL couldn't set these to the desired values. The value is autotuned based on things like max_connections. One option is to explicitly set them to a lower value, but changing OS limits might be a better solution when running in production.

Wagner Bianchi said...

I agree with the comments you made on the Attempt #2 Giuseppe. Those should be more intelligent and provide solutions to solve the warning or at least, point the docs where we can get more information in an attempt to get a clean database server initialization. I came to this blog after seeing Roel doing some work around this: https://bugs.mysql.com/bug.php?id=78495 Additionally, if we need to take with error log verbosity level, we can have a clean log, but, messages with wrong classes such as [Info], [Warning] and [ERROR] will carry on existing while what we need to push them to adjust is to better classify those in order to make it more intelligent.

As I’ve got curious to take a closer look on this as this blog was written an ~ year ago:

[root@test102546 mysql-5.7.16-linux-glibc2.5-x86_64]# bin/mysqld --no-defaults --initialize --user=mysql --datadir=${MYSQL_DATADIR} --basedir=${MYSQL_BASEDIR} --lc-messages-dir=./share/english/
2016-11-21T12:41:15.656320Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-11-21T12:41:15.656457Z 0 [Warning] Using pre 5.5 semantics to load error messages from /usr/local/mysql-5.7.16-linux-glibc2.5-x86_64/share/english/.
2016-11-21T12:41:15.656497Z 0 [Warning] If this is not intended, refer to the documentation for valid usage of --lc-messages-dir and --language parameters.
2016-11-21T12:41:15.845693Z 0 [Warning] InnoDB: New log files created, LSN=45790
2016-11-21T12:41:15.878994Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2016-11-21T12:41:15.936831Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: cafe9a21-afe7-11e6-a135-0800276b5788.
2016-11-21T12:41:15.939857Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2016-11-21T12:41:15.941214Z 1 [Note] A temporary password is generated for root@localhost: <uyMi1qazG3(

And talking about the message mentioned by Roel on http://bugs.mysql.com/bug.php?id=78495 we can see that the Warning about the Gtid table is maybe irrelevant at this point (I used maybe to make it open for more discussions).

Wagner Bianchi said...

By the way, considering the final test, it looks a bit different than an year ago, but yet, it's just suppressing log events that needs better classification.

[root@test102546 mysql-5.7.16-linux-glibc2.5-x86_64]# bin/mysqld --no-defaults --initialize --user=mysql --datadir=${MYSQL_DATADIR} --basedir=${MYSQL_BASEDIR} --log-error-verbosity=1
2016-11-21T12:52:22.537287Z 1 [Note] A temporary password is generated for root@localhost: gJGmR!re*9eB

Cheers,