MHA故障failover执行不成功的背后的大坑

richard.xia_志培

发布于 2022-06-14 14:23:05

5210

发布于 2022-06-14 14:23:05

文章被收录于专栏：PT运维技术PT运维技术

背景&&现象:

线上环境OS为centos7.6 x64, DBA 在机房演练MHA故障切换，但每次切换脚本执行失败。

[root@sgaws1a-ops-db-mhamgr ~]# ps axuw|grep mha
root 28104 0.4 1.1 193520 21684 pts/5 S 02:37 0:00 perl /usr/local/bin/masterha_manager --conf=/data/soft/mha/conf/abc/mha_abc.cnf
root 28268 0.0 0.0 9556 1160 pts/5 S 02:37 0:00 sh -c /data/soft/mha/scripts/abc/master_ip_failover --command=start --ssh_user=root --orig_master_host=10.30.82.175 --orig_master_ip=10.30.82.175 --orig_master_port=3306 --new_master_host=10.30.78.108 --new_master_ip=10.30.78.108 --new_master_port=3306 --new_master_user='dba' --new_master_password='75qkheLG' >> /data/soft/mha/log/abc/manager.log 2>&1
root 28269 0.0 0.2 27444 3696 pts/5 S 02:37 0:00 perl /data/soft/mha/scripts/abc/master_ip_failover --command=start --ssh_user=root --orig_master_host=10.130.82.175 --orig_master_ip=10.130.82.175 --orig_master_port=3306 --new_master_host=10.130.78.108 --new_master_ip=10.130.78.108 --new_master_port=3306 --new_master_user=dba --new_master_password=t54er43rf334
root 28274 0.0 0.0 9556 1356 pts/5 S 02:37 0:00 /bin/bash /data/soft/mha/scripts/abc/aws_change_vip.sh eni-05cd71f269c6e9a88 eth1 10.130.82.175 10.130.78.108 10.130.64.1
root 28341 0.0 0.0 9556 576 pts/5 S 02:37 0:00 /bin/bash /data/soft/mha/scripts/abc/aws_change_vip.sh eni-05cd71f269c6e9a88 eth1 10.130.82.175 10.130.78.108 10.130.64.1
root 28346 0.0 0.0 9088 672 pts/0 R+ 02:37 0:00 grep --color=auto mha
[root@sgaws1a-ops-db-mhamgr ~]# ps axuw|grep mha
root 28104 0.4 1.1 193520 21684 pts/5 T 02:37 0:00 perl /usr/local/bin/masterha_manager --conf=/data/soft/mha/conf/abc/mha_abc.cnf
root 28268 0.0 0.0 9556 1160 pts/5 T 02:37 0:00 sh -c /data/soft/mha/scripts/abc/master_ip_failover --command=start --ssh_user=root --orig_master_host=10.130.82.175 --orig_master_ip=10.130.82.175 --orig_master_port=3306 --new_master_host=10.130.78.108 --new_master_ip=10.130.78.108 --new_master_port=3306 --new_master_user='dba' --new_master_password='t54er43rf334' >> /data/soft/mha/log/abc/manager.log 2>&1
root 28269 0.0 0.2 27444 3696 pts/5 T 02:37 0:00 perl /data/soft/mha/scripts/abc/master_ip_failover --command=start --ssh_user=root --orig_master_host=10.130.82.175 --orig_master_ip=10.130.82.175 --orig_master_port=3306 --new_master_host=10.130.78.108 --new_master_ip=10.130.78.108 --new_master_port=3306 --new_master_user=dba --new_master_password=mha3333
root 28274 0.0 0.0 9556 1368 pts/5 T 02:37 0:00 /bin/bash /data/soft/mha/scripts/abc/aws_change_vip.sh eni-05cd71f269c6e9a88 eth1 10.130.82.175 10.130.78.108 10.130.64.1
root 28364 0.0 0.0 9088 672 pts/0 S+ 02:37 0:00 grep --color=auto mha

问题分析:

