Cat error log when mysqld fails to start

[morgo]

I have debugged a number of user issues, where the underlying cause is written to the mysqld error log.. but the user does not realize they have to read this log. Examples include:

• Executing the local example as root (mysql will fail to run as root by default).
• Breaking the mysqld config file, and then running bootstrap
• Not enough memory
• File permission errors.

Here is an example showing this feature with a bad my.cnf file:

morgo@morgox1:~/vitess/src/vitess.io/vitess$ ./launch-my-vitess.sh 
13148 etcd
13208 vtctld
13344 vttablet
13345 vttablet
13346 vttablet
Fri 18 Oct 2019 01:09:24 PM MDT: Building source tree
enter etcd2 env
add /vitess/global
add /vitess/zone1
add zone1 CellInfo
etcd start done...
enter etcd2 env
Starting vtctld...
Access vtctld web UI at http://morgox1:15000
Send commands with: vtctlclient -server morgox1:15999 ...
enter etcd2 env
Starting MySQL for tablet zone1-0000000100...
Starting MySQL for tablet zone1-0000000101...
Starting MySQL for tablet zone1-0000000102...
E1018 13:09:42.503935   14244 mysqld.go:721] mysqld --initialize-insecure failed: /usr/sbin/mysqld: exit status 1, output: 2019-10-18T19:09:40.823725Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-10-18T19:09:40.823757Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2019-10-18T19:09:40.823761Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2019-10-18T19:09:40.929999Z 0 [Warning] InnoDB: New log files created, LSN=45790
2019-10-18T19:09:41.020525Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2019-10-18T19:09:41.074136Z 0 [ERROR] unknown option '--totally-bs-option'
2019-10-18T19:09:41.074192Z 0 [ERROR] Aborting

E1018 13:09:42.504435   14244 mysqlctl.go:254] failed init mysql: /usr/sbin/mysqld: exit status 1, output: 
E1018 13:09:42.542678   14246 mysqld.go:721] mysqld --initialize-insecure failed: /usr/sbin/mysqld: exit status 1, output: 2019-10-18T19:09:40.821143Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-10-18T19:09:40.821178Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2019-10-18T19:09:40.821182Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2019-10-18T19:09:40.930012Z 0 [Warning] InnoDB: New log files created, LSN=45790
2019-10-18T19:09:41.016395Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2019-10-18T19:09:41.018450Z 0 [ERROR] unknown option '--totally-bs-option'
2019-10-18T19:09:41.018469Z 0 [ERROR] Aborting

E1018 13:09:42.543442   14246 mysqlctl.go:254] failed init mysql: /usr/sbin/mysqld: exit status 1, output: 
E1018 13:09:42.547948   14243 mysqld.go:721] mysqld --initialize-insecure failed: /usr/sbin/mysqld: exit status 1, output: 2019-10-18T19:09:40.823291Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-10-18T19:09:40.823319Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2019-10-18T19:09:40.823322Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2019-10-18T19:09:40.930012Z 0 [Warning] InnoDB: New log files created, LSN=45790
2019-10-18T19:09:41.020525Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2019-10-18T19:09:41.022838Z 0 [ERROR] unknown option '--totally-bs-option'
2019-10-18T19:09:41.022855Z 0 [ERROR] Aborting

E1018 13:09:42.548560   14243 mysqlctl.go:254] failed init mysql: /usr/sbin/mysqld: exit status 1, output: 
Starting vttablet for zone1-0000000100...
Access tablet zone1-0000000100 at http://morgox1:15100/debug/status
Starting vttablet for zone1-0000000101...
Access tablet zone1-0000000101 at http://morgox1:15101/debug/status
Starting vttablet for zone1-0000000102...
Access tablet zone1-0000000102 at http://morgox1:15102/debug/status
W1018 13:09:57.609002   14419 main.go:64] W1018 19:09:57.607113 reparent.go:182] master-elect tablet zone1-0000000100 is not the shard master, proceeding anyway as -force was used
W1018 13:09:57.610764   14419 main.go:64] W1018 19:09:57.607923 reparent.go:188] master-elect tablet zone1-0000000100 is not a master in the shard, proceeding anyway as -force was used

Signed-off-by: Morgan Tocker tocker@gmail.com

[morgo]

Note to reviewers: I can see this as being potentially problematic if the MySQL error log is very large (for example after several restarts, the log file is never rotated and eventually there is a failure).

I am open to suggestions on how to handle. For example, if the mysql error log is over 4096 bytes, we could print an error saying MySQL error log too large to output here. View /path/to/error.log for more information.

[enisoc]

I can see how this will help UX, but at a technical level I don't think hooking it up this way is going to be resilient to the wide range of ways people use Vitess (see below for an example). I also share the concern you had about the log potentially being large.

As an alternative, perhaps we could:

1. Document that a good way to make mysqld errors more discoverable is to configure the error log to be a symlink to /dev/stderr. This causes mysqlctld to automatically reflect everything mysqld logs into its own logs (since we capture it via a pipe), making it easier to see what's happening and how everything correlates in time.
2. Change all our local and k8s examples to do the above by default.

[enisoc]

LGTM