MySQL Bugs: #68200: Password logging doesn't work as documented

Bug #68200	Password logging doesn't work as documented
Submitted:	28 Jan 2013 8:54	Modified:	10 Mar 2013 16:03
Reporter:	Daniël van Eeden (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Security: Privileges	Severity:	S3 (Non-critical)
Version:	5.6.9-rc	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
From http://dev.mysql.com/doc/refman/5.6/en/password-logging.html
"As of MySQL 5.6.3, passwords in statements written to the general query log, slow query log, and binary log are rewritten by the server not to occur literally in plain text."

However this doesn't seem to work.

How to repeat:
Setup MySQL with binlog, slow query log and general log. And INSERT

slow_query_log_file             = /mysql/sandboxes/msb_5_6_9-rc/data/msandbox-slow.log
slow_query_log                  = ON
long_query_time                 = 0

general_log                     = ON
general_log_file                = /mysql/sandboxes/msb_5_6_9-rc/data/msandbox.log

The query with the super secret password:
INSERT INTO t1(name) VALUES(PASSWORD('secret_test_password'))

# Time: 130128  9:46:11
# User@Host: msandbox[msandbox] @ localhost []  Id:     3
# Query_time: 0.002308  Lock_time: 0.000281 Rows_sent: 0  Rows_examined: 0
SET timestamp=1359362771;
INSERT INTO t1(name) VALUES(PASSWORD('secret_test_password'));

130128  9:46:11     3 Query     INSERT INTO t1(name) VALUES(PASSWORD('secret_test_password'))

# at 743
#130128  9:46:11 server id 1  end_log_pos 743 CRC32 0xad29bcc9 	Intvar
SET INSERT_ID=7/*!*/;
#130128  9:46:11 server id 1  end_log_pos 878 CRC32 0x8283831e 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1359362771/*!*/;
INSERT INTO t1(name) VALUES(PASSWORD('secret_test_password'))
/*!*/;

I did try to set the 'log-raw' option to OFF, but that results in the following message:
2013-01-28 09:39:32 0 [Warning] /home/dveeden/opt/mysql/5.6.9-rc/bin/mysqld: ignoring option '--log-raw' due to invalid value 'OFF'

This is both a  request for better documentation and a feature request. 

We should document properly what is actually working and what is not working.

This is not a documentation bug. Removing assignment from docs person, and changing category to General.

Stefan

Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products.

http://dev.mysql.com/doc/refman/5.6/en/password-logging.html
now indicates specifically which statements are subject to password
rewriting.

I tried one of the listed statements and now the password hiding works.

Statement:
GRANT ALL ON *.* TO 'insecure2'@'127.0.0.2' IDENTIFIED BY 'secret';

Binlog:
GRANT ALL PRIVILEGES ON *.* TO 'insecure2'@'127.0.0.2' IDENTIFIED BY PASSWORD '*14E65567ABDB5135D0CFD9A70B3032C179A49EE7';

But setting log-raw doesn't change anything. I confirmed with './my sqld --verbose --help' (mysqlsandbox) that the log-raw option indeed switched to on.

"I tried one of the listed statements and now the password hiding works."

Not sure what you mean by "now" works? Are you saying that since password rewriting was first implemented that GRANT ... IDENTIFIED BY was not rewritten? Your initial bug description reported a non-rewritten statement, but that was INSERT (which is not rewritten), not GRANT.

"But setting log-raw doesn't change anything. I confirmed with './my sqld --verbose --help' (mysqlsandbox) that the log-raw option indeed switched to on."

I cannot confirm this.

With log-raw or log-raw=ON:

130307  7:15:32     2 Query grant usage on *.* to lograwon identified by 'abcdefABC0@'

With no log-raw option or log-raw=OFF:

130307  7:17:21     2 Query GRANT USAGE ON *.* TO 'lograwoff'@'%' IDENTIFIED BY PASSWORD '*858BDB6D641AC2921CD62A08DAE9D7C64D890A02'

Regarding this:
"But setting log-raw doesn't change anything. I confirmed with './my sqld --verbose --help' (mysqlsandbox) that the log-raw option indeed switched to on."

With log-raw=OFF, I get that same warning in 5.6.9, but not 5.6.10.

In http://dev.mysql.com/doc/relnotes/mysql/5.6/en/news-5-6-10.html I see this:

"At startup, some InnoDB boolean system variables could be set to 1 or 0, but not ON or OFF. These included innodb_file_per_table, innodb_force_load_corrupted, and innodb_large_prefix. (Bug #14494893)"

Perhaps that bug fix affected some other options as well.

Initial settings for 5.6.10 sandbox:
log-error=msandbox.err
log-bin
long-query-time=0.0
slow-query-log-file=msandbox-slow.log
slow-query-log=ON
general-log-file=msandbox-general.log
general-log=ON

$ ./my sql -u root -e "GRANT ALL PRIVILEGES ON *.* TO 'lograw-insec'@'127.0.0.2' IDENTIFIED BY 'secure-pwd';"

Add "log-raw=ON" to my.sandbox.cnf and restart
$ vi my.sandbox.cnf 
$ ./restart
. sandbox server started

$ ./my sql -u root -e "GRANT ALL PRIVILEGES ON *.* TO 'lograw-0-insec'@'127.0.0.2' IDENTIFIED BY 'secure-pwd';"
~/sandboxes/msb_5_6_10$ ./stop

General Log:
$ grep -i grant data/msandbox-general.log 
		    2 Query	GRANT ALL PRIVILEGES ON *.* TO 'lograw-insec'@'127.0.0.2' IDENTIFIED BY PASSWORD '*10B5F2061DEFB160B9B09182F508656CF0FFDCF9'
		    1 Query	GRANT ALL PRIVILEGES ON *.* TO 'lograw-0-insec'@'127.0.0.2' IDENTIFIED BY 'secure-pwd'

Slow Query Log:
$ grep -i grant data/msandbox-slow.log 
GRANT ALL PRIVILEGES ON *.* TO 'lograw-insec'@'127.0.0.2' IDENTIFIED BY PASSWORD '*10B5F2061DEFB160B9B09182F508656CF0FFDCF9';
GRANT ALL PRIVILEGES ON *.* TO 'lograw-insec'@'127.0.0.2' IDENTIFIED BY PASSWORD '*10B5F2061DEFB160B9B09182F508656CF0FFDCF9';
GRANT ALL PRIVILEGES ON *.* TO 'lograw-0-insec'@'127.0.0.2' IDENTIFIED BY PASSWORD '*10B5F2061DEFB160B9B09182F508656CF0FFDCF9';
GRANT ALL PRIVILEGES ON *.* TO 'lograw-0-insec'@'127.0.0.2' IDENTIFIED BY PASSWORD '*10B5F2061DEFB160B9B09182F508656CF0FFDCF9';

Binary Log:
$ ./my sqlbinlog data/mysql_sandbox5610-bin.000001 data/mysql_sandbox5610-bin.000002 | grep -i grant
GRANT ALL PRIVILEGES ON *.* TO 'lograw-insec'@'127.0.0.2' IDENTIFIED BY PASSWORD '*10B5F2061DEFB160B9B09182F508656CF0FFDCF9'
GRANT ALL PRIVILEGES ON *.* TO 'lograw-0-insec'@'127.0.0.2' IDENTIFIED BY PASSWORD '*10B5F2061DEFB160B9B09182F508656CF0FFDCF9'

Conclusion:
The password hiding works. I really like this feature.
When log-raw is enabled this only works for the General Log, not for the binlogs and slow query logs. When I first read the documentation (before it was updated) I thought that the log-raw setting should influence all kinds of logging and disable the password hiding feature completely. After re-reading the documentation it is correct.
This means that this bug is fixed now.

One final note:
To allow monitoring (and enforcing?) of this setting it should be readable by 'SELECT @@log_raw'. This might be required for a reliable advisor in MEM and other monitoring software. (esp. if the mem agent is not on the same server).