reset master does not reset

Server version: 5.5.38-35.2-log Percona Server (GPL), Release 35.2, Revision 674

Linux 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

CentOS release 6.5 (Final)

It happened again on another server.

# mysql -e"show master status\G ; reset master ; show master status\G"
*************************** 1. row ***************************
            File: bin.000022
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:
*************************** 1. row ***************************
            File: bin.000022
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:

Here it reverted to the previous numbered version of the file

# mysql -e"show master status\G ; reset master ; show master status\G"
*************************** 1. row ***************************
            File: bin.000023
        Position: 372451
    Binlog_Do_DB:
Binlog_Ignore_DB:
*************************** 1. row ***************************
            File: bin.000022
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:

Here is the expected behavior from a different server (running the same versions of Percona and Cent OS).

# mysql -e"show master status\G ; reset master ; show master status\G"
*************************** 1. row ***************************
            File: bin.000021
        Position: 6266415
    Binlog_Do_DB:
Binlog_Ignore_DB:
*************************** 1. row ***************************
            File: bin.000001
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:

bash-4.1# cat /etc/*release*
CentOS release 6.5 (Final)

mysql> show global variables like '%version%';
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.5.38-35.2 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.5.38-35.2-log |
| version_comment | Percona Server (GPL), Release 35.2, Revision 674 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+--------------------------------------------------+

mysql> show master status; reset master; show master status;
+------------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000003 | 3874 | | |
+------------------+----------+--------------+------------------+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.05 sec)

+------------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000001 | 107 | | |
+------------------+----------+--------------+------------------+
1 row in set (0.00 sec)

we are unable to reproduce this issue. Can you please provide more details on it. e.g. my.cnf and what processes were running during "reset master" ? Can you please provide show porcesslist output during "reset master"

+------+----------------+-----------------+----+---------+------+-------+------------------+-----------+---------------+-----------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined | Rows_read |
+------+----------------+-----------------+----+---------+------+-------+------------------+-----------+---------------+-----------+
| 579 | SUSR_Heartbeat | 127.0.0.1:56079 | | Sleep | 18 | | | 0 | 0 | 0 |
| 963 | root | localhost | | Query | 0 | | show processlist | 0 | 0 | 0 |
| 1031 | root | localhost | | Sleep | 0 | | | 0 | 0 | 0 |
+------+----------------+-----------------+----+---------+------+-------+------------------+-----------+---------------+-----------+

# ls -lt
total 6184
-rw-rw---- 1 mysql mysql 31493 Aug 13 20:24 bin.000018
-rw-rw---- 1 mysql mysql 49 Aug 13 20:21 bin.index
-rw-rw---- 1 mysql mysql 126 Jul 28 02:34 bin.000017
-rw-rw---- 1 mysql mysql 126 Jul 28 02:32 bin.000016
-rw-rw---- 1 mysql mysql 126 Jul 28 02:08 bin.000015
-rw-rw---- 1 mysql mysql 126 Jul 28 01:38 bin.000014
-rw-rw---- 1 mysql mysql 126 Jul 28 01:08 bin.000013
-rw-rw---- 1 mysql mysql 126 Jul 28 00:38 bin.000012
-rw-rw---- 1 mysql mysql 126 Jul 28 00:07 bin.000011
-rw-rw---- 1 mysql mysql 6266434 Jul 27 23:37 bin.000010

# mysql -e"show master status\G ; reset master ; show master status\G"
*************************** 1. row ***************************
            File: bin.000018
        Position: 32201
    Binlog_Do_DB:
Binlog_Ignore_DB:
*************************** 1. row ***************************
            File: bin.000018
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:

