Ubuntu 16.04

Might relate to MDEV-20215.

Hi oli!

If you are still following this issue, I have a question. I see in the brman source code in lib/doBinlogBackup.inc, before the PURGE BINARY LOGS TO call, there is a comment.
// Be carefull with this step if you have slaves!

Does your environment have any slaves when you encounter this issue? In particular, if an old binlog is being read/used anywhere when the PURGE is issued, it will be ignored in the purge. A few examples of this are:
1. A slave is reading the binlog from the master during the same time period that the PURGE is issued
2. mysql-binlog, invoked with --read-from-remote-server, is active while the PURGE is issued
3. The SHOW BINLOG EVENTS command is running while the purge is issued

Given your observation that this issue occurs with short purge intervals, if something is reading an old binlog file during the purge, I could see this issue happening. I have a proposed fix, but would first like to confirm the cause of the issue.

Thanks!

Hello Brandon

Sorry for my late replay but I was in vacation...

The comment is more about that one should not purge binary logs if you have slaves and they did not read/apply those binary logs yet...

That was a complete testing environment. Typically mariadb-103 is a stand-alone instance. Otherwise I would call it something like mariadb-103m or so. But I cannot guarantee 100% for this... So most probably NO slave.
--read-from-remote-server I did NOT in this case.
SHOW BINLOG EVENTS I did NOT run and I cannot find it anywhere in the code either.

According to my notes this should simulate the problem: "This typically happens when only one binary log is there (little traffic or short purge interval)."

So I can try again, if I still can reproduce the issue without our brman...

BR,
Oli

Hi Oli!

Thanks for the reply! I have a thought, but would like to ask a few follow-up questions first:

1) In your test environment, do you remember how the data was being ingested? I saw that the utl folder in the brman source code has some scripts that create/populate tables. Do you remember if you used one of those? (to aid in my own attempts to correctly reproduce your behavior).

2) Do you have information on the cfg file and options used for running your MariaDB server instance?

3) If you could reproduce this, that would be great. Could you also attach the last two binlogs, e.g. binlog.000395 and binlog.000396, to aid in my analysis? Additionally if you can only reproduce this using brman, could you additionally attach the backup version of the problem binlog, e.g. bck_binlog.000395.gz?

Thanks!

Hello Brandon

OK. It tried to reproduce it. But without success! There were to many things changing since 2019: Machine?, Ubuntu version (16.04 vs 18.04), MariaDB version 10.3.16 vs. 10.3.20, brman version, config, etc...

• Load: I am not sure any more but typically I use our simple insert_test.sh script from myenv/utl. It just does INSERTs in a loop.
• Then I wrote a script to simulate brman (attached). But it did not provoke the problem
• Then I used brman instead (newest version). But it did not provoke the problem either...
• Then I added a 10.3 Slave to it. But it also did not provoke the problem.

while [ 1 ] ; do bman --target=brman:secret@127.0.0.1:3318 --type=binlog --policy=binlog --mode=logical --backupdir=/home/mysql/bck/mariadb-103 | grep 'End backup' ; sleep 60 ; done
End backup at 2021-09-22 10:03:00 (rc=0)
End backup at 2021-09-22 10:04:00 (rc=0)
End backup at 2021-09-22 10:05:00 (rc=0)
End backup at 2021-09-22 10:06:00 (rc=0)
End backup at 2021-09-22 10:07:01 (rc=0)
End backup at 2021-09-22 10:08:01 (rc=0)
End backup at 2021-09-22 10:09:01 (rc=0)
End backup at 2021-09-22 10:10:01 (rc=0)
End backup at 2021-09-22 10:11:02 (rc=0)
End backup at 2021-09-22 10:12:02 (rc=0)
End backup at 2021-09-22 10:13:02 (rc=0)
End backup at 2021-09-22 10:14:02 (rc=0)
End backup at 2021-09-22 10:15:03 (rc=0)
End backup at 2021-09-22 10:16:03 (rc=0)
End backup at 2021-09-22 10:17:03 (rc=0)
End backup at 2021-09-22 10:18:03 (rc=0)
End backup at 2021-09-22 10:19:04 (rc=0)
End backup at 2021-09-22 10:20:04 (rc=0)
End backup at 2021-09-22 10:21:04 (rc=0)

• Config I do not know any more. This is a testing system and the config there is very dynamic.

Do you have an idea what I shall try to provoke the problem? I will keep the system in the current state for a while...

Regards,
Oli

Before the interval was 60 seconds. But if I do the interval to random I get an error...

while [ 1 ] ; do bman --target=brman:secret@127.0.0.1:3318 --type=binlog --policy=binlog --mode=logical --backupdir=/home/mysql/bck/mariadb-103 | grep 'End backup' ; sleep $(echo $(($RANDOM % 60))) ; done
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000510.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-22 10:29:12 (rc=0)
End backup at 2021-09-22 10:29:19 (rc=0)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000512.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-22 10:29:23 (rc=0)
End backup at 2021-09-22 10:29:26 (rc=0)
End backup at 2021-09-22 10:29:55 (rc=0)

