MySQL Bugs: #75507: --log-bin overwrites binlog when basename contains period chars

Bug #75507	--log-bin overwrites binlog when basename contains period chars
Submitted:	14 Jan 2015 17:47	Modified:	16 Jan 2015 10:31
Reporter:	Valeriy Kravchuk	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.7.31, 8.0.21	OS:	Linux
Assigned to:		CPU Architecture:	x86
Tags:	--log-bin, log_bin, relay_log

Description:
Manual (http://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#option_mysqld_l...) says:

"The option value, if given, is the basename for the log sequence. The server creates binary log files in sequence by adding a numeric suffix to the basename. It is recommended that you specify a basename (see Section B.5.8, “Known Issues in MySQL”, for the reason). Otherwise, MySQL uses host_name-bin as the basename."

It says nothing about any restriction on basename. But if you use dot ('.') there, anything after the dot is truncated. Same probably applies to relay_log setting as well.

Linux basename utility that one may have in mind preserves "suffixes" by default:

[openxs@centos ~]$ basename a.b.c.a-bin-log
a.b.c.a-bin-log
[openxs@centos ~]$ basename /var/lib/mysql/a.b.c.a-bin-log
a.b.c.a-bin-log

How to repeat:
Set log-bin to a name with dot, like this:

[openxs@centos ~]$ cat /etc/my.cnf | grep log-bin
log-bin=a.b.c.a-bin-log

Now enjoy:

mysql> show variables like 'log_bin%';
+---------------------------------+------------------------+
| Variable_name                   | Value                  |
+---------------------------------+------------------------+
| log_bin                         | ON                     |
| log_bin_basename                | /var/lib/mysql/a       |
| log_bin_index                   | /var/lib/mysql/a.index |
| log_bin_trust_function_creators | OFF                    |
| log_bin_use_v1_row_events       | OFF                    |
+---------------------------------+------------------------+
5 rows in set (0.01 sec)

[root@centos openxs]# ls -l /var/lib/mysql/a*
-rw-rw----. 1 mysql mysql 224 Jan 14 19:34 /var/lib/mysql/a.000001
-rw-rw----. 1 mysql mysql  11 Jan 14 19:34 /var/lib/mysql/a.index
-rw-rw----. 1 mysql mysql  56 Jun  6  2014 /var/lib/mysql/auto.cnf

If you set relay_log to something like a.b.c.a-relay-log, you'll get a nice mix up of binary logs and relay logs on slave... Now think about naming logs after host name explicitly to imagine the impact.

Suggested fix:
Do not truncate basename for log_bin and relay_log at the first dot.

Alternatively, document how it is really processed to get log names.

Hello Valeriy,

Thank you for the report and test case.
Observed similar behavior with 5.6.22.

Thanks,
Umesh

/ 5.6.22

[root@cluster-repo ~]# vi /etc/my.cnf
[root@cluster-repo ~]# cat /etc/my.cnf | grep log_bin
log_bin=a.b.c.a-bin-log

[root@cluster-repo ~]# /etc/init.d/mysqld restart
Stopping mysqld:                                           [  OK  ]
Starting mysqld:                                           [  OK  ]
[root@cluster-repo ~]# ls -l /var/lib/mysql/
total 1393484
-rw-rw---- 1 mysql mysql        120 Jan 18 17:27 a.000001
-rw-rw---- 1 mysql mysql         11 Jan 18 17:27 a.index

[(none)]> show variables like 'log_bin%';
+---------------------------------+------------------------+
| Variable_name                   | Value                  |
+---------------------------------+------------------------+
| log_bin                         | ON                     |
| log_bin_basename                | /var/lib/mysql/a       |
| log_bin_index                   | /var/lib/mysql/a.index |
| log_bin_trust_function_creators | OFF                    |
| log_bin_use_v1_row_events       | OFF                    |
+---------------------------------+------------------------+
5 rows in set (0.00 sec)

[(none)]> show master logs;
+----------+-----------+
| Log_name | File_size |
+----------+-----------+
| a.000001 |       120 |
+----------+-----------+
1 row in set (0.00 sec)

[(none)]> flush logs;
Query OK, 0 rows affected (0.01 sec)

[(none)]> show master logs;
+----------+-----------+
| Log_name | File_size |
+----------+-----------+
| a.000001 |       159 |
| a.000002 |       120 |
+----------+-----------+
2 rows in set (0.00 sec)

// 5.7.6

bin/mysql_install_db --basedir=/export/umesh/mysql-5.7.6 --datadir=/export/umesh/mysql-5.7.6/75510 -v

[umshastr@hod03]/export/umesh/mysql-5.7.6: bin/mysqld --basedir=/export/umesh/mysql-5.7.6 --datadir=/export/umesh/mysql-5.7.6/75510 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/mysql-5.7.6/75510/log.err --log-bin=a.b.c.d.a-bin --server-id=1 2>&1 &

mysql> show variables like '%version%';
+-------------------------+---------------------------------------------------------+
| Variable_name           | Value                                                   |
+-------------------------+---------------------------------------------------------+
| innodb_version          | 5.7.6                                                   |
| protocol_version        | 10                                                      |
| slave_type_conversions  |                                                         |
| version                 | 5.7.6-m16-enterprise-commercial-advanced-log            |
| version_comment         | MySQL Enterprise Server - Advanced Edition (Commercial) |
| version_compile_machine | x86_64                                                  |
| version_compile_os      | Linux                                                   |
+-------------------------+---------------------------------------------------------+
7 rows in set (0.00 sec)

mysql> show variables like 'log_bin%';
+---------------------------------+-----------------------------------------+
| Variable_name                   | Value                                   |
+---------------------------------+-----------------------------------------+
| log_bin                         | ON                                      |
| log_bin_basename                | /export/umesh/mysql-5.7.6/75510/a       |
| log_bin_index                   | /export/umesh/mysql-5.7.6/75510/a.index |
| log_bin_trust_function_creators | OFF                                     |
| log_bin_use_v1_row_events       | OFF                                     |
+---------------------------------+-----------------------------------------+
5 rows in set (0.00 sec)

mysql> show master logs;
+----------+-----------+
| Log_name | File_size |
+----------+-----------+
| a.b.c.d  |       120 |
| a.b.c.d  |       120 |
+----------+-----------+
2 rows in set (0.00 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.00 sec)

mysql> show master logs;
+----------+-----------+
| Log_name | File_size |
+----------+-----------+
| a.b.c.d  |       120 |
| a.b.c.d  |       120 |
| a.b.c.d  |       120 |
+----------+-----------+
3 rows in set (0.00 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.00 sec)

mysql> show master logs;
+----------+-----------+
| Log_name | File_size |
+----------+-----------+
| a.b.c.d  |       120 |
| a.b.c.d  |       120 |
| a.b.c.d  |       120 |
| a.b.c.d  |       120 |
+----------+-----------+
4 rows in set (0.00 sec)

[umshastr@hod03]/export/umesh/mysql-5.7.6: ls -l 75510/a*
-rw-rw---- 1 umshastr common 158 Jan 16 11:27 75510/a.b.c.d
-rw-rw---- 1 umshastr common  40 Jan 16 11:27 75510/a.index
-rw-rw---- 1 umshastr common  56 Jan 16 10:30 75510/auto.cnf
[umshastr@hod03]/export/umesh/mysql-5.7.6: more 75510/a.index

./a.b.c.d
./a.b.c.d
./a.b.c.d
./a.b.c.d

Bug #88788 marked as duplicate of this one

Bug 88576 marked as a duplicate of this

Documentation issues should use Documentation category, else Docs team might not see them.

Changed category, assigned to myself for resolution.

Running 8.0.22 compiled from git repo, server started with --log-bin=a.b.c.d has the following effects:

1. log_bin_basename value is "a". (Already noted.)

2. log_bin_index value is "a.index". (Already noted.)

3. Binary log file created in datadir is named "a.b.c". (Not previously reported.)

4. Binary log file does *not* have .000001, .000002, etc., suffix appended to basename. (Not previously reported)

5. Binary log file "a.b.c" is reused following a restart of the server:

5a. Start the server with --log-bin=a.b.c.d; log in with mysql client and run a few SQL statements; shut it down. Now run mysqlbinlog --base64-output=decode-rows --verbose ../data/a.b.c (adjust path to match location of your datadir); this log file can be read as usual, and the output from mysqlbinlog contains the SQL statements just run in the mysql client.

5b. Start the server again with --log-bin=a.b.c.d; log in with mysql client run a few SQL statements; stop the server.

5c. Observe that files a.b.c and a.index have been updated.

5d. At this point, a.index contains 2 duplicate entries:

./a.b.c
./a.b.c

This should never happen.

5e. Now run mysqlbinlog --base64-output=decode-rows --verbose ../data/a.b.c again. The SQL statements entered during the first mysql client session are no longer there. The statements entered during the second mysql client session are present, but so is the following:

ERROR: Could not read entry at offset 509: Error in log format or read error 1.
ERROR: binlog truncated in the middle of event; consider out of disk space

Obtained similar result using 5.7.31 compiled from git tree (with the additional requirement of adding server startup option --server-id=1).

I don't see how this can be bandaged over as a documentation issue; not only is the 5.6 behaviour not really acceptable (I've confirmed using 5.6.49-git), but the problem has actually grown *worse* in 5.7 and 8.0.

Changing category to Server:Logging. Setting severity S2 because someone doing this and not being aware of the consequences could lose their data due to the binlog file being overwritten.

I'm not going to do any testing with --relay-log or other related options to see what happens, but this definitely needs to be done.

As to whether or not we should emulate Unix basename behaviour, that's not for me to determine. But we need to provide consistent behaviour and the server should AFAICT never overwrite existing log files in this fashion.

Bug #104665 marked as duplicate of this one.