# ls -lt
total 6156
-rw-rw---- 1 mysql mysql 459 Aug 13 20:24 bin.000018
-rw-rw---- 1 mysql mysql 49 Aug 13 20:24 bin.index
-rw-rw---- 1 mysql mysql 126 Jul 28 02:34 bin.000017
-rw-rw---- 1 mysql mysql 126 Jul 28 02:32 bin.000016
-rw-rw---- 1 mysql mysql 126 Jul 28 02:08 bin.000015
-rw-rw---- 1 mysql mysql 126 Jul 28 01:38 bin.000014
-rw-rw---- 1 mysql mysql 126 Jul 28 01:08 bin.000013
-rw-rw---- 1 mysql mysql 126 Jul 28 00:38 bin.000012
-rw-rw---- 1 mysql mysql 126 Jul 28 00:07 bin.000011
-rw-rw---- 1 mysql mysql 6266434 Jul 27 23:37 bin.000010

Attached /etc/my.cnf

Attached /etc/mysql/conf.d/001-basic-config.cnf

The problem appeared on only a few servers.

I am still not able to reproduce this problem with provided my.cnf

I have an existing server that is exhibiting the bug.

Please, upload content of that bin.index file.

# cat bin.index
/opt/mysql/dblogs1/test-p0/bin/bin.000018

Please, send the output of:

lsof | grep 0000

I wonder if some of the binary logs are kept open by some process for some reason.

mysqld 21239 mysql 38w REG 9,2 230403395 503316756 /opt/mysql/dblogs1/test-p0/bin/bin.000018

I tried by removing binlog entries from binary log index file but still i can't reproduce.

Server version: 5.5.38-35.2-log Percona Server (GPL), Release 35.2, Revision 674

-rw-rw---- 1 root root 4240 Sep 9 13:54 mysql-bin.000003
-rw-rw---- 1 root root 4230 Sep 9 13:55 mysql-bin.000004
-rw-rw---- 1 root root 4250 Sep 9 13:56 mysql-bin.000005
-rw-rw---- 1 root root 4250 Sep 9 13:57 mysql-bin.000006
-rw-rw---- 1 root root 2200 Sep 9 13:57 mysql-bin.000007
-rw-rw---- 1 root root 107 Sep 9 13:57 mysql-bin.000008
-rw-rw---- 1 root root 19 Sep 9 13:58 mysql-bin.index

[root@centos63 data]# cat mysql-bin.index
./mysql-bin.000008

mysql [localhost] {root} ((none)) > show master status\G ; reset master ; show master status\G
*************************** 1. row ***************************
            File: mysql-bin.000008
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:
1 row in set (0.00 sec)

ERROR:
No query specified

Query OK, 0 rows affected (0.04 sec)

*************************** 1. row ***************************
            File: mysql-bin.000001
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:
1 row in set (0.00 sec)

Can you please provide mysql error log, /var/log/messages file and dmesg output during PURGE ?

I have keep this instance running only to work on this bug with you. I agree that is it not easy to reproduce. I have seen it on only three different instances.

How can we move forward on this bug?

Thanks.

Can you, please, share the error log of MySQL server affected? Muhammad asked for it once already.

Attaching MySQL server error log file

It happened again on a newly condensed slave server.

Server version: 5.6.21-69.0-log Percona Server (GPL), Release 69.0, Revision 675
CentOS release 6.5 (Final)
Linux 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

# mysql -uroot -e "STOP SLAVE; RESET SLAVE ALL ; RESET MASTER ; SHOW MASTER STATUS\G SET GLOBAL read_only=0"
*************************** 1. row ***************************
             File: bin.000010
         Position: 120
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:

# ls -lt /opt/mysql/dblogs1/packages-q0/bin/
total 6944
-rw-rw---- 1 mysql mysql 205891 Oct 9 01:26 bin.000011
-rw-rw---- 1 mysql mysql 92 Oct 9 01:17 bin.index
-rw-rw---- 1 mysql mysql 34889 Oct 9 01:17 bin.000010
-rw-rw---- 1 mysql mysql 143 Oct 9 01:01 bin.000009
-rw-rw---- 1 mysql mysql 143 Oct 9 00:59 bin.000008
-rw-rw---- 1 mysql mysql 143 Oct 9 00:58 bin.000007
-rw-rw---- 1 mysql mysql 143 Oct 9 00:58 bin.000006
-rw-rw---- 1 mysql mysql 143 Oct 9 00:45 bin.000005
-rw-rw---- 1 mysql mysql 143 Oct 9 00:28 bin.000004
-rw-rw---- 1 mysql mysql 143 Oct 8 23:58 bin.000003
-rw-rw---- 1 mysql mysql 6580682 Oct 8 23:28 bin.000002

