Ceph » rbd

We can't say exactly when the network was restored, but know it was only down for a few minutes.

And unfortunately we don't have a core dump :(

This happened again after a network outage yesterday (again 0.94.9 librbd):

2017-01-31 16:07:13.650311 7f8e25a82700 -1 librbd::ImageWatcher: 0x7f9cfed84d00 image watch failed: 140312834614016, (107) Transport endpoint is not connected
2017-01-31 16:09:00.503499 7f9ce4fc2700  1 heartbeat_map is_healthy 'librbd::thread_pool thread 0x7f8e25281700' had timed out after 60
2017-01-31 16:09:05.503584 7f9ce4fc2700  1 heartbeat_map is_healthy 'librbd::thread_pool thread 0x7f8e25281700' had timed out after 60
2017-01-31 16:09:10.503634 7f9ce4fc2700  1 heartbeat_map is_healthy 'librbd::thread_pool thread 0x7f8e25281700' had timed out after 60

No core dump available.

It happened again:

2017-02-03 11:38:56.185795 7fa6029a9700  1 heartbeat_map is_healthy 'librbd::thread_pool thread 0x7fa5fe09f700' had timed out after 60

and we got a backtrace:

(gdb) thread 2607
[Switching to thread 2607 (Thread 0x7fa5fe09f700 (LWP 8486))]
#0  0x00007fa60ec91e24 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
(gdb) bt
#0  0x00007fa60ec91e24 in pthread_rwlock_rdlock () from /lib64/libpthread.so.0
#1  0x00007fa615f725c0 in RWLock::get_read (this=0x7fa61ca0a1f8) at common/RWLock.h:76
#2  0x00007fa615fb0aac in RLocker (lock=..., this=<synthetic pointer>) at common/RWLock.h:130
#3  librbd::aio_write (ictx=0x7fa61ca0a000, off=654269480960, len=8257536,
    buf=0x7fa62ea34000 "000 (2538309.000.000) 01/29 12:41:25 Job submitted from host: <188.184.92.231:4080?addrs=188.184.92.231-4080&noUDP&sock=3450_78c5_70>\n    DAG Node: Job6\n...\n000 (2538310.000.000) 01/29 12:41:25 Job su"..., c=0x7fa62de77380, op_flags=0) at librbd/internal.cc:3388
#4  0x00007fa615f6a6b9 in Context::complete (this=0x7fa6266a5740, r=<optimized out>) at include/Context.h:65
#5  0x00007fa616084766 in ThreadPool::worker (this=0x7fa61be90340, wt=0x7fa61c9fd4d0) at common/WorkQueue.cc:128
#6  0x00007fa6160857e0 in ThreadPool::WorkThread::entry (this=<optimized out>) at common/WorkQueue.h:397
#7  0x00007fa60ec8edc5 in start_thread () from /lib64/libpthread.so.0
#8  0x00007fa60e9bd73d in clone () from /lib64/libc.so.6

We're gcore'ing that kvm process. Where can we post it? (It's several 10's of GB in size).

@Dan van der Ster:

Please use the "ceph-post-file" utility to upload the core dump along with a listing of installed packages+versions on that host.

Thanks!

Hi Jason -- our security officer is hesitating to let me post the machine memory dump. Could we meet on IRC and I can run what you need?

@Dan van der Ster:

If you can install all necessary debug packages and get a complete gdb core backtrace via "thread apply all bt", that would be a good start.

I'm seeing a similar issue but I'm not sure we're actually loosing network at that moment. However, I get the same output in the client log and have a stuck VM available.

I'll try to see to get a core dump right now. No security issues on my side as it's a testing machine, but we see a similar issue in production, too.

BTW: this is also on hammer (0.94.7).

Grr. My setup doesn't have debug symbols. I'm trying to get them but I may not be able to apply them to the currently running process. We'll see.

Something I'm not seeing in my logs is the `heartbeat_map is_healthy 'librbd::thread_pool thread 0x7f6a93dfd700' had timed out after 60` message. Is that something you could relate to whether this is the same issue?

I'll try to find out what other environmental things were happening at the point in time when the VM got stuck.

Here's what we see on our statistics for the VM at the time when it got stuck:

https://stats.flyingcircus.io/grafana/dashboard/snapshot/UZb8rvC3mIZe6m7Ya6LywQUwN3X0MDfF

Hey, @jdillaman, on IRC you mentioned no threads were stuck, but we lost touch. Is your indication that this isn't a Ceph issue but something else? (I.e. maybe a guest issue?)

@Christian: I just think you need to recreate and get a fresh set of backtraces. Since you had the log message of "heartbeat_map is_healthy 'librbd::thread_pool thread 0x7f6a93dfd700' had timed out after 60", you should have had a stuck thread.

Ah, that was maybe a confusion. My instance of this error only had the first message:

librbd::ImageWatcher: 0x7f796f2b4fc0 image watch failed: 140159514277632, (107) Transport endpoint is not connected

But not the heartbeat one. Maybe we hav a different issue here. I guess the logging level should not be an issue here if the first message made it into the log but not the second ... right?

I think I found the culprit and I also think this may have been completely independent from Ceph. In our case, I found some VMs were stuck after having had a qemu guest agent "freeze" called semi-unsuccessfully (it returned an error but was frozen) and then the following thaw commands failed, too. This explains why the VM wasn't seeing IO any longer but was functional and all components like Ceph, Qemu itself, etc. appeared mysteriously fine. I applied a fix in our environment but maybe this was different from the original report in this issue after all ...