MySQL Bugs: #106637: mysql.slow_log system table doesn't show sql

Bug #106637	mysql.slow_log system table doesn't show sql_text correctly
Submitted:	4 Mar 2022 8:12	Modified:	4 Mar 2022 10:50
Reporter:	Brian Yue (OCA)	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	8.0.27	OS:	Any (rhel-7.4)
Assigned to:		CPU Architecture:	Any (x86-64)
Tags:	mysql.slow_log, slow_log, sql_text

Description:
Hello, 
  I'm recently try to make slow logs to be recorded in mysql.slow_log system table, but it's found that the sql_text is not recorded correctly, which seems to be hex content.

How to repeat:

```
[yxx_findb@localhost ~]$ mysql -uroot -p'db10$ZTE' -S bin/mysql1.sock
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 18
Server version: 8.0.27 Source distribution

Copyright (c) 2000, 2021, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE  |
+---------------+-------+
1 row in set (0.00 sec)

mysql> set @@global.log_output = 'TABLE';
Query OK, 0 rows affected (0.00 sec)

mysql> select * from mysql.slow_log;
Empty set (0.06 sec)

mysql> set @@global.slow_query_log = ON;
Query OK, 0 rows affected (0.00 sec)

mysql> set @@session.long_query_time = 0;
Query OK, 0 rows affected (0.00 sec)

mysql> select sleep(1);
+----------+
| sleep(1) |
+----------+
|        0 |
+----------+
1 row in set (1.00 sec)

mysql> select * from mysql.slow_log;
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+----------------------------------------------------------------------+-----------+
| start_time                 | user_host                 | query_time      | lock_time       | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text                                                             | thread_id |
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+----------------------------------------------------------------------+-----------+
| 2022-03-04 16:04:58.524733 | root[root] @ localhost [] | 00:00:00.050986 | 00:00:00.002816 |         0 |             0 |    |              0 |         0 |      1399 | 0x73656C656374202A2066726F6D206D7973716C2E736C6F775F6C6F67           |        18 |
| 2022-03-04 16:05:21.869617 | root[root] @ localhost [] | 00:00:00.000181 | 00:00:00.000000 |         0 |             0 |    |              0 |         0 |      1399 | 0x73657420404073657373696F6E2E6C6F6E675F71756572795F74696D65203D2030 |        18 |
| 2022-03-04 16:05:29.028744 | root[root] @ localhost [] | 00:00:01.000401 | 00:00:00.000000 |         1 |             1 |    |              0 |         0 |      1399 | 0x73656C65637420736C656570283129                                     |        18 |
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+----------------------------------------------------------------------+-----------+
3 rows in set (0.00 sec)

mysql> select start_time, sql_text from mysql.slow_log;
+----------------------------+----------------------------------------------------------------------+
| start_time                 | sql_text                                                             |
+----------------------------+----------------------------------------------------------------------+
| 2022-03-04 16:04:58.524733 | 0x73656C656374202A2066726F6D206D7973716C2E736C6F775F6C6F67           |
| 2022-03-04 16:05:21.869617 | 0x73657420404073657373696F6E2E6C6F6E675F71756572795F74696D65203D2030 |
| 2022-03-04 16:05:29.028744 | 0x73656C65637420736C656570283129                                     |
| 2022-03-04 16:05:31.635774 | 0x73656C656374202A2066726F6D206D7973716C2E736C6F775F6C6F67           |
+----------------------------+----------------------------------------------------------------------+
4 rows in set (0.00 sec)
```

Hello Brian Yue,

Thank you for the bug report and feedback.
IMHO this is expected behavior. Quoting from 8.0.19 change log -
"

When the mysql client operates in interactive mode, the --binary-as-hex option now is enabled by default. In addition, output from the status (or \s) command includes this line when the option is enabled implicitly or explicitly:

Binary data as: Hexadecimal

