Parsing of tcpdump capture from MySQL 5.6 with pt-query-digest adds erroneous \x0mysql_native_password to "use database" statements

Bug #1402776 reported by Ovais Tariq on 2014-12-15
42
This bug affects 7 people
Affects Status Importance Assigned to Milestone
Percona Toolkit moved to https://jira.percona.com/projects/PT
Fix Released
Medium
Carlos Salguero

Bug Description

When parsing a tcpdump file created with MySQL 5.6 with pt-query-digest the "use database" statements are parsed incorrectly.

The database name is appended with a null character and the string "mysql_native_password".

The Percona toolkit version used is 2.2.11.

The tcpdump command line used is the following:
/usr/sbin/tcpdump -i eth0 -s 65535 -x -n -q -tttt 'port 3306 and tcp[1] & 7 == 2 and tcp[3] & 7 == 2'

The pt-query-digest command line used is the following:
/usr/bin/pt-query-digest --type tcpdump /tmp/mysql.tcp.out --output slowlog --no-report --filter '($event->{fingerprint} =~ m/^select/i) && ($event->{arg} !~ m/for update/i) && ($event->{fingerprint} !~ m/some_table_name_to_ignore/i)' > /tmp/slow.log.out 2> /dev/null

description: updated
Ovais Tariq (ovais-tariq) wrote :

Here is a sample dump of $event:

$VAR1 = {
  No_good_index_used => 'No',
  No_index_used => 'Yes',
  Query_time => '0.000811',
  Rows_affected => 0,
  Thread_id => 7181212,
  Warning_count => 0,
  arg => '/* mysql-connector-java-5.1.24 ( Revision: ${bzr.revision-id} ) */SHOW VARIABLES WHERE Variable_name =\'language\' OR Variable_name = \'net_write_timeout\' OR Variable_name = \'interactive_timeout\' OR Variable_name = \'wait_timeout\' OR Variable_name = \'character_set_client\' OR Variable_name = \'character_set_connection\' OR Variable_name = \'character_set\' OR Variable_name = \'character_set_server\' OR Variable_name = \'tx_isolation\' OR Variable_name = \'transaction_isolation\' OR Variable_name = \'character_set_results\' OR Variable_name = \'timezone\' OR Variable_name = \'time_zone\' OR Variable_name = \'system_time_zone\' OR Variable_name = \'lower_case_table_names\' OR Variable_name = \'max_allowed_packet\' OR Variable_name = \'net_buffer_length\' OR Variable_name = \'sql_mode\' OR Variable_name = \'query_cache_type\' OR Variable_name = \'query_cache_size\' OR Variable_name = \'init_connect\'',
  bytes => 873,
  cmd => 'Query',
  db => 'db_name^@mysql_native_password',
  fingerprint => 'show variables where variable_name =? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ? or variable_name = ?',
  host => '192.168.10.25',
  ip => '192.168.10.25',
  port => '54170',
  pos_in_log => 3191192,
  ts => '141212 15:33:45.829984',
  user => 'db_name'
};

everflux (tklaunchpad) wrote :

I can confirm this bug, I think it should be reported upstream.
The bug was reproducible using mysql-java driver 5.1.34 as well as using PHP.

everflux (tklaunchpad) wrote :

Example statements to trigger the problem:

USE information_schema;
SHOW TABLES;
USE mydb;
SHOW TABLES;
SELECT * FROM sometable;

result of pt-query-digest:

...
# Databases mydbmysql_native_password
....
# SHOW TABLE STATUS FROM `mydbmysql_native_password` LIKE 'sometable'\G
....

everflux (tklaunchpad) wrote :

Seems to be even worse if the tcpdump captures a connect/disconnect from the database:

tcpdump -i eth0 -s 65535 -x -nn -q -tttt port 3306 > mysql.tcp.txt
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
^C2409 packets captured
2409 packets received by filter
0 packets dropped by kernel

pt-query-digest --limit 20 --type tcpdump mysql.tcp.txt