DBA反映问题出现在执行aws_change_vip.sh脚本上，长时间挂起。以上通过ps 抓取出来的进程列表显示，进程很长的时间内，都没有变化（一直挂起）。细心的同学已经观察到，前后2次的抓取的进程列表的最大的差别是: 所有的进程从S状态变成了T状态。由于进程的T状态可能有多种原因造成，例如收到SIGSTOP, SIGTSTP, SIGTTIN, SIGTTOU 等信号(后面2种跟终端有关系), 所以不确定是什么原因导致。

跟DBA详细了解后，发现MHA的监视进程是通过后台启动的：

/usr/local/bin/masterha_manager --conf=/data/soft/mha/conf/abc/mha_abc.cnf &

于是着手重现调试，重现后，查看T状态的进程到底是收到什么信号。

查看进程的状态

cat /proc/28274/status 
Name: bash
Umask: 0022
State: T (stopped)
Tgid: 28274
Ngid: 0
Pid: 28274
PPid: 28269

首先可以排除strace/ptrace导致的SIGTSTP, 因为strace状态进程status状态字段:State: t (tracing stop)。印象中SIGSTOP信号只能通过显式kill -SIGSTOP这样的方式产生（但也不能排除）或者通过键盘ctrl +Z发送给后台进程。接下来可以大胆尝试strace跟踪整个masterha_manager进程了。模拟DBA的方式启动MHA监视进程 :

strace -ff -tt -s 4096 masterha_manager --conf=/data/soft/mha/conf/abc/mha_abc.cnf >/tmp/trace.log 2>&1 &

关闭主库，触发failover, 果然又一次复现故障。进程全部进入T状态，然后挂起。

拿到trace.log ,内容如下:

[pid 30919] 07:31:21.357638 access("/bin/ssh", R_OK) = 0
[pid 30919] 07:31:21.357688 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [], 8) = 0
[pid 30919] 07:31:21.357734 rt_sigprocmask(SIG_BLOCK, [CHLD], [INT CHLD], 8) = 0
[pid 30919] 07:31:21.357779 rt_sigprocmask(SIG_SETMASK, [INT CHLD], NULL, 8) = 0
[pid 30919] 07:31:21.357823 clone(strace: Process 31049 attached
[pid 30919] 07:31:21.357950 rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 30919] 07:31:21.357982 <... rt_sigprocmask resumed> NULL, 8) = 0
[pid 30919] 07:31:21.358036 rt_sigprocmask(SIG_BLOCK, [CHLD],  <unfinished ...>
[pid 30919] 07:31:21.358070 <... rt_sigprocmask resumed> [], 8) = 0
[pid 30919] 07:31:21.358099 rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 30919] 07:31:21.358137 <... rt_sigprocmask resumed> NULL, 8) = 0
[pid 30919] 07:31:21.358182 rt_sigprocmask(SIG_BLOCK, [CHLD],  <unfinished ...>
[pid 30919] 07:31:21.358216 <... rt_sigprocmask resumed> [], 8) = 0
[pid 30919] 07:31:21.358246 rt_sigaction(SIGINT, {0x43e750, [], SA_RESTORER, 0x7f6f3b66e280},  <unfinished ...>
[pid 30919] 07:31:21.358280 <... rt_sigaction resumed> {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, 8) = 0
[pid 30919] 07:31:21.358311 wait4(-1,  <unfinished ...>
[pid 30919] 07:31:21.458888 <... wait4 resumed> 0x7ffdbac6cff0, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 30919] 07:31:21.458957 --- SIGTTOU {si_signo=SIGTTOU, si_code=SI_KERNEL} ---
[pid 31049] 07:31:21.458792 ioctl(0, TCGETS, {B38400 opost isig -icanon -echo ...}) = 
[pid 31049] 07:31:21.458833 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 -opost -isig -icanon -echo ...}) = ? ERESTARTSYS (To be restarted if SA_
RESTART is set)
[pid 30919] 07:31:21.458888 <... wait4 resumed> 0x7ffdbac6cff0, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 30914] 07:31:21.458901 <... wait4 resumed> 0x7fff2fc428b8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 30913] 07:31:21.458913 <... wait4 resumed> 0x7ffda8f43360, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 30769] 07:31:21.458925 <... wait4 resumed> 0x7ffccdc73848, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid 31049] 07:31:21.458946 --- SIGTTOU {si_signo=SIGTTOU, si_code=SI_KERNEL} ---
[pid 30919] 07:31:21.458957 --- SIGTTOU {si_signo=SIGTTOU, si_code=SI_KERNEL} ---
[pid 30914] 07:31:21.458968 --- SIGTTOU {si_signo=SIGTTOU, si_code=SI_KERNEL} ---
[pid 30913] 07:31:21.458980 --- SIGTTOU {si_signo=SIGTTOU, si_code=SI_KERNEL} ---
[pid 30769] 07:31:21.458992 --- SIGTTOU {si_signo=SIGTTOU, si_code=SI_KERNEL} ---
[pid 31049] 07:31:21.459012 --- stopped by SIGTTOU ---
[pid 30919] 07:31:21.459018 --- stopped by SIGTTOU ---
[pid 30914] 07:31:21.459023 --- stopped by SIGTTOU ---
[pid 30913] 07:31:21.459028 --- stopped by SIGTTOU ---
[pid 30769] 07:31:21.459032 --- stopped by SIGTTOU ---

