MySQL Bugs: #41925: Warning 1366 Incorrect string value: ... for column processlist.info

Bug #41925	Warning 1366 Incorrect string value: ... for column processlist.info
Submitted:	7 Jan 2009 15:43	Modified:	8 Jan 2009 18:50
Reporter:	Matthias Leich	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Information schema	Severity:	S3 (Non-critical)
Version:	5.6.30, 5.7.12, 8.0.0	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	random

Description:
IMHO any simple SELECT on information_schema.processlist
must not throw a warning. But I get sometimes

SELECT * INTO OUTFILE "<outfile>"
FIELDS TERMINATED BY '<-->' OPTIONALLY ENCLOSED BY '"'
FROM information_schema.processlist;
Warnings:
Warning 1366    Incorrect string value: '\x8F\x8F\x8F\x8F\x8F\x8F...' for column 'INFO' at row 1

Whenever my test suffered from this problem the printed piece
of the incorrect string value was '\x8F\x8F\x8F\x8F\x8F\x8F...'.

The content of the outfile is:
------------------------------
13<-->"root"<-->"localhost"<-->"events_test"<-->"Connect"<-->0<-->"logging slow query"<-->""
12<-->"event_scheduler"<-->"localhost"<-->\N<-->"Daemon"<-->0<-->"Waiting for next activation"<-->\N
2<-->"root"<-->"localhost"<-->"events_test"<-->"Query"<-->0<-->"executing"<-->"SELECT *, hex(info) INTO OUTFILE \"/work2/5.1/mysql-5.1-bugteam-work1/mysql-test/var/tmp/outfile-test.4\"\
FIELDS TERMINATED BY '<-->' OPTIONALLY ENCLOSED BY '\"'\
FROM information_schema.processlist"

The session with ID = 13 is just around the end of the
execution of an event.
Other example:
16<-->"root"<-->"localhost"<-->"events_test"<-->"Connect"<-->0<-->\N<-->""
<entries of some not important sessions deleted>

Bug#28582 event_scheduler uses uninitialized variable
          in show processlist 'info' output
seems to be the same problem and is set to "Can't repeat".
Therefore I assume that the current bug is within the implementation
of the "processlist" (SHOW PROCESSLIST) but not within the
implementation of the information_schema table.

The reason why I decided to create a new bug and not to
reopen the old one is because
- the last comment in Bug#28582 says
  "I confirm this is not repeatable ...." which most probably
  means the program for bug reproduction in Bug#28582 is no more
  able to reveal the problem within the scenarios it checks
- my replay program is able to reveal open problems

How to repeat:
I will add scripts for the reproduction of the
problem soon.

Archive with replay testcase

Attachment: bug41925.tgz (application/x-compressed-tar, text), 2.36 KiB.

How to replay the problem:
cd mysql-test
tar xvzf bug41925.tgz
rm var
   Just to be sure that var does not point to a tmpfs.
   Running on a disk based filesystem increases the probability
   for replaying the problem.
./mysql-test-run.pl `perl -e 'for (1 .. 300) { print "bug41925 "}'`

My environment:
- MySQL compiled from source
  6.0-bugteam last changeset 2009-01-08
  5.1-bugteam last changeset 2008-12-31
  (BUILD/compile-pentium64-debug-max)
- Intel Core2Duo (64 Bit)
- OpenSuSE Linux 11 (64 Bit)

This is still the case in 5.6.23. Even if INFO column is not retrieved.

root@[hostname] [information_schema]> select HOST from PROCESSLIST;
...
4 rows in set, 3 warnings (0.01 sec)

root@m[hostname] [information_schema]> show warnings
    -> ;
+---------+------+----------------------------------------------------------------------------+
| Level   | Code | Message                                                                    |
+---------+------+----------------------------------------------------------------------------+
| Warning | 1366 | Incorrect string value: '\xB1\xA2\xF0N\'...' for column 'INFO' at row 1    |
| Warning | 1366 | Incorrect string value: '\x8DL\xAB\xE8\"...' for column 'INFO' at row 1    |
| Warning | 1366 | Incorrect string value: '\x84\xF3d\xD6\xC2B...' for column 'INFO' at row 1 |
+---------+------+----------------------------------------------------------------------------+
3 rows in set (0.00 sec)

MySQL should not warn on columns which are not even touched by the query.

Still an active bug in 5.6.25 and also evident in performance_schema.events_statements_current.SQL_TEXT