I am seeing the problem on a few other servers I condensed.

# mysql -uroot -e "SHOW MASTER STATUS\G RESET MASTER ; SHOW MASTER STATUS\G"
*************************** 1. row ***************************
             File: bin.000019
         Position: 10615687
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
*************************** 1. row ***************************
             File: bin.000018
         Position: 513
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:

# mysql -uroot -e "SHOW MASTER STATUS\G RESET MASTER ; SHOW MASTER STATUS\G"
*************************** 1. row ***************************
             File: bin.000034
         Position: 21517422
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
*************************** 1. row ***************************
             File: bin.000033
         Position: 120
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:

# mysql -uroot -e "SHOW MASTER STATUS\G RESET MASTER ; SHOW MASTER STATUS\G"
*************************** 1. row ***************************
             File: bin.000046
         Position: 7783340
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
*************************** 1. row ***************************
             File: bin.000046
         Position: 511
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:

# mysql -uroot -e "SHOW MASTER STATUS\G RESET MASTER ; SHOW MASTER STATUS\G"
*************************** 1. row ***************************
             File: bin.000032
         Position: 15853463
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:
*************************** 1. row ***************************
             File: bin.000032
         Position: 120
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set:

The problem is caused when there are binary logs in the directory that are not in the bin.index file.

I am not sure what caused that.

# cat bin.index
/opt/mysql/dblogs1/test-p0/bin/bin.000018
/opt/mysql/dblogs1/test-p0/bin/bin.000019
/opt/mysql/dblogs1/test-p0/bin/bin.000020
/opt/mysql/dblogs1/test-p0/bin/bin.000021

# ls -lt
total 1272212
-rw-rw---- 1 mysql mysql 796199653 Oct 10 00:06 bin.000021
-rw-rw---- 1 mysql mysql 196 Sep 14 06:04 bin.index
-rw-rw---- 1 mysql mysql 130469 Sep 14 06:04 bin.000020
-rw-rw---- 1 mysql mysql 27016 Sep 14 05:58 bin.000019
-rw-rw---- 1 mysql mysql 495810670 Sep 14 05:57 bin.000018
-rw-rw---- 1 mysql mysql 126 Jul 28 02:34 bin.000017
-rw-rw---- 1 mysql mysql 126 Jul 28 02:32 bin.000016
-rw-rw---- 1 mysql mysql 126 Jul 28 02:08 bin.000015
-rw-rw---- 1 mysql mysql 126 Jul 28 01:38 bin.000014
-rw-rw---- 1 mysql mysql 126 Jul 28 01:08 bin.000013
-rw-rw---- 1 mysql mysql 126 Jul 28 00:38 bin.000012
-rw-rw---- 1 mysql mysql 126 Jul 28 00:07 bin.000011
-rw-rw---- 1 mysql mysql 6266434 Jul 27 23:37 bin.000010

# mysql -uroot -e "SHOW MASTER STATUS\G RESET MASTER ; SHOW MASTER STATUS\G"
*************************** 1. row ***************************
            File: bin.000021
        Position: 796271253
    Binlog_Do_DB:
Binlog_Ignore_DB:
*************************** 1. row ***************************
            File: bin.000018
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:

