Project

General

Profile

Bug #19803

osd_op_reply for stat does not contain data (ceph-mds crashes with unhandled buffer::end_of_buffer exception)

Added by Andreas Gerstmayr almost 7 years ago. Updated almost 7 years ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
EC Pools
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Hi,

our MDS crashes reproducible after some hours when we're extracting lots of zip archives (with many small files) to CephFS from 8 different clients in parallel.
Unfortunately the bad operation gets persisted in the MDS journal, and when another MDS gets active and wants to replay the journal (clientreplay_start), it crashes also.

Initial crash:

what():  buffer::end_of_buffer
*** Caught signal (Aborted) **
terminate called after throwing an instance of 'ceph::buffer::end_of_buffer'
1: (()+0x53677a) [0x55d7ecf6a77a]
2: (()+0xf370) [0x7f300b6e9370]
ceph version 11.2.0 (f223e27eeb35991352ebc1f67423d4ebc252adb7)
in thread 7f30090a1700 thread_name:ceph-mds
3: (gsignal()+0x37) [0x7f300a70b1d7]
6: (()+0x5e946) [0x7f300b00d946]
4: (abort()+0x148) [0x7f300a70c8c8]
5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f300b00f9d5]
8: (()+0xb52c5) [0x7f300b0642c5]
9: (()+0x7dc5) [0x7f300b6e1dc5]
7: (()+0x5e973) [0x7f300b00d973]
10: (clone()+0x6d) [0x7f300a7cd73d]
2017-04-28 00:49:58.691715 7f30090a1700 -1 *** Caught signal (Aborted) **
in thread 7f30090a1700 thread_name:ceph-mds
ceph version 11.2.0 (f223e27eeb35991352ebc1f67423d4ebc252adb7)
3: (gsignal()+0x37) [0x7f300a70b1d7]
1: (()+0x53677a) [0x55d7ecf6a77a]
2: (()+0xf370) [0x7f300b6e9370]
4: (abort()+0x148) [0x7f300a70c8c8]
5: (__gnu_cxx::__verbose_terminate_handler()+0x165) [0x7f300b00f9d5]
6: (()+0x5e946) [0x7f300b00d946]
8: (()+0xb52c5) [0x7f300b0642c5]
7: (()+0x5e973) [0x7f300b00d973]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
10: (clone()+0x6d) [0x7f300a7cd73d]
9: (()+0x7dc5) [0x7f300b6e1dc5]
--- begin dump of recent events ---
-10000> 2017-04-28 00:49:33.714423 7f3004126700  2 Event(0x55d7f7930680 nevent=5000 time_id=1101).wakeup
-9999> 2017-04-28 00:49:33.714473 7f3004126700  1 -- 10.250.21.12:6800/3482923004 --> 10.250.21.15:6839/3187 -- osd_op(unknown.0.134963:3091941 27.f2c81b03 100067f8439.00000000 [create 0~0,setxattr parent (528),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e72474) v7 -- 0x55d8310c6c00 con 0
terminate called recursively
-9997> 2017-04-28 00:49:33.714506 7f3004126700  1 -- 10.250.21.12:6800/3482923004 --> 10.250.21.12:6831/313676 -- osd_op(unknown.0.134963:3091942 1.f2c81b03 100067f8439.00000000 [create 0~0,setxattr parent (528)] snapc 0=[] ondisk+write+known_if_redirected+full_force e72474) v7 -- 0x55d82f736000 con 0
-9998> 2017-04-28 00:49:33.714495 7f30090a1700  5 -- 10.250.21.12:6800/3482923004 >> 10.250.21.15:6813/28389 conn(0x55d7f837d000 :-1 s=STATE_OPEN_MESSAGE_READ_FOOTER_AND_DISPATCH pgs=142080 cs=1 l=1). rx osd.104 seq 22898 0x55d7f7b1a840 osd_op_reply(3091489 100067f8dd1.00000000 [create 0~0,setxattr (528),setxattr (30)] v0'0 uv234058 ondisk = 0) v7
terminate called recursively
-9995> 2017-04-28 00:49:33.714512 7f30090a1700  1 -- 10.250.21.12:6800/3482923004 <== osd.104 10.250.21.15:6813/28389 22898 ==== osd_op_reply(3091489 100067f8dd1.00000000 [create 0~0,setxattr (528),setxattr (30)] v0'0 uv234058 ondisk = 0) v7 ==== 224+0+0 (2199786887 0 0) 0x55d7f7b1a840 con 0x55d7f837d000
-9994> 2017-04-28 00:49:33.714511 7f30098a2700  5 -- 10.250.21.12:6800/3482923004 >> 10.250.21.11:6825/46129 conn(0x55d7f82d7000 :-1 s=STATE_OPEN_MESSAGE_READ_FOOTER_AND_DISPATCH pgs=113646 cs=1 l=1). rx osd.20 seq 45062 0x55d7faed4b00 osd_op_reply(3091378 100067f83d2.00000000 [create 0~0,setxattr (528),setxattr (30)] v0'0 uv231835 ondisk = 0) v7
-9996> 2017-04-28 00:49:33.714514 7f3004126700  2 Event(0x55d7f7930680 nevent=5000 time_id=1101).wakeup
-9993> 2017-04-28 00:49:33.714530 7f30098a2700  1 -- 10.250.21.12:6800/3482923004 <== osd.20 10.250.21.11:6825/46129 45062 ==== osd_op_reply(3091378 100067f83d2.00000000 [create 0~0,setxattr (528),setxattr (30)] v0'0 uv231835 ondisk = 0) v7 ==== 224+0+0 (3127545423 0 0) 0x55d7faed4b00 con 0x55d7f82d7000
-9992> 2017-04-28 00:49:33.714550 7f3004126700  1 -- 10.250.21.12:6800/3482923004 --> 10.250.21.15:6839/3187 -- osd_op(unknown.0.134963:3091943 27.e38456d3 100067f8bf4.00000000 [create 0~0,setxattr parent (528),setxattr layout (30)] snapc 0=[] ondisk+write+known_if_redirected+full_force e72474) v7 -- 0x55d82f0fe2c0 con 0
/entrypoint.sh: line 339: 619559 Aborted                 /usr/bin/ceph-mds ${CEPH_OPTS} -d -i ${MDS_NAME} --setuser ceph --setgroup ceph

The following logs/stacktraces occur when replaying the journal:

2017-04-28 00:50:54.788216 7f85301a3700  1 mds.0.134974 handle_mds_map i am now mds.0.134974
2017-04-28 00:50:54.788225 7f85301a3700  1 mds.0.134974 handle_mds_map state change up:reconnect --> up:rejoin
2017-04-28 00:50:54.788449 7f85301a3700  1 mds.0.134974 rejoin_joint_start
2017-04-28 00:50:54.788237 7f85301a3700  1 mds.0.134974 rejoin_start
2017-04-28 00:50:54.879546 7f852b99a700  1 mds.0.134974 rejoin_done
2017-04-28 00:50:55.790125 7f85301a3700  1 mds.0.134974 handle_mds_map state change up:rejoin --> up:clientreplay
2017-04-28 00:50:55.790116 7f85301a3700  1 mds.0.134974 handle_mds_map i am now mds.0.134974
2017-04-28 00:50:55.790138 7f85301a3700  1 mds.0.134974 recovery_done -- successful recovery!
2017-04-28 00:50:55.790323 7f85301a3700  1 mds.0.134974 clientreplay_start
terminate called recursively
terminate called after throwing an instance of 'ceph::buffer::end_of_buffer'
what():  buffer::end_of_buffer
*** Caught signal (Aborted) **
in thread 7f853311a700 thread_name:ceph-mds
/entrypoint.sh: line 339: 600855 Aborted                 /usr/bin/ceph-mds ${CEPH_OPTS} -d -i ${MDS_NAME} --setuser ceph --setgroup ceph

Backtrace of the core dump:

(gdb) bt
#0  0x00007f7afcace1d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f7afcacf8c8 in __GI_abort () at abort.c:90
#2  0x00007f7afd3d2965 in __gnu_cxx::__verbose_terminate_handler () at ../../../../libstdc++-v3/libsupc++/vterminate.cc:50
#3  0x00007f7afd3d0946 in __cxxabiv1::__terminate (handler=<optimized out>) at ../../../../libstdc++-v3/libsupc++/eh_terminate.cc:38
#4  0x00007f7afd3d0973 in std::terminate () at ../../../../libstdc++-v3/libsupc++/eh_terminate.cc:48
#5  0x00007f7afd4272c5 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:92
#6  0x00007f7afdaa4dc5 in start_thread (arg=0x7f7afbc65700) at pthread_create.c:308
#7  0x00007f7afcb9073d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Running with gdb, showing backtraces of all exceptions:

2017-04-28 14:32:50.666872 7ffff1544700  1 mds.0.153707 reconnect_done
2017-04-28 14:32:51.661987 7ffff1544700  1 mds.0.153707 handle_mds_map i am now mds.0.153707
2017-04-28 14:32:51.661990 7ffff1544700  1 mds.0.153707 handle_mds_map state change up:reconnect --> up:rejoin
2017-04-28 14:32:51.661999 7ffff1544700  1 mds.0.153707 rejoin_start
2017-04-28 14:32:51.662189 7ffff1544700  1 mds.0.153707 rejoin_joint_start
2017-04-28 14:32:51.686178 7fffecd3b700  1 mds.0.153707 rejoin_done
2017-04-28 14:32:52.667188 7ffff1544700  1 mds.0.153707 handle_mds_map i am now mds.0.153707
2017-04-28 14:32:52.667195 7ffff1544700  1 mds.0.153707 handle_mds_map state change up:rejoin --> up:clientreplay
2017-04-28 14:32:52.667207 7ffff1544700  1 mds.0.153707 recovery_done -- successful recovery!
2017-04-28 14:32:52.667394 7ffff1544700  1 mds.0.153707 clientreplay_start
[Switching to Thread 0x7ffff44bb700 (LWP 759717)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe11f0, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe11f0, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff44b9730, len=<optimized out>, dest=0x7ffff44b9720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x55555edfaf50, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x55555edfaf50, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x555560facb00) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x555560facb00) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x555560facb00, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x555560facb00) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x555563458000) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7e080, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560d0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff44bb700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
terminate called after throwing an instance of 'ceph::buffer::end_of_buffer'
[Switching to Thread 0x7ffff34b9700 (LWP 759719)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe2480, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe2480, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff34b7730, len=<optimized out>, dest=0x7ffff34b7720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x55555edfbe30, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x55555edfbe30, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x555560fac000) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x555560fac000) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x555560fac000, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x555560fac000) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x55556345b000) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7ea80, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560e0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff34b9700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
  what():  buffer::end_of_buffer
