Bug #74963 changes in 5.7.5 logging verbosity seem surprising and unexpected
Submitted: 21 Nov 2014 14:33 Modified: 13 Jan 2015 23:02
Reporter: Simon Mudd (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Documentation Severity:S3 (Non-critical)
Version:5.7.5 OS:Any
Assigned to: Paul Dubois CPU Architecture:Any

[21 Nov 2014 14:33] Simon Mudd
Description:
Yes, this is documented but that could be improved ...

See: http://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_log_warnings
See: http://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_log_error_verbo...

The end result of this is logging is much more verbose in 5.7 then before in 5.6.
What I don't see (here) is an explanation of what you are trying to achieve with this change.

On my systems I see a lot more noise which is unexpected, and requires me to now explicitly change the log levels when before this was not needed.

How to repeat:
Check logs in a server after upgrading to 5.7.2+.

In my case "load balancer checks" to a recently started up box which is cold fail (because access credentials are configured to deliberately not match) and this generates a huge amount of unneeded noise.

Suggested fix:
(1) Don't make 2 different changes at the same time: (the log level and the need to set a different configuration setting in 5.7).
(2) In the documentation make it clear that the log_level setting is really a wrapper around the new log_error_verbosity setting, and only refer to the values it had in 5.6.  And tell people to set
log_error_verbosity and NOT to change the value of log_warnings.
(3) Ensure that changes to log_warnings generate a warning that the value is going away (even if most people don't read warnings, some might.)
(4) If log_warnings is configured explicitly then add a warning to set log_error_verbosity.
(5) personally I'd prefer for you not to change the behaviour of a setting

If you want to make this change more visible then:
(1) on startup _if_ log_warnings is set explicitly then generate a log message in the log file saying this variable is deprecated and to configure log_error_verbosity.

If it's not documented already please add a section on this variable in "incompatible changes" (1) because the verbosity has changed, and (2) because the user should look to configure the new variable.

So really the thing here is to make the log_warnings documentation mention the previous settings for log_warnings and say it's a wrapper around log_error_verbosity and to set and look at that value instead.  Also mention that logging is now more verbose so this setting may need to be adjusted to a less verbose level.
[25 Nov 2014 13:20] Umesh Shastry
Hello Simon,

Thank you for the report.
Upgraded 5.6.23 instance to 5.7.5 and ran a tiny bash script to connect upgraded 5.7.5 instance with wrong credentials and end result was error log flooded with Notes etc

-- time for i in `seq 1 1000`; do bin/mysql -uroot -p123;sleep 0.0001; done

// snippet from error log

2014-11-27T14:28:03.245050Z 1066 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.254483Z 1067 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.263902Z 1068 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.273226Z 1069 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.282510Z 1070 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.291697Z 1071 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.301306Z 1072 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.310790Z 1073 [Note] Access denied for user 'root'@'localhost' (using password: YES)

..
.
2014-11-27T14:28:12.629942Z 2060 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:12.639222Z 2061 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:12.648834Z 2062 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:12.658407Z 2063 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:12.667949Z 2064 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:12.677447Z 2065 [Note] Access denied for user 'root'@'localhost' (using password: YES)

With 5.6, above notes are not logged to the error log..

Thanks,
Umesh
[17 Dec 2014 11:16] Tatjana Nuernberg
Hi Simon,

(1) You're right in that the WL item in question did bundle
a general code clean-up (which required re-assigning some messages
to different severity levels) and the introduction of the new
variable. That said, the old variable still exists, so there is
no immediate need to set a different variable yet, just an
advisory that such a need may arise in the future. I.e. there
is only one change that requires immediate user attention
(that being the re-assignment of some messages), which seems
congruent with your request.

(2) The docs already state that one variable is deprecated so the
other should be used, and enumerates the legal values, and how
the legal values of both variables map onto each other. Docs
will be updated to further clarify that in an effort to ease
transition, the options update each other (until such a time
as the deprecated one is removed), thanks for the suggestion!

(3)/(4) Use of log_warnings throws a deprecation warning on use
both from the SQL layer and from the command line. If the server 
is started via mysqld_safe, the deprecation warning should go to 
the error log file specified there. When mysqld is started 
"manually" (without the mysqld_safe wrapper), then the deprecation
warning should go to stderr, i.e. it should by default be printed 
to the shell and terminal from whence the server was started.
(A non-standard caller at this point takes responsibility for appropriately
directing stdout/stderr for the user's attention.)

(5) So noted. In some cases however, it's hard to avoid (in the present
example, the former behavior, for example calling a message a warning,
but printing it with "information" severity, or vice versa, was considered
a bug). 
A new facility for logging to unix syslog (and thereby leveraging
a plethora of existing tools) is provided in the current milestone in the
hopes of letting the user filter error messages to align the content of
their (view on the) log more closely with their use case.

Best regards,
-T-
[7 Jan 2015 16:24] Paul Dubois
This was turned into a docs bug, to be addressed by pointing out that setting either of the two system variables in question sets the other.

I have added a sentence to the description for each variable to point out this behavior:

http://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_log_error_verbo...
(new last sentence)

log_error_verbosity was added in MySQL 5.7.2. It is preferred over, and should be used instead of, the older log_warnings system variable. See the description of log_warnings for information about how that variable relates to log_error_verbosity. In particular, assigning a value to log_warnings assigns a value to log_error_verbosity and vice versa.

http://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_log_warnings
has the details about the relationship, I added this after that:

One implication of the behavior just described is that assigning a value to log_warnings assigns a value to log_error_verbosity and vice versa.
[13 Jan 2015 22:49] Simon Mudd
Note: this needs to be reopened I think.
The specific error message I see is now only changeable by changing the log_error_verbosity to 2.
However, following the docs and by setting the log_error_verbosity to 2 logging pretty much stops for everything. I did a recent restart on a server with log_error_verbosity set to 2 and the shutdown logging was reduced to:

2015-01-13T22:11:28.222960Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 6003704  user: 'xxxx'
2015-01-13T22:11:28.223128Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 5985667  user: 'yyyy'
2015-01-13 23:11:28 0x7f8c161fc700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool
2015-01-13 23:11:28 0x7f8c161fc700 InnoDB: Buffer pool(s) dump completed at 150113 23:11:28
150113 23:11:40 mysqld_safe mysqld from pid file /path/to/mysqld.pid ended

that's brief.

The startup was equally brief :

150113 23:11:41 mysqld_safe Starting mysqld daemon with databases from /path/to/data/dir
2015-01-13T22:11:49.811489Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-01-13 23:12:04 0x7f39a6bfd700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool
2015-01-13T22:12:04.595164Z 0 [Warning] Failed to setup SSL
2015-01-13T22:12:04.595265Z 0 [Warning] SSL error: SSL context is not usable without certificate and private key
2015-01-13T22:12:05.111008Z 2 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.

All in all it's pretty silent and if I wanted to follow what was happening that wouldn't really be possible.
So I need to go back to log_error_verbosity = 3 and suffer without any way to filter now it seems this specific type of message:

2014-11-27T14:28:03.245050Z 1066 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2014-11-27T14:28:03.254483Z 1067 [Note] Access denied for user 'root'@'localhost' (using password: YES)
..

In my environment due to how health checks and load balancer checks run I deliberately prevent access to the checkers to tell them the server should not be reached. The end result is logging similar to that above, so on some servers this completely pollutes my logs.

I see 2 issues:
(1) the impact of what you may or may not see at "warnings and errors only" is not that clear. The startup/stop logging (or almost lack of) surprised me a lot: it should be made quite clear I think, or possibly excluded so the information is _always there_.
(2) the specific log message may be useful sometimes and I can see that the default setting should be to make it visible when someone is failing to login. However, that should be tuneable, and that doesn't really relate to any other options. So I think that you should really have a flag: log_client_access_failures YES/NO, default YES. On busy servers or servers where failures may be expected this would probably be turned off except for debugging. We should have other counters in p_s.host_cache to tell us if we need to look for more details and the magnitude of these "problems" if we actually turn off the explicit logging.