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: | |
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
[25 Nov 2014 13:20]
MySQL Verification Team
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.