terminate called recursively
[Switching to Thread 0x7ffff3cba700 (LWP 759718)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe2240, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe2240, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff3cb8730, len=<optimized out>, dest=0x7ffff3cb8720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x55555edfb420, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x55555edfb420, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x5555607842c0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x5555607842c0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x5555607842c0, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x5555607842c0) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x55555ed65000) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7e680, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560f0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff3cba700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff34b9700 (LWP 759719)]
0x00007ffff53241d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56      return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb)

Running with gdb, debug_mds=20, showing backtraces of all exceptions:

2017-04-28 15:06:27.391885 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f9745 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B06.gml auth v164 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758298]
2017-04-28 15:06:27.391892 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f9745 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B06.gml auth v164 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758298]
2017-04-28 15:06:27.391897 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f9745 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B06.gml auth v164 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758298]
2017-04-28 15:06:27.391901 7ffff1544700 10 mds.0.cache.ino(100067f9745) auth_pin by 0x55555ed4e9b8 on [inode 100067f9745 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B06.gml auth v164 ap=2+0 recovering dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758298] now 2+0
2017-04-28 15:06:27.391906 7ffff1544700 15 mds.0.cache.dir(100067f971d) adjust_nested_auth_pins 1/1 on [dir 100067f971d /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+123+123 state=1610612738|complete f(v0 m2017-04-28 00:48:49.795657 68=68+0) n(v0 rc2017-04-28 00:48:49.795657 b1133693 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555563db16b8] by 0x555564758298 count now 0 + 123
2017-04-28 15:06:27.391915 7ffff44bb700  0 -- 10.250.21.11:6800/2668642040 >> - conn(0x5555655ce000 :6800 s=STATE_ACCEPTING_WAIT_BANNER_ADDR pgs=0 cs=0 l=0).fault with nothing to send and in the half  accept state just closed
2017-04-28 15:06:27.391914 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f9746 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_NODATA_B08.gml auth v216 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758880]
2017-04-28 15:06:27.391919 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f9746 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_NODATA_B08.gml auth v216 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758880]
2017-04-28 15:06:27.391924 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f9746 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_NODATA_B08.gml auth v216 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758880]
2017-04-28 15:06:27.391927 7ffff1544700 10 mds.0.cache.ino(100067f9746) auth_pin by 0x55555ed4e9b8 on [inode 100067f9746 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_NODATA_B08.gml auth v216 ap=2+0 recovering dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564758880] now 2+0
2017-04-28 15:06:27.391932 7ffff1544700 15 mds.0.cache.dir(100067f971d) adjust_nested_auth_pins 1/1 on [dir 100067f971d /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+124+124 state=1610612738|complete f(v0 m2017-04-28 00:48:49.795657 68=68+0) n(v0 rc2017-04-28 00:48:49.795657 b1133693 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555563db16b8] by 0x555564758880 count now 0 + 124
2017-04-28 15:06:27.391938 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f9748 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B10.gml auth v240 ap=1+0 dirtyparent s=7972 n(v0 b7972 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759450]
2017-04-28 15:06:27.391945 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f9748 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B10.gml auth v240 ap=1+0 dirtyparent s=7972 n(v0 b7972 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759450][Switching to Thread 0x7ffff34b9700 (LWP 760057)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe22d0, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe22d0, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff34b7730, len=<optimized out>, dest=0x7ffff34b7720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x55556383f560, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x55556383f560, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x5555639e9340) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x5555639e9340) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x5555639e9340, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x5555639e9340) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x55555edee800) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7ea80, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560e0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff34b9700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