....
# Databases mydbmysql_native_password�_runtime_ver...
...
# SHOW TABLE STATUS FROM `mydbmysql_native_password�_runtime_versio1.8.0_25_client_version5.1.34
                                                                                                        _client_nameMySQL Connector Java_client_licenseGPL_runtime_vendorOracle Corporation` LIKE 'cdata'\G
# SHOW CREATE TABLE `mydbmysql_native_password�_runtime_versio1.8.0_25_client_version5.1.34
                                                                                                   _client_nameMySQL Connector Java_client_licenseGPL_runtime_vendorOracle Corporation`.`cdata`\G
# EXPLAIN /*!50100 PARTITIONS*/
....

Download full text (15.3 KiB)

Tried to reproduce the same with attached script FirstExample.java but unable to get that error. I'm seeing normal database name. Please let me know if I'm missing anything here. or need to correct script.

nilnandan@desktop:~$ sudo tcpdump -i eth0 -s 65535 -x -nn -q -tttt port 3306 > mysql.tcp.txt
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
^C68 packets captured
68 packets received by filter
0 packets dropped by kernel
nilnandan@desktop:~$
nilnandan@desktop:~$ sudo /home/nilnandan/Downloads/percona-toolkit-2.2.11/bin/pt-query-digest --limit 20 --type tcpdump mysql.tcp.txt

# 140ms user time, 10ms system time, 32.66M rss, 105.42M vsz
# Current date: Mon Jan 19 16:47:05 2015
# Hostname: desktop
# Files: mysql.tcp.txt
# Overall: 15 total, 13 unique, 204.17 QPS, 0.40x concurrency ____________
# Time range: 2015-01-19 16:46:59.453236 to 16:46:59.526706
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 29ms 0 27ms 2ms 1ms 7ms 93us
# Rows affecte 0 0 0 0 0 0 0
# Query size 330 7 57 22 31.70 11.80 21.45
# Warning coun 0 0 0 0 0 0 0
# Boolean:
# No index use 13% yes, 86% no

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x5D51E5F01B88B79E 0.0269 91.4% 1 0.0269 0.00 ADMIN CONNECT
# 2 0x911658842DA64DC4 0.0011 3.6% 1 0.0011 0.00 SHOW VARIABLES
# 3 0xA2750AF24EA2AEE6 0.0004 1.2% 1 0.0004 0.00 SHOW COLLATION
# 4 0x132628303F99240D 0.0003 1.0% 2 0.0001 0.00 SHOW TABLES
# 5 0x6C099B0B73EA7633 0.0002 0.5% 2 0.0001 0.00
# 6 0x3A021F4F9152841C 0.0001 0.5% 1 0.0001 0.00 SHOW TABLE STATUS
# 7 0x6602589ABA5C746C 0.0001 0.3% 1 0.0001 0.00 SELECT test
# 8 0x38B3D80280BBFA2A 0.0001 0.3% 1 0.0001 0.00 SET
# 9 0x3AEAAD0E15D725B5 0.0001 0.3% 1 0.0001 0.00 SET
# 10 0xE4CF7146873CCC28 0.0001 0.3% 1 0.0001 0.00 SET
# 11 0xC5F2D057EEEC328B 0.0001 0.2% 1 0.0001 0.00 SHOW CREATE TABLE
# 12 0x44001A2E53C1AB70 0.0001 0.2% 1 0.0001 0.00 SET
# 13 0xAA353644DE4C4CB4 0.0000 0.0% 1 0.0000 0.00 ADMIN QUIT

# Query 1: 0 QPS, 0x concurrency, ID 0x5D51E5F01B88B79E at byte 1540 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2015-01-19 16:46:59.453236
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 1
# Exec time 91 27ms 27ms 27ms 27ms 27ms 0 27ms
# Rows affecte 0 0 0 0 0 0 0 0
# Query size 9 30 30 30 30 30 0 30
# Warning coun 0 0 0 0 0 0 ...

Changed in percona-toolkit:
status: New → Incomplete

The output of above script will be. (run from another instance)

[root@centos65 ~]# java -cp .:mysql-connector-java-3.1.14-bin.jar FirstExample
Connecting to database...
Creating statement...
ID: 1, Name: nilnandanGoodbye!
[root@centos65 ~]#
[root@centos65 ~]#

everflux (tklaunchpad) wrote :

Would it help if I create a tcpdump dump and provide it for further investigation?

Tim Pearson (ttpears) wrote :

Confirming bug.

Percona toolkit version: 2.2.11
MySQL Server version: 5.5.40-rel36.1-707.wheezy
TCPDump version: 4.3.0-1

TCPDump command issued:
tcpdump -s 65535 -x -nn -q -tttt -i eth0 -c 500000 port 3306 > mysqltcp.txt

pt-query-digest command:
pt-query-digest --type tcpdump mysqltcp.txt

Output examples:
# String:
# Databases ^@mysql_nat... (1398/76%), <removed>... (421/23%), mysql_nati... (3/0%), <removed>... (1/0%)
# Hosts <removed>
# Users <removed>
# Query_time distribution
# 1us
# 10us
# 100us ##########################################
# 1ms ################################################################
# 10ms ####
# 100ms #
# 1s #
# 10s+
# Tables
# SHOW TABLE STATUS FROM `^@mysql_native_password` LIKE <removed>
# SHOW CREATE TABLE `^@mysql_native_password`.<removed>

Changed in percona-toolkit:
status: Incomplete → Triaged
importance: Undecided → Medium
tags: added: pt-query-digest
Ovais Tariq (ovais-tariq) wrote :

Any ideas when we should expect this to be fixed.

Changed in percona-toolkit:
assignee: nobody → Frank Cizmich (frank-cizmich)
milestone: none → 2.2.14
Frank Cizmich (frank-cizmich) wrote :

Targeted it for 2.2.14
Will post a patch when it's fixed.

everflux (tklaunchpad) wrote :

Awesome. Please make sure to also verify with a tool that reads various other meta data. (I believe that was the cause for the really bad output when using the free java/jdbc tool http://www.sql-workbench.net/ just accessing a database I posted earlier.)

Ovais Tariq (ovais-tariq) wrote :

Thanks Frank.

Ovais Tariq (ovais-tariq) wrote :

Here is some more bash foo in case you want to parse the schema names correctly and you know what the schema names are like:

/usr/bin/pt-query-digest --type tcpdump mysql.tcp --output slowlog | sed 's/\(^use schema_name\).*/\1 /g' | awk '{ if($0 ~ /use schema_name/) {print $1" "$2} else { print $0 } }'

Changed in percona-toolkit:
milestone: 2.2.14 → none
Jervin R (revin) wrote :

Checking if this bug will still be fixed, thought it was targetted for 2.2.14? :)

Frank Cizmich (frank-cizmich) wrote :

Hi Jervin,

Yes, the bug is still unfixed, although in progress. The cause is a change in MySQL tcp protocol and how it handles authentication, so I needed to revise the whole parsing internals, which bogged me down, .. and as often is the case, other stuff overtook priority.
Will take a new look now.

Changed in percona-toolkit:
status: Triaged → In Progress
milestone: none → 2.3.1
Changed in percona-toolkit:
milestone: 2.2.17 → 2.2.18
tags: added: i67231
Sveta Smirnova (svetasmirnova) wrote :

Version 5.5 also affected.

everflux (tklaunchpad) wrote :

Is there a work around available or a snapshot version of pt-query-digest with a patch?

@everflux: Try running it like this:
PERCONA_TOOLKIT_TCP_ERRORS_FILE=/dev/null pt-query-digest --type=tcpdump . . .

Sveta Smirnova (svetasmirnova) wrote :

Bug is repeatable with version 2.2.17

Test I used.

1. Start MySQL 5.7.13 from MTR:

./mtr --start-dirty innodb &

2. Start tcpdump:

sudo tcpdump -s 65535 -X -nn -q -tttt -i any -c 25 port 13000 > mysqltcp.txt

3. Run following PHP script few times:

php -r '$m=mysqli_connect("127.0.0.1","root","","test",13000); mysqli_real_query($m, "USE information_schema"); mysqli_real_query($m, "SHOW TABLES"); mysqli_real_query($m, "select * from tables");'

sveta@Thinkie:~/build/mysql-5.7/mysql-test$ php --version
PHP 5.5.9-1ubuntu4.17 (cli) (built: May 19 2016 19:05:57)
Copyright (c) 1997-2014 The PHP Group
Zend Engine v2.5.0, Copyright (c) 1998-2014 Zend Technologies
    with Zend OPcache v7.0.3, Copyright (c) 1999-2014, by Zend Technologies

Installed from Ubuntu repo

4. Process tcpdump:

PTDEBUG=1 ~/src/percona-toolkit/bin/pt-query-digest --type tcpdump --watch-server 127.0.0.1:13000 --limit 100% mysqltcp.txt 2>err.log >out.log

5. Find in out.log:

# Query 1: 4.50 QPS, 0.01x concurrency, ID 0x5D51E5F01B88B79E at byte 14320
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
...
# Databases test^@mysql_native_password
...
administrator command: Connect\G

Full out.log and tcpdump output will be attached.

Sveta Smirnova (svetasmirnova) wrote :
Sveta Smirnova (svetasmirnova) wrote :
Sveta Smirnova (svetasmirnova) wrote :
Sveta Smirnova (svetasmirnova) wrote :

Workaround to specify PERCONA_TOOLKIT_TCP_ERRORS_FILE=/dev/null does not work for me

Changed in percona-toolkit:
status: In Progress → Fix Committed
Sveta Smirnova (svetasmirnova) wrote :

I see same corruption if run just pulled pt-query-digest on the attached tcpdump output

Sveta Smirnova (svetasmirnova) wrote :

With today pull it works fine

Changed in percona-toolkit:
status: Fix Committed → Fix Released

Still happening with 5.7 and pt-query-digest 2.2.19

Steps:

On server:
sudo tcpdump -s 65535 -x -nn -q -tttt -i any -c 10000 port 3306 > pepe

Run a couple of queries:
mysql> use `percona`
mysql> select * from `percona`.`sbtest99`;
mysql> select * from `percona`.`sbtest99`;
mysql> select * from `percona`.`sbtest99`;
...

Use pt-query-digest:
root@reports:~# cat pepe | pt-query-digest --type tcpdump --output slowlog | head -n50
Reading from STDIN ...
# Time: 161116 20:53:15.726698
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.001404 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
# administrator command: Connect;
# Time: 161116 20:53:15.727415
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000210 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
select @@version_comment limit 1;
# Time: 161116 20:53:18.533741
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000231 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
SELECT DATABASE();
# Time: 161116 20:53:18.535239
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000203 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
# administrator command: Init_db;
# Time: 161116 20:53:18.537493
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000511 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
show databases;
# Time: 161116 20:53:18.540470
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.002153 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
show tables;
# Time: 161116 20:53:18.545246
# User@Host: root[root] @ 192.168.0.10 []
# Client: 192.168.0.10:51981
# Thread_id: 16
# Query_time: 0.000536 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use mysql_native_password;
# administrator command: Field_list;
# Caught SIGPIPE.

Check the presence of "use mysql_native_password;" on each statement

Changed in percona-toolkit:
milestone: 2.2.18 → 2.2.20
status: Fix Released → In Progress
assignee: Frank Cizmich (frank-cizmich) → Carlos Salguero (carlos-salguero)
Changed in percona-toolkit:
milestone: 2.2.20 → 2.2.21

Updated MySQL Protocol Parser to make it able to handle connection flags to properly detect the DB name or leave the field empty if necessary.

Changed in percona-toolkit:
status: In Progress → Fix Committed
Changed in percona-toolkit:
status: Fix Committed → Fix Released

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PT-667

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers