MySQL Bugs: #87910: make mysqld stop and start ALWAYS report the mysqld version

Bug #87910	make mysqld stop and start ALWAYS report the mysqld version
Submitted:	29 Sep 2017 10:05	Modified:	16 Mar 2018 2:01
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S4 (Feature request)
Version:	8.0.3, 8.0.4	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	debugging, logging, support, version

Description:
When stopping and starting mysql the last and first log lines do not show the version of mysqld being used. This information is vital for debugging when testing new versions and for confirming which binaries were applicable.

How to repeat:
8.0.3 stopping and restarting mysqld my logging show this:

...<other log lines>
2017-09-29T06:25:54.301917Z 0 [NOTE] [001079] /usr/sbin/mysqld: Shutdown complete
=====================================================
2017-09-29T06:25:55.296522Z 0 [Note] [000000] Basedir set to /usr/
...<other log lines>

Notice also how one part of the logging shows [NOTE] (upper case) and the other [Note] (mixed case). Please be consistent in logging. I thought 8.0 logging was more standardised now?

Suggested fix:
Please ensure that logging shows the version on startup (first log line)
and on shutdown (last log line)

Why? when doing upgrades you can then be 100% sure which version of the binary is being used and which version was present previously.

I've asked for this somewhere else several times and for diagnosis etc it's really useful but no-one sees why this is important. Please consider adjusting these log lines to include this information.  Your support people will be really happy if you do.

e.g.

2017-09-29T06:25:54.301917Z 0 [NOTE] [001079] /usr/sbin/mysqld: Shutdown complete for MySQL 8.0.3-rc1
=====================================================
2017-09-29T06:25:55.296522Z 0 [Note] [000000] Starting MySQL 8.0.3-rc1
2017-09-29T06:25:55.296522Z 0 [Note] [000000] Basedir set to /usr/

Hi Simon,

I think you have an early build, which gives the NOTE in capitals (this was an attempt, which we pulled, to indicate that this is a message that always will be printed). We are working on an improved solution for this.

Wrt to version numbers, we will look into it now.

Hi Ståle,

Yes, I was given early access to 8.0.3, so hand't considered the version I was using was different to the DMR 8.0.3 released publicly.  If the report is incorrect because of that then thanks for clarifying and please ignore it.

Hi Simon,

Just wanted to touch base with you on this.
MySQL 8.0.4 (2018-01-23, Release Candidate) was out last month and I'm not seeing those reported issues at my end and hence wanted to check if the concerns raised by you in this report are addressed or not. If there is nothing left then I would like to close this report if you have no objections.

Thanks,
Umesh

8.0.4-rc shutdown (on CentOS 7) shows:

$ sudo service mysqld stop
Redirecting to /bin/systemctl stop mysqld.service
$ sudo tail -10 /var/log/mysqld.log
2018-02-09T11:37:20.259074Z 0 [Note] [MY-011066] InnoDB: Shutdown completed; log sequence number 40850248733275
2018-02-09T11:37:20.259602Z 0 [Note] [MY-011066] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-02-09T11:37:20.259642Z 0 [Note] [MY-010733] Shutting down plugin 'MEMORY'
2018-02-09T11:37:20.259661Z 0 [Note] [MY-010733] Shutting down plugin 'CSV'
2018-02-09T11:37:20.259672Z 0 [Note] [MY-010733] Shutting down plugin 'sha2_cache_cleaner'
2018-02-09T11:37:20.259680Z 0 [Note] [MY-010733] Shutting down plugin 'caching_sha2_password'
2018-02-09T11:37:20.259692Z 0 [Note] [MY-010733] Shutting down plugin 'sha256_password'
2018-02-09T11:37:20.259696Z 0 [Note] [MY-010733] Shutting down plugin 'mysql_native_password'
2018-02-09T11:37:20.260117Z 0 [Note] [MY-010733] Shutting down plugin 'binlog'
2018-02-09T11:37:20.274600Z 0 [System] [MY-010910] /usr/sbin/mysqld: Shutdown complete.

Which version is this? I have no idea short of checking the binaries with:
$ rpm -q mysql-community-server
mysql-community-server-8.0.4-0.1.rc.el7.x86_64

But maybe I built my mysql version and the binaries being used are not the same version as the installed rpm?

So shutdown does not show (at the end) the version of MySQL being used. If you think this is resolved can you show me how I can see it?

The shutdown logging starts a bit earlier with:

2018-02-09T11:36:47.582186Z 0 [Note] [MY-010067] Giving 3 client threads a chance to die gracefully
2018-02-09T11:36:47.583136Z 0 [Note] [MY-010117] Shutting down slave threads
2018-02-09T11:36:47.584622Z 4 [Note] [MY-010596] Error reading relay log event for channel '': slave SQL thread was killed
...

but I see no reference from this point to the final shutdown message indicating the version of MySQL that's running.

========================================================

Starting this server shows:

$ sudo service mysqld start
Redirecting to /bin/systemctl start mysqld.service

and the configured log file shows:

2018-02-09T11:40:56.111295Z 0 [Warning] [MY-010086] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-02-09T11:40:56.112420Z 0 [Warning] [MY-010088] 'NO_AUTO_CREATE_USER' sql mode was not set.
2018-02-09T11:40:56.117849Z 0 [Note] [MY-010949] Basedir set to /usr/.
2018-02-09T11:40:56.117862Z 0 [System] [MY-010116] /usr/sbin/mysqld (mysqld 8.0.4-rc-log) starting as process 22094 ...
2018-02-09T11:40:56.162292Z 0 [Note] [MY-011066] InnoDB: Using Linux native AIO
2018-02-09T11:40:56.162784Z 0 [Note] [MY-010747] Plugin 'FEDERATED' is disabled.
2018-02-09T11:40:56.164820Z 1 [Note] [MY-011066] InnoDB: PUNCH HOLE support available
2018-02-09T11:40:56.164863Z 1 [Note] [MY-011066] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-02-09T11:40:56.164870Z 1 [Note] [MY-011066] InnoDB: Uses event mutexes
....

So clearly there's an attempt to log on startup the version but it actually happens after some logging has already happened. (that's a bit confusing but better). Perhaps this is the result of the multi-threaded startup, I'm not sure.  If possible it might be nicer to log a little earlier?

My feeling is that startup logging is better, but not quite right and shutdown logging does not show the version at the moment.

If I'm missing something please let me know. (I can provide my configuration settings if that makes a difference).

Thank you for the feedback.
Verifying as a feature request to log version details as requested.

Thanks,
Umesh

Posted by developer:
 
Fixed in 8.0.11.

Server shutdown lines written to the error log now include the server
version.