2017-04-28 15:06:27.391949 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f9748 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B10.gml auth v240 ap=1+0 dirtyparent s=7972 n(v0 b7972 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759450]
2017-04-28 15:06:27.391953 7ffff1544700 10 mds.0.cache.ino(100067f9748) auth_pin by 0x55555ed4e9b8 on [inode 100067f9748 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B10.gml auth v240 ap=2+0 recovering dirtyparent s=7972 n(v0 b7972 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759450] now 2+0
2017-04-28 15:06:27.391957 7ffff1544700 15 mds.0.cache.dir(100067f971d) adjust_nested_auth_pins 1/1 on [dir 100067f971d /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+125+125 state=1610612738|complete f(v0 m2017-04-28 00:48:49.795657 68=68+0) n(v0 rc2017-04-28 00:48:49.795657 b1133693 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555563db16b8] by 0x555564759450 count now 0 + 125
2017-04-28 15:06:27.391964 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f9749 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/GENERAL_QUALITY.xml auth v242 ap=1+0 dirtyparent s=3210 n(v0 b3210 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759a38]
2017-04-28 15:06:27.391981 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f9749 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/GENERAL_QUALITY.xml auth v242 ap=1+0 dirtyparent s=3210 n(v0 b3210 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759a38]
2017-04-28 15:06:27.391985 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f9749 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/GENERAL_QUALITY.xml auth v242 ap=1+0 dirtyparent s=3210 n(v0 b3210 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759a38]
2017-04-28 15:06:27.391989 7ffff1544700 10 mds.0.cache.ino(100067f9749) auth_pin by 0x55555ed4e9b8 on [inode 100067f9749 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/GENERAL_QUALITY.xml auth v242 ap=2+0 recovering dirtyparent s=3210 n(v0 b3210 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564759a38] now 2+0
2017-04-28 15:06:27.391993 7ffff1544700 15 mds.0.cache.dir(100067f971d) adjust_nested_auth_pins 1/1 on [dir 100067f971d /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+126+126 state=1610612738|complete f(v0 m2017-04-28 00:48:49.795657 68=68+0) n(v0 rc2017-04-28 00:48:49.795657 b1133693 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555563db16b8] by 0x555564759a38 count now 0 + 126
2017-04-28 15:06:27.392001 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f974a [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B8A.gml auth v178 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a020]
2017-04-28 15:06:27.392007 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f974a [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B8A.gml auth v178 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a020]
2017-04-28 15:06:27.392011 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f974a [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B8A.gml auth v178 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a020]
2017-04-28 15:06:27.392015 7ffff1544700 10 mds.0.cache.ino(100067f974a) auth_pin by 0x55555ed4e9b8 on [inode 100067f974a [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B8A.gml auth v178 ap=2+0 recovering dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a020] now 2+0
2017-04-28 15:06:27.392021 7ffff1544700 15 mds.0.cache.dir(100067f971d) adjust_nested_auth_pins 1/1 on [dir 100067f971d /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+127+127 state=1610612738|complete f(v0 m2017-04-28 00:48:49.795657 68=68+0) n(v0 rc2017-04-28 00:48:49.795657 b1133693 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555563db16b8] by 0x55556475a020 count now 0 + 127
2017-04-28 15:06:27.392027 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f974b [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B05.gml auth v244 ap=1+0 dirtyparent s=7970 n(v0 b7970 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a608]
2017-04-28 15:06:27.392034 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f974b [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B05.gml auth v244 ap=1+0 dirtyparent s=7970 n(v0 b7970 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a608]
2017-04-28 15:06:27.392038 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f974b [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B05.gml auth v244 ap=1+0 dirtyparent s=7970 n(v0 b7970 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a608]
2017-04-28 15:06:27.392042 7ffff1544700 10 mds.0.cache.ino(100067f974b) auth_pin by 0x55555ed4e9b8 on [inode 100067f974b [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B05.gml auth v244 ap=2+0 recovering dirtyparent s=7970 n(v0 b7970 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475a608] now 2+0
2017-04-28 15:06:27.392046 7ffff1544700 15 mds.0.cache.dir(100067f971d) adjust_nested_auth_pins 1/1 on [dir 100067f971d /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+128+128 state=1610612738|complete f(v0 m2017-04-28 00:48:49.795657 68=68+0) n(v0 rc2017-04-28 00:48:49.795657 b1133693 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555563db16b8] by 0x55556475a608 count now 0 + 128
2017-04-28 15:06:27.392053 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f974c [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B11.gml auth v200 ap=1+0 dirtyparent s=7969 n(v0 b7969 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475abf0]
terminate called after throwing an instance of 'ceph::buffer::end_of_buffer'
  what():  buffer::end_of_buffer2017-04-28 15:06:27.392059 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f974c [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B11.gml auth v200 ap=1+0 dirtyparent s=7969 n(v0 b7969 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475abf0]

2017-04-28 15:06:27.392063 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f974c [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B11.gml auth v200 ap=1+0 dirtyparent s=7969 n(v0 b7969 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475abf0]
2017-04-28 15:06:27.392067 7ffff1544700 10 mds.0.cache.ino(100067f974c) auth_pin by 0x55555ed4e9b8 on [inode 100067f974c [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_DETFOO_B11.gml auth v200 ap=2+0 recovering dirtyparent s=7969 n(v0 b7969 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475abf0] now 2+0
2017-04-28 15:06:27.392071 7ffff1544700 15 mds.0.cache.dir(100067f971d) adjust_nested_auth_pins 1/1 on [dir 100067f971d /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+129+129 state=1610612738|complete f(v0 m2017-04-28 00:48:49.795657 68=68+0) n(v0 rc2017-04-28 00:48:49.795657 b1133693 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555563db16b8] by 0x55556475abf0 count now 0 + 129
[Switching to Thread 0x7ffff44bb700 (LWP 760055)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe1e50, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe1e50, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff44b9730, len=<optimized out>, dest=0x7ffff44b9720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x5555612d6770, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x5555612d6770, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x555561dd23c0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x555561dd23c0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x555561dd23c0, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x555561dd23c0) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x55556545a800) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7e080, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560d0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff44bb700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
2017-04-28 15:06:27.392078 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f974d [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B10.gml auth v246 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile *->scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475b1d8]
2017-04-28 15:06:27.392083 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f974d [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T46WFA_20170410T052644.SAFE/GRANULE/L1C_T46WFA_A009397_20170410T052644/QI_DATA/MSK_SATURA_B10.gml auth v246 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638767=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556475b1d8]

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff34b9700 (LWP 760057)]
0x00007ffff53241d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56      return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);

Ceph version: 11.2.0
1 active MDS, 5 standby MDS
Clients: kernel client, kernel version 4.2.0-16-generic (ubuntu)

Please tell me if you need additional debug info.

History

#1 Updated by Nathan Cutler almost 7 years ago

  • Project changed from Ceph to CephFS

#2 Updated by Zheng Yan almost 7 years ago

The crash is strange,it happened when decoding on-wire message from osd. Please add 'debug ms = 1' to mds config and try again.

#3 Updated by Andreas Gerstmayr almost 7 years ago

Thanks for looking into this.
Here is the output with debug_mds=20 and debug_ms=1:

2017-05-03 15:50:50.541604 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f9c9b [2,head] /archive/S2A_MSIL1C_20170410T022321_N0204_R103_T51PUM_20170410T022324.SAFE/GRANULE/L1C_T51PUM_A009395_20170410T022324/QI_DATA/MSK_NODATA_B01.gml auth v248 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2372623=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556454bbf8]
2017-05-03 15:50:50.541608 7ffff1544700 10 mds.0.cache.ino(100067f9c9b) auth_pin by 0x55555edc89b8 on [inode 100067f9c9b [2,head] /archive/S2A_MSIL1C_20170410T022321_N0204_R103_T51PUM_20170410T022324.SAFE/GRANULE/L1C_T51PUM_A009395_20170410T022324/QI_DATA/MSK_NODATA_B01.gml auth v248 ap=2+0 recovering dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2372623=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x55556454bbf8] now 2+0
2017-05-03 15:50:50.541612 7ffff1544700 15 mds.0.cache.dir(100067f9c6a) adjust_nested_auth_pins 1/1 on [dir 100067f9c6a /archive/S2A_MSIL1C_20170410T022321_N0204_R103_T51PUM_20170410T022324.SAFE/GRANULE/L1C_T51PUM_A009395_20170410T022324/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+136+136 state=1610612738|complete f(v0 m2017-04-28 00:48:28.154984 68=68+0) n(v0 rc2017-04-28 00:48:28.154984 b309251 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x555564174908] by 0x55556454bbf8 count now 0 + 136
2017-05-03 15:50:50.541619 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f9a8c [2,head] /archive/S2A_MSIL1C_20170410T171301_N0204_R112_T14SPH_20170410T172128.SAFE/GRANULE/L1C_T14SPH_A009404_20170410T172128/AUX_DATA/AUX_ECMWFT auth v4 ap=1+0 dirtyparent s=810 n(v0 b810 1=1+0) (ifile *->scan) (iversion lock) cr={2372617=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x5555647688a0]
2017-05-03 15:50:50.541626 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f9a8c [2,head] /archive/S2A_MSIL1C_20170410T171301_N0204_R112_T14SPH_20170410T172128.SAFE/GRANULE/L1C_T14SPH_A009404_20170410T172128/AUX_DATA/AUX_ECMWFT auth v4 ap=1+0 dirtyparent s=810 n(v0 b810 1=1+0) (ifile scan) (iversion lock) cr={2372617=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x5555647688a0]
2017-05-03 15:50:50.541631 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f9a8c [2,head] /archive/S2A_MSIL1C_20170410T171301_N0204_R112_T14SPH_20170410T172128.SAFE/GRANULE/L1C_T14SPH_A009404_20170410T172128/AUX_DATA/AUX_ECMWFT auth v4 ap=1+0 dirtyparent s=810 n(v0 b810 1=1+0) (ifile scan) (iversion lock) cr={2372617=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x5555647688a0]
2017-05-03 15:50:50.541634 7ffff1544700 10 mds.0.cache.ino(100067f9a8c) auth_pin by 0x55555edc89b8 on [inode 100067f9a8c [2,head] /archive/S2A_MSIL1C_20170410T171301_N0204_R112_T14SPH_20170410T172128.SAFE/GRANULE/L1C_T14SPH_A009404_20170410T172128/AUX_DATA/AUX_ECMWFT auth v4 ap=2+0 recovering dirtyparent s=810 n(v0 b810 1=1+0) (ifile scan) (iversion lock) cr={2372617=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x5555647688a0] now 2+0
2017-05-03 15:50:50.541639 7ffff1544700 15 mds.0.cache.dir(100067f9a8b) adjust_nested_auth_pins 1/1 on [dir 100067f9a8b /archive/S2A_MSIL1C_20170410T171301_N0204_R112_T14SPH_20170410T172128.SAFE/GRANULE/L1C_T14SPH_A009404_20170410T172128/AUX_DATA/ [2,head] auth v=5 cv=0/0 ap=0+2+2 state=1610612738|complete f(v0 m2017-04-28 00:48:34.152720 1=1+0) n(v0 rc2017-04-28 00:48:34.152720 b810 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 0x5555641a2958] by 0x5555647688a0 count now 0 + 2
2017-05-03 15:50:50.541647 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f1dea [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B04.gml auth v168 ap=1+0 s=428 n(v0 b428 1=1+0) (ifile *->scan) (iversion lock) cr={2375910=0-4194304@1} | authpin=1 0x5555649f93d8]
2017-05-03 15:50:50.541651 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f1dea [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B04.gml auth v168 ap=1+0 s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | authpin=1 0x5555649f93d8]
2017-05-03 15:50:50.541655 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f1dea [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B04.gml auth v168 ap=1+0 s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | authpin=1 0x5555649f93d8]
2017-05-03 15:50:50.541659 7ffff1544700 10 mds.0.cache.ino(100067f1dea) auth_pin by 0x55555edc89b8 on [inode 100067f1dea [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B04.gml auth v168 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | authpin=1 0x5555649f93d8] now 2+0
2017-05-03 15:50:50.541663 7ffff1544700 15 mds.0.cache.dir(100067f1dd3) adjust_nested_auth_pins 1/1 on [dir 100067f1dd3 /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/ [2,head] auth v=269 cv=0/0 ap=0+114+114 state=1073741824 f(v0 m2017-04-28 00:47:09.269199 67=67+0) n(v0 rc2017-04-28 00:47:09.269199 b427435 67=67+0) hs=57+0,ss=0+0 dirty=33 | child=1 0x5555623e9b30] by 0x5555649f93d8 count now 0 + 114
2017-05-03 15:50:50.541669 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067f9d9a [2,head] /archive/S2A_MSIL1C_20170410T084601_N0204_R107_T35TQH_20170410T085422.SAFE/GRANULE/L1C_T35TQH_A009399_20170410T085422/QI_DATA/MSK_DEFECT_B12.gml auth v196 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile *->scan) (iversion lock) cr={1638773=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a9de08]
2017-05-03 15:50:50.541675 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067f9d9a [2,head] /archive/S2A_MSIL1C_20170410T084601_N0204_R107_T35TQH_20170410T085422.SAFE/GRANULE/L1C_T35TQH_A009399_20170410T085422/QI_DATA/MSK_DEFECT_B12.gml auth v196 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638773=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a9de08]
2017-05-03 15:50:50.541679 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067f9d9a [2,head] /archive/S2A_MSIL1C_20170410T084601_N0204_R107_T35TQH_20170410T085422.SAFE/GRANULE/L1C_T35TQH_A009399_20170410T085422/QI_DATA/MSK_DEFECT_B12.gml auth v196 ap=1+0 dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638773=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a9de08]
2017-05-03 15:50:50.541683 7ffff1544700 10 mds.0.cache.ino(100067f9d9a) auth_pin by 0x55555edc89b8 on [inode 100067f9d9a [2,head] /archive/S2A_MSIL1C_20170410T084601_N0204_R107_T35TQH_20170410T085422.SAFE/GRANULE/L1C_T35TQH_A009399_20170410T085422/QI_DATA/MSK_DEFECT_B12.gml auth v196 ap=2+0 recovering dirtyparent s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={1638773=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a9de08] now 2+0
2017-05-03 15:50:50.541687 7ffff1544700 15 mds.0.cache.dir(100067f9d66) adjust_nested_auth_pins 1/1 on [dir 100067f9d66 /archive/S2A_MSIL1C_20170410T084601_N0204_R107_T35TQH_20170410T085422.SAFE/GRANULE/L1C_T35TQH_A009399_20170410T085422/QI_DATA/ [2,head] auth v=269 cv=0/0 ap=0+134+134 state=1610612738|complete f(v0 m2017-04-28 00:48:46.546752 67=67+0) n(v0 rc2017-04-28 00:48:46.546752 b544221 67=67+0) hs=67+0,ss=0+0 dirty=67 | child=1 dirty=1 0x5555641e2330] by 0x555564a9de08 count now 0 + 134
2017-05-03 15:50:50.541694 7ffff1544700  7 mds.0.locker file_recover (ifile *->scan) on [inode 100067fa164 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T48XWF_20170410T052644.SAFE/GRANULE/L1C_T48XWF_A009397_20170410T052644/QI_DATA/MSK_TECQUA_B07.gml auth v182 ap=1+0 dirtyparent s=4924 n(v0 b4924 1=1+0) (ifile *->scan) (iversion lock) cr={2372623=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a36848]
2017-05-03 15:50:50.541699 7ffff1544700 10 mds.0.cache queue_file_recover [inode 100067fa164 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T48XWF_20170410T052644.SAFE/GRANULE/L1C_T48XWF_A009397_20170410T052644/QI_DATA/MSK_TECQUA_B07.gml auth v182 ap=1+0 dirtyparent s=4924 n(v0 b4924 1=1+0) (ifile scan) (iversion lock) cr={2372623=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a36848]
2017-05-03 15:50:50.541704 7ffff1544700 15 mds.0 RecoveryQueue::enqueue RecoveryQueue::enqueue [inode 100067fa164 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T48XWF_20170410T052644.SAFE/GRANULE/L1C_T48XWF_A009397_20170410T052644/QI_DATA/MSK_TECQUA_B07.gml auth v182 ap=1+0 dirtyparent s=4924 n(v0 b4924 1=1+0) (ifile scan) (iversion lock) cr={2372623=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a36848]
2017-05-03 15:50:50.541708 7ffff1544700 10 mds.0.cache.ino(100067fa164) auth_pin by 0x55555edc89b8 on [inode 100067fa164 [2,head] /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T48XWF_20170410T052644.SAFE/GRANULE/L1C_T48XWF_A009397_20170410T052644/QI_DATA/MSK_TECQUA_B07.gml auth v182 ap=2+0 recovering dirtyparent s=4924 n(v0 b4924 1=1+0) (ifile scan) (iversion lock) cr={2372623=0-4194304@1} | dirtyparent=1 dirty=1 authpin=1 0x555564a36848] now 2+0
2017-05-03 15:50:50.541712 7ffff1544700 15 mds.0.cache.dir(100067f9d40) adjust_nested_auth_pins 1/1 on [dir 100067f9d40 /archive/S2A_MSIL1C_20170410T052641_N0204_R105_T48XWF_20170410T052644.SAFE/GRANULE/L1C_T48XWF_A009397_20170410T052644/QI_DATA/ [2,head] auth v=273 cv=0/0 ap=0+136+136 state=1610612738|complete f(v0 m2017-04-28 00:48:44.747142 68=68+0) n(v0 rc2017-04-28 00:48:44.747142 b495544 68=68+0) hs=68+0,ss=0+0 dirty=68 | child=1 dirty=1 0x5555641dd5d8] by 0x555564a36848 count now 0 + 136
2017-05-03 15:50:50.541719 7ffff1544700 10 mds.0 RecoveryQueue::advance 2117 queued, 0 prioritized, 0 recovering
2017-05-03 15:50:50.541722 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1df9 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B02.gml auth v204 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279b700]
2017-05-03 15:50:50.541795 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.12:6822/3669 -- osd_op(unknown.0.153847:39 27.fe7f3ab9 100067f1df9.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561b62100 con 0
2017-05-03 15:50:50.541811 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1df8 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B03.gml auth v206 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279bce8]
2017-05-03 15:50:50.541844 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.14:6834/3049 -- osd_op(unknown.0.153847:40 27.cc643ad9 100067f1df8.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561b62680 con 0
2017-05-03 15:50:50.541853 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 166533 {2375910=0-4194304@1} [inode 100067f1df5 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/T52TGQ_20170410T020651_PVI.jp2 auth v208 ap=2+0 recovering s=166533 n(v0 b166533 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279c2d0]
2017-05-03 15:50:50.541881 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.14:6806/2731 -- osd_op(unknown.0.153847:41 27.ed41ad21 100067f1df5.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561b61600 con 0
2017-05-03 15:50:50.541888 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 7434 {2375910=0-4194304@1} [inode 100067f1dfe [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DETFOO_B10.gml auth v210 ap=2+0 recovering s=7434 n(v0 b7434 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279c8b8]
2017-05-03 15:50:50.541909 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.11:6819/44764 -- osd_op(unknown.0.153847:42 27.d22f4a75 100067f1dfe.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555563438b00 con 0
2017-05-03 15:50:50.541918 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1dff [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_SATURA_B8A.gml auth v212 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279cea0]
2017-05-03 15:50:50.541943 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.11:6842/45802 -- osd_op(unknown.0.153847:43 27.a9219398 100067f1dff.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555563438580 con 0
2017-05-03 15:50:50.541953 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 7440 {2375910=0-4194304@1} [inode 100067f1e00 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DETFOO_B05.gml auth v214 ap=2+0 recovering s=7440 n(v0 b7440 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279d488]
2017-05-03 15:50:50.541982 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.15:6841/3112 -- osd_op(unknown.0.153847:44 27.e257a4ad 100067f1e00.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555563439340 con 0
2017-05-03 15:50:50.541996 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1dfa [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_TECQUA_B09.gml auth v216 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279da70]
2017-05-03 15:50:50.542027 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.13:6821/3076 -- osd_op(unknown.0.153847:45 27.8cfe23d8 100067f1dfa.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x5555634382c0 con 0
2017-05-03 15:50:50.542042 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e02 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_SATURA_B10.gml auth v218 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279e058]
2017-05-03 15:50:50.542076 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6822/2905 -- osd_op(unknown.0.153847:46 27.66aa0111 100067f1e02.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555563c398c0 con 0
2017-05-03 15:50:50.542082 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e04 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B10.gml auth v220 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279e640]
2017-05-03 15:50:50.542116 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.13:6827/3087 -- osd_op(unknown.0.153847:47 27.a4906ae9 100067f1e04.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561c11180 con 0
2017-05-03 15:50:50.542127 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e05 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DEFECT_B07.gml auth v222 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279ec28]
2017-05-03 15:50:50.542193 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.12:6817/3659 -- osd_op(unknown.0.153847:48 27.9f2a1550 100067f1e05.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561c0f600 con 0
2017-05-03 15:50:50.542208 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e06 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_TECQUA_B05.gml auth v224 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279f210]
2017-05-03 15:50:50.542252 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6809/2903 -- osd_op(unknown.0.153847:49 27.343e213b 100067f1e06.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555562ea0840 con 0
2017-05-03 15:50:50.542268 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 3038 {2375910=0-4194304@1} [inode 100067f1e09 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B11.gml auth v226 ap=2+0 recovering s=3038 n(v0 b3038 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279f7f8]
2017-05-03 15:50:50.542314 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6814/2906 -- osd_op(unknown.0.153847:50 27.ef56eac3 100067f1e09.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555562ea1b80 con 0
2017-05-03 15:50:50.542328 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 7438 {2375910=0-4194304@1} [inode 100067f1e08 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DETFOO_B06.gml auth v228 ap=2+0 recovering s=7438 n(v0 b7438 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556279fde0]
2017-05-03 15:50:50.542368 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.12:6808/3562 -- osd_op(unknown.0.153847:51 27.d4e419bc 100067f1e08.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555562ea1e40 con 0
2017-05-03 15:50:50.542381 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 1346 {2375910=0-4194304@1} [inode 100067f1e0a [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_NODATA_B07.gml auth v230 ap=2+0 recovering s=1346 n(v0 b1346 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a03c8]
2017-05-03 15:50:50.542429 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6803/3245 -- osd_op(unknown.0.153847:52 27.9887cd6 100067f1e0a.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555562ea23c0 con 0
2017-05-03 15:50:50.542445 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e0b [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_TECQUA_B04.gml auth v232 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a09b0]
2017-05-03 15:50:50.542490 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.15:6801/300637 -- osd_op(unknown.0.153847:53 27.2f88691f 100067f1e0b.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f348c00 con 0
2017-05-03 15:50:50.542505 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e0f [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DEFECT_B01.gml auth v234 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a0f98]
2017-05-03 15:50:50.542537 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.11:6825/46129 -- osd_op(unknown.0.153847:54 27.27086e10 100067f1e0f.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f346dc0 con 0
2017-05-03 15:50:50.542550 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e10 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_TECQUA_B10.gml auth v236 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a1580]
2017-05-03 15:50:50.542581 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.15:6837/3874 -- osd_op(unknown.0.153847:55 27.bd1f93dc 100067f1e10.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f346b00 con 0
2017-05-03 15:50:50.542593 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 7448 {2375910=0-4194304@1} [inode 100067f1e11 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DETFOO_B12.gml auth v238 ap=2+0 recovering s=7448 n(v0 b7448 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a1b68]
2017-05-03 15:50:50.542631 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.13:6822/3194 -- osd_op(unknown.0.153847:56 27.73e08676 100067f1e11.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f348940 con 0
2017-05-03 15:50:50.542639 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 7443 {2375910=0-4194304@1} [inode 100067f1e12 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DETFOO_B02.gml auth v240 ap=2+0 recovering s=7443 n(v0 b7443 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a2150]
2017-05-03 15:50:50.542673 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.12:6829/3575 -- osd_op(unknown.0.153847:57 27.d355cba6 100067f1e12.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f349c80 con 0
2017-05-03 15:50:50.542681 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e14 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_SATURA_B01.gml auth v242 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a2738]
2017-05-03 15:50:50.542706 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.11:6816/340639 -- osd_op(unknown.0.153847:58 27.a8864ea8 100067f1e14.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f32b340 con 0
2017-05-03 15:50:50.542713 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e16 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DEFECT_B04.gml auth v244 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a2d20]
2017-05-03 15:50:50.542736 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.12:6826/3779 -- osd_op(unknown.0.153847:59 27.244fe562 100067f1e16.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f32b600 con 0
2017-05-03 15:50:50.542742 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 810 {2375910=0-4194304@1} [inode 100067f4b1b [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/AUX_DATA/AUX_ECMWFT auth v4 ap=2+0 recovering s=810 n(v0 b810 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a38f0]
2017-05-03 15:50:50.542774 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6802/307167 -- osd_op(unknown.0.153847:60 27.ff4e1a54 100067f4b1b.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f32ab00 con 0
2017-05-03 15:50:50.542782 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e0d [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_TECQUA_B8A.gml auth v246 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a3ed8]
2017-05-03 15:50:50.542805 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.15:6822/3088 -- osd_op(unknown.0.153847:61 27.1c556cc 100067f1e0d.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f32adc0 con 0
2017-05-03 15:50:50.542813 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1df6 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_DEFECT_B08.gml auth v248 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x5555627a44c0]
2017-05-03 15:50:50.542832 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.15:6808/364604 -- osd_op(unknown.0.153847:62 27.3ea3406a 100067f1df6.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x55555f32a000 con 0
2017-05-03 15:50:50.542841 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 428 {2375910=0-4194304@1} [inode 100067f1e13 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/QI_DATA/MSK_TECQUA_B11.gml auth v250 ap=2+0 recovering s=428 n(v0 b428 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-4194304@1} | dirty=1 authpin=1 0x55556347a358]
2017-05-03 15:50:50.542860 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6822/2905 -- osd_op(unknown.0.153847:63 27.416b9be2 100067f1e13.00000000 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555564f02ec0 con 0
2017-05-03 15:50:50.542867 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 28512312 {2375910=0-67108864@1} [inode 100067f4b23 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/IMG_DATA/T52TGQ_20170410T020651_B12.jp2 auth v142 ap=2+0 recovering s=28512312 n(v0 b28512312 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-67108864@1} | dirty=1 authpin=1 0x55556347af28]
2017-05-03 15:50:50.542901 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.13:6808/4011 -- osd_op(unknown.0.153847:64 27.5a25c479 100067f4b23.0000000f [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555564f03440 con 0
2017-05-03 15:50:50.542913 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 3175277 {2375910=0-8388608@1} [inode 100067f4b22 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/IMG_DATA/T52TGQ_20170410T020651_B01.jp2 auth v144 ap=2+0 recovering s=3175277 n(v0 b3175277 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-8388608@1} | dirty=1 authpin=1 0x55556347b510]
2017-05-03 15:50:50.542938 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.15:6801/300637 -- osd_op(unknown.0.153847:65 27.3ebcb3b6 100067f4b22.00000001 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555564f00000 con 0
2017-05-03 15:50:50.542948 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 112283692 {2375910=0-268435456@1} [inode 100067f4b21 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/IMG_DATA/T52TGQ_20170410T020651_B08.jp2 auth v146 ap=2+0 recovering s=112283692 n(v0 b112283692 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-268435456@1} | dirty=1 authpin=1 0x55556347baf8]
2017-05-03 15:50:50.542967 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.13:6808/4011 -- osd_op(unknown.0.153847:66 27.b9b167cd 100067f4b21.0000003f [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561d12580 con 0
2017-05-03 15:50:50.542975 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 104304380 {2375910=0-268435456@1} [inode 100067f4b20 [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/IMG_DATA/T52TGQ_20170410T020651_B04.jp2 auth v148 ap=2+0 recovering s=104304380 n(v0 b104304380 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-268435456@1} | dirty=1 authpin=1 0x55556347c0e0]
2017-05-03 15:50:50.542995 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6800/370871 -- osd_op(unknown.0.153847:67 27.3d3f2a3e 100067f4b20.0000003f [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561d12b00 con 0
2017-05-03 15:50:50.543002 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 29478857 {2375910=0-67108864@1} [inode 100067f4b1f [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/IMG_DATA/T52TGQ_20170410T020651_B11.jp2 auth v150 ap=2+0 recovering s=29478857 n(v0 b29478857 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-67108864@1} | dirty=1 authpin=1 0x55556347c6c8]
2017-05-03 15:50:50.543023 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.13:6833/3875 -- osd_op(unknown.0.153847:68 27.e2610fb 100067f4b1f.0000000f [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555561d923c0 con 0
2017-05-03 15:50:50.543029 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 3756405 {2375910=0-8388608@1} [inode 100067f4b1e [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/IMG_DATA/T52TGQ_20170410T020651_B09.jp2 auth v152 ap=2+0 recovering s=3756405 n(v0 b3756405 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-8388608@1} | dirty=1 authpin=1 0x55556347ccb0]
2017-05-03 15:50:50.543051 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.16:6828/2902 -- osd_op(unknown.0.153847:69 27.f9642baa 100067f4b1e.00000001 [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555562516c00 con 0
2017-05-03 15:50:50.543058 7ffff1544700 10 mds.0 RecoveryQueue::_start starting 31271872 {2375910=0-67108864@1} [inode 100067f4b1d [2,head] /archive/S2A_MSIL1C_20170410T020651_N0204_R103_T52TGQ_20170410T020803.SAFE/GRANULE/L1C_T52TGQ_A009395_20170410T020803/IMG_DATA/T52TGQ_20170410T020651_B07.jp2 auth v154 ap=2+0 recovering s=31271872 n(v0 b31271872 1=1+0) (ifile scan) (iversion lock) cr={2375910=0-67108864@1} | dirty=1 authpin=1 0x55556347d298]
2017-05-03 15:50:50.543088 7ffff1544700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.12:6811/3538 -- osd_op(unknown.0.153847:70 27.624721fc 100067f4b1d.0000000f [stat] snapc 0=[] ack+read+rwordered+known_if_redirected+full_force e80302) v7 -- 0x555562516ec0 con 0
2017-05-03 15:50:50.543104 7ffff1544700 10 mds.0.bal check_targets have  need  want 
2017-05-03 15:50:50.543109 7ffff1544700 15 mds.0.bal   map: i imported [dir 1 / [2,head] auth v=2137480 cv=0/0 dir_auth=0 ap=0+0+1 state=1610612738|complete f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177046=29418880+3758166) hs=4+0,ss=0+0 | child=1 subtree=1 subtreetemp=0 dirty=1 waiter=0 authpin=0 0x555561a82000] from 0
2017-05-03 15:50:50.543122 7ffff1544700 15 mds.0.bal   map: i imported [dir 100 ~mds0/ [2,head] auth v=53710089 cv=0/0 dir_auth=0 ap=1+0+0 state=1073741952 f(v0 10=0+10) n(v43473 rc2017-04-27 21:11:49.444609 b4710339696 962=811+151) hs=0+0,ss=0+0 | subtree=1 subtreetemp=0 waiter=1 authpin=1 0x555561a82318] from 0
2017-05-03 15:50:50.543129 7ffff1544700  5 mds.0.bal rebalance done
2017-05-03 15:50:50.543132 7ffff1544700 15 mds.0.cache show_subtrees
2017-05-03 15:50:50.543141 7ffff1544700 10 mds.0.cache |__ 0    auth [dir 100 ~mds0/ [2,head] auth v=53710089 cv=0/0 dir_auth=0 ap=1+0+0 state=1073741952 f(v0 10=0+10) n(v43473 rc2017-04-27 21:11:49.444609 b4710339696 962=811+151) hs=0+0,ss=0+0 | subtree=1 subtreetemp=0 waiter=1 authpin=1 0x555561a82318]
2017-05-03 15:50:50.543150 7ffff1544700 10 mds.0.cache |__ 0    auth [dir 1 / [2,head] auth v=2137480 cv=0/0 dir_auth=0 ap=0+0+1 state=1610612738|complete f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177046=29418880+3758166) hs=4+0,ss=0+0 | child=1 subtree=1 subtreetemp=0 dirty=1 waiter=0 authpin=0 0x555561a82000]
2017-05-03 15:50:50.543291 7fffeed3f700 15 mds.0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 42, cpu 0.81>
2017-05-03 15:50:50.543306 7ffff1544700  1 -- 10.250.21.11:6800/579443874 <== mon.1 10.250.21.13:6789/0 103 ==== mdsbeacon(3260902/mds-server1.mgmt.internal.sbdsc.catalysts.cc up:clientreplay seq 89 v153850) v7 ==== 169+0+0 (2798718327 0 0) 0x555563fa96c0 con 0x55555eca4800
2017-05-03 15:50:50.543316 7ffff1544700 10 mds.beacon.mds-server1.mgmt.internal.sbdsc.catalysts.cc handle_mds_beacon up:clientreplay seq 89 rtt 17.367174
2017-05-03 15:50:50.543335 7fffeed3f700 10 mds.0.server find_idle_sessions.  laggy until 0.000000
2017-05-03 15:50:50.543339 7fffeed3f700 20 mds.0.server laggiest active session is client.88968 10.250.21.100:0/2352623288
2017-05-03 15:50:50.543336 7ffff1544700  1 -- 10.250.21.11:6800/579443874 <== mon.1 10.250.21.13:6789/0 104 ==== mdsbeacon(3260902/mds-server1.mgmt.internal.sbdsc.catalysts.cc up:clientreplay seq 90 v153850) v7 ==== 169+0+0 (68737609 0 0) 0x555563d763c0 con 0x55555eca4800
2017-05-03 15:50:50.543344 7fffeed3f700 10 mds.0.server new stale session client.88968 10.250.21.100:0/2352623288 last 2017-05-03 15:44:32.729040
2017-05-03 15:50:50.543351 7fffeed3f700 10 mds.0.locker revoke_stale_caps for client.88968
2017-05-03 15:50:50.543353 7ffff1544700 10 mds.beacon.mds-server1.mgmt.internal.sbdsc.catalysts.cc handle_mds_beacon up:clientreplay seq 90 rtt 10.844301
2017-05-03 15:50:50.543360 7ffff1544700  1 -- 10.250.21.11:6800/579443874 <== mon.1 10.250.21.13:6789/0 105 ==== mdsbeacon(3260902/mds-server1.mgmt.internal.sbdsc.catalysts.cc up:clientreplay seq 91 v153850) v7 ==== 169+0+0 (2567193868 0 0) 0x555563d76700 con 0x55555eca4800
2017-05-03 15:50:50.543366 7ffff1544700 10 mds.beacon.mds-server1.mgmt.internal.sbdsc.catalysts.cc handle_mds_beacon up:clientreplay seq 91 rtt 5.682841
2017-05-03 15:50:50.543370 7ffff1544700  1 -- 10.250.21.11:6800/579443874 <== mon.1 10.250.21.13:6789/0 106 ==== mdsbeacon(3260902/mds-server1.mgmt.internal.sbdsc.catalysts.cc up:clientreplay seq 92 v153850) v7 ==== 169+0+0 (1147601604 0 0) 0x555563fa3400 con 0x55555eca4800
2017-05-03 15:50:50.543375 7ffff1544700 10 mds.beacon.mds-server1.mgmt.internal.sbdsc.catalysts.cc handle_mds_beacon up:clientreplay seq 92 rtt 0.029729
2017-05-03 15:50:50.543353 7fffeed3f700 10 mds.0.locker  revoking pAsLsXsFs on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=pAsLsXsFs/p@0,88968=pAsLsXsFs/-@0,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543380 7ffff1544700  1 -- 10.250.21.11:6800/579443874 <== mon.1 10.250.21.13:6789/0 107 ==== mdsbeacon(3260902/mds-server1.mgmt.internal.sbdsc.catalysts.cc up:clientreplay seq 93 v153850) v7 ==== 169+0+0 (3648757121 0 0) 0x555563d76a40 con 0x55555eca4800
2017-05-03 15:50:50.543386 7ffff1544700 10 mds.beacon.mds-server1.mgmt.internal.sbdsc.catalysts.cc handle_mds_beacon up:clientreplay seq 93 rtt 0.029579
2017-05-03 15:50:50.543389 7ffff1544700  1 -- 10.250.21.11:6800/579443874 <== mds.0 10.250.21.11:6800/579443874 0 ==== mds_table_request(snaptable server_ready) v1 ==== 0+0+0 (0 0 0) 0x55555f5fba80 con 0x55555eca0000
2017-05-03 15:50:50.543384 7fffeed3f700 10 mds.0.locker eval 2496 [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=pAsLsXsFs/p@0,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543415 7fffeed3f700 10 mds.0.locker eval doesn't want loner
2017-05-03 15:50:50.543418 7fffeed3f700  7 mds.0.locker file_eval wanted= loner_wanted= other_wanted=  filelock=(ifile sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=pAsLsXsFs/p@0,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543444 7fffeed3f700 10 mds.0.locker simple_eval (iauth sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=pAsLsXsFs/p@0,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543462 7fffeed3f700 10 mds.0.locker simple_eval (ilink sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=pAsLsXsFs/p@0,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543482 7fffeed3f700 10 mds.0.locker simple_eval (ixattr sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=pAsLsXsFs/p@0,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543497 7fffeed3f700 10 mds.0.locker eval done
2017-05-03 15:50:50.543498 7fffeed3f700 10 mds.0.locker remove_stale_leases for client.88968
2017-05-03 15:50:50.543501 7fffeed3f700 10 mds.0.153847 send_message_client client.88968 10.250.21.100:0/2352623288 client_session(stale) v2
2017-05-03 15:50:50.543803 7fffeed3f700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.100:0/2352623288 -- client_session(stale) v2 -- 0x55556243d440 con 0
2017-05-03 15:50:50.543804 7ffff34b9700  1 -- 10.250.21.11:6800/579443874 <== osd.4 10.250.21.11:6819/44764 2 ==== osd_op_reply(42 100067f1dfe.00000000 [stat] v0'0 uv232016 ack = 0) v7 ==== 140+0+0 (207182829 0 0) 0x55555f348940 con 0x55555ee4d000
2017-05-03 15:50:50.543822 7fffeed3f700 20 mds.0.server laggiest active session is client.54399 10.250.21.107:0/2839472496
2017-05-03 15:50:50.543827 7fffeed3f700 10 mds.0.server new stale session client.54399 10.250.21.107:0/2839472496 last 2017-05-03 15:44:32.729035
2017-05-03 15:50:50.543832 7fffeed3f700 10 mds.0.locker revoke_stale_caps for client.54399
2017-05-03 15:50:50.543835 7fffeed3f700 10 mds.0.locker  revoking pAsLsXsFs on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=pAsLsXsFs/p@0,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543860 7fffeed3f700 10 mds.0.locker eval 2496 [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=p/p@1,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:50.543882 7fffeed3f700 10 mds.0.locker eval doesn't want loner
[Switching to Thread 0x7ffff34b9700 (LWP 848200)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe25a0, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe25a0, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff34b7730, len=<optimized out>, dest=0x7ffff34b7720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x55555f4ca530, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x55555f4ca530, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x55555f348940) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x55555f348940) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x55555f348940, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x55555f348940) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x55555ee4d000) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7ea80, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560e0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff34b9700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
2017-05-03 15:50:50.543885 7fffeed3f700  7 mds.0.locker file_eval wanted= loner_wanted= other_wanted=  filelock=(ifile sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=p/p@1,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:51.922790 7fffeed3f700 10 mds.0.locker simple_eval (iauth sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=p/p@1,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:51.922834 7fffeed3f700 10 mds.0.locker simple_eval (ilink sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=p/p@1,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:51.922850 7ffff3cba700  1 -- 10.250.21.11:6800/579443874 <== osd.11 10.250.21.11:6816/340639 1 ==== osd_op_reply(58 100067f1e14.00000000 [stat] v0'0 uv233697 ack = 0) v7 ==== 140+0+0 (3496233932 0 0) 0x555561d12580 con 0x555564040000
2017-05-03 15:50:51.922852 7ffff44bb700  1 -- 10.250.21.11:6800/579443874 <== osd.138 10.250.21.16:6814/2906 1 ==== osd_op_reply(50 100067f1e09.00000000 [stat] v0'0 uv232099 ack = 0) v7 ==== 140+0+0 (1010021233 0 0) 0x555562516ec0 con 0x55555f5ed800
2017-05-03 15:50:51.922860 7fffeed3f700 10 mds.0.locker simple_eval (ixattr sync) on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=p/p@1,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
2017-05-03 15:50:51.922887 7fffeed3f700 10 mds.0.locker eval done
2017-05-03 15:50:51.922890 7fffeed3f700 10 mds.0.locker remove_stale_leases for client.54399
2017-05-03 15:50:51.922896 7fffeed3f700 10 mds.0.153847 send_message_client client.54399 10.250.21.107:0/2839472496 client_session(stale) v2
terminate called after throwing an instance of '2017-05-03 15:50:51.922904 7fffeed3f700  1 -- 10.250.21.11:6800/579443874 --> 10.250.21.107:0/2839472496 -- client_session(stale) v2 -- 0x555565219b00 con 0
ceph::buffer::end_of_buffer[Switching to Thread 0x7ffff44bb700 (LWP 848198)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe2240, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe2240, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff44b9730, len=<optimized out>, dest=0x7ffff44b9720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x5555651e8af0, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x5555651e8af0, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x555562516ec0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x555562516ec0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x555562516ec0, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x555562516ec0) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x55555f5ed800) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7e080, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560d0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff44bb700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
'
2017-05-03 15:50:51.922922 7fffeed3f700 20 mds.0.server laggiest active session is client.2372614 10.250.21.102:0/3039498436
2017-05-03 15:50:52.002991 7fffeed3f700 10 mds.0.server new stale session client.2372614 10.250.21.102:0/3039498436 last 2017-05-03 15:44:32.728987
2017-05-03 15:50:52.002998 7fffeed3f700 10 mds.0.locker revoke_stale_caps for client.2372614[Switching to Thread 0x7ffff3cba700 (LWP 848199)]
Catchpoint 1 (exception thrown), __cxxabiv1::__cxa_throw (obj=0x55555ebe2120, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
62    {
#0  __cxxabiv1::__cxa_throw (obj=0x55555ebe2120, tinfo=0x5555561312b0 <typeinfo for ceph::buffer::end_of_buffer>, dest=0x5555557f41e0 <ceph::buffer::end_of_buffer::~end_of_buffer()>) at ../../../../libstdc++-v3/libsupc++/eh_throw.cc:62
#1  0x0000555555cdfa05 in ceph::buffer::list::iterator_impl<false>::copy (this=0x7ffff3cb8730, len=<optimized out>, dest=0x7ffff3cb8720 "") at /usr/src/debug/ceph-11.2.0/src/common/buffer.cc:1158
#2  0x0000555555ad1dbb in decode_raw<ceph_le64> (p=..., t=...) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:61
#3  decode (p=..., v=<synthetic pointer>) at /usr/src/debug/ceph-11.2.0/src/include/encoding.h:107
#4  Objecter::C_Stat::finish (this=0x5555651e91f0, r=0) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.h:1348
#5  0x00005555557bead9 in Context::complete (this=0x5555651e91f0, r=<optimized out>) at /usr/src/debug/ceph-11.2.0/src/include/Context.h:70
#6  0x0000555555aa94aa in Objecter::handle_osd_op_reply (this=this@entry=0x55555ec02700, m=m@entry=0x555561d12580) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:3411
#7  0x0000555555abc9db in Objecter::ms_dispatch (this=0x55555ec02700, m=0x555561d12580) at /usr/src/debug/ceph-11.2.0/src/osdc/Objecter.cc:973
#8  0x0000555555d0f546 in ms_fast_dispatch (m=0x555561d12580, this=0x55555ec02000) at /usr/src/debug/ceph-11.2.0/src/msg/Messenger.h:564
#9  DispatchQueue::fast_dispatch (this=0x55555ec02150, m=m@entry=0x555561d12580) at /usr/src/debug/ceph-11.2.0/src/msg/DispatchQueue.cc:71
#10 0x0000555555d492f9 in AsyncConnection::process (this=0x555564040000) at /usr/src/debug/ceph-11.2.0/src/msg/async/AsyncConnection.cc:769
#11 0x0000555555bb9459 in EventCenter::process_events (this=this@entry=0x55555eb7e680, timeout_microseconds=<optimized out>, timeout_microseconds@entry=30000000) at /usr/src/debug/ceph-11.2.0/src/msg/async/Event.cc:405
#12 0x0000555555bbbe5a in NetworkStack::__lambda0::operator() (__closure=0x55555eb560f0) at /usr/src/debug/ceph-11.2.0/src/msg/async/Stack.cc:46
#13 0x00007ffff5c7d230 in std::(anonymous namespace)::execute_native_thread_routine (__p=<optimized out>) at ../../../../../libstdc++-v3/src/c++11/thread.cc:84
#14 0x00007ffff62fadc5 in start_thread (arg=0x7ffff3cba700) at pthread_create.c:308
#15 0x00007ffff53e673d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

  what():  buffer::end_of_buffer
2017-05-03 15:50:52.003001 7fffeed3f700 10 mds.0.locker  revoking pAsLsXsFs on [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=p/p@1,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=pAsLsXsFs/-@0,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
terminate called recursively
2017-05-03 15:50:52.081091 7fffeed3f700 10 mds.0.locker eval 2496 [inode 1 [...2,head] / auth v865489 snaprealm=0x55555ede78c0 f(v0 m2017-04-18 19:45:29.416725 4=0+4) n(v194003 rc2017-04-28 00:49:02.431311 b146278998319066 33177047=29418880+3758167)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={40264=pAsLsXsFs/-@0,54399=p/p@1,88968=p/-@1,1413736=pAsLsXsFs/-@0,1638767=pAsLsXsFs/-@0,1638773=pAsLsXsFs/-@0,1638776=pAsLsXsFs/-@0,2372614=p/-@1,2372617=pAsLsXsFs/-@0,2372623=pAsLsXsFs/-@0} | dirtyscattered=1 dirfrag=1 caps=1 dirty=1 0x55555ee1c5e8]
terminate called recursively
2017-05-03 15:50:52.081121 7fffeed3f700 10 mds.0.locker eval doesn't want loner

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff34b9700 (LWP 848200)]
0x00007ffff53241d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56      return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);

#4 Updated by Zheng Yan almost 7 years ago

  • Project changed from CephFS to Ceph
  • Subject changed from ceph-mds crashes with unhandled buffer::end_of_buffer exception to osd_op_reply for stat does not contain data (ceph-mds crashes with unhandled buffer::end_of_buffer exception)

osd op replies for 'stat' do not contain data. (140+0+0 in these lines)

2017-05-03 15:50:51.922850 7ffff3cba700  1 -- 10.250.21.11:6800/579443874 <== osd.11 10.250.21.11:6816/340639 1 ==== osd_op_reply(58 100067f1e14.00000000 [stat] v0'0 uv233697 ack = 0) v7 ==== 140+0+0 (3496233932 0 0) 0x555561d12580 con 0x555564040000
2017-05-03 15:50:51.922852 7ffff44bb700  1 -- 10.250.21.11:6800/579443874 <== osd.138 10.250.21.16:6814/2906 1 ==== osd_op_reply(50 100067f1e09.00000000 [stat] v0'0 uv232099 ack = 0) v7 ==== 140+0+0 (1010021233 0 0) 0x555562516ec0 con 0x55555f5ed800

Correct osd op reply for 'stat' should be something like below. (140+0+16 in the line)

2017-05-04 08:37:54.373484 7fe5ff610700  1 -- 192.168.122.1:0/3708675731 <== osd.1 192.168.122.1:6809/21851 1 ==== osd_op_reply(1 10000f76956.00000000 [stat] v0'0 uv540272 ondisk = 0) v7 ==== 140+0+16 (1193114959 0 2334852946) 0x7fe5f0001e60 con 0x55fbdbbf64d0

please run command "rados -p <cephfs_data_pool> stat 100067f1e14.00000000 --debug_ms=1". check if the osd op reply contains data and check if rados command crashes.

If the reply still does not contain data, osd is misbehavior.

#5 Updated by Andreas Gerstmayr almost 7 years ago

Unfortunately my colleague already fixed the MDS (recover_dentries, journal reset) - now the op reply contains data.
Please don't close this bug yet, I'll run the rados command and check the osd op reply size as soon as this issue occurs again.

If this issue isn't strictly related to the MDS, I should mention that we're using an EC pool and a cache tiering setup with proxy mode.
Unfortunately writes aren't proxied (the size of the cache pool increases during writes), but reads are proxied correctly (which is what we want, we don't want to promote reads from the backing storage).

#6 Updated by Andreas Gerstmayr almost 7 years ago

After switching to writeback cache mode, this error didn't occur again. So I'm confident the proxy mode of the cache tier was the issue here.

#7 Updated by Greg Farnum almost 7 years ago

  • Project changed from Ceph to RADOS
  • Category set to EC Pools

Also available in: Atom PDF