[pid 30919] 07:31:08.129167 open("/dev/tty", O_RDWR|O_NONBLOCK) = 7
[pid 30919] 07:31:08.129223 close(7) = 0
[pid 30919] 07:31:08.129286 brk(NULL) = 0x210b000
[pid 30919] 07:31:08.129358 brk(NULL) = 0x210b000
[pid 30919] 07:31:08.129400 brk(0x212c000) = 0x212c000
[pid 30919] 07:31:08.129443 brk(NULL) = 0x212c000
[pid 30919] 07:31:08.129497 getuid() = 0
[pid 30919] 07:31:08.129540 getgid() = 0
[pid 30919] 07:31:08.129583 geteuid() = 0
[pid 30919] 07:31:08.129625 getegid() = 0
[pid 30919] 07:31:08.129674 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
[pid 30919] 07:31:08.129740 open("/proc/meminfo", O_RDONLY|O_CLOEXEC) = 7
[pid 30919] 07:31:08.129797 fstat(7, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
[pid 30919] 07:31:08.129844 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6f3c052000
[pid 30919] 07:31:08.129890 read(7, "MemTotal: 1843276 kB\nMemFree: 794444 kB\nMemAvailable: 1310836 kB\nBuffers: 133
904 kB\nCached: 562552 kB\nSwapCached: 0 kB\nActive: 661740 kB\nInactive: 160636 kB\nActive(anon): 173
180 kB\nInactive(anon): 60060 kB\nActive(file): 488560 kB\nInactive(file): 100576 kB\nUnevictable: 0 kB\nMlocked:
0 kB\nSwapTotal: 0 kB\nSwapFree: 0 kB\nDirty: 17092 kB\nWriteback: 0 kB\nAnonPages: 126
064 kB\nMapped: 26716 kB\nShmem: 107188 kB\nSlab: 159600 kB\nSReclaimable: 114580 kB\nSUnreclaim: 45
020 kB\nKernelStack: 2368 kB\nPageTables: 9496 kB\nNFS_Unstable: 0 kB\nBounce: 0 kB\nWritebackTmp:
0 kB\nCommitLimit: 921636 kB\nCommitted_AS: 491796 kB\nVmallocTotal: 34359738367 kB\nVmallocUsed: 7988 kB\nVmallocChunk: 34
359727312 kB\nHardwareCorrupted: 0 kB\nAnonHugePages: 16384 kB\nCmaTotal: ", 1024) = 1024
[pid 30919] 07:31:08.129964 close(7) = 0
[pid 30919] 07:31:08.130009 munmap(0x7f6f3c052000, 4096) = 0
[pid 30919] 07:31:08.130083 rt_sigaction(SIGCHLD, {SIG_DFL, [], SA_RESTORER|SA_RESTART, 0x7f6f3b66e280}, {SIG_DFL, [], 0}, 8) = 0
[pid 30919] 07:31:08.130131 rt_sigaction(SIGCHLD, {SIG_DFL, [], SA_RESTORER|SA_RESTART, 0x7f6f3b66e280}, {SIG_DFL, [], SA_RESTORER|SA_RESTART, 0x
7f6f3b66e280}, 8) = 0
[pid 30919] 07:31:08.130188 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, {SIG_DFL, [], 0}, 8) = 0
[pid 30919] 07:31:08.130234 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, 8) = 0
[pid 30919] 07:31:08.130279 rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, {SIG_DFL, [], 0}, 8) = 0 
[pid 30919] 07:31:08.130325 rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, 8) = 0
[pid 30919] 07:31:08.130372 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0 
[pid 30919] 07:31:08.130417 rt_sigaction(SIGQUIT, {SIG_IGN, [], SA_RESTORER, 0x7f6f3b66e280}, {SIG_DFL, [], SA_RESTORER, 0x7f6f3b66e280}, 8) = 0
[pid 30919] 07:31:08.130466 uname({sysname="Linux", nodename="sgaws1a-ops-db-mhamgr", ...}) = 0 
[pid 30919] 07:31:08.130533 stat("/data/soft/mha/log", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 
[pid 30919] 07:31:08.130583 stat(".", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

这次抓到是进程收到:SIGTTOU而挂起。

到此问题的原因基本清楚了:

MHA监视进程是以后台进程启动的，failvoer脚本也应该是MHA监视进程的子进程, 也属于后台进程，后台进程存在写终端(STDOUT)的操作，触发SIGTTOUT 导致进入到T状态。

结合进程列表中的pid, trace日志文件中最早出现SIGTTOU的日志，找到触发的进程是ssh, 根据pid找到进程执行的脚本文件aws_change_vip.sh, 检查aws_change_vip.sh的代码中存在着一段代码 ‘ssh -t @xxx.xxx’ ，查看man文档， -t参数是强制使用终端。

查看了下默认的终端设置参数:

[root@localhost ~]# stty --all|grep  tostop
isig icanon iexten echo echoe echok -echonl -noflsh -xcase -tostop -echoprt

如果配置为“tostop”的话，将不输出到终端,“-tostop”表示会输出到终端，默认值是-tostop。

SSH -t参数要求ssh使用终端，终端默认是-tostop, ssh上的输出全部写到终端，而当前的进程属于后台进程组，故会收到SIGTTOUT信号。

按照常理讲，父子进程独立，子进程进入T状态，父进程，父父进程怎么也会进入到T状态呢？

这个要跟masterha_manager进程调用脚本的流程说起：

由于MHA是Perl编写的，加上有点基础，所以很快就找到相关的MHA进程创建相关的关键调用关系:

masterha_manager 脚本 --调用--->MHA::ManagerUtil::exec_system — > MHA::NodeUtil::system_rc — > master_ip_faillover_script

MasterFailover.pm
my ( $high, $low ) = MHA::ManagerUtil::exec_system( $command, $g_logfile );
if ( $high == 0 && $low == 0 ) {
$log->info(" OK.");
$mail_body .=
$new_master->get_hostinfo() . ": OK: Activated master IP address.\n";
}


ManagerUtil.pm

sub exec_system {
my $cmd = shift;
my $log_output = shift;
if ($log_output) {
return MHA::NodeUtil::system_rc( system("$cmd >> $log_output 2>&1") );
}
else {
return MHA::NodeUtil::system_rc( system($cmd) );
}
}


NodeUtil.pm

sub system_rc($) {
my $rc = shift;
my $high = $rc >> 8;
my $low = $rc & 255;
return ( $high, $low );
}

从代码上看，masterha_manager进程调用第三方scripts的时候，使用的是system() 来调用（本身还是以beforeground的方式fork进程+sh 第三方脚本方式），所以所有的进程全部继承终端，终端的SIGTTOU信号全发送给关联进程，所以造成以上的现象。

以下是用shell脚本重现的例子:

[root@10_174_129_85_nginx ~]# cat g.sh 
#!/bin/bash
./parent.sh

[root@10_174_129_85_nginx ~]# cat parent.sh 
#!/bin/bash
./child.sh
[root@10_174_129_85_nginx ~]# cat child.sh 
#!/bin/bash
i=1
while [ $i -lt 10 ]
do
        cat -
        sleep 1
        ((i++))
done

[root@10_174_129_85_nginx ~]# ./g.sh &
[1] 4481
[root@10_174_129_85_nginx ~]# 

[1]+  Stopped                 ./g.sh
[root@10_174_129_85_nginx ~]#

解决办法: