Project

General

Profile

Bug #7996

0.78: OSD is not suspend-friendly (unresponsive cluster on OSD crash)

Added by Dmitry Smirnov almost 10 years ago. Updated over 9 years ago.

Status:
Won't Fix
Priority:
Normal
Assignee:
-
Category:
OSD
Target version:
-
% Done:

0%

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

Description

One machine running MON and OSD got suspended.
Shortly after (within seconds) the whole cluster got unresponsive for over 1000 seconds
while `ceph osd tree` were still showing OSD on suspended machine as 'up'.
Waking up affected computer did not recover cluster for minutes.
It remained frozen i.e. all rbd devices were not responding etc.
OSD log examination revealed the following:

    -1> 2014-04-05 13:52:44.658331 7f5037fb7700  3 osd.9 14396 handle_osd_map epochs [14397,14399], i have 14396, src has [13847,14399]
     0> 2014-04-05 13:52:44.772065 7f50495f5700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f50495f
5700 time 2014-04-05 13:52:42.320776
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.78 (f6c746c314d7b87b8419b6e584c94bfe4511dbd4)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f504de1d1b9]
 2: (ceph::HeartbeatMap::is_healthy()+0xb6) [0x7f504de1da26]
 3: (ceph::HeartbeatMap::check_touch_file()+0x17) [0x7f504de1e037]
 4: (CephContextServiceThread::entry()+0x154) [0x7f504dee6d14]
 5: (()+0x8062) [0x7f504cdad062]
 6: (clone()+0x6d) [0x7f504b4d9a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 keyvaluestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---
2014-04-05 13:52:44.772305 7f50405d0700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f50405d0700 tim
e 2014-04-05 13:52:42.320793
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.78 (f6c746c314d7b87b8419b6e584c94bfe4511dbd4)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f504de1d1b9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f504de1d4c2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f504dbd0b1a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f504dbd517c]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f504dbd5300]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f504dec4441]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f504dec5330]
 8: (()+0x8062) [0x7f504cdad062]
 9: (clone()+0x6d) [0x7f504b4d9a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

2014-04-05 13:52:44.772076 7f5040dd1700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f5040dd1700 time 2014-04-05 13:52:42.320775
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.78 (f6c746c314d7b87b8419b6e584c94bfe4511dbd4)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f504de1d1b9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f504de1d4c2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f504dbd0b1a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f504dbd517c]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f504dbd5300]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f504dec4441]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f504dec5330]
 8: (()+0x8062) [0x7f504cdad062]
 9: (clone()+0x6d) [0x7f504b4d9a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
    -1> 2014-04-05 13:52:44.772305 7f50405d0700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f50405d0700 time 2014-04-05 13:52:42.320793
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.78 (f6c746c314d7b87b8419b6e584c94bfe4511dbd4)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f504de1d1b9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f504de1d4c2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f504dbd0b1a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f504dbd517c]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f504dbd5300]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f504dec4441]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f504dec5330]
 8: (()+0x8062) [0x7f504cdad062]
 9: (clone()+0x6d) [0x7f504b4d9a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

     0> 2014-04-05 13:52:44.772076 7f5040dd1700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f5040dd1700 time 2014-04-05 13:52:42.320775
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.78 (f6c746c314d7b87b8419b6e584c94bfe4511dbd4)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f504de1d1b9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f504de1d4c2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f504dbd0b1a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f504dbd517c]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f504dbd5300]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f504dec4441]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f504dec5330]
 8: (()+0x8062) [0x7f504cdad062]
 9: (clone()+0x6d) [0x7f504b4d9a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 keyvaluestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---
--- begin dump of recent events ---
--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 keyvaluestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---

We started OSD some minutes after waking up computer and noticed that cluster
became responsive only when OSD initialised.

There are 10 OSDs total on 5 hosts with 4 replicas per pool.
Cluster is fully operational when the particular computer/OSD is down (it is the only OSD on the suspended machine).
OSD do not crash every time on suspend but when it crashes
it causes significant and unexpected down time for the entire cluster.
IMHO cluster should not be affected that badly on OSD crash just like loss of connectivity with machine/OSD is not freezing cluster at all.

Perhaps something can be improved in handling unresponsive OSDs when they did not brought down gracefully...

ceph-osd.9.log.suicide-timeout.xz (139 KB) Dmitry Smirnov, 05/03/2014 05:13 PM

History

#1 Updated by Sage Weil almost 10 years ago

I suspect that the mon on that machine is the key factor at play here. There was a fix that went in just after 0.78 (5132699145a6f5017553403d941f2dac0e357fe2) that may have prevented clients from failing over to another mon when the host suspended.

I take it this is something you can easily reproduce?

The fact that the osd on the suspended machine sometimes crashes on resume is not super surprising; the assert that triggered is a check that an operation doesn't take too long, and if we go to sleep for minutes at random points in time that will sometimes trigger.

#2 Updated by Dmitry Smirnov almost 10 years ago

Sage Weil wrote:

I suspect that the mon on that machine is the key factor at play here. There was a fix that went in just after 0.78 (5132699145a6f5017553403d941f2dac0e357fe2) that may have prevented clients from failing over to another mon when the host suspended.

I'll test this and report if it fix the problem.

I take it this is something you can easily reproduce?

I got few crashes like this, somewhat one crash per 8...10 suspends (conservatively). Then as workaround I installed pm-suspend handler to stop Ceph services on suspend and start on resume...

The fact that the osd on the suspended machine sometimes crashes on resume is not super surprising; the assert that triggered is a check that an operation doesn't take too long, and if we go to sleep for minutes at random points in time that will sometimes trigger.

Then perhaps we should ship pm-suspend handler to gracefully handle suspend events? I'll submit pull request if you wish.

#3 Updated by Dmitry Smirnov almost 10 years ago

I reproduced this problem on 0.79. It looks like it is no different from 0.78 in regards to this problem.

I suspended machine with MON and OSD. Cluster became frozen, rbd devices stopped responding.
After ~14 minutes I lost patience and woke up suspended machine.
OSD crashed as already described (suicide timeout) but monitor was running.
Interestingly crashed OSD were still appearing as "up" in osd tree.
For another ~15 minutes cluster remained frozen and status of affected OSD didn't change until I started OSD.
Only then situation improved and cluster became operational again, rbd devices resumed etc.

#4 Updated by Greg Farnum almost 10 years ago

What's the output of "ceph -s" while the cluster is stable, while it's frozen, and after it's recovered?

#5 Updated by Dmitry Smirnov almost 10 years ago

When cluster is stable output of `ceph -s` is normal, showing health status HEALTH_OK, 5 monitors and 11 OSDs up and in.
When machine with MON and 1 OSD is suspended (but OSD do not crash with "suicide timeout") cluster froze for a minute until affected OSD shown as "down" in `ceph osd tree` and in `ceph -s`.

Today (once again) I had situation when computer with MON and OSD was suspended but OSD crashed:

     0> 2014-04-11 10:17:13.655083 7f9bc6d40700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f9bc6d40700 time 2014-04-11 10:17:12.358930
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f9bcb56add9]
 2: (ceph::HeartbeatMap::is_healthy()+0xb6) [0x7f9bcb56b646]
 3: (ceph::HeartbeatMap::check_touch_file()+0x17) [0x7f9bcb56bc57]
 4: (CephContextServiceThread::entry()+0x154) [0x7f9bcb6363a4]
 5: (()+0x8062) [0x7f9bca6fc062]
 6: (clone()+0x6d) [0x7f9bc8c24a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

-----

2014-04-11 10:17:13.655118 7f9bbef15700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f9bbef15700 time 2014-04-11 10:17:12.358926
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f9bcb56add9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f9bcb56b0e2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f9bcb453c7a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f9bcb4582dc]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f9bcb458460]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f9bcb613b91]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f9bcb614a80]
 8: (()+0x8062) [0x7f9bca6fc062]
 9: (clone()+0x6d) [0x7f9bc8c24a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

2014-04-11 10:17:13.655175 7f9bbe714700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f9bbe714700 time 2014-04-11 10:17:12.358978
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f9bcb56add9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f9bcb56b0e2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f9bcb453c7a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f9bcb4582dc]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f9bcb458460]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f9bcb613b91]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f9bcb614a80]
 8: (()+0x8062) [0x7f9bca6fc062]
 9: (clone()+0x6d) [0x7f9bc8c24a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 keyvaluestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---
2014-04-11 10:17:13.655118 7f9bbef15700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f9bbef15700 time 2014-04-11 10:17:12.358926
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f9bcb56add9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f9bcb56b0e2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f9bcb453c7a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f9bcb4582dc]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f9bcb458460]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f9bcb613b91]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f9bcb614a80]
 8: (()+0x8062) [0x7f9bca6fc062]
 9: (clone()+0x6d) [0x7f9bc8c24a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

2014-04-11 10:17:13.655175 7f9bbe714700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f9bbe714700 time 2014-04-11 10:17:12.358978
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f9bcb56add9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f9bcb56b0e2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f9bcb453c7a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f9bcb4582dc]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f9bcb458460]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f9bcb613b91]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f9bcb614a80]
 8: (()+0x8062) [0x7f9bca6fc062]
 9: (clone()+0x6d) [0x7f9bc8c24a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

2014-04-11 10:17:13.655303 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59799 s=2 pgs=1108 cs=523 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.656693 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59800 s=2 pgs=1109 cs=525 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.658086 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59801 s=2 pgs=1110 cs=527 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.659560 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59802 s=2 pgs=1111 cs=529 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.661035 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59803 s=2 pgs=1112 cs=531 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.662468 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59804 s=2 pgs=1113 cs=533 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.663904 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59805 s=2 pgs=1114 cs=535 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.667800 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59806 s=2 pgs=1115 cs=537 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.676584 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59807 s=2 pgs=1116 cs=539 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.683789 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59808 s=2 pgs=1117 cs=541 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.685490 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59809 s=2 pgs=1118 cs=543 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.687003 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59810 s=2 pgs=1119 cs=545 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.692433 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59811 s=2 pgs=1120 cs=547 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.694733 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59812 s=2 pgs=1121 cs=549 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.696399 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59813 s=2 pgs=1122 cs=551 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.697850 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59814 s=2 pgs=1123 cs=553 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.699243 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59815 s=2 pgs=1124 cs=555 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.700679 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59816 s=2 pgs=1125 cs=557 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.702281 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59817 s=2 pgs=1126 cs=559 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.703691 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59818 s=2 pgs=1127 cs=561 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.708771 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59819 s=2 pgs=1128 cs=563 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.710677 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59820 s=2 pgs=1129 cs=565 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.712162 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59821 s=2 pgs=1130 cs=567 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.713958 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59822 s=2 pgs=1131 cs=569 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.716168 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59823 s=2 pgs=1132 cs=571 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.717557 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59824 s=2 pgs=1133 cs=573 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.718908 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59825 s=2 pgs=1134 cs=575 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.720260 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59826 s=2 pgs=1135 cs=577 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.721530 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59827 s=2 pgs=1136 cs=579 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.722881 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59828 s=2 pgs=1137 cs=581 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.724233 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59829 s=2 pgs=1138 cs=583 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.725584 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59830 s=2 pgs=1139 cs=585 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.727058 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59831 s=2 pgs=1140 cs=587 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.728895 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59832 s=2 pgs=1141 cs=589 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.730253 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59833 s=2 pgs=1142 cs=591 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
2014-04-11 10:17:13.731737 7f9bb7360700  0 -- 192.168.0.7:6805/1004098 >> 192.168.0.250:6830/30948 pipe(0x7f9be7deef80 sd=68 :59834 s=2 pgs=1143 cs=593 l=0 c=0x7f9beee8cb00).fault, initiating reconnect
--- begin dump of recent events ---
  -109> 2014-04-11 10:17:13.655118 7f9bbef15700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f9bbef15700 time 2014-04-11 10:17:12.358926
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f9bcb56add9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f9bcb56b0e2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f9bcb453c7a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f9bcb4582dc]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f9bcb458460]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f9bcb613b91]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f9bcb614a80]
 8: (()+0x8062) [0x7f9bca6fc062]
 9: (clone()+0x6d) [0x7f9bc8c24a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

  -108> 2014-04-11 10:17:13.655175 7f9bbe714700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f9bbe714700 time 2014-04-11 10:17:12.358978
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f9bcb56add9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x72) [0x7f9bcb56b0e2]
 3: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0x24a) [0x7f9bcb453c7a]
 4: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x6c) [0x7f9bcb4582dc]
 5: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x160) [0x7f9bcb458460]
 6: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7f9bcb613b91]
 7: (ThreadPool::WorkThread::entry()+0x10) [0x7f9bcb614a80]
 8: (()+0x8062) [0x7f9bca6fc062]
 9: (clone()+0x6d) [0x7f9bc8c24a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

Please note that time stamps in the crashed OSD log match wake-up time (when machine was resumed from suspend).

Immediately after suspend cluster froze and remained frozen for at least 20 (!) minutes.
`ceph -s` showed "1 mons down, quorum 0,1,3,4 " (i.e. 1 of 5 monitors down, quorum among remaining monitors).
All the time while cluster was frozen both `ceph osd tree` and `ceph -s` showed "11 osds: 11 up, 11 in" while one OSD was down (inactive, not responding, suspended).
It took at least 20 minutes until suspended OSD appeared as "down" in `ceph -s` and `ceph osd tree`. Only then cluster became operational again.

#6 Updated by Dmitry Smirnov almost 10 years ago

I reproduced this problem on 0.80~rc1. On healthy cluster suspend of the machine with one OSD have very ill effect on several other OSDs where "slow requests" appear and stay for longer than 2000 seconds. Some PGs stuck in "peering" state for a long time; RBD devices remain unresponsive etc.
Suspending during recovery do not seems to affect other OSDs as badly as during HEALTH_OK.

#7 Updated by Dmitry Smirnov almost 10 years ago

Sage Weil wrote:

I suspect that the mon on that machine is the key factor at play here.

No MON doesn't matter. I removed MON from the affected machine and still I can reproduce the issue just as easily on 0.80~rc1.

The fact that the osd on the suspended machine sometimes crashes on resume is not super surprising; the assert that triggered is a check that an operation doesn't take too long, and if we go to sleep for minutes at random points in time that will sometimes trigger.

I recognise (at least) two problems here:

  • why don't we respawn OSD automatically?
  • suicidal OSD nature affect cluster in a bad manner.
    As soon as OSD comes back from suspend it announce its existence so PGs go to "peering" and/or "inactive" state.
    Then OSD dies without saying "good bye" hence PGs are staying stuck without response for quite a while and everything waits.
    Even worse, active MDS is knocked down too:
1 mds.-1.-1 handle_mds_map i (192.168.0.250:6800/28073) dne in the mdsmap, respawning myself

but actually it doesn't respawn on 0.80~rc1 due to #8211 so in addition to downtime there are two daemons to (re-)start manually (i.e. affected OSD and MDS).

As workaround I had some success with pm-suspend handler to stop OSD before suspend and start it on wake-up.

The following log shows the beginning of OSD wake-up:

2014-05-03 20:36:43.748177 7f34c772b700  0 -- 192.168.0.7:6801/4588 >> 192.168.0.2:6803/17561 pipe(0x7f34f7903e00 sd=46 :59728 s=2 pgs=37 cs=3 l=0 c=0x7f3513f86680).fault with nothing to send, going to standby
2014-05-03 20:52:02.487451 7f34defc0700  0 -- 192.168.0.7:6800/4588 submit_message osd_op_reply(168 200011dae62.00000000 [write 0~132947] v29999'357862 uv357862 ondisk = 0) v6 remote, 192.168.0.7:0/2558, failed lossy con, dropping message 0x7f3515eab200
2014-05-04 09:22:55.933836 7f34cca46700  1 heartbeat_map reset_timeout 'OSD::disk_tp thread 0x7f34cca46700' had timed out after 4
2014-05-04 09:22:55.933906 7f34cc245700  1 heartbeat_map reset_timeout 'OSD::command_tp thread 0x7f34cc245700' had timed out after 4
2014-05-04 09:22:55.933920 7f34cd247700  1 heartbeat_map reset_timeout 'OSD::recovery_tp thread 0x7f34cd247700' had timed out after 4
2014-05-04 09:22:55.933930 7f34cda48700  1 heartbeat_map reset_timeout 'OSD::op_tp thread 0x7f34cda48700' had timed out after 4
2014-05-04 09:22:55.933938 7f34ce249700  1 heartbeat_map reset_timeout 'OSD::op_tp thread 0x7f34ce249700' had timed out after 4
2014-05-04 09:22:55.934123 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.0 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934130 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.1 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934138 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.3 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934144 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.4 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934151 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.5 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934156 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.7 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934162 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.8 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934169 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.10 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934175 7f34cba44700 -1 osd.9 29999 heartbeat_check: no reply from osd.11 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.934121)
2014-05-04 09:22:55.934330 7f34dffc2700  1 heartbeat_map reset_timeout 'FileStore::op_tp thread 0x7f34dffc2700' had timed out after 4
2014-05-04 09:22:55.934336 7f34e1fc6700  1 heartbeat_map reset_timeout 'FileStore::op_tp thread 0x7f34e1fc6700' had timed out after 4
2014-05-04 09:22:55.934552 7f34c8135700  0 -- 192.168.0.7:6801/4588 >> 192.168.0.250:6807/23144 pipe(0x7f34f7902f00 sd=153 :36922 s=2 pgs=160 cs=1 l=0 c=0x7f3513f84b00).fault with nothing to send, going to standby
2014-05-04 09:22:55.934589 7f34c8034700  0 -- 192.168.0.7:6801/4588 >> 192.168.0.2:6812/18223 pipe(0x7f34f7903680 sd=155 :51623 s=2 pgs=24 cs=1 l=0 c=0x7f3513f84f20).fault with nothing to send, going to standby
2014-05-04 09:22:55.937145 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.0 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937159 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.1 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937165 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.3 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937170 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.4 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937175 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.5 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937181 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.7 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937186 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.8 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937191 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.10 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.937196 7f34e675c700 -1 osd.9 29999 heartbeat_check: no reply from osd.11 since back 2014-05-03 23:03:51.192178 front 2014-05-03 23:03:51.192178 (cutoff 2014-05-04 09:22:35.937143)
2014-05-04 09:22:55.938365 7f34c8438700  0 -- 192.168.0.7:0/4588 >> 192.168.0.250:6816/23569 pipe(0x7f3518758080 sd=212 :0 s=1 pgs=0 cs=0 l=1 c=0x7f350f8bcdc0).fault
2014-05-04 09:22:55.939771 7f34c8337700  0 -- 192.168.0.7:6801/4588 >> 192.168.0.250:6815/6138 pipe(0x7f34f7902a00 sd=151 :58790 s=2 pgs=32970 cs=1 l=0 c=0x7f3513f84580).fault with nothing to send, going to standby
2014-05-04 09:22:55.947648 7f34c792d700  0 -- 192.168.0.7:0/4588 >> 192.168.0.250:6814/23569 pipe(0x7f3511386500 sd=172 :0 s=1 pgs=0 cs=0 l=1 c=0x7f350f8bc000).fault
2014-05-04 09:22:55.963398 7f34d4a56700  0 log [WRN] : map e30035 wrongly marked me down
2014-05-04 09:22:57.823205 7f34c5611700  0 -- 192.168.0.7:6800/4588 >> 192.168.0.2:6801/16783 pipe(0x7f3502140800 sd=202 :6800 s=0 pgs=0 cs=0 l=1 c=0x7f35109b4dc0).accept replacing existing (lossy) channel (new one lossy=1)

Then it remains active for some minutes but reports many timeouts:

2014-05-04 09:25:32.087311 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.205007 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.205472 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.221638 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.221710 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.260667 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.260674 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.706168 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.706188 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.851186 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:32.851194 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:33.673322 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:33.673675 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:33.922239 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:33.922253 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:33.951828 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:33.951912 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:34.434975 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:34.435106 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:34.495567 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15

[...]

2014-05-04 09:25:53.081025 7f34e675c700  0 log [WRN] : slow request 73.602309 seconds old, received at 2014-05-04 09:24:39.478603: osd_op(mds.0.165:648600 1000010999d.00000000 [omap-get-header 0~0,omap-get-vals 0~16] 1.621bc1f3 RETRY=1 ack+retry+read e30036) v4 currently no flag points reached
2014-05-04 09:25:53.081032 7f34e675c700  0 log [WRN] : slow request 73.601146 seconds old, received at 2014-05-04 09:24:39.479766: osd_op(mds.0.165:653115 1000010aa85.00000000 [omap-get-header 0~0,omap-get-vals 0~16] 1.cdc54c73 RETRY=1 ack+retry+read e30036) v4 currently no flag points reached
2014-05-04 09:25:53.081037 7f34e675c700  0 log [WRN] : slow request 73.599972 seconds old, received at 2014-05-04 09:24:39.480940: osd_op(mds.0.165:653216 100001c8b04.00000000 [omap-get-header 0~0,omap-get-vals 0~16] 1.e058f8f3 RETRY=1 ack+retry+read e30036) v4 currently no flag points reached
2014-05-04 09:25:53.081048 7f34e675c700  0 log [WRN] : slow request 70.309343 seconds old, received at 2014-05-04 09:24:42.771569: MOSDPGPush(2.d 30038 [PushOp(6764630d/rb.0.2ba94.2ae8944a.000000008bf2/head//2, version: 30035'155075, data_included: [0~4194304], data_size: 4194304, omap_header_size: 0, omap_entries_size: 0, attrset_size: 2, recovery_info: ObjectRecoveryInfo(6764630d/rb.0.2ba94.2ae8944a.000000008bf2/head//2@30035'155075, copy_subset: [0~4194304], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:4194304, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))]) v2 currently no flag points reached
2014-05-04 09:25:53.081052 7f34e675c700  0 log [WRN] : slow request 36.702064 seconds old, received at 2014-05-04 09:25:16.378848: osd_sub_op(client.2141388.1:26139 2.11 a0f35f91/rb.0.6761c.238e1f29.000000009d97/head//2 [] v 30038'217901 snapset=0=[]:[] snapc=0=[]) v10 currently no flag points reached
2014-05-04 09:25:53.099792 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:53.099799 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:53.125728 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:53.125776 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:53.706383 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:25:53.706400 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15

Finally it crashes with "suicide timeout" and long dump of recent events:

2014-05-04 09:27:09.721742 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:27:10.222606 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
2014-05-04 09:27:10.222610 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had suicide timed out after 150
2014-05-04 09:27:10.253135 7f34d2251700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f34d2251700 time 2014-05-04 09:27:10.222623
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.80-rc1 (6769f4dc88425396921f94e1a37a1c90758aa3ea)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f34ecf93989]
 2: (ceph::HeartbeatMap::is_healthy()+0xb6) [0x7f34ecf941f6]
 3: (OSD::handle_osd_ping(MOSDPing*)+0x7bb) [0x7f34ecc2333b]
 4: (OSD::heartbeat_dispatch(Message*)+0x343) [0x7f34ecc247a3]
 5: (DispatchQueue::entry()+0x57a) [0x7f34ed0e8eba]
 6: (DispatchQueue::DispatchThread::entry()+0xd) [0x7f34ed02ecad]
 7: (()+0x8062) [0x7f34ec11c062]
 8: (clone()+0x6d) [0x7f34ea644a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
-10000> 2014-05-04 09:24:19.036039 7f34d4a56700  5 -- op tracker -- , seq: 501377, time: 2014-05-04 09:24:19.036012, event: dispatched, request: osd_op(mds.0.165:621684 100003f28c7.00000000 [getxattr parent] 0.3a992974 RETRY=1 ack+retry+read e30036) v4
 -9999> 2014-05-04 09:24:19.036046 7f34d4a56700  5 -- op tracker -- , seq: 501377, time: 2014-05-04 09:24:19.036046, event: waiting_for_osdmap, request: osd_op(mds.0.165:621684 100003f28c7.00000000 [getxattr parent] 0.3a992974 RETRY=1 ack+retry+read e30036) v4
 -9998> 2014-05-04 09:24:19.065255 7f34e675c700  5 osd.9 30038 tick

[...]

   -16> 2014-05-04 09:27:09.460386 7f34d2a52700  1 -- 192.168.0.7:0/4588 <== osd.10 192.168.0.2:6805/17561 72 ==== osd_ping(ping_reply e30038 stamp 2014-05-04 09:27:09.459582) v2 ==== 47+0+0 (2175744293 0 0) 0x7f3515ba9500 con 0x7f34fca52b00
   -15> 2014-05-04 09:27:09.460413 7f34d2a52700  1 -- 192.168.0.7:0/4588 <== osd.8 192.168.0.2:6829/19621 72 ==== osd_ping(ping_reply e30038 stamp 2014-05-04 09:27:09.459582) v2 ==== 47+0+0 (2175744293 0 0) 0x7f351c866f40 con 0x7f3514310100
   -14> 2014-05-04 09:27:09.460430 7f34d2a52700  1 -- 192.168.0.7:0/4588 <== osd.5 192.168.0.250:6804/22422 72 ==== osd_ping(ping_reply e30038 stamp 2014-05-04 09:27:09.459582) v2 ==== 47+0+0 (2175744293 0 0) 0x7f3514154140 con 0x7f34f8bdf2e0
   -13> 2014-05-04 09:27:09.460452 7f34d2a52700  1 -- 192.168.0.7:0/4588 <== osd.8 192.168.0.2:6830/19621 72 ==== osd_ping(ping_reply e30038 stamp 2014-05-04 09:27:09.459582) v2 ==== 47+0+0 (2175744293 0 0) 0x7f35040f68c0 con 0x7f34f0479860
   -12> 2014-05-04 09:27:09.460666 7f34d2a52700  1 -- 192.168.0.7:0/4588 <== osd.5 192.168.0.250:6803/22422 72 ==== osd_ping(ping_reply e30038 stamp 2014-05-04 09:27:09.459582) v2 ==== 47+0+0 (2175744293 0 0) 0x7f34f8158700 con 0x7f350dd1dfa0
   -11> 2014-05-04 09:27:09.460700 7f34d2a52700  1 -- 192.168.0.7:0/4588 <== osd.3 192.168.0.2:6813/18223 72 ==== osd_ping(ping_reply e30038 stamp 2014-05-04 09:27:09.459582) v2 ==== 47+0+0 (2175744293 0 0) 0x7f350b7961c0 con 0x7f350398d180
   -10> 2014-05-04 09:27:09.460719 7f34d2a52700  1 -- 192.168.0.7:0/4588 <== osd.4 192.168.0.250:6809/23144 72 ==== osd_ping(ping_reply e30038 stamp 2014-05-04 09:27:09.459582) v2 ==== 47+0+0 (2175744293 0 0) 0x7f3503011640 con 0x7f3509fd2ec0
    -9> 2014-05-04 09:27:09.721402 7f34d2251700  1 -- 192.168.0.7:6807/1004588 <== osd.0 192.168.0.250:0/26515 78 ==== osd_ping(ping e30038 stamp 2014-05-04 09:27:09.726426) v2 ==== 47+0+0 (1035498638 0 0) 0x7f3503011100 con 0x7f34f2794160
    -8> 2014-05-04 09:27:09.721439 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
    -7> 2014-05-04 09:27:09.721726 7f34d124f700  1 -- 192.168.0.7:6806/1004588 <== osd.0 192.168.0.250:0/26515 78 ==== osd_ping(ping e30038 stamp 2014-05-04 09:27:09.726426) v2 ==== 47+0+0 (1035498638 0 0) 0x7f350678ebc0 con 0x7f35159f6000
    -6> 2014-05-04 09:27:09.721742 7f34d124f700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
    -5> 2014-05-04 09:27:10.094870 7f34e675c700  5 osd.9 30038 tick
    -4> 2014-05-04 09:27:10.222567 7f34d2251700  1 -- 192.168.0.7:6807/1004588 <== osd.0 192.168.0.250:0/26515 79 ==== osd_ping(ping e30038 stamp 2014-05-04 09:27:10.227453) v2 ==== 47+0+0 (4094003680 0 0) 0x7f351141f6c0 con 0x7f34f2794160
    -3> 2014-05-04 09:27:10.222606 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had timed out after 15
    -2> 2014-05-04 09:27:10.222610 7f34d2251700  1 heartbeat_map is_healthy 'OSD::op_tp thread 0x7f34cda48700' had suicide timed out after 150
    -1> 2014-05-04 09:27:10.222720 7f34d124f700  1 -- 192.168.0.7:6806/1004588 <== osd.0 192.168.0.250:0/26515 79 ==== osd_ping(ping e30038 stamp 2014-05-04 09:27:10.227453) v2 ==== 47+0+0 (4094003680 0 0) 0x7f3514f8c300 con 0x7f35159f6000
     0> 2014-05-04 09:27:10.253135 7f34d2251700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f34d2251700 time 2014-05-04 09:27:10.222623
common/HeartbeatMap.cc: 79: FAILED assert(0 == "hit suicide timeout")

 ceph version 0.80-rc1 (6769f4dc88425396921f94e1a37a1c90758aa3ea)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f34ecf93989]
 2: (ceph::HeartbeatMap::is_healthy()+0xb6) [0x7f34ecf941f6]
 3: (OSD::handle_osd_ping(MOSDPing*)+0x7bb) [0x7f34ecc2333b]
 4: (OSD::heartbeat_dispatch(Message*)+0x343) [0x7f34ecc247a3]
 5: (DispatchQueue::entry()+0x57a) [0x7f34ed0e8eba]
 6: (DispatchQueue::DispatchThread::entry()+0xd) [0x7f34ed02ecad]
 7: (()+0x8062) [0x7f34ec11c062]
 8: (clone()+0x6d) [0x7f34ea644a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 keyvaluestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---
2014-05-04 09:27:10.322946 7f34d2251700 -1 *** Caught signal (Aborted) **
 in thread 7f34d2251700

 ceph version 0.80-rc1 (6769f4dc88425396921f94e1a37a1c90758aa3ea)
 1: (()+0x5a5daf) [0x7f34ecf6adaf]
 2: (()+0xf880) [0x7f34ec123880]
 3: (gsignal()+0x39) [0x7f34ea5943a9]
 4: (abort()+0x148) [0x7f34ea5974c8]
 5: (__gnu_cxx::__verbose_terminate_handler()+0x155) [0x7f34eae815e5]
 6: (()+0x5e746) [0x7f34eae7f746]
 7: (()+0x5e773) [0x7f34eae7f773]
 8: (()+0x5e9b2) [0x7f34eae7f9b2]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x1f2) [0x7f34ed04bcf2]
 10: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f34ecf93989]
 11: (ceph::HeartbeatMap::is_healthy()+0xb6) [0x7f34ecf941f6]
 12: (OSD::handle_osd_ping(MOSDPing*)+0x7bb) [0x7f34ecc2333b]
 13: (OSD::heartbeat_dispatch(Message*)+0x343) [0x7f34ecc247a3]
 14: (DispatchQueue::entry()+0x57a) [0x7f34ed0e8eba]
 15: (DispatchQueue::DispatchThread::entry()+0xd) [0x7f34ed02ecad]
 16: (()+0x8062) [0x7f34ec11c062]
 17: (clone()+0x6d) [0x7f34ea644a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
     0> 2014-05-04 09:27:10.322946 7f34d2251700 -1 *** Caught signal (Aborted) **
 in thread 7f34d2251700

 ceph version 0.80-rc1 (6769f4dc88425396921f94e1a37a1c90758aa3ea)
 1: (()+0x5a5daf) [0x7f34ecf6adaf]
 2: (()+0xf880) [0x7f34ec123880]
 3: (gsignal()+0x39) [0x7f34ea5943a9]
 4: (abort()+0x148) [0x7f34ea5974c8]
 5: (__gnu_cxx::__verbose_terminate_handler()+0x155) [0x7f34eae815e5]
 6: (()+0x5e746) [0x7f34eae7f746]
 7: (()+0x5e773) [0x7f34eae7f773]
 8: (()+0x5e9b2) [0x7f34eae7f9b2]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x1f2) [0x7f34ed04bcf2]
 10: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2a9) [0x7f34ecf93989]
 11: (ceph::HeartbeatMap::is_healthy()+0xb6) [0x7f34ecf941f6]
 12: (OSD::handle_osd_ping(MOSDPing*)+0x7bb) [0x7f34ecc2333b]
 13: (OSD::heartbeat_dispatch(Message*)+0x343) [0x7f34ecc247a3]
 14: (DispatchQueue::entry()+0x57a) [0x7f34ed0e8eba]
 15: (DispatchQueue::DispatchThread::entry()+0xd) [0x7f34ed02ecad]
 16: (()+0x8062) [0x7f34ec11c062]
 17: (clone()+0x6d) [0x7f34ea644a3d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
   0/ 5 none
   0/ 1 lockdep
   0/ 1 context
   1/ 1 crush
   1/ 5 mds
   1/ 5 mds_balancer
   1/ 5 mds_locker
   1/ 5 mds_log
   1/ 5 mds_log_expire
   1/ 5 mds_migrator
   0/ 1 buffer
   0/ 1 timer
   0/ 1 filer
   0/ 1 striper
   0/ 1 objecter
   0/ 5 rados
   0/ 5 rbd
   0/ 5 journaler
   0/ 5 objectcacher
   0/ 5 client
   0/ 5 osd
   0/ 5 optracker
   0/ 5 objclass
   1/ 3 filestore
   1/ 3 keyvaluestore
   1/ 3 journal
   0/ 5 ms
   1/ 5 mon
   0/10 monc
   1/ 5 paxos
   0/ 5 tp
   1/ 5 auth
   1/ 5 crypto
   1/ 1 finisher
   1/ 5 heartbeatmap
   1/ 5 perfcounter
   1/ 5 rgw
   1/ 5 javaclient
   1/ 5 asok
   1/ 1 throttle
  -2/-2 (syslog threshold)
  -1/-1 (stderr threshold)
  max_recent     10000
  max_new         1000
  log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---

#8 Updated by Sage Weil almost 10 years ago

  • Priority changed from High to Normal

#9 Updated by Samuel Just over 9 years ago

  • Status changed from New to Won't Fix

#10 Updated by Dmitry Smirnov over 9 years ago

"Won't fix" should be normally accompanied by explanation...

Also available in: Atom PDF