[MDEV-9520] xtrabackup-v2 to support systemd node provisioning Created: 2016-02-04  Updated: 2018-12-07  Resolved: 2016-03-30

Status: Closed
Project: MariaDB Server
Component/s: Galera SST
Affects Version/s: 10.1.11
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: VAROQUI Stephane Assignee: Nirbhay Choubey (Inactive)
Resolution: Won't Fix Votes: 0
Labels: need_feedback
Environment:

Centos 7


Issue Links:
Problem/Incident
is caused by MDEV-9202 Systemd timeout is not sufficient for... Closed
Relates
relates to MDEV-17571 Make systemd timeout behavior more co... Closed
relates to MDEV-17934 Make systemd timeout behavior more co... Closed

 Description   

After SST, the receiver node is shutdown but never restarted

Is there a workaround and where exactly is that shutdown done a quick inspection of xtrabackup SST script does not look to trigger shutdown ?

ON DONOR (innobackup.backup.log) :

160204 11:53:07 innobackupex: Starting the backup operation
 
IMPORTANT: Please check that the backup run completes successfully.
           At the end of a successful backup run innobackupex
           prints "completed OK!".
 
160204 11:53:07 Connecting to MySQL server host: localhost, user: galerabkp, password: not set, port: 0, socket: /var/lib/mysql/mysql.sock
Using server version 10.1.11-MariaDB-log
innobackupex version 2.3.3 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 525ca7d)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /home/mysql
xtrabackup: open files limit requested 0, set to 16364
xtrabackup: using the following InnoDB configuration:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 8
xtrabackup:   innodb_log_file_size = 536870912
xtrabackup: using O_DIRECT
160204 11:53:07 >> log scanned up to (83463863966)
xtrabackup: Generating a list of tablespaces
160204 11:53:07 [01] Streaming ./ibdata1
160204 11:53:08 [01]        ...done
160204 11:53:08 >> log scanned up to (83463879153)
160204 11:53:08 [01] Streaming ./mysql/innodb_table_stats.ibd
160204 11:53:08 [01]        ...done
160204 11:53:08 [01] Streaming ./mysql/innodb_index_stats.ibd
160204 11:53:08 [01]        ...done
160204 11:53:08 [01] Streaming ./mysql/gtid_slave_pos.ibd
160204 11:53:08 [01]        ...done
160204 11:53:08 [01] Streaming ./db_calameo_v2/tbl_amazon_upload_queues.ibd
160204 11:53:08 [01]        ...done
160204 11:53:08 [01] Streaming ./db_calameo_v2/tbl_annotations.ibd
 
160204 12:04:07 [01]        ...done
160204 12:04:07 [01] Streaming ./db_calameo_v2/tbl_book_downloads.frm to <STDOUT>
160204 12:04:07 [01]        ...done
160204 12:04:07 Finished backing up non-InnoDB tables and files
160204 12:04:07 [00] Streaming xtrabackup_galera_info
160204 12:04:07 [00]        ...done
xtrabackup: The latest check point (for incremental): '83470194891'
xtrabackup: Stopping log copying thread.
.160204 12:04:07 >> log scanned up to (83470387726)
 
160204 12:04:07 Executing UNLOCK TABLES
160204 12:04:07 All tables unlocked
160204 12:04:07 [00] Streaming ib_buffer_pool to <STDOUT>
160204 12:04:07 [00]        ...done
160204 12:04:07 Backup created in directory '/tmp/tmp.CrTCxlgvHm'
160204 12:04:07 [00] Streaming backup-my.cnf
160204 12:04:07 [00]        ...done
160204 12:04:07 [00] Streaming xtrabackup_info
160204 12:04:07 [00]        ...done
xtrabackup: Transaction log of lsn (83455063062) to (83470387726) was copied.
160204 12:04:07 completed OK!
 
ON JOINER (innobackup.prepare.log) :
160204 12:04:07 innobackupex: Starting the apply-log operation
 
IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".
 
innobackupex version 2.3.3 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 525ca7d)
xtrabackup: cd to /home/mysql//.sst
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=17252352, start_lsn=(83455063062)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 1
xtrabackup:   innodb_log_file_size = 17252352
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 1
xtrabackup:   innodb_log_file_size = 17252352
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.7
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 83455063062
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 83460305920 (34%)
InnoDB: Doing recovery: scanned up to log sequence number 83465548800 (68%)
InnoDB: Doing recovery: scanned up to log sequence number 83470387726 (99%)
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 83470387726
 
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 83470390901
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 8
xtrabackup:   innodb_log_file_size = 536870912
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.7
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Setting log file ./ib_logfile101 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile1 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile2 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile3 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile4 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile5 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile6 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile7 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=83470390901
InnoDB: Highest supported file format is Barracuda.
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 83470391308
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 83470395168
160204 12:04:24 completed OK!

MARIADB.SERVICE

#
# /etc/systemd/system/mariadb.service
#
# This file is free software; you can redistribute it and/or modify it
# under the terms of the GNU Lesser General Public License as published by
# the Free Software Foundation; either version 2.1 of the License, or
# (at your option) any later version.
#
# Thanks to:
# Daniel Black
# Erkan Yanar
# David Strauss
# and probably others
 
[Unit]
Description=MariaDB database server
After=network.target
After=syslog.target
 
[Install]
WantedBy=multi-user.target
Alias=mysql.service
Alias=mysqld.service
 
 
[Service]
 
##############################################################################
## Core requirements
##
 
Type=notify
 
# Setting this to true can break replication and the Type=notify settings
# See also bind-address mysqld option.
PrivateNetwork=false
 
##############################################################################
## Package maintainers
##
 
User=mysql
Group=mysql
 
# To allow memlock to be used as non-root user if set in configuration
CapabilityBoundingSet=CAP_IPC_LOCK
 
# Execute pre and post scripts as root, otherwise it does it as User=
PermissionsStartOnly=true
 
# Needed to create system tables etc.
# ExecStartPre=/usr/bin/mysql_install_db -u mysql
 
# Start main service
# MYSQLD_OPTS here is for users to set in /etc/systemd/system/mariadb.service.d/MY_SPECIAL.conf
# Use the [service] section and Environment="MYSQLD_OPTS=...".
# This isn't a replacement for my.cnf.
# _WSREP_NEW_CLUSTER is for the exclusive use of the script galera_new_cluster
 
ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER
 
 
KillMode=process
KillSignal=SIGTERM
 
# Don't want to see an automated SIGKILL ever
SendSIGKILL=no
 
# Restart crashed server only, on-failure would also restart, for example, when
# my.cnf contains unknown option
Restart=on-abort
RestartSec=5s
 
UMask=007
 
##############################################################################
## USERs can override
##
##
## by creating a file in /etc/systemd/system/mariadb.service.d/MY_SPECIAL.conf
## and adding/setting the following will override this file's settings.
 
# Useful options not previously available in [mysqld_safe]
 
# Kernels like killing mysqld when out of memory because its big.
# Lets temper that preference a little.
# OOMScoreAdjust=-600
 
# Explicitly start with high IO priority
# BlockIOWeight=1000
 
# If you don't use the /tmp directory for SELECT ... OUTFILE and
# LOAD DATA INFILE you can enable PrivateTmp=true for a little more security.
PrivateTmp=false
 
##
## Options previously available to be set via [mysqld_safe]
## that now needs to be set by systemd config files as mysqld_safe
## isn't executed.
##
 
# Number of files limit. previously [mysqld_safe] open-file-limit
LimitNOFILE=16364
 
# Maximium core size. previously [mysqld_safe] core-file-size
# LimitCore=
 
# Nice priority. previously [mysqld_safe] nice
# Nice=-5
 
# Timezone. previously [mysqld_safe] timezone
# Environment="TZ=UTC"
 
# Library substitutions. previously [mysqld_safe] malloc-lib with explict paths
# (in LD_LIBRARY_PATH) and library name (in LD_PRELOAD).
# Environment="LD_LIBRARY_PATH=/path1 /path2" "LD_PRELOAD=
 
# Flush caches. previously [mysqld_safe] flush-caches=1
# ExecStartPre=sync
# ExecStartPre=sysctl -q -w vm.drop_caches=3
 
# numa-interleave=1 equalivant
# Change ExecStart=numactl --interleave=all /usr/sbin/mysqld......
 
# crash-script equalivent
# FailureAction=



 Comments   
Comment by VAROQUI Stephane [ 2016-02-04 ]

https://github.com/deviantony/xtrabackup-scripts/issues/32

Comment by Nirbhay Choubey (Inactive) [ 2016-02-26 ]

stephane@skysql.com

After SST, the receiver node is shutdown but never restarted

Why did the node terminate? Was it due to some SST related error (abort)? This should be visible in the nodes error log.

Is there a workaround and where exactly is that shutdown done a quick inspection of xtrabackup SST script does not look to trigger shutdown ?

Workaround to what? The reason for shutdown should be visible in error log.
Do you still have the error logs? The attached innobackup logs do not show any error.
How exactly do you see this problem relates to systemd?

Comment by VAROQUI Stephane [ 2016-02-27 ]

I request it via Email, thanks for taking care.

Comment by Nirbhay Choubey (Inactive) [ 2016-03-10 ]

Its due to systemd timeout. You can either set TimeoutStartSec to some higher value or disable it (see MDEV-9202).

Feb  3 21:22:03 mysqld: WSREP_SST: [INFO] Waiting for SST streaming to complete! (20160203 21:22:03.757)
Feb  3 21:22:05 mysqld: 2016-02-03 21:22:05 140235480495872 [Note] WSREP: (c8c917d8, 'tcp://0.0.0.0:4567') turning message relay requesting off
Feb  3 21:23:32 systemd: mariadb.service start operation timed out. Terminating.
Feb  3 21:25:02 systemd: mariadb.service stop-final-sigterm timed out. Skipping SIGKILL. Entering failed mode.
Feb  3 21:25:02 systemd: Failed to start MariaDB database server.
Feb  3 21:25:02 systemd: Unit mariadb.service entered failed state.
Feb  3 21:25:02 systemd: mariadb.service failed.
Feb  3 21:27:30 systemd-logind: Removed session 5.
Feb  3 21:27:30 systemd: Removed slice user-0.slice.
Feb  3 21:27:30 systemd: Stopping user-0.slice.

Generated at Thu Feb 08 07:35:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.