runsisi's

technical notes

ceph-mds/ceph-mgr shutdown abort

2019-01-16 runsisi#debug#ceph

故障现象

ceph-mds 日志如下:

2018-11-27 13:56:19.900056 7fd4066581c0 -1 auth: unable to find a keyring on /var/lib/ceph/mds/ceph-xxx/keyring: (2) No such file or directory
2018-11-27 13:56:19.900107 7fd4066581c0 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
2018-11-27 13:56:19.900123 7fd4066581c0 -1 mds.192.168.9.6 ERROR: failed to get monmap: (2) No such file or directory
2018-11-27 13:56:19.900135 7fd4066581c0 1 mds.192.168.9.6 suicide! Wanted state up:boot
2018-11-27 13:56:20.005382 7fd4066581c0 -1 *** Caught signal (Aborted) **
in thread 7fd4066581c0 thread_name:ceph-mds
ceph version 12.2.9-1-115-g65a1791 (65a179185d09c37c443f050741d58c3fae15d73c) luminous (stable)
1: (()+0x60f981) [0x7fd406c82981]
2: (()+0xf370) [0x7fd404749370]
3: (gsignal()+0x37) [0x7fd4039791d7]
4: (abort()+0x148) [0x7fd40397a8c8]
5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7fd40427d9d5]
6: (()+0x5e946) [0x7fd40427b946]
7: (()+0x5e973) [0x7fd40427b973]
8: (()+0x5eb9f) [0x7fd40427bb9f]
9: (std::__throw_system_error(int)+0x90) [0x7fd4042d09b0]
10: (std::thread::join()+0x18) [0x7fd4042d1b58]
11: (Beacon::shutdown()+0xa8) [0x7fd406977178]
12: (MDSDaemon::suicide()+0x241) [0x7fd40692f301]
13: (MDSDaemon::init()+0x17be) [0x7fd406933c0e]
14: (main()+0xb90) [0x7fd40691cb90]
15: (__libc_start_main()+0xf5) [0x7fd403965b35]
16: (()+0x2b6503) [0x7fd406929503]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

ceph-mgr 日志如下:

2018-11-30 11:06:22.935031 7fe9675f2780  0 ceph version 12.2.9-1-115-g65a1791 (65a179185d09c37c443f050741d58c3fae15d73c) luminous (stable), process ceph-mgr, pid 17831
2018-11-30 11:06:22.935237 7fe9675f2780  0 pidfile_write: ignore empty --pid-file
2018-11-30 11:06:22.939610 7fe9675f2780 -1 failed for service _ceph-mon._tcp
2018-11-30 11:06:22.946862 7fe95dd63700 -1 *** Caught signal (Aborted) **
 in thread 7fe95dd63700 thread_name:fn_anonymous

 ceph version 12.2.9-1-115-g65a1791 (65a179185d09c37c443f050741d58c3fae15d73c) luminous (stable)
 1: (()+0x42b1b1) [0x7fe967a3a1b1]
 2: (()+0xf370) [0x7fe96531f370]
 3: (gsignal()+0x37) [0x7fe96454f1d7]
 4: (abort()+0x148) [0x7fe9645508c8]
 5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7fe964e539d5]
 6: (()+0x5e946) [0x7fe964e51946]
 7: (()+0x5e973) [0x7fe964e51973]
 8: (()+0x5f4df) [0x7fe964e524df]
 9: (()+0x7dc5) [0x7fe965317dc5]
 10: (clone()+0x6d) [0x7fe96461176d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

故障分析

ceph-mds

根据 [1] 我们能完全得出 ceph-mds 挂掉的原因是主线程结束的太快,而 Beacon::sender 线程还没来得及初始化完成,可以用如下的方法 100% 复现(a 是一个不存在的 mds id,有合法的 /etc/ceph/ceph.conf 存在,但不要求 mon_hosts 可以连上,即并不要求有可以真正运行的集群):

~# ceph-mds -i a --setuser ceph --setgroup ceph -d

在终端中能看到如下的错误:

2018-12-01 17:42:54.872188 7f33d3017240 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
2018-12-01 17:42:54.872199 7f33d3017240 -1 mds.a ERROR: failed to get monmap: (2) No such file or directory
2018-12-01 17:42:54.872206 7f33d3017240  1 mds.a suicide! Wanted state up:boot
terminate called after throwing an instance of 'std::system_error'
  what():  Invalid argument
*** Caught signal (Aborted) **
 in thread 7f33d3017240 thread_name:ceph-mds
 ceph version 12.2.9-2-5-g00b0f3b (00b0f3bcff6f18a96dab66ad0bae1f845d761202) luminous (stable)

这和前面的日志稍有区别,因为附件中没有这个 C++ 异常,实际原因是因为日志并没有记录终端的输出,如果通过如下的方式复现:

~# ceph-mds -i a --setuser ceph --setgroup ceph -f

会从日志文件得到完全一致的输出:

2018-12-01 16:04:32.191438 7f2e990fc240 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
2018-12-01 16:04:32.191449 7f2e990fc240 -1 mds.a ERROR: failed to get monmap: (2) No such file or directory
2018-12-01 16:04:32.191457 7f2e990fc240  1 mds.a suicide! Wanted state up:boot
2018-12-01 16:04:32.194301 7f2e990fc240 -1 *** Caught signal (Aborted) **
 in thread 7f2e990fc240 thread_name:ceph-mds

 ceph version 12.2.9-2-5-g00b0f3b (00b0f3bcff6f18a96dab66ad0bae1f845d761202) luminous (stable)

[1] C++11 std::thread join crashes with system_error exception and SIGABRT

https://stackoverflow.com/questions/30970123/c11-stdthread-join-crashes-with-system-error-exception-and-sigabrt-on-xcode

ceph-mgr

mgr abort 的原因应该也与 ceph-mds 类似,mgr 的复现操作与 mds 的复现操作一致,但并不是 100% 复现:

~# ceph-mgr -i a --setuser ceph --setgroup ceph -f

终端输出:

2018-12-01 17:47:05.913340 7f07373fe780 -1 auth: unable to find a keyring on /var/lib/ceph/mgr/ceph-a/keyring: (2) No such file or directory
2018-12-01 17:47:05.913353 7f07373fe780 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
Error in initialization: (2) No such file or directory
pure virtual method called
terminate called without an active exception
*** Caught signal (Aborted) **
 in thread 7f072db6f700 thread_name:fn_anonymous
 ceph version 12.2.9-2-7-g22d1443 (22d1443024fb56b8e521d3b669f85ac7437fb11c) luminous (stable)
~# ceph-mgr -i a --setuser ceph --setgroup ceph -d

日志:

   -22> 2018-12-01 17:47:05.910290 7f07373fe780  5 asok(0x7f0741bf61c0) init /var/run/ceph/ceph-mgr.a.asok
   -21> 2018-12-01 17:47:05.910311 7f07373fe780  5 asok(0x7f0741bf61c0) bind_and_listen /var/run/ceph/ceph-mgr.a.asok
   -20> 2018-12-01 17:47:05.910545 7f07373fe780  5 asok(0x7f0741bf61c0) register_command 0 hook 0x7f0741bb60c8
   -19> 2018-12-01 17:47:05.910555 7f07373fe780  5 asok(0x7f0741bf61c0) register_command version hook 0x7f0741bb60c8
   -18> 2018-12-01 17:47:05.910558 7f07373fe780  5 asok(0x7f0741bf61c0) register_command git_version hook 0x7f0741bb60c8
   -17> 2018-12-01 17:47:05.910562 7f07373fe780  5 asok(0x7f0741bf61c0) register_command help hook 0x7f0741bb8140
   -16> 2018-12-01 17:47:05.910566 7f07373fe780  5 asok(0x7f0741bf61c0) register_command get_command_descriptions hook 0x7f0741bb8150
   -15> 2018-12-01 17:47:05.911451 7f0731376700  2 Event(0x7f0741bed880 nevent=5000 time_id=1).set_owner idx=1 owner=139668867213056
   -14> 2018-12-01 17:47:05.912869 7f0731b77700  2 Event(0x7f0741bed480 nevent=5000 time_id=1).set_owner idx=0 owner=139668875605760
   -13> 2018-12-01 17:47:05.912897 7f0730b75700  2 Event(0x7f0741bedc80 nevent=5000 time_id=1).set_owner idx=2 owner=139668858820352
   -12> 2018-12-01 17:47:05.913220 7f07373fe780  1  Processor -- start
   -11> 2018-12-01 17:47:05.913267 7f07373fe780  1 -- - start start
   -10> 2018-12-01 17:47:05.913271 7f07373fe780 10 monclient: build_initial_monmap
    -9> 2018-12-01 17:47:05.913314 7f07373fe780 10 monclient: init
    -8> 2018-12-01 17:47:05.913322 7f07373fe780  5 adding auth protocol: cephx
    -7> 2018-12-01 17:47:05.913325 7f07373fe780 10 monclient: auth_supported 2 method cephx
    -6> 2018-12-01 17:47:05.913340 7f07373fe780 -1 auth: unable to find a keyring on /var/lib/ceph/mgr/ceph-a/keyring: (2) No such file or directory
    -5> 2018-12-01 17:47:05.913353 7f07373fe780 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
    -4> 2018-12-01 17:47:05.913360 7f07373fe780 10 monclient: shutdown
    -3> 2018-12-01 17:47:05.913365 7f07373fe780  1 -- - shutdown_connections
    -2> 2018-12-01 17:47:05.914874 7f07373fe780  1 -- - shutdown_connections
    -1> 2018-12-01 17:47:05.914909 7f07373fe780  1 -- - wait complete.
     0> 2018-12-01 17:47:05.915736 7f072db6f700 -1 *** Caught signal (Aborted) **
 in thread 7f072db6f700 thread_name:fn_anonymous

 ceph version 12.2.9-2-7-g22d1443 (22d1443024fb56b8e521d3b669f85ac7437fb11c) luminous (stable)
 1: (()+0x425421) [0x7f0737840421]
 2: (()+0xf370) [0x7f073512b370]
 3: (gsignal()+0x37) [0x7f073435b1d7]
 4: (abort()+0x148) [0x7f073435c8c8]
 5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f0734c5f9d5]
 6: (()+0x5e946) [0x7f0734c5d946]
 7: (()+0x5e973) [0x7f0734c5d973]
 8: (()+0x5f4df) [0x7f0734c5e4df]
 9: (()+0x7dc5) [0x7f0735123dc5]
 10: (clone()+0x6d) [0x7f073441d76d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

另一次复现的日志:

   -21> 2018-12-01 18:13:05.718071 7f04b9a1b780  5 asok(0x7f04c481c1c0) register_command version hook 0x7f04c47dc0c8
   -20> 2018-12-01 18:13:05.718075 7f04b9a1b780  5 asok(0x7f04c481c1c0) register_command git_version hook 0x7f04c47dc0c8
   -19> 2018-12-01 18:13:05.718079 7f04b9a1b780  5 asok(0x7f04c481c1c0) register_command help hook 0x7f04c47de130
   -18> 2018-12-01 18:13:05.718082 7f04b9a1b780  5 asok(0x7f04c481c1c0) register_command get_command_descriptions hook 0x7f04c47de140
   -17> 2018-12-01 18:13:05.723867 7f04b3192700  2 Event(0x7f04c4813c80 nevent=5000 time_id=1).set_owner idx=2 owner=139658161366784
   -16> 2018-12-01 18:13:05.723915 7f04b3993700  2 Event(0x7f04c4813880 nevent=5000 time_id=1).set_owner idx=1 owner=139658169759488
   -15> 2018-12-01 18:13:05.723933 7f04b4194700  2 Event(0x7f04c4813480 nevent=5000 time_id=1).set_owner idx=0 owner=139658178152192
   -14> 2018-12-01 18:13:05.724270 7f04b9a1b780  1  Processor -- start
   -13> 2018-12-01 18:13:05.724321 7f04b9a1b780  1 -- - start start
   -12> 2018-12-01 18:13:05.724326 7f04b9a1b780 10 monclient: build_initial_monmap
   -11> 2018-12-01 18:13:05.724382 7f04b9a1b780 10 monclient: init
   -10> 2018-12-01 18:13:05.724393 7f04b9a1b780  5 adding auth protocol: cephx
    -9> 2018-12-01 18:13:05.724396 7f04b9a1b780 10 monclient: auth_supported 2 method cephx
    -8> 2018-12-01 18:13:05.724412 7f04b9a1b780 -1 auth: unable to find a keyring on /var/lib/ceph/mgr/ceph-a/keyring: (2) No such file or directory
    -7> 2018-12-01 18:13:05.724427 7f04b9a1b780 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
    -6> 2018-12-01 18:13:05.724434 7f04b9a1b780 10 monclient: shutdown
    -5> 2018-12-01 18:13:05.724440 7f04b9a1b780  1 -- - shutdown_connections
    -4> 2018-12-01 18:13:05.727907 7f04b9a1b780  1 -- - shutdown_connections
    -3> 2018-12-01 18:13:05.727949 7f04b9a1b780  1 -- - wait complete.
    -2> 2018-12-01 18:13:05.728328 7f04b9a1b780  1 -- - >> - conn(0x7f04c4a64000 :-1 s=STATE_NONE pgs=0 cs=0 l=0).mark_down
    -1> 2018-12-01 18:13:05.728345 7f04b9a1b780  2 -- - >> - conn(0x7f04c4a64000 :-1 s=STATE_NONE pgs=0 cs=0 l=0)._stop
     0> 2018-12-01 18:13:05.729083 7f04b018c700 -1 *** Caught signal (Aborted) **
 in thread 7f04b018c700 thread_name:fn_anonymous

 ceph version 12.2.9-2-7-g22d1443 (22d1443024fb56b8e521d3b669f85ac7437fb11c) luminous (stable)

显然,abort 并不是一定是在 AdminSocket::shutdown,要认识到 pthread_create 一旦创建成功就表示线程可以被 join 了,因此我们要考虑那些通过 std::thread 创建的线程,而且考虑到执行 join 的线程名字为 fn_anonymous,我们要考虑那些 join 的 caller 为 Finisher 线程(因为只有它们的名字是 fn_anonymous)。

从 MgrStandby 的代码可以看到,只要 monc.init 失败,主线程等待 msgr 结束之后会析构 MgrStandby 并马上退出:

int r = monc.init();
if (r < 0) {
  monc.shutdown();
  client_messenger->shutdown();
  client_messenger->wait();
  return r;
}

从上面的输出能看到:

2018-12-01 17:47:05.913353 7f07373fe780 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
Error in initialization: (2) No such file or directory
pure virtual method called
terminate called without an active exception
*** Caught signal (Aborted) **

即已经开始析构 MgrStandby,MgrStandby 中有什么线程资源这时还没有释放,msgr? mds client?

经过多次复现,并增大 msgr 的日志级别到 50,发现并没有值得怀疑的地方,但是 mds client 在构造时就会启动 objecter_finisher 线程,且没有看到有明显的停止线程的操作。

增加 finisher 的日志级别,可以看到如下的打印:

   -27> 2018-12-01 19:30:32.064838 7f2bf11b7780  5 asok(0x7f2bfc13a1c0) register_command git_version hook 0x7f2bfc0fa0c8
   -26> 2018-12-01 19:30:32.064841 7f2bf11b7780  5 asok(0x7f2bfc13a1c0) register_command help hook 0x7f2bfc0fc130
   -25> 2018-12-01 19:30:32.064845 7f2bf11b7780  5 asok(0x7f2bfc13a1c0) register_command get_command_descriptions hook 0x7f2bfc0fc140
   -24> 2018-12-01 19:30:32.079845 7f2bec131700  5 asok(0x7f2bfc13a1c0) entry start
   -23> 2018-12-01 19:30:32.079868 7f2beb930700  2 Event(0x7f2bfc131480 nevent=5000 time_id=1).set_owner idx=0 owner=139826612602624
   -22> 2018-12-01 19:30:32.079866 7f2bea92e700  2 Event(0x7f2bfc131c80 nevent=5000 time_id=1).set_owner idx=2 owner=139826595817216
   -21> 2018-12-01 19:30:32.079908 7f2beb12f700  2 Event(0x7f2bfc131880 nevent=5000 time_id=1).set_owner idx=1 owner=139826604209920
   -20> 2018-12-01 19:30:32.080160 7f2bf11b7780 10 finisher(0x7f2bfc1153d0) start
   -19> 2018-12-01 19:30:32.080187 7f2bf11b7780 10 finisher(0x7ffdc67839d8) start
   -18> 2018-12-01 19:30:32.080240 7f2bf11b7780  1  Processor -- start
   -17> 2018-12-01 19:30:32.080431 7f2bf11b7780  1 -- - start start
   -16> 2018-12-01 19:30:32.080439 7f2bf11b7780 10 monclient: build_initial_monmap
   -15> 2018-12-01 19:30:32.080489 7f2bf11b7780 10 monclient: init
   -14> 2018-12-01 19:30:32.080499 7f2bf11b7780  5 adding auth protocol: cephx
   -13> 2018-12-01 19:30:32.080502 7f2bf11b7780 10 monclient: auth_supported 2 method cephx
   -12> 2018-12-01 19:30:32.080518 7f2bf11b7780 -1 auth: unable to find a keyring on /var/lib/ceph/mgr/ceph-a/keyring: (2) No such file or directory
   -11> 2018-12-01 19:30:32.080534 7f2bf11b7780 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
   -10> 2018-12-01 19:30:32.080542 7f2bf11b7780 10 monclient: shutdown
    -9> 2018-12-01 19:30:32.080546 7f2bf11b7780  1 -- - shutdown_connections
    -8> 2018-12-01 19:30:32.082449 7f2be8129700 10 finisher(0x7f2bfc1153d0) finisher_thread start
    -7> 2018-12-01 19:30:32.082455 7f2be8129700 10 finisher(0x7f2bfc1153d0) finisher_thread empty
    -6> 2018-12-01 19:30:32.082457 7f2be8129700 10 finisher(0x7f2bfc1153d0) finisher_thread sleeping
    -5> 2018-12-01 19:30:32.085931 7f2bf11b7780  1 -- - shutdown_connections
    -4> 2018-12-01 19:30:32.085966 7f2bf11b7780  1 -- - wait complete.
    -3> 2018-12-01 19:30:32.086020 7f2bf11b7780 10 finisher(0x7f2bfc1153d0) stop
    -2> 2018-12-01 19:30:32.086090 7f2be8129700 10 finisher(0x7f2bfc1153d0) finisher_thread stop
    -1> 2018-12-01 19:30:32.086118 7f2bf11b7780 10 finisher(0x7f2bfc1153d0) stop finish
     0> 2018-12-01 19:30:32.086861 7f2be7928700 -1 *** Caught signal (Aborted) **
 in thread 7f2be7928700 thread_name:fn_anonymous

 ceph version 12.2.9-1-115-g65a1791 (65a179185d09c37c443f050741d58c3fae15d73c) luminous (stable)

这里存在两个 finisher,其中一个是 ObjectCacher 的,一个是 Client 的,其中 ObjectCacher 的 finisher 在 Client 析构时(由 MgrStandby 析构驱动)stop,但 Client 的 objecter_finisher 并不会 stop(可以从代码中清晰的看到)。

而结合 [1] 中的信息,我们猜测问题就出在 Client 已析构,但 objecter_finisher 的线程函数仍然在运行上。

这里要注意到 C++ 的构造顺序和析构顺序,构造时类成员以定义的顺序构造,而析构则相反。在 MgrStandby 中,msgr 定义在 client 之前,因此是先析构 client 然后析构 msgr,因此可以从日志中观察到 abort 时 msgr 基本上都还没有析构完成。

对比正常的 finisher 日志:

2018-12-01 19:51:55.478069 7fe86dcab780 10 finisher(0x7fe87827b3d0) start
2018-12-01 19:51:55.478106 7fe86dcab780 10 finisher(0x7ffea1b6a6c8) start
2018-12-01 19:51:55.478223 7fe86441c700 10 finisher(0x7ffea1b6a6c8) finisher_thread start
2018-12-01 19:51:55.478231 7fe86441c700 10 finisher(0x7ffea1b6a6c8) finisher_thread empty
2018-12-01 19:51:55.478232 7fe86441c700 10 finisher(0x7ffea1b6a6c8) finisher_thread sleeping
2018-12-01 19:51:55.478522 7fe86dcab780 -1 auth: unable to find a keyring on /var/lib/ceph/mgr/ceph-a/keyring: (2) No such file or directory
2018-12-01 19:51:55.478541 7fe86dcab780 -1 monclient: ERROR: missing keyring, cannot use cephx for authentication
2018-12-01 19:51:55.478586 7fe864c1d700 10 finisher(0x7fe87827b3d0) finisher_thread start
2018-12-01 19:51:55.478592 7fe864c1d700 10 finisher(0x7fe87827b3d0) finisher_thread empty
2018-12-01 19:51:55.478593 7fe864c1d700 10 finisher(0x7fe87827b3d0) finisher_thread sleeping
Error in initialization: (2) No such file or directory
2018-12-01 19:51:55.478894 7fe86dcab780 10 finisher(0x7fe87827b3d0) stop
2018-12-01 19:51:55.478923 7fe864c1d700 10 finisher(0x7fe87827b3d0) finisher_thread stop
2018-12-01 19:51:55.478947 7fe86dcab780 10 finisher(0x7fe87827b3d0) stop finish

显然正常的时候 objecter_finisher 线程(0x7ffea1b6a6c8)在 sleep 等待,而 abort 的时候,线程应该是之前暂时被调度出去了(所以不是必现),然后在重新被调度的时候调用了 Thread 的虚函数 entry 执行线程函数导致 abort。

[1] GCC pure virtual method called

https://tombarta.wordpress.com/2008/07/10/gcc-pure-virtual-method-called/