mysql -u root -h [host] -e "SELECT procs.id, procs.time, procs.user, substring_index(procs.host,':',1) host, procs.command, stmts.current_schema, trim(stmts.sql_text) sql_text, trim(stmts.digest_text) digest_text, coalesce(stmts.digest,'N/A') digest FROM information_schema.processlist procs JOIN performance_schema.threads th ON procs.id = th.processlist_id JOIN performance_schema.events_statements_current stmts ON stmts.thread_id = th.thread_id WHERE procs.time > 5 AND procs.command NOT LIKE ('Binlog%') AND stmts.sql_text NOT LIKE ('commit') AND stmts.sql_text NOT LIKE ('rollback') ORDER BY procs.time DESC; show warnings"
+---------+------+------+-----------+---------+----------------+--------------------+--------------------+----------------------------------+
| id      | time | user | host      | command | current_schema | sql_text           | digest_text        | digest                           |
+---------+------+------+-----------+---------+----------------+--------------------+--------------------+----------------------------------+
| 1282379 |    9 | root | localhost | Sleep   | NULL           | SELECT @@read_only | SELECT @@READ_ONLY | 6205606e4120d0069d65dddbcb12f565 |
+---------+------+------+-----------+---------+----------------+--------------------+--------------------+----------------------------------+
+---------+------+---------------------------------------------------------------------------------------+
| Level   | Code | Message                                                                               |
+---------+------+---------------------------------------------------------------------------------------+
| Warning | 1366 | Incorrect string value: '\x80\x02cdro...' for column 'INFO' at row 1                  |
| Warning | 1366 | Incorrect string value: '\x92\xA4\x96\xB7K)...' for column 'INFO' at row 1            |
| Warning | 1366 | Incorrect string value: '\x92\xA4\x96\xB7K)...' for column 'SQL_TEXT' at row 61       |
| Warning | 1366 | Incorrect string value: '\xDA\xC3\xF9,?\x97...' for column 'SQL_TEXT' at row 61       |
| Warning | 1366 | Incorrect string value: '\xF7\Z\x83FV...' for column 'SQL_TEXT' at row 61             |
| Warning | 1366 | Incorrect string value: '\x8E\xFA\x9F\x89\x03\xDF...' for column 'SQL_TEXT' at row 61 |
| Warning | 1366 | Incorrect string value: '\x87\xB1\xEF`A\xE8...' for column 'SQL_TEXT' at row 61       |
| Warning | 1366 | Incorrect string value: '\x80\x02cdro...' for column 'SQL_TEXT' at row 61             |
| Warning | 1366 | Incorrect string value: '\xDA\xC3\xF9,?\x97...' for column 'SQL_TEXT' at row 61       |
| Warning | 1366 | Incorrect string value: '\xF7\Z\x83FV...' for column 'SQL_TEXT' at row 61             |
| Warning | 1366 | Incorrect string value: '\x8E\xFA\x9F\x89\x03\xDF...' for column 'SQL_TEXT' at row 61 |
+---------+------+---------------------------------------------------------------------------------------+

still repeatable on current 5.6.30, 5.7.12, 5.8.0.

mysql> SELECT id FROM information_schema.processlist;show warnings;show processlist;
+----+
| id |
+----+
|  3 |
|  4 |
|  5 |
|  6 |
|  7 |
|  8 |
|  9 |
+----+
7 rows in set, 4 warnings (0.00 sec)

+---------+------+-------------------------------------------------------------------------------+
| Level   | Code | Message                                                                       |
+---------+------+-------------------------------------------------------------------------------+
| Warning | 1366 | Incorrect string value: '\x90\x89\xC7@\xA9\xCD...' for column 'INFO' at row 1 |
| Warning | 1366 | Incorrect string value: '\xB6\x8B\xA8w~r...' for column 'INFO' at row 1       |
| Warning | 1366 | Incorrect string value: '\xDF\xE0\xEDq\x05 ...' for column 'INFO' at row 1    |
| Warning | 1366 | Incorrect string value: '\x9C\xC6\xABn\x8F<...' for column 'INFO' at row 1    |
+---------+------+-------------------------------------------------------------------------------+
4 rows in set (0.00 sec)

+----+------+-----------+------+---------+------+-------------------+-----------------------------------------------------------+
| Id | User | Host      | db   | Command | Time | State             | Info                                                      |
+----+------+-----------+------+---------+------+-------------------+-----------------------------------------------------------+
|  3 | root | localhost | test | Sleep   |    0 |                   | NULL                                                      |
|  4 | root | localhost | test | Query   |    0 | Sending to client | select "????}??d?:{t ?T?O?W?H?]z?♫???↓ a?D&s? [???►h???]" |
|  5 | root | localhost | test | Sleep   |    0 | cleaning up       | NULL                                                      |
|  6 | root | localhost | test | Query   |    0 | starting          | select "??????<"                                          |
|  7 | root | localhost | test | Sleep   |    0 |                   | NULL                                                      |
|  8 | root | localhost | NULL | Query   |    0 | starting          | show processlist                                          |
|  9 | root | localhost | test | Query   |    0 | starting          | select "?`????[O }?<?8↓ ??+??▬?w?s?b??w P+♣↓►??gj.??£?=?" |
+----+------+-----------+------+---------+------+-------------------+-----------------------------------------------------------+
7 rows in set (0.00 sec)

Bug #81226 marked as duplicate of this one

Posted by developer:
 
Reported version value updated to reflect release name change from 5.8 to 8.0

It's been over 8 YEARS since this bug was filed and it STILL hasn't been fixed???   This is astonishing.  This bug substantially hampers troubleshooting of, especially, live production systems in which one cannot simply log every query that hits the database or even attach a debugger to the querying program, but where it is critical to identify queries that bottleneck the system.