Support error/info log desensitization

[kolbe]

Feature Request

Is your feature request related to a problem? Please describe:

Sensitive data can be written to the error log in many cases. This is problematic for environments where strict controls must be placed on sensitive, identifying, or financial data.

Describe the feature you'd like:

We should ensure that sensitive data is not written to error and other informational logs. These are different from logs that are explicitly enabled by the user (the general query log, slow query log, etc.), for which desensitization procedures would be different.

To resolve this issue will require an extensive audit of how we write log entries. There are many cases where the contents of SQL statements are written to the log (permission failures, syntax errors, etc.), and all of those need to be dealt with to resolve this task.

Describe alternatives you've considered:

Teachability, Documentation, Adoption, Migration Strategy:

[ghost]

I think the only way you can really be sure to do this safely, is the error log can not output any user input directly. It has to be the prepared statement form of the query.

The slow query log needs to be off by default, and it should state that it outputs raw user data in an unencrypted form.

[kolbe]

In particular, server/conn.go is often responsible for printing the full query text if there is an execution problem. This would be a good place to start with masking query content. Perhaps a system variable to control whether error log output is desensitized (default ON) and some changes to func (cc getLastStmtInConn) String() string (https://github.com/pingcap/tidb/blob/release-4.0/server/conn.go#L1604) would be a good start.

[nolouch]

closed by #18578

[zz-jason]

when tidb_log_desensitization is set to 1, the duplicated key is printed to the log. I'm going to reopen this since it has not been fixed totally.

Here is an example:

create table t(a bigint primary key, b bigint);
insert into t values(1, 1);
insert into t values(1, 1); -- returns: ERROR 1062 (23000): Duplicate entry '1' for key 'PRIMARY'

the log printed for the last insert statement:

[2020/08/06 08:52:21.984 +08:00] [WARN] [session.go:471] ["can not retry txn"] [conn=3] [label=general] [error="[kv:1062]Duplicate entry '1' for key 'PRIMARY'"] [IsBatchInsert=false] [IsPessimistic=false] [InRestrictedSQL=false] [tidb_retry_limit=10] [tidb_disable_txn_auto_retry=true]
[2020/08/06 08:52:21.984 +08:00] [WARN] [session.go:487] ["commit failed"] [conn=3] ["finished txn"="Txn{state=invalid}"] [error="[kv:1062]Duplicate entry '1' for key 'PRIMARY'"]
[2020/08/06 08:52:21.984 +08:00] [ERROR] [conn.go:744] ["command dispatched failed"] [conn=3] [connInfo="id:3, addr:127.0.0.1:55984 status:10, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="insert into t values ( ... )"] [txn_mode=OPTIMISTIC] [err="[kv:1062]Duplicate entry '1' for key 'PRIMARY'"]
[2020/08/06 08:52:21.985 +08:00] [INFO] [2pc.go:739] ["2PC clean up done"] [conn=3] [txnStartTS=418558808419729408]

[zz-jason]

@zanmato1984 PTAL, thanks.

[zz-jason]

maybe we can write a tool to monitor the log file. report a security issue if it prints data in the table or from the query.

[zz-jason]

when tidb_log_desensitization is set to 1, the duplicated key is printed to the log. I'm going to reopen this since it has not been fixed totally.

Here is an example:

create table t(a bigint primary key, b bigint);
insert into t values(1, 1);
insert into t values(1, 1); -- returns: ERROR 1062 (23000): Duplicate entry '1' for key 'PRIMARY'

the log printed for the last insert statement:

[2020/08/06 08:52:21.984 +08:00] [WARN] [session.go:471] ["can not retry txn"] [conn=3] [label=general] [error="[kv:1062]Duplicate entry '1' for key 'PRIMARY'"] [IsBatchInsert=false] [IsPessimistic=false] [InRestrictedSQL=false] [tidb_retry_limit=10] [tidb_disable_txn_auto_retry=true]
[2020/08/06 08:52:21.984 +08:00] [WARN] [session.go:487] ["commit failed"] [conn=3] ["finished txn"="Txn{state=invalid}"] [error="[kv:1062]Duplicate entry '1' for key 'PRIMARY'"]
[2020/08/06 08:52:21.984 +08:00] [ERROR] [conn.go:744] ["command dispatched failed"] [conn=3] [connInfo="id:3, addr:127.0.0.1:55984 status:10, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="insert into t values ( ... )"] [txn_mode=OPTIMISTIC] [err="[kv:1062]Duplicate entry '1' for key 'PRIMARY'"]
[2020/08/06 08:52:21.985 +08:00] [INFO] [2pc.go:739] ["2PC clean up done"] [conn=3] [txnStartTS=418558808419729408]

It exposes another issue: we can reduce the logs of Duplicate entry error. #19052 was created to track this log expansion.

[zz-jason]

I noticed that it's a P0 sub-task in #18084, also we'd better backport this security improvement to release 4.0

[zz-jason]

we also need to consider the debug level logs.

[zz-jason]

the privilege of turning the global variable tidb_log_desensitization also needs careful design. for example, only users with super privilege can turn on or turn off this variable.

[ghost]

we also need to consider the debug level logs.

I think it might be more practical to document that it is only supported for INFO and higher levels? Debug implies verbose, so as a user I don't have a full expectation I can have both. But for safety, it might be useful to handle this in config check, and refuse to allow DEBUG if tidb_log_desensitization is enabled warn when attempting to enable tidb_log_desensitization w/DEBUG see comment here.

[nolouch]

cc @crazycs520

[kolbe]

@nullnotnil I agree. I like the idea of disallowing DEBUG logs if the tidb_log_desensitization is set.

@zz-jason only a user with SUPER can change the value of a GLOBAL variable, so this is already the case, but good point and it's important to mention!

[crazycs520]

I noticed that it's a P0 sub-task in #18084, also we'd better backport this security improvement to release 4.0

Already cherry-pick to release-4.0: #18581

[crazycs520]

we also need to consider the debug level logs.

I think it might be more practical to document that it is only supported for INFO and higher levels? Debug implies verbose, so as a user I don't have a full expectation I can have both. But for safety, it might be useful to handle this in config check, and refuse to allow DEBUG if tidb_log_desensitization is enabled.

This check is added in #19103

[SunRunAway]

After #20436 merged, we are now working together to review all errors which may have sensitive information and redact them. See https://docs.google.com/document/d/1dOVzkaahH-P8fTYgtuBdKRTRlT8BEV7DM8LJPQwZaAQ/edit#heading=h.x2vdsn83mi0d