I try to narrow down the problem.

It happens randomly:

End backup at 2021-09-22 10:35:53 (rc=0)
End backup at 2021-09-22 10:36:04 (rc=0)
End backup at 2021-09-22 10:36:06 (rc=0)
End backup at 2021-09-22 10:36:12 (rc=0)
End backup at 2021-09-22 10:36:30 (rc=0)
End backup at 2021-09-22 10:36:34 (rc=0)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000537.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-22 10:36:40 (rc=0)
End backup at 2021-09-22 10:37:00 (rc=0)
End backup at 2021-09-22 10:37:05 (rc=0)
End backup at 2021-09-22 10:37:11 (rc=0)
End backup at 2021-09-22 10:37:11 (rc=0)

I just found, that we optimized the code yet in new brman releases:
$ret = compressFile($aOptions, $dst);
if ( (4178 == $ret) && (1 == $lBinlogCount) )

Fix was introduced in v2.2.1

With v2.2.0 it looks better:
End backup at 2021-09-22 11:06:00 (rc=0)
End backup at 2021-09-22 11:06:08 (rc=0)
End backup at 2021-09-22 11:06:11 (rc=0)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000605.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-22 11:06:20 (rc=4178)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000605.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-22 11:06:36 (rc=4178)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000605.gz already exists and you did not specify --backup-overwrite. (rc=4178)

Files attached...

So I can break it now regularly but not at will...

Thanks for your effort into reproducing this error! For clarification, in an earlier comment you mentioned that you added a slave into your testing environment. Did you stop/remove it afterwards? That is, was it running when you were able to reproduce the error?

Slave WAS running when I reproduced the problem. Running it again now with a shutdown slave.

I tried it again with and without a Slave. The results lead me to the conclusion that it is about 95% sure that it is the Slave:

Without a Slave:

mysql@chef:~ [mariadb-103, 3318]> while [ 1 ] ; do /home/mysql/product/brman-2.2.0/bin/bman --target=brman:secret@127.0.0.1:3318 --type=binlog --policy=binlog --mode=logical --backupdir=/home/mysql/bck/mariadb-103 | grep 'End backup' ; sleep $(echo $(($RANDOM % 20))) ; done
End backup at 2021-09-23 08:07:05 (rc=0)
... 79 times the same result
End backup at 2021-09-23 08:18:39 (rc=0)

Starting the Slave:

mysql@chef:~ [mariadb-103, 3318]> while [ 1 ] ; do /home/mysql/product/brman-2.2.0/bin/bman --target=brman:secret@127.0.0.1:3318 --type=binlog --policy=binlog --mode=logical --backupdir=/home/mysql/bck/mariadb-103 | grep 'End backup' ; sleep $(echo $(($RANDOM % 20))) ; done
End backup at 2021-09-23 08:19:03 (rc=0)
... 3 times the same result
End backup at 2021-09-23 08:19:34 (rc=0)
End backup at 2021-09-23 08:19:39 (rc=0)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000774.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-23 08:19:56 (rc=4178)

Removed the problematic file. Then:

End backup at 2021-09-23 08:20:40 (rc=0)
... 24 times the same result
End backup at 2021-09-23 08:24:52 (rc=0)
End backup at 2021-09-23 08:24:52 (rc=0)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000804.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-23 08:25:03 (rc=4178)

Removed the problematic file. Then:

End backup at 2021-09-23 08:26:50 (rc=0)
... 56 times the same result
End backup at 2021-09-23 08:36:25 (rc=0)
End backup at 2021-09-23 08:36:30 (rc=0)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.000872.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-23 08:36:40 (rc=4178)

Stop slave. Then:

End backup at 2021-09-23 08:38:02 (rc=0)
... 270 times the same result
End backup at 2021-09-23 09:20:43 (rc=0)

It was running now for 6 hours without a problem... If we calculate every 30 seconds a run in average this makes about 2400 runs. But then it broke again! WITHOUT a Slave attached...

...
End backup at 2021-09-23 15:18:40 (rc=0)
End backup at 2021-09-23 15:18:47 (rc=0)
ERROR: Zipped file /home/mysql/bck/mariadb-103/binlog/bck_binlog.003351.gz already exists and you did not specify --backup-overwrite. (rc=4178)
End backup at 2021-09-23 15:18:51 (rc=4178)

So it looks like this happens more probable WITH Slave. But it also happens rarely WITHOUT Slave... Does this make sense?

Interesting! Can you attach the problematic binary log file (live from the base directory), its gzipped backup version (assuming it was not overwritten?), and the next binary log file? So that would be binlog.003351, bck_binlog.003351.gz, and binlog.003352.

Edit: The previous binlog may be helpful too, binlog.003350

Hmm, my hunch didn't pan out.

Thanks for attaching the binlog files. Can you also attach the applicable server/error logs?

Uploaded.