# ls -lt
total 6164
-rw-rw---- 1 mysql mysql 11403 Oct 10 00:10 bin.000018
-rw-rw---- 1 mysql mysql 49 Oct 10 00:09 bin.index
-rw-rw---- 1 mysql mysql 126 Jul 28 02:34 bin.000017
-rw-rw---- 1 mysql mysql 126 Jul 28 02:32 bin.000016
-rw-rw---- 1 mysql mysql 126 Jul 28 02:08 bin.000015
-rw-rw---- 1 mysql mysql 126 Jul 28 01:38 bin.000014
-rw-rw---- 1 mysql mysql 126 Jul 28 01:08 bin.000013
-rw-rw---- 1 mysql mysql 126 Jul 28 00:38 bin.000012
-rw-rw---- 1 mysql mysql 126 Jul 28 00:07 bin.000011
-rw-rw---- 1 mysql mysql 6266434 Jul 27 23:37 bin.000010

# rm bin.00001[0-7]

# ls -lt
total 36
-rw-rw---- 1 mysql mysql 30873 Oct 10 00:11 bin.000018
-rw-rw---- 1 mysql mysql 49 Oct 10 00:09 bin.index

# mysql -uroot -e "SHOW MASTER STATUS\G RESET MASTER ; SHOW MASTER STATUS\G"
*************************** 1. row ***************************
            File: bin.000018
        Position: 39015
    Binlog_Do_DB:
Binlog_Ignore_DB:
*************************** 1. row ***************************
            File: bin.000001
        Position: 107
    Binlog_Do_DB:
Binlog_Ignore_DB:

# ls -lt
total 8
-rw-rw---- 1 mysql mysql 3281 Oct 10 00:11 bin.000001
-rw-rw---- 1 mysql mysql 49 Oct 10 00:11 bin.index

Finally i am able to reproduce this problem on PS 5.6.

mysql [localhost] {msandbox} ((none)) > show global variables like '%version%';
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.6.21-rel69.0 |
| protocol_version| 10 |
| slave_type_conversions | |
| version | 5.6.21-69.0-log |
| version_comment | Percona Server (GPL), Release 69.0, Revision 675 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+--------------------------------------------------+
7 rows in set (0.00 sec)

 root: ~/sandboxes/msb_PS-5_6_21/data
# ll
total 183016
-rw-rw---- 1 root root 56 Oct 10 02:53 auto.cnf
-rw-rw---- 1 root root 242814 Oct 10 03:31 bin.000001
-rw-rw---- 1 root root 2427052 Oct 10 03:34 bin.000002
-rw-rw---- 1 root root 242888 Oct 10 03:35 bin.000003
-rw-rw---- 1 root root 242888 Oct 10 03:36 bin.000004
-rw-rw---- 1 root root 242888 Oct 10 03:37 bin.000005
-rw-rw---- 1 root root 485633 Oct 10 03:39 bin.000006
-rw-rw---- 1 root root 242888 Oct 10 03:40 bin.000007
-rw-rw---- 1 root root 242888 Oct 10 03:40 bin.000008
-rw-rw---- 1 root root 243773 Oct 10 03:42 bin.000009
-rw-rw---- 1 root root 242888 Oct 10 03:42 bin.000010
-rw-rw---- 1 root root 242888 Oct 10 03:43 bin.000011
-rw-rw---- 1 root root 242888 Oct 10 03:43 bin.000012
-rw-rw---- 1 root root 242888 Oct 10 03:44 bin.000013
-rw-rw---- 1 root root 242888 Oct 10 03:44 bin.000014
-rw-rw---- 1 root root 242888 Oct 10 03:46 bin.000015
-rw-rw---- 1 root root 242888 Oct 10 03:46 bin.000016
-rw-rw---- 1 root root 242785 Oct 10 03:52 bin.000017
-rw-rw---- 1 root root 242888 Oct 10 03:54 bin.000018
-rw-rw---- 1 root root 1029 Oct 10 03:55 bin.000019
-rw-rw---- 1 root root 247 Oct 10 03:54 bin.index

root: ~/sandboxes/msb_PS-5_6_21/data
# cat bin.index
./bin.000016
./bin.000017
./bin.000018
./bin.000019

