Created attachment 1058008 [details] OS Installation Crash Description of problem: While trying to install an OS on a VM having and exported rbd image, the OS installation is getting Crashed. Cluster is based out of Ubuntu 3.13.0.59 Ceph version - 0.94.1.2 dpkg -l |grep librbd ii librbd1 0.94.1.4-1trusty amd64 RADOS block device client library Client is based out of RHEL 7.1 (QEMU Client ) I just enabled tools in Client, i.e.rhel-7-server-ceph-1.3-tools-test And the version is rpm -qf /usr/lib64/librbd.so.1 librbd1-0.94.1-15.el7cp.x86_64 Then i exported the rbd image to the Client VM (And the Image was visible as a VirtIO disk to the VM ) But when i am trying to install OS on top of it, i am getting a crash on VM installation (PFA) Note: [Client was separately installed as ceph-deploy install from Ubuntu will fail because my Client is RHEL 7.1 ] I hope Ceph allows this cross platform configuration ( Ubuntu Cluster on 0.94.1.2 version + RHEL Client having 0.94.1-15 ) ubuntu@magna103:~$ sudo rbd -p Tanay-RBD --image testingClone_new8 info rbd image 'testingClone_new8': size 102400 MB in 25600 objects order 22 (4096 kB objects) block_name_prefix: rbd_data.adc42eb141f2 format: 2 features: layering, exclusive, object map flags: parent: Tanay-RBD/testing8@testingsnap8 overlap: 102400 MB Version-Release number of selected component (if applicable): ceph version 0.94.1.4 (944951aae2783417100ff0f1078a20bcdcdb605d) How reproducible: 100% Steps to Reproduce: 1. Create a rbd image on your Ubuntu Cluster. #!/bin/bash for i in {1..10} do rbd create Tanay-RBD/testing$i --size 10240 --image-format 2 --image-features 13 --order 22 rbd snap create Tanay-RBD/testing$i@testingsnap$i rbd snap protect Tanay-RBD/testing$i@testingsnap$i rbd clone Tanay-RBD/testing$i@testingsnap$i Tanay-RBD/testingClone_new$i --image-features 13 i=`expr $i+1` done 2. Map the testingClone_new8 to the VM, i.e attach the Disk to install the OS on top of it. ( Disks get visible to the VM ) 3. When installation starts, it is getting Crashed (PFA) Actual results: OS installation should succeed. Expected results: OS installation is getting failed and i can see the the Flags showing as flags: object map invalid ubuntu@magna103:~$ sudo rbd -p Tanay-RBD --image testingClone_new8 info rbd image 'testingClone_new8': size 102400 MB in 25600 objects order 22 (4096 kB objects) block_name_prefix: rbd_data.adc42eb141f2 format: 2 features: layering, exclusive, object map flags: object map invalid parent: Tanay-RBD/testing8@testingsnap8 overlap: 102400 MB Additional info: The same test runs file if i don't use the --image-features 13 flag. Clones using this script is working fine, and i am able to install OS on top of it ( i.e without --image-features 13) #!/bin/bash for i in {1..10} do rbd create Tanay-RBD/testing$i --size 10240 --image-format 2 -order 22 rbd snap create Tanay-RBD/testing$i@testingsnap$i rbd snap protect Tanay-RBD/testing$i@testingsnap$i rbd clone Tanay-RBD/testing$i@testingsnap$i Tanay-RBD/testingClone_new$i i=`expr $i+1` done
Can you provide the core backtrace or the RBD debug logs from the crash?
Actually the VM is not crashing but the Installation stops when it tries to create partition on Disk ( RBD Disk ) I tried to debug with gdb and log files This is the only message what i got from vm.log file red_dispatcher_set_cursor_peer: inputs_connect: inputs channel client create block I/O error in device 'drive-virtio-disk0': Invalid argument (22) block I/O error in device 'drive-virtio-disk0': Invalid argument (22) There was no Error on Monitor as well. Neither i could find any bt on gdb. Its very much reproducible when i select OS disk size > or equals 70 GB. I have tried to install OS on 10-60 GB, and it worked perfectly. Can you please log into my test-bed and check. IP details: 10.8.128.103: Admin & Mon Node Other OSD Nodes are: sudo ceph osd tree ID WEIGHT TYPE NAME UP/DOWN REWEIGHT PRIMARY-AFFINITY -1 13.49991 root default -2 2.69998 host magna094 0 0.89999 osd.0 up 1.00000 1.00000 1 0.89999 osd.1 up 1.00000 1.00000 2 0.89999 osd.2 up 1.00000 1.00000 -3 2.69998 host magna112 3 0.89999 osd.3 up 1.00000 1.00000 4 0.89999 osd.4 up 1.00000 1.00000 5 0.89999 osd.5 up 1.00000 1.00000 -4 2.69998 host magna114 6 0.89999 osd.6 up 1.00000 1.00000 7 0.89999 osd.7 up 1.00000 1.00000 8 0.89999 osd.8 up 1.00000 1.00000 -5 2.69998 host magna106 9 0.89999 osd.9 up 1.00000 1.00000 10 0.89999 osd.10 up 1.00000 1.00000 11 0.89999 osd.11 up 1.00000 1.00000 -6 2.69998 host magna034 12 0.89999 osd.12 up 1.00000 1.00000 13 0.89999 osd.13 up 1.00000 1.00000 14 0.89999 osd.14 up 1.00000 1.00000 QEMU Client IP details are: 10.12.27.16 - QEMU1 10.12.27.17 - QEMU2 Credential: Cluster: ubuntu/redhat Client : root/redhat You can connect to QEMU1 and launch both the VMs (Host16 and New). Currently both are stuck at installation screen.
This is also reproducible with Rhel Clients with Ceph 1.3.0 rpm -qf /usr/lib64/librbd.so.1 librbd1-0.94.1-15.el7cp.x86_64 Getting the same Error message while installing the OS. rpm -qa |grep qemu qemu-img-1.5.3-86.el7.x86_64 libvirt-daemon-driver-qemu-1.2.8-16.el7.x86_64 ipxe-roms-qemu-20130517-6.gitc4bce43.el7.noarch qemu-kvm-common-1.5.3-86.el7.x86_64 qemu-kvm-1.5.3-86.el7.x86_64
Can you enable ceph logging by putting this in ceph.conf on the client node before starting the vm: log file = /var/log/libvirt/qemu/rbd-$pid.$cctid.log debug ms = 1 debug rbd = 20 debug objectcacher = 20 If files don't appear in /var/log/libvirt/qemu when the vm starts using rbd, there may be some permissions issues or DAC you need to disable in libvirt. With the logging in place, reproducing the problem should show us how the I/O error is getting to qemu, and hopefully why as well. I also see rbd_clone_copy_on_read = true for both clients. Does this still reproduce with that disabled? You may have uncovered another bug too. Looking at the qemu logs, I noticed a backtrace in a couple of the existing VM: qemu: terminating on signal 15 from pid 28804 osdc/ObjectCacher.cc: In function 'ObjectCacher::~ObjectCacher()' thread 7fe8a3279a40 time 2015-07-31 04:45:16.194110 osdc/ObjectCacher.cc: 551: FAILED assert(i->empty()) ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff) 1: (()+0x160a15) [0x7fe89e22ba15] 2: (()+0x3a3dd1) [0x7fe89e46edd1] 3: (()+0x57346) [0x7fe89e122346] 4: (()+0x7d859) [0x7fe89e148859] 5: (rbd_close()+0x9) [0x7fe89e107719] 6: (()+0xa709d) [0x7fe8a335909d] 7: (()+0x8ace9) [0x7fe8a333cce9] 8: (()+0x8aba8) [0x7fe8a333cba8] 9: (()+0x8ad73) [0x7fe8a333cd73] 10: (()+0x8ae18) [0x7fe8a333ce18] 11: (()+0x75d0f) [0x7fe8a3327d0f] 12: (__libc_start_main()+0xf5) [0x7fe8991a4af5] 13: (()+0x7714d) [0x7fe8a332914d] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. terminate called after throwing an instance of 'ceph::FailedAssertion' Can you check for this to see how you produced it? It looks like it may just be from shutting down the VM after doing a bunch of writes, but we shouldn't crash there. Can you open a new bug for that?
That ObjectCacher crash sounds like this commit upstream: https://github.com/majianpeng/ceph/commit/35def5c81f7fc83d55d18320e4860c6a63d4c7f5 If an IO error blocks a cache writeback, on shutdown the cache will throw that assertion.
Josh, Please find the attached rbd.log (rbd.log.gz). Yes i am able to reproduce it after disabling 'rbd_clone_copy_on_read' Copying the snippet 2015-08-04 05:07:03.692901 7f717f7fe700 -1 librbd::ObjectMap: failed to update object map: (22) Invalid argument 2015-08-04 05:07:03.692938 7f717f7fe700 20 librbd::AioRequest: write 0x7f7170004ee0 rbd_data.2132e79e2a9e3.0000000000004587 4182016~12288 should_complete: r = -22 2015-08-04 05:07:03.692954 7f717f7fe700 20 librbd::AioRequest: WRITE_PRE 2015-08-04 05:07:03.692959 7f717f7fe700 20 librbd::AioRequest: complete 0x7f7170004ee0 2015-08-04 05:07:03.692965 7f717f7fe700 20 librbdwriteback: C_OrderedWrite completing 0x7f717006e360 2015-08-04 05:07:03.692975 7f717f7fe700 20 librbdwriteback: complete_writes() oid rbd_data.2132e79e2a9e3.0000000000004587 2015-08-04 05:07:03.692986 7f717f7fe700 20 librbdwriteback: complete_writes() completing 0x7f717006e360 2015-08-04 05:07:03.693014 7f717f7fe700 20 librbd::AioCompletion: AioCompletion::complete_request() 0x7f71a632bf40 complete_cb=0x7f71a38e6290 pending 1 2015-08-04 05:07:03.693026 7f717f7fe700 20 librbd::AioCompletion: AioCompletion::finalize() 0x7f71a632bf40 rval -22 read_buf 0 read_bl 0 2015-08-04 05:07:03.693039 7f717f7fe700 20 librbd::AsyncOperation: 0x7f71a632c070 finish_op 2015-08-04 05:07:03.693080 7f717f7fe700 20 librbdwriteback: C_OrderedWrite finished 0x7f717006e360 2015-08-04 05:07:03.693211 7f71a3806a40 20 librbd: close_image 0x7f71a63650c0 2015-08-04 05:07:03.693244 7f71a3806a40 10 librbd::ImageCtx: canceling async requests: count=0 2015-08-04 05:07:03.693725 7f71a3806a40 10 librbd::ImageCtx: prune_parent_extents image overlap 74658611200, object overlap 4194304 from image extents [74654416896,4194304] 2015-08-04 05:07:03.693776 7f71a3806a40 20 librbdwriteback: write will wait for result 0x7f71a636ff10 2015-08-04 05:07:03.693791 7f71a3806a40 20 librbd::AioRequest: send 0x7f71a632c660 rbd_data.2132e79e2a9e3.0000000000004587 4182016~12288 2015-08-04 05:07:03.693804 7f71a3806a40 20 librbd::AioRequest: send_pre 0x7f71a632c660 rbd_data.2132e79e2a9e3.0000000000004587 4182016~12288 2015-08-04 05:07:03.693817 7f71a3806a40 20 librbd::ObjectMap: 0x7f71a63650c0 aio_update: start=17799, end=17800, new_state=1 2015-08-04 05:07:03.693832 7f71a3806a40 20 librbd::ObjectMap: 0x7f71a63650c0 updating on-disk object map: [17799,17800) = ->1 2015-08-04 05:07:03.696669 7f717f7fe700 20 librbd::ObjectMap: 0x7f71a63650c0 should_complete: r=-22 2015-08-04 05:07:03.696712 7f717f7fe700 -1 librbd::ObjectMap: failed to update object map: (22) Invalid argument
Created attachment 1059024 [details] RBD debug log
Somehow the (rbd.log.gz) didnt got upload, i have uploaded the original in text.
I ran the same test with mandatory lock enabled i.e. --image-features 5 sudo rbd -p Tanay-RBD --image mandatorye3 info rbd image 'mandatorye3': size 81200 MB in 20300 objects order 22 (4096 kB objects) block_name_prefix: rbd_data.285f83d1b58ba format: 2 features: layering, exclusive flags: parent: Tanay-RBD/mandatory3@mandatorysnap3 overlap: 81200 MB And i am unable to reproduce the same Issue.
(In reply to Josh Durgin from comment #5) > Can you enable ceph logging by putting this in ceph.conf on the client node > before starting the vm: > > log file = /var/log/libvirt/qemu/rbd-$pid.$cctid.log > debug ms = 1 > debug rbd = 20 > debug objectcacher = 20 > > If files don't appear in /var/log/libvirt/qemu when the vm starts using rbd, > there may be some permissions issues or DAC you need to disable in libvirt. > With the logging in place, reproducing the problem should show us how the > I/O error is getting to qemu, and hopefully why as well. > > I also see rbd_clone_copy_on_read = true for both clients. Does this still > reproduce with that disabled? > > You may have uncovered another bug too. Looking at the qemu logs, I noticed > a backtrace in a couple of the existing VM: > > qemu: terminating on signal 15 from pid 28804 > osdc/ObjectCacher.cc: In function 'ObjectCacher::~ObjectCacher()' thread > 7fe8a3279a40 time 2015-07-31 04:45:16.194110 > osdc/ObjectCacher.cc: 551: FAILED assert(i->empty()) > ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff) > 1: (()+0x160a15) [0x7fe89e22ba15] > 2: (()+0x3a3dd1) [0x7fe89e46edd1] > 3: (()+0x57346) [0x7fe89e122346] > 4: (()+0x7d859) [0x7fe89e148859] > 5: (rbd_close()+0x9) [0x7fe89e107719] > 6: (()+0xa709d) [0x7fe8a335909d] > 7: (()+0x8ace9) [0x7fe8a333cce9] > 8: (()+0x8aba8) [0x7fe8a333cba8] > 9: (()+0x8ad73) [0x7fe8a333cd73] > 10: (()+0x8ae18) [0x7fe8a333ce18] > 11: (()+0x75d0f) [0x7fe8a3327d0f] > 12: (__libc_start_main()+0xf5) [0x7fe8991a4af5] > 13: (()+0x7714d) [0x7fe8a332914d] > NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to > interpret this. > terminate called after throwing an instance of 'ceph::FailedAssertion' > > Can you check for this to see how you produced it? It looks like it may just > be from shutting down the VM after doing a bunch of writes, but we shouldn't > crash there. Can you open a new bug for that? Hi Josh, Yes i am able to reproduce the Assertion Failed Bug. https://bugzilla.redhat.com/show_bug.cgi?id=1250042 After i hit this Bug (1249004), when i force_off the VM. I am seeing the Crash Dump in vm.log file
Can you also attach the OSD logs as well? The OSDs are sending an -EINVAL (-22) error code back to the librbd client. The reason for this error condition should hopefully be included in the OSD logs w/o the need to increase OSD log levels. I created an upstream tracker for how librbd incorrectly handles this unexpected error from the OSD, but we will also need to fix the original source of the issue.
PFA attached 2 OSD logs. If you need some other logs from different OSD's, can you please log into the OSD hosts mentioned above.
Created attachment 1059171 [details] log files 1
Created attachment 1059173 [details] log files 2
OSD error message: /var/log/ceph/ceph-osd.8.log.1.gz:2015-08-04 05:06:05.151676 7f837a876700 0 <cls> cls/rbd/cls_rbd.cc:2109: failed to decode data chunk [4096]: buffer::end_of_buffer
Cloned BZ to track the root cause for the object map being invalidated. This issue will be used to track the IO errors that result after failing to update the object map.
What is the resolution for this bug in 1.3.0 Ubuntu? Will it be fixed or Release noted? Also, as mentioned earlier in comment 4, this Bug is also reproducible with RHEL 1.3.0 Build, which is already in customer place. How are we planning to communicate it to the existing 1.3.0 RHEL customers?
(In reply to Tanay Ganguly from comment #19) > What is the resolution for this bug in 1.3.0 Ubuntu? Will it be fixed or > Release noted? Since we're fixing this in the RHEL 1.3.1 release, my plan was to fix it in the Ubuntu 1.3.1 release too. > Also, as mentioned earlier in comment 4, this Bug is also reproducible with > RHEL 1.3.0 Build, which is already in customer place. How are we planning to > communicate it to the existing 1.3.0 RHEL customers? I don't know the answer to this. Docs team?
Moving back to ASSIGNED for inclusion in 1.3.0.
Ran Librbd test aggressively ( Both Using librbd API and installing OS on rbd Image) for more than 2 days, i am unable to hit the BUG again. Hence marking this BUG as verified ceph version 0.94.1.7 Tested both with RHEL and Ubuntu Client.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2015:1881