To disable hexadecimal notation, use --skip-binary-as-hex (Bug #24432545)
". Please see https://dev.mysql.com/doc/relnotes/mysql/8.0/en/news-8-0-19.html
and https://dev.mysql.com/doc/refman/8.0/en/mysql-command-options.html#option_mysql_binary-as-...

-- with default

 bin/mysql -uroot -S /tmp/mysql_ushastry3306.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 12
Server version: 8.0.28-commercial MySQL Enterprise Server - Commercial

Copyright (c) 2000, 2022, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select start_time, sql_text from mysql.slow_log;
+----------------------------+--------------------------------------------------------------------------------------------------+
| start_time                 | sql_text                                                                                         |
+----------------------------+--------------------------------------------------------------------------------------------------+
| 2022-03-04 10:10:33.678248 | 0x73657420404073657373696F6E2E6C6F6E675F71756572795F74696D65203D2030                             |
| 2022-03-04 10:10:42.678264 | 0x73656C65637420736C656570283129                                                                 |
| 2022-03-04 10:10:49.458132 | 0x73656C656374202A2066726F6D206D7973716C2E736C6F775F6C6F67                                       |
| 2022-03-04 10:11:05.088249 | 0x73656C6563742073746172745F74696D652C2073716C5F746578742066726F6D206D7973716C2E736C6F775F6C6F67 |
| 2022-03-04 10:25:48.572480 | 0x51756974                                                                                       |
+----------------------------+--------------------------------------------------------------------------------------------------+
5 rows in set (0.00 sec)

mysql> \s
--------------
bin/mysql  Ver 8.0.28-commercial for Linux on x86_64 (MySQL Enterprise Server - Commercial)

Connection id:          13
Current database:
Current user:           root@localhost
SSL:                    Not in use
Current pager:          more
Using outfile:          ''
Using delimiter:        ;
Server version:         8.0.28-commercial MySQL Enterprise Server - Commercial
Protocol version:       10
Connection:             Localhost via UNIX socket
Server characterset:    utf8mb4
Db     characterset:    utf8mb4
Client characterset:    utf8mb4
Conn.  characterset:    utf8mb4
UNIX socket:            /tmp/mysql_ushastry3306.sock
Binary data as:         Hexadecimal
Uptime:                 2 hours 23 min 20 sec

- with skip

 bin/mysql -uroot -S /tmp/mysql_ushastry3306.sock --skip-binary-as-hex
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 11
Server version: 8.0.28-commercial MySQL Enterprise Server - Commercial

Copyright (c) 2000, 2022, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select start_time, sql_text from mysql.slow_log;
+----------------------------+-------------------------------------------------+
| start_time                 | sql_text                                        |
+----------------------------+-------------------------------------------------+
| 2022-03-04 10:10:33.678248 | set @@session.long_query_time = 0               |
| 2022-03-04 10:10:42.678264 | select sleep(1)                                 |
| 2022-03-04 10:10:49.458132 | select * from mysql.slow_log                    |
| 2022-03-04 10:11:05.088249 | select start_time, sql_text from mysql.slow_log |
| 2022-03-04 10:25:48.572480 | Quit                                            |
+----------------------------+-------------------------------------------------+
5 rows in set (0.00 sec)

mysql> \s
--------------
bin/mysql  Ver 8.0.28-commercial for Linux on x86_64 (MySQL Enterprise Server - Commercial)

Connection id:          14
Current database:
Current user:           root@localhost
SSL:                    Not in use
Current pager:          more
Using outfile:          ''
Using delimiter:        ;
Server version:         8.0.28-commercial MySQL Enterprise Server - Commercial
Protocol version:       10
Connection:             Localhost via UNIX socket
Server characterset:    utf8mb4
Db     characterset:    utf8mb4
Client characterset:    utf8mb4
Conn.  characterset:    utf8mb4
UNIX socket:            /tmp/mysql_ushastry3306.sock
Uptime:                 2 hours 26 min 24 sec

Threads: 2  Questions: 39  Slow queries: 5  Opens: 199  Flush tables: 4  Open tables: 50  Queries per second avg: 0.004
--------------

regards,
Umesh

Alternatively, you can use https://dev.mysql.com/doc/refman/8.0/en/mysql-command-options.html#option_mysql_binary-as-...

bin/mysql -uroot -S /tmp/mysql_ushastry3306.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 16
Server version: 8.0.28-commercial MySQL Enterprise Server - Commercial

Copyright (c) 2000, 2022, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select start_time, convert(sql_text using utf8mb4) from mysql.slow_log;
+----------------------------+-------------------------------------------------+
| start_time                 | convert(sql_text using utf8mb4)                 |
+----------------------------+-------------------------------------------------+
| 2022-03-04 10:10:33.678248 | set @@session.long_query_time = 0               |
| 2022-03-04 10:10:42.678264 | select sleep(1)                                 |
| 2022-03-04 10:10:49.458132 | select * from mysql.slow_log                    |
| 2022-03-04 10:11:05.088249 | select start_time, sql_text from mysql.slow_log |
| 2022-03-04 10:25:48.572480 | Quit                                            |
+----------------------------+-------------------------------------------------+
5 rows in set (0.00 sec)