root: ~/sandboxes/msb_PS-5_6_21/data
# ../use -e "SHOW MASTER STATUS"
+------------+----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------+----------+--------------+------------------+-------------------+
| bin.000019 | 1029 | | | |
+------------+----------+--------------+------------------+-------------------+

root: ~/sandboxes/msb_PS-5_6_21/data
# ../use -e "SHOW MASTER STATUS; RESET MASTER; SHOW MASTER STATUS;"
+------------+----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------+----------+--------------+------------------+-------------------+
| bin.000019 | 1029 | | | |
+------------+----------+--------------+------------------+-------------------+
+------------+----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------+----------+--------------+------------------+-------------------+
| bin.000016 ...

i repeated the same test case (as per comment#29) for Percona Server 5.5.38 but not able to reproduce it worked as expected.

# ../use -uroot -p -e "SHOW GLOBAL VARIABLES LIKE '%version%';"
Enter password:
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.5.38-35.2 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.5.38-35.2-log |
| version_comment | Percona Server (GPL), Release 35.2, Revision 674 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+--------------------------------------------------+

# ls -la
-rw-rw---- 1 root root 243370 Oct 10 15:40 bin.000001
-rw-rw---- 1 root root 243370 Oct 10 15:40 bin.000002
-rw-rw---- 1 root root 243370 Oct 10 15:41 bin.000003
-rw-rw---- 1 root root 243370 Oct 10 15:41 bin.000004
-rw-rw---- 1 root root 243370 Oct 10 15:42 bin.000005
-rw-rw---- 1 root root 243370 Oct 10 15:42 bin.000006
-rw-rw---- 1 root root 243370 Oct 10 15:43 bin.000007
-rw-rw---- 1 root root 243370 Oct 10 15:44 bin.000008
-rw-rw---- 1 root root 243370 Oct 10 15:44 bin.000009
-rw-rw---- 1 root root 243390 Oct 10 15:45 bin.000010
-rw-rw---- 1 root root 243390 Oct 10 15:45 bin.000011
-rw-rw---- 1 root root 243390 Oct 10 15:46 bin.000012
-rw-rw---- 1 root root 243390 Oct 10 15:46 bin.000013
-rw-rw---- 1 root root 243390 Oct 10 15:46 bin.000014
-rw-rw---- 1 root root 243390 Oct 10 15:47 bin.000015
-rw-rw---- 1 root root 243390 Oct 10 15:47 bin.000016
-rw-rw---- 1 root root 243390 Oct 10 15:48 bin.000017
-rw-rw---- 1 root root 243390 Oct 10 15:48 bin.000018
-rw-rw---- 1 root root 1042 Oct 10 15:49 bin.000019
-rw-rw---- 1 root root 247 Oct 10 15:48 bin.index
-rw-rw---- 1 root root 18874368 Oct 10 15:49 ibdata1
-rw-rw---- 1 root root 5242880 Oct 10 15:49 ib_logfile0
-rw-rw---- 1 root root 5242880 Oct 10 15:49 ib_logfile1
-rw-rw---- 1 root root 4406 Oct 10 15:49 innodb_status.14960

# ../use -uroot -p -e "SHOW MASTER STATUS;"
Enter password:
+------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------+----------+--------------+------------------+
| bin.000019 | 1042 | | |
+------------+----------+--------------+------------------+
# cat bin.index
./bin.000015
./bin.000016
./bin.000017
./bin.000018
./bin.000019

# ../use -uroot -p -e "SHOW MASTER STATUS; RESET MASTER; SHOW MASTER STATUS;"
Enter password:
+------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------+----------+--------------+------------------+
| bin.000019 | 1042 | | ...

Muhammad, is this an upstream issue?

I am able to reproduce this issue on Percona Server 5.1.73 too.

The problem previously occurred in 5.5 (see comment #1) and it happened again today.

mysql Ver 14.14 Distrib 5.5.40-36.1, for Linux (x86_64) using readline 5.1

Server version: 5.5.40-36.1-log Percona Server (GPL), Release 36.1, Revision 707

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