Ceph » CephFS

I just saw this (or similar shutdown bug) for the first time in an automated test: http://qa-proxy.ceph.com/teuthology/jspray-2016-06-13_14:56:46-fs-wip-jcsp-testing-quota-2-distro-basic-mira/257048/teuthology.log (see remote/mira122/log/ceph-mds.a-s.log.gz in the output)

This is rearing its head in general testing now:
http://pulpito.ceph.com/jspray-2016-06-15_05:28:02-fs-wip-jcsp-testing-20160615---basic-mira/261446/
(remote/mira088/log/ceph-mds.a-s.log.gz in that one)

Hi guys,

Looks like this issue is very similar to this one here: http://tracker.ceph.com/issues/16396

Interesting, #16396 is with async messenger (and is probably the issue we're seeing in current master testing), but we originally got this issue on Red Hat testing of Jewel which would presumably have been using the simple messenger.

Could it be via following paths to call MDSDaemon::ms_handle_reset() like async msgr?

One mds thread: ... -> SimpleMessenger::shutdown -> SimpleMessenger::mark_down_all -> dispatch_queue.queue_reset

Another simple msgr's dispatch thread: DispatchQueue::entry -> dequeue reset item from dispatch_queue -> messenger::ms_deliver_handle_reset -> ...

I'm able to reproduce this with vstart.sh and `cp -a /usr ...`. I'm seeing this every 10 seconds:

2016-06-30 13:43:41.632422 7f1cca736700 10 monclient: tick
2016-06-30 13:43:41.632445 7f1cca736700 10 cephx: validate_tickets want 39 have 39 need 0
2016-06-30 13:43:41.632448 7f1cca736700 20 cephx client: need_tickets: want=39 need=0 have=39
2016-06-30 13:43:41.632454 7f1cca736700 10 monclient: _check_auth_rotating have uptodate secrets (they expire after 2016-06-30 13:43:11.632451)
2016-06-30 13:43:41.632460 7f1cca736700 10 auth: dump_rotating:
2016-06-30 13:43:41.632461 7f1cca736700 10 auth:  id 1 AQAEhHVXorWfGxAAuFNIH8KnXtfFXjsFDIw8Lg== expires 2016-06-30 14:41:40.463444
2016-06-30 13:43:41.632474 7f1cca736700 10 auth:  id 2 AQAEhHVX9OafGxAAEDpBCWZxiLU3mnbD451yKg== expires 2016-06-30 15:41:40.463444
2016-06-30 13:43:41.632479 7f1cca736700 10 auth:  id 3 AQAEhHVXjROgGxAAtk1jWbJVcc1HpFgelwQFSg== expires 2016-06-30 16:41:40.463444
2016-06-30 13:43:43.631140 7f1ccdf3d700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2016-06-30 13:43:48.631231 7f1ccdf3d700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15

The thread processing the SIGTERM I sent is here:

#0  0x00007f1cd0ad4297 in pthread_join (threadid=139761580963584, thread_return=0x0) at pthread_join.c:92
#1  0x00007f1cd175fd90 in Thread::join (this=this@entry=0x7f1cdd3a99e0, prval=prval@entry=0x0) at common/Thread.cc:171
#2  0x00007f1cd16aabdd in Finisher::stop (this=0x7f1cdd3a98c0) at common/Finisher.cc:27
#3  0x00007f1cd13b2146 in MDSRankDispatcher::shutdown (this=0x7f1cdd441200) at mds/MDSRank.cc:225
#4  0x00007f1cd139b471 in MDSDaemon::suicide (this=this@entry=0x7f1cdd440000) at mds/MDSDaemon.cc:1079
#5  0x00007f1cd139b5f8 in MDSDaemon::handle_signal (this=0x7f1cdd440000, signum=<optimized out>) at mds/MDSDaemon.cc:1045
#6  0x00007f1cd1681667 in SignalHandler::entry (this=0x7f1cdd3b01a0) at global/signal_handler.cc:255
#7  0x00007f1cd0ad2f33 in start_thread (arg=0x7f1cc8631700) at pthread_create.c:309
#8  0x00007f1ccee73ead in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Other threads:

  24   Thread 0x7f1cce73e700 (LWP 15265) "log" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  23   Thread 0x7f1ccdf3d700 (LWP 15266) "service" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
  22   Thread 0x7f1ccd73c700 (LWP 15267) "admin_socket" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  21   Thread 0x7f1cccf3b700 (LWP 15268) "ms_reaper" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  20   Thread 0x7f1ccc73a700 (LWP 15269) "ceph-mds" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
  19   Thread 0x7f1ccbf39700 (LWP 15270) "ms_dispatch" __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  18   Thread 0x7f1ccb738700 (LWP 15271) "ms_local" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  17   Thread 0x7f1ccaf37700 (LWP 15272) "ms_accepter" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  16   Thread 0x7f1cca736700 (LWP 15273) "safe_timer" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
  15   Thread 0x7f1cc9f35700 (LWP 15274) "fn_anonymous" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  14   Thread 0x7f1cd1154700 (LWP 15275) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  13   Thread 0x7f1cc9734700 (LWP 15278) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  12   Thread 0x7f1cc8631700 (LWP 15314) "sginal_handler" 0x00007f1cd0ad4297 in pthread_join (threadid=139761580963584, thread_return=0x0)
    at pthread_join.c:92
  11   Thread 0x7f1cc7e30700 (LWP 15315) "mds_rank_progr" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  10   Thread 0x7f1cc762f700 (LWP 15316) "fn_anonymous" __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  9    Thread 0x7f1cc6e2e700 (LWP 15317) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  8    Thread 0x7f1cc652c700 (LWP 15321) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  7    Thread 0x7f1cc642b700 (LWP 15322) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  6    Thread 0x7f1cc632a700 (LWP 15325) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  5    Thread 0x7f1cc6229700 (LWP 15326) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  4    Thread 0x7f1cc6128700 (LWP 15328) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  3    Thread 0x7f1cc6027700 (LWP 15478) "ms_pipe_read" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  2    Thread 0x7f1cc5f26700 (LWP 15479) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
* 1    Thread 0x7f1cd115a180 (LWP 15264) "ceph-mds" 0x00007f1cd0ad4297 in pthread_join (threadid=139761649157888, thread_return=0x0) at pthread_join.c:92

I can confirm that http://tracker.ceph.com/issues/16396 is unrelated. I applied #9884 to v10.2.1 without any change in behavior.