Sunday, March 18, 2012

MySQL 5.6 too verbose when creating data directory

When I install a MySQL package using MySQL Sandbox, if everything goes smoothly, I get an informative message on standard output, and I keep working.

This is OK

$HOME/opt/mysql/5.5.15/scripts/mysql_install_db --no-defaults \
  --user=$USER --basedir=$HOME/opt/mysql/5.5.15 \
  --datadir=$HOME/sandboxes/msb_5_5_15/data \
  --lower_case_table_names=2
Installing MySQL system tables...
OK
Filling help tables...
OK

To start mysqld at boot time you have to copy
support-files/mysql.server to the right place for your system

PLEASE REMEMBER TO SET A PASSWORD FOR THE MySQL root USER !
To do so, start the server, then issue the following commands:

/Users/gmax/opt/mysql/5.5.15/bin/mysqladmin -u root password 'new-password'
/Users/gmax/opt/mysql/5.5.15/bin/mysqladmin -u root -h gmac4.local password 'new-password'

Alternatively you can run:
/Users/gmax/opt/mysql/5.5.15/bin/mysql_secure_installation

which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.

See the manual for more instructions.

You can start the MySQL daemon with:
cd /Users/gmax/opt/mysql/5.5.15 ; /Users/gmax/opt/mysql/5.5.15/bin/mysqld_safe &

You can test the MySQL daemon with mysql-test-run.pl
cd /Users/gmax/opt/mysql/5.5.15/mysql-test ; perl mysql-test-run.pl

Please report any problems with the /Users/gmax/opt/mysql/5.5.15/scripts/mysqlbug script!
I can actually suppress this output, confident that, if something goes wrong, the error comes to my screen loud and clear. For example, if I try to install to a data directory that is write protected, I get this:
chmod 444 $HOME/sandboxes/msb_5_5_15/data
$HOME/opt/mysql/5.5.15/scripts/mysql_install_db --no-defaults \
  --user=$USER --basedir=$HOME/opt/mysql/5.5.15 \
  --datadir=$HOME/sandboxes/msb_5_5_15/data \
  --lower_case_table_names=2  > /dev/null

mkdir: /Users/gmax/sandboxes/msb_5_5_15/data: Permission denied
chmod: /Users/gmax/sandboxes/msb_5_5_15/data: Permission denied
chown: /Users/gmax/sandboxes/msb_5_5_15/data: Permission denied
This, way, I know that there was an error, it is very clear and readable. I don't need to hunt it down within the regular messages. The standard error is a separate file descriptor, which can be read independently from the standard input.

After fixing permissions:

chmod 755 ~/sandboxes/msb_5_5_15/
$HOME/opt/mysql/5.5.15/scripts/mysql_install_db --no-defaults \
  --user=$USER --basedir=$HOME/opt/mysql/5.5.15 \
  --datadir=$HOME/sandboxes/msb_5_5_15/data \
  --lower_case_table_names=2  > /dev/null
# empty line: means all OK

This is very convenient, and it is the Unix way.

This is not OK

Now, let's try the same with MySQL 5.6

$BASEDIR/scripts/mysql_install_db --no-defaults --user=tungsten \
  --basedir=$BASEDIR --datadir=/home/tungsten/sandboxes/msb_5_6_4/data \
  --tmpdir=/home/tungsten/sandboxes/msb_5_6_4/tmp  > /dev/null
120318 10:10:44 InnoDB: The InnoDB memory heap is disabled
120318 10:10:44 InnoDB: Mutexes and rw_locks use GCC atomic builtins
120318 10:10:44 InnoDB: Compressed tables use zlib 1.2.3
120318 10:10:44 InnoDB: Using Linux native AIO
120318 10:10:44 InnoDB: CPU supports crc32 instructions
120318 10:10:44 InnoDB: Initializing buffer pool, size = 128.0M
120318 10:10:44 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
120318 10:10:44 InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
120318 10:10:44 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
120318 10:10:44 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
120318 10:10:44 InnoDB: 128 rollback segment(s) are active.
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
120318 10:10:44 InnoDB: 1.2.4 started; log sequence number 0
120318 10:10:44 [Warning] Info table is not ready to be used. Table 'mysql.slave_master_info' cannot be opened.
120318 10:10:44 [Warning] Error while checking replication metadata. Setting the requested repository in order to give users the chance to fix the problem and restart the server. If this is a live upgrade please consider using mysql_upgrade to fix the problem.
120318 10:10:44 [Warning] Info table is not ready to be used. Table 'mysql.slave_relay_log_info' cannot be opened.
120318 10:10:44 [Warning] Error while checking replication metadata. Setting the requested repository in order to give users the chance to fix the problem and restart the server. If this is a live upgrade please consider using mysql_upgrade to fix the problem.
120318 10:10:44 [Note] Binlog end
120318 10:10:44 [Note] Shutting down plugin 'partition'
120318 10:10:44 [Note] Shutting down plugin 'ARCHIVE'
120318 10:10:44 [Note] Shutting down plugin 'BLACKHOLE'
120318 10:10:44 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_FT_DELETED'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_FT_INSERTED'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_METRICS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_CMPMEM'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_CMP_RESET'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_CMP'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_LOCKS'
120318 10:10:44 [Note] Shutting down plugin 'INNODB_TRX'
120318 10:10:44 [Note] Shutting down plugin 'InnoDB'
120318 10:10:44  InnoDB: FTS optimize thread exiting.
120318 10:10:44  InnoDB: Starting shutdown...
120318 10:10:46 InnoDB: Shutdown completed; log sequence number 1602841
120318 10:10:46 [Note] Shutting down plugin 'CSV'
120318 10:10:46 [Note] Shutting down plugin 'MEMORY'
120318 10:10:46 [Note] Shutting down plugin 'MyISAM'
120318 10:10:46 [Note] Shutting down plugin 'MRG_MYISAM'
120318 10:10:46 [Note] Shutting down plugin 'mysql_old_password'
120318 10:10:46 [Note] Shutting down plugin 'mysql_native_password'
120318 10:10:46 [Note] Shutting down plugin 'binlog'
120318 10:10:46 InnoDB: The InnoDB memory heap is disabled
120318 10:10:46 InnoDB: Mutexes and rw_locks use GCC atomic builtins
120318 10:10:46 InnoDB: Compressed tables use zlib 1.2.3
120318 10:10:46 InnoDB: Using Linux native AIO
120318 10:10:46 InnoDB: CPU supports crc32 instructions
120318 10:10:46 InnoDB: Initializing buffer pool, size = 128.0M
120318 10:10:46 InnoDB: Completed initialization of buffer pool
120318 10:10:46 InnoDB: highest supported file format is Barracuda.
120318 10:10:46 InnoDB: 128 rollback segment(s) are active.
120318 10:10:46 InnoDB: Waiting for the background threads to start
120318 10:10:47 InnoDB: 1.2.4 started; log sequence number 1602841
120318 10:10:47 [Note] Binlog end
120318 10:10:47 [Note] Shutting down plugin 'partition'
120318 10:10:47 [Note] Shutting down plugin 'ARCHIVE'
120318 10:10:47 [Note] Shutting down plugin 'BLACKHOLE'
120318 10:10:47 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_FT_DELETED'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_FT_INSERTED'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_METRICS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_CMPMEM'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_CMP_RESET'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_CMP'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_LOCKS'
120318 10:10:47 [Note] Shutting down plugin 'INNODB_TRX'
120318 10:10:47 [Note] Shutting down plugin 'InnoDB'
120318 10:10:47  InnoDB: FTS optimize thread exiting.
120318 10:10:47  InnoDB: Starting shutdown...
120318 10:10:49 InnoDB: Shutdown completed; log sequence number 1602851
120318 10:10:49 [Note] Shutting down plugin 'CSV'
120318 10:10:49 [Note] Shutting down plugin 'MEMORY'
120318 10:10:49 [Note] Shutting down plugin 'MyISAM'
120318 10:10:49 [Note] Shutting down plugin 'MRG_MYISAM'
120318 10:10:49 [Note] Shutting down plugin 'mysql_old_password'
120318 10:10:49 [Note] Shutting down plugin 'mysql_native_password'
120318 10:10:49 [Note] Shutting down plugin 'binlog'
Why is this bad? Because you don't see at a glance what is right and what is wrong. All the above messages are printed to the standard error, the kind of output that should be reserved for, well, errors! If the standard error is used for regular messages, you may miss the important error messages that are instead mixed with the "all is OK" messages.

There is Bug#60934 filed about this issue, but it has been considered a feature request, and as such unlikely to be fixed.

In the above text there is something more. There are warnings, mixed with the standard text, telling me of errors that the bootstrap operation is not in a position to fix, like replication metadata and slave_master_info.

MySQL developers, please fix this issue. Users need error messages when there is something wrong, and warning or error messages about something that can actually be fixed. When MySQL 5.6 goes GA, this issue will hit most everybody.

8 comments:

Anonymous said...

> [..] output that should be reserved for, well, errors!

Actually, it's also for diagnostic output.

Giuseppe Maxia said...

@anonymous,
> also for diagnostic output.

True, and also in this case it is expected to get text separated from the regular output.

What is not acceptable is using standard error for things that should go to the standard output.

Moreover, a procedure that for more than a decade has written to standard error only when an error occurs, should not change its behavior.

Daniƫl van Eeden said...

I can spot another bug: the reference to mysqlbug. #43870 #29716

Anonymous said...

> What is not acceptable is using standard error for things that should go to the standard output.

A notice is appropriate for stderr.

> Moreover, a procedure that for more than a decade has written to standard error only when an error occurs, should not change its behavior.

There might be no change in behavior, historically all messages are written to stderr if not redirected (and this is actually the problem... see print_buffer_to_file).

Giuseppe Maxia said...

@anonymous,
Let's try not to convert this discussion into a bicycle shed color debate.
The issue here is that developers do this kind of thing because they need debugging information (it happened with the event scheduler, which was writing every event start and stop to the error log and was removed after popular outcry) and some of the developers don't try to put themselves in the DBA's shoes.
So, ask any DBA if they consider useful to mix notices and errors, and see what you get.
And ask anyone who needs to write a wrapper around the bootstrap to package MySQL for a specific installer, if they find this new "feature" useful, and see what kind of consensus you may get.

Anonymous said...

Maybe there is room for compromise.
During install/bootstrap, maybe some of this information is extraneous. An obvious step here would be to cut back on the detailed shutdown information.
(In normal operation this would be useful to users with large installations where shutting down can take a very long time.)
For now, grep is the easy and obvious fix for normal operation, but recent servers have analogs of sql_print_error/info/warning() for use by plugins, so who knows what the future might hold once everything goes through a central facility?

Giuseppe Maxia said...

@anonymous,
the purpose of mysqld --bootstrap is to create a data directory. What the user wants at this stage is "it was installed" or "it was not installed, and this is the reason".

Anything else, is just too much information, which forces the user to look for signs of errors in this avalanche of text.

By polluting the screen this way, you aren't doing the user a favor.

Anonymous said...

Oracle is making, mysql similar to oracle (complex). So, that every body is forced to take mysql support from oracle. Without which resolution won't be possible.