| Bug #100913 | Enterprise backup did failed to use Redolog archive feature | ||
|---|---|---|---|
| Submitted: | 22 Sep 2020 12:56 | Modified: | 10 Jan 2021 19:15 |
| Reporter: | Marco Tusa | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Enterprise Backup | Severity: | S2 (Serious) |
| Version: | 8.0.21 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | Backup, Enterprise, redolog | ||
[22 Sep 2020 12:57]
Marco Tusa
Forgot to add. Was following the documentation here: https://dev.mysql.com/doc/refman/8.0/en/innodb-redo-log.html#innodb-redo-log-archiving https://dev.mysql.com/doc/mysql-enterprise-backup/8.0/en/backup-incremental-options.html
[23 Sep 2020 6:42]
Ingo Strüwing
This is likely a bug in mysqlbackup. It creates the directory with 0777. So it allows world access. That should be fixed. If that is indeed the problem, you could work around this by setting umask with a 7 at the end. Can you please verify, if that fixes the problem? Regarding the suspect, that mysqlbackup does not create the directory, I recommend to add --trace=3 to the mysqlbackup command line. The log is way more detailed then, and the creation of the directory should be logged. When mysqlbackup cannot start the redo logging, it removes the directory, so that it doesn't leave it behind. That is the likely reason, that you don't find it afterwards. --trace=3 should also log that deletion.
[23 Sep 2020 11:13]
Marco Tusa
Thank you Ingo! Yes I confirm that the issue was on the permission and with umask on the mountpoint I was able to run it and got: [root@master3 archive]# ll 16008594410996540/ total 284 -r--------. 1 mysql mysql 290816 Sep 23 2020 archive.42911622-fc08-11ea-8b18-08002734ed50.000001.log I will still keep as Feature request that when there is an already running process dumping the redolog changes, mysqlbackup should use that instead asking to perform a STOP.
[23 Sep 2020 12:33]
MySQL Verification Team
Thank you for the report and feedback.
I'm not seeing the exact error but do observed that MEB fails to create the target directory.
rm -rf 100913/
bin/mysqld --initialize-insecure --basedir=$PWD --datadir=$PWD/100913 --log-error-verbosity=3
bin/mysqld --no-defaults --basedir=$PWD --datadir=$PWD/100913 --core-file --socket=/tmp/mysql_ushastry.sock --port=3333 --log-error=$PWD/100913/log.err --mysqlx=0 --log-error-verbosity=3 --secure-file-priv="" --performance-schema=ON 2>&1 &
umask
0022
mkdir -p /export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive/
-
bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 7
Server version: 8.0.21-commercial MySQL Enterprise Server - Commercial
Copyright (c) 2000, 2020, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> SET GLOBAL innodb_redo_log_archive_dirs='full:/export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive/;';
Query OK, 0 rows affected (0.00 sec)
mysql> show global variables like 'innodb_redo_log_archive_dirs';
+------------------------------+-------------------------------------------------------------------------------+
| Variable_name | Value |
+------------------------------+-------------------------------------------------------------------------------+
| innodb_redo_log_archive_dirs | full:/export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive/; |
+------------------------------+-------------------------------------------------------------------------------+
1 row in set (0.00 sec)
With --trace=3
-
bin/mysqlbackup --trace=3 --show-progress=stdout --user=root --socket=/tmp/mysql_ushastry.sock --process-threads=4 --port=3333 --backup-dir=/tmp/mysql_backup/meb/1 backup > file.txt 2>&1
-
200923 14:22:34 MAIN TRACE_1: Executing MySQL query 'SELECT @@GLOBAL.innodb_redo_log_archive_dirs'
200923 14:22:34 MAIN TRACE_3: query result requested: 1, stored: 1
200923 14:22:34 MAIN TRACE_3: mysql_conn_query returns 0 (0 == success)
200923 14:22:34 MAIN TRACE_2: Global server system variable 'innodb_redo_log_archive_dirs' is 'full:/export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive/;'.
200923 14:22:34 MAIN TRACE_2: [MKDIR] /export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive/16008637540602760
200923 14:22:34 MAIN TRACE_2: Directory '/' does already exist.
200923 14:22:34 MAIN TRACE_2: Directory '/export' does already exist.
200923 14:22:34 MAIN TRACE_2: Directory '/export/umesh' does already exist.
200923 14:22:34 MAIN TRACE_2: Directory '/export/umesh/server' does already exist.
200923 14:22:34 MAIN TRACE_2: Directory '/export/umesh/server/binaries' does already exist.
200923 14:22:34 MAIN TRACE_2: Directory '/export/umesh/server/binaries/GABuilds' does already exist.
200923 14:22:34 MAIN TRACE_2: Directory '/export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21' does already exist.
200923 14:22:34 MAIN TRACE_2: Directory '/export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive' does already exist.
200923 14:22:34 MAIN TRACE_3: Created path '/export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive/16008637540602760'
200923 14:22:34 MAIN TRACE_1: Executing MySQL query 'DO innodb_redo_log_archive_start('full','16008637540602760');'
-
ls -l archive/
total 0
- manually
mysql> DO innodb_redo_log_archive_start('full','16008638940647671');
ERROR 3844 (HY000): Redo log archive directory '/export/umesh/server/binaries/GABuilds/mysql-commercial-8.0.21/archive/16008638940647671' does not exist or is not a directory
mysql> \q
[23 Sep 2020 14:11]
Ingo Strüwing
Hi Marco, so your feature request is to allow multiple sessions to run archive logging in parallel? When we designed the redo log archiving feature, we had some thoughts about this. However it looked too difficult for a first implementation. We identified two possible options to implement it. A) [This is probably, what you suggest.] Start redo log archiving when the first session requests it. Count the sessions, that request to start archiving while it is going on already. Decrement the counter when a session requests to stop redo log archiving. When the counter reaches zero, stop redo log archiving. That way we have just one redo log archive file. The redo log blocks need to be written twice only (to the ib_logfile* and to the archive file). The downside is, that the file could grow very large, if many sessions request archiving overlapping. This could be mitigated by hole punching, if we remember, which segment of the log belongs to which session. Also we need extra algorithms to determine, when the file can be deleted altogether. B) Allow each session to have its own redo log archive file. The ownership of the file remains with the client. It can still delete its file when no longer needed. The downside is, that the redo log blocks have to be written multiple times, which could cause a slow-down of the server if many session run that in parallel. In summary I would appreciate, if you could file a separate feature request, explaining as detailed as possible, how you imagine, that it should work. Regards Ingo
[23 Sep 2020 14:19]
Marco Tusa
Ingo, actually you capture my idea with A). But I will discuss internally also to collect more feedback and will confirm, which can be the best option for us. Thank you again.
[7 Oct 2020 14:24]
Marco Tusa
Ingo, as I was supposing we all think that the A) solution with a single file, is preferable.
[7 Oct 2020 14:35]
Ingo Strüwing
Ok, fine. Can you please file a separate bug report and mark it as S4 (feature request)? The directory permission problem will be fixed in MEB and should be available in a release next year.
[10 Jan 2021 19:15]
Daniel So
Posted by developer: Added the following entry to the MySQL Enterprise Backup 8.0.23 changelog: "On a Windows platform, when the value of the server's system variable innodb_redo_log_archive_dirs was an absolute path name without a label, a backup operation for the server failed with the error message that the archive directory was accessible to all OS users. This was due to mysqlbackup misinterpreting the path name in the situation. With this fix, the path name is now properly interpreted, and if the archive does not exist, a proper error is thrown."
[13 Jan 2021 2:12]
Daniel So
Posted by developer: Corrected the changelog entry to the following: "A backup using redo log archiving failed, because mysqlbackup created a subdirectory under the redo log archiving directory (specified in innodb_redo_log_archive_dirs) that was accessible to all OS users, and that was not allowed. With this fix, a subdirectory with the proper permission is created under the situation."
Description: when using MEB in conjunction with Mysql 8.0.21 and try to use redolog archiving. MEB fails to create the target directory. How to repeat: [root@master3 archive]# mysqlbackup --version MySQL Enterprise Backup Ver 8.0.21-commercial for Linux on x86_64 (MySQL Enterprise - Commercial) Copyright (c) 2003, 2020, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Run mysqlbackup --help for help information. (root@localhost) [(none)]>\s -------------- /opt/mysql_templates/mysql-8P/bin/mysql Ver 8.0.21-commercial for Linux on x86_64 (MySQL Enterprise Server - Commercial) Connection id: 11 Current database: Current user: root@localhost SSL: Not in use Current pager: stdout Using outfile: '' Using delimiter: ; Server version: 8.0.21-commercial MySQL Enterprise Server - Commercial Protocol version: 10 Connection: Localhost via UNIX socket Server characterset: utf8mb4 Db characterset: utf8mb4 Client characterset: utf8mb4 Conn. characterset: utf8mb4 UNIX socket: /opt/mysql_instances/master8/mysql.sock Binary data as: Hexadecimal Uptime: 8 sec Threads: 5 Questions: 40 Slow queries: 0 Opens: 178 Flush tables: 3 Open tables: 99 Queries per second avg: 5.000 (root@localhost) [(none)]>show global variables like 'innodb_redo_log_archive_dirs'; +------------------------------+-------+ | Variable_name | Value | +------------------------------+-------+ | innodb_redo_log_archive_dirs | | +------------------------------+-------+ 1 row in set (0.01 sec) (root@localhost) [(none)]>SET GLOBAL innodb_redo_log_archive_dirs='full:/vagrant/mysql_backup/archive/;'; Query OK, 0 rows affected (0.00 sec) (root@localhost) [(none)]>show global variables like 'innodb_redo_log_archive_dirs'; +------------------------------+--------------------------------------+ | Variable_name | Value | +------------------------------+--------------------------------------+ | innodb_redo_log_archive_dirs | full:/vagrant/mysql_backup/archive/; | +------------------------------+--------------------------------------+ 1 row in set (0.00 sec) Then running: mysqlbackup --show-progress=stdout --user=backup -pbackup --host=127.0.0.1 --process-threads=4 --port=3306 --backup-dir=/vagrant/mysql_backup/meb/1 backup Got the following : [root@master3 mysql_backup]# export da=`date`; time mysqlbackup --show-progress=stdout --user=backup -pbackup --host=127.0.0.1 --process-threads=4 --port=3306 --backup-dir=/vagrant/mysql_backup/meb/1 backup;echo $da; date; MySQL Enterprise Backup Ver 8.0.21-commercial for Linux on x86_64 (MySQL Enterprise - Commercial) Copyright (c) 2003, 2020, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Starting with following command line ... mysqlbackup --show-progress=stdout --user=backup -pxxxxxx --host=127.0.0.1 --process-threads=4 --port=3306 --backup-dir=/vagrant/mysql_backup/meb/1 backup IMPORTANT: Please check that mysqlbackup run completes successfully. At the end of a successful 'backup' run mysqlbackup prints "mysqlbackup completed OK!". 200922 08:18:03 MAIN INFO: No SSL options specified. 200922 08:18:03 MAIN INFO: MySQL server version is '8.0.21-commercial' 200922 08:18:03 MAIN INFO: MySQL server compile os version is 'Linux' 200922 08:18:03 MAIN INFO: SSL/TLS version used for connection is TLSv1.3 200922 08:18:03 MAIN INFO: Got some server configuration information from running server. 200922 08:18:03 MAIN INFO: Establishing connection to server for locking. 200922 08:18:03 MAIN INFO: No SSL options specified. 200922 08:18:03 MAIN INFO: Backup directory created: '/vagrant/mysql_backup/meb/1' 200922 08:18:03 MAIN INFO: MySQL server version_comment is 'MySQL Enterprise Server - Commercial' 200922 08:18:03 MAIN INFO: Mysqlbackup component not installed. 200922 08:18:03 MAIN INFO: MEB logfile created at /vagrant/mysql_backup/meb/1/meta/MEB_2020-09-22.08-18-03.log 200922 08:18:03 MAIN INFO: The MySQL server has no active keyring. -------------------------------------------------------------------- Server Repository Options: -------------------------------------------------------------------- datadir = /opt/mysql_instances/master8/data/ innodb_data_home_dir = /opt/mysql_instances/master8/data innodb_data_file_path = ibdata1:100M:autoextend innodb_log_group_home_dir = /opt/mysql_instances/master8/logs innodb_log_files_in_group = 3 innodb_log_file_size = 52428800 innodb_undo_directory = /opt/mysql_instances/master8/data/ innodb_undo_tablespaces = 2 innodb_buffer_pool_filename = ib_buffer_pool innodb_page_size = 16384 innodb_checksum_algorithm = crc32 -------------------------------------------------------------------- Backup Config Options: -------------------------------------------------------------------- datadir = /vagrant/mysql_backup/meb/1/datadir innodb_data_home_dir = /vagrant/mysql_backup/meb/1/datadir innodb_data_file_path = ibdata1:100M:autoextend innodb_log_group_home_dir = /vagrant/mysql_backup/meb/1/datadir innodb_log_files_in_group = 3 innodb_log_file_size = 52428800 innodb_undo_directory = /vagrant/mysql_backup/meb/1/datadir innodb_undo_tablespaces = 2 innodb_buffer_pool_filename = ib_buffer_pool innodb_page_size = 16384 innodb_checksum_algorithm = crc32 200922 08:18:04 MAIN INFO: Unique generated backup id for this is 16007770839078067 200922 08:18:04 MAIN INFO: Copying the server config file '/opt/mysql_instances/master8/data/auto.cnf' 200922 08:18:04 MAIN INFO: Testing, if we can reach zero temporary slave tables within the configured timeout of 300 seconds. 200922 08:18:04 MAIN INFO: Reached zero temporary slave tables. 200922 08:18:04 MAIN INFO: Creating 10 buffers each of size 16777216. 200922 08:18:04 MAIN WARNING: MySQL query 'DO innodb_redo_log_archive_start('full','16007770839078067');': 3846, Redo log archive directory '/vagrant/mysql_backup/archive/16007770839078067' is accessible to all OS users 200922 08:18:04 MAIN INFO: Failed to start redo log archiving... 200922 08:18:04 MAIN INFO: Found checkpoint at lsn 155515819333. 200922 08:18:04 MAIN INFO: Starting log scan from lsn = 155515819008 at offset = 18066432 and checkpoint = 155515819333 in file /opt/mysql_instances/master8/logs/ib_logfile2. 200922 08:18:04 MAIN INFO: Full Backup operation starts with following threads 1 read-threads 4 process-threads 1 write-threads 200922 08:18:04 MAIN INFO: Starting to copy all innodb files... 200922 08:18:04 MAIN INFO: No SSL options specified. Progress: 0 of 228 MB; state: Copying system tablespace ... So backup failed to use Redolog given: "Redo log archive directory '/vagrant/mysql_backup/archive/16007770839078067' is accessible to all OS users" Which is not true: [root@master3 mysql_backup]# pwd /vagrant/mysql_backup [root@master3 mysql_backup]# ll . total 16 drwx------. 1 mysql mysql 4096 Sep 22 08:35 archive drwxrwxr-x. 1 mysql mysql 4096 Sep 22 08:35 meb drwxrwxr-x. 1 mysql mysql 4096 Sep 22 04:56 original drwxrwxr-x. 1 mysql mysql 4096 Sep 22 04:56 xb [root@master3 mysql_backup]# ll -R archive archive: total 12 drwx------. 1 mysql mysql 4096 Sep 22 05:03 compressed drwx------. 1 mysql mysql 4096 Sep 22 08:33 full drwx------. 1 mysql mysql 4096 Sep 22 05:03 incremental archive/compressed: total 0 archive/full: total 0 archive/incremental: total 0 Instead to me it seems that the problem is due the fact MEB is trying to use the directory "/vagrant/mysql_backup/archive/16007770839078067" without create it. If I try to run the DO command: (root@localhost) [(none)]>DO innodb_redo_log_archive_start('full','16007770839078067'); ERROR 3844 (HY000): Redo log archive directory '/vagrant/mysql_backup/archive/16007770839078067' does not exist or is not a directory (root@localhost) [(none)]> As expected it will fails given directory doesn't exists. If I create it: [root@master3 archive]# mkdir /vagrant/mysql_backup/archive/16007770839078067 [root@master3 archive]# ll drwx------. 1 mysql mysql 4096 Sep 22 08:40 16007770839078067 drwx------. 1 mysql mysql 4096 Sep 22 05:03 compressed drwx------. 1 mysql mysql 4096 Sep 22 08:33 full drwx------. 1 mysql mysql 4096 Sep 22 05:03 incremental it will start as expected: (root@localhost) [(none)]>DO innodb_redo_log_archive_start('full','16007770839078067'); Query OK, 0 rows affected (0.08 sec) (root@localhost) [(none)]>SELECT innodb_redo_log_archive_stop(); +--------------------------------+ | innodb_redo_log_archive_stop() | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (0.01 sec) If I try to bypass it and have that done manually, starting the external Archiving like with: (root@localhost) [(none)]>DO innodb_redo_log_archive_start('full','full'); Query OK, 0 rows affected (0.05 sec) MEB generate an WARNING given is not accepting the already running process: 200922 08:44:33 MAIN WARNING: MySQL query 'DO innodb_redo_log_archive_start('full','16007786726180681');': 3848, Redo log archiving has been started on '/vagrant/mysql_backup/archive/full/archive.42911622-fc08-11ea-8b18-08002734ed50.000001.log' - Call innodb_redo_log_archive_stop() first 200922 08:44:33 MAIN INFO: Failed to start redo log archiving... Suggested fix: Given the above I see: 1) Error message is misleading and inaccurate error is not permission but the directory that is not existing, provide the correct error 2) MEB is not correctly creating the target, Create the target 3) MEB doesn't allow user to decide the target, if already in place use the running target, given you know which is.