Patchwork [Bug,1191606] Re: qemu crashes with iscsi initiator (libiscsi) when using virtio

login
register
mail settings
Submitter Laszlo Ersek
Date June 19, 2013, 9:17 a.m.
Message ID <51C17724.5040309@redhat.com>
Download mbox | patch
Permalink /patch/252522/
State New
Headers show

Comments

Laszlo Ersek - June 19, 2013, 9:17 a.m.
On 06/19/13 06:34, ronnie sahlberg wrote:
> I can reproduce with current QEMU.
> 
> Ubuntu 13 crashes with if=virtio but if=ide is fine.
> 
> 
> But it seems dependent on the guest/kernel.
> 
> For example Fedora-18-x86_64-Live-Desktop.iso  installs and runs just
> fine, even with virtio
> But both ubuntu-12.04-desktop-amd64.iso or
> ubuntu-13.04-desktop-amd64.iso crash with if=virtio
> 
> 
> Stack backtrace I got is
> #0  0x00007f7a9e22d037 in __GI_raise (sig=sig@entry=6)
>     at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
> #1  0x00007f7a9e230698 in __GI_abort () at abort.c:90
> #2  0x00007f7aa0a93ec8 in qemu_ram_addr_from_host_nofail (
>     ptr=ptr@entry=0x2020202024008000) at /DATA/SRC/qemu-kvm/qemu/exec.c:1399
> #3  0x00007f7aa0a94a50 in address_space_unmap (as=<optimised out>,
>     buffer=0x2020202024008000, len=<optimised out>, is_write=<optimised out>,
>     access_len=1) at /DATA/SRC/qemu-kvm/qemu/exec.c:2155
> #4  0x00007f7aa0a94bef in cpu_physical_memory_unmap (buffer=<optimised out>,
>     len=<optimised out>, is_write=<optimised out>, access_len=<optimised out>)
>     at /DATA/SRC/qemu-kvm/qemu/exec.c:2189
> #5  0x00007f7aa0ad7867 in virtqueue_fill (vq=vq@entry=0x7f7aa34277f0,
>     elem=elem@entry=0x7f7aa37ca328, len=1, idx=idx@entry=0)
>     at /DATA/SRC/qemu-kvm/qemu/hw/virtio/virtio.c:243
> #6  0x00007f7aa0ad79cf in virtqueue_push (vq=0x7f7aa34277f0,
>     elem=elem@entry=0x7f7aa37ca328, len=<optimised out>)
>     at /DATA/SRC/qemu-kvm/qemu/hw/virtio/virtio.c:279
> #7  0x00007f7aa0aa9989 in virtio_blk_req_complete (
>     req=req@entry=0x7f7aa37ca320, status=status@entry=0)
>     at /DATA/SRC/qemu-kvm/qemu/hw/block/virtio-blk.c:49
> #8  0x00007f7aa0aa9ffb in virtio_blk_handle_request (
>     req=req@entry=0x7f7aa37ca320, mrb=mrb@entry=0x7fff7a7b2060)
>     at /DATA/SRC/qemu-kvm/qemu/hw/block/virtio-blk.c:376

Can you try the attached patch? It will produce quite a bit of output on
stderr.

Thanks
Laszlo
From 18b0c531e9ff1c33cce517c308c8330dd7d33a43 Mon Sep 17 00:00:00 2001
From: Laszlo Ersek <lersek@redhat.com>
Date: Wed, 19 Jun 2013 10:37:31 +0200
Subject: [PATCH] log map/unmap in virtqueue_map_sg() and virtqueue_fill(), plus blk req type


Signed-off-by: Laszlo Ersek <lersek@redhat.com>
---
 hw/block/virtio-blk.c |    1 +
 hw/virtio/virtio.c    |    9 +++++++++
 2 files changed, 10 insertions(+), 0 deletions(-)
ronniesahlberg@gmail.com - June 20, 2013, 1:33 p.m.
http://pastebin.com/EuwZPna1

Last few thousand lines from the log with your patch.


The crash happens immediately after qemu has called out to iscsi_ioctl
with SG_IO to read the serial numbers vpd page.
We get the reply back from the target but as soon as ioctl_cb returns we crash.
If you comment out SG_IO in iscsi_ioctl then the crash does not happen
(but the qemu does nto get serial number either)


I will look more into it tonight.


On Wed, Jun 19, 2013 at 2:17 AM, Laszlo Ersek <lersek@redhat.com> wrote:
> On 06/19/13 06:34, ronnie sahlberg wrote:
>> I can reproduce with current QEMU.
>>
>> Ubuntu 13 crashes with if=virtio but if=ide is fine.
>>
>>
>> But it seems dependent on the guest/kernel.
>>
>> For example Fedora-18-x86_64-Live-Desktop.iso  installs and runs just
>> fine, even with virtio
>> But both ubuntu-12.04-desktop-amd64.iso or
>> ubuntu-13.04-desktop-amd64.iso crash with if=virtio
>>
>>
>> Stack backtrace I got is
>> #0  0x00007f7a9e22d037 in __GI_raise (sig=sig@entry=6)
>>     at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
>> #1  0x00007f7a9e230698 in __GI_abort () at abort.c:90
>> #2  0x00007f7aa0a93ec8 in qemu_ram_addr_from_host_nofail (
>>     ptr=ptr@entry=0x2020202024008000) at /DATA/SRC/qemu-kvm/qemu/exec.c:1399
>> #3  0x00007f7aa0a94a50 in address_space_unmap (as=<optimised out>,
>>     buffer=0x2020202024008000, len=<optimised out>, is_write=<optimised out>,
>>     access_len=1) at /DATA/SRC/qemu-kvm/qemu/exec.c:2155
>> #4  0x00007f7aa0a94bef in cpu_physical_memory_unmap (buffer=<optimised out>,
>>     len=<optimised out>, is_write=<optimised out>, access_len=<optimised out>)
>>     at /DATA/SRC/qemu-kvm/qemu/exec.c:2189
>> #5  0x00007f7aa0ad7867 in virtqueue_fill (vq=vq@entry=0x7f7aa34277f0,
>>     elem=elem@entry=0x7f7aa37ca328, len=1, idx=idx@entry=0)
>>     at /DATA/SRC/qemu-kvm/qemu/hw/virtio/virtio.c:243
>> #6  0x00007f7aa0ad79cf in virtqueue_push (vq=0x7f7aa34277f0,
>>     elem=elem@entry=0x7f7aa37ca328, len=<optimised out>)
>>     at /DATA/SRC/qemu-kvm/qemu/hw/virtio/virtio.c:279
>> #7  0x00007f7aa0aa9989 in virtio_blk_req_complete (
>>     req=req@entry=0x7f7aa37ca320, status=status@entry=0)
>>     at /DATA/SRC/qemu-kvm/qemu/hw/block/virtio-blk.c:49
>> #8  0x00007f7aa0aa9ffb in virtio_blk_handle_request (
>>     req=req@entry=0x7f7aa37ca320, mrb=mrb@entry=0x7fff7a7b2060)
>>     at /DATA/SRC/qemu-kvm/qemu/hw/block/virtio-blk.c:376
>
> Can you try the attached patch? It will produce quite a bit of output on
> stderr.
>
> Thanks
> Laszlo
Laszlo Ersek - June 20, 2013, 2:47 p.m.
On 06/20/13 15:33, ronnie sahlberg wrote:
> http://pastebin.com/EuwZPna1
> 
> Last few thousand lines from the log with your patch.
> 
> 
> The crash happens immediately after qemu has called out to iscsi_ioctl
> with SG_IO to read the serial numbers vpd page.
> We get the reply back from the target but as soon as ioctl_cb returns we crash.
> If you comment out SG_IO in iscsi_ioctl then the crash does not happen
> (but the qemu does nto get serial number either)
> 
> 
> I will look more into it tonight.

  virtqueue_map_sg: mapped gpa=00000000790a9000 at hva=0x7f0cb10a9000 for length=4, is_write=1  (out: data)
  virtqueue_map_sg: mapped gpa=000000007726fc70 at hva=0x7f0caf26fc70 for length=96, is_write=1 (out: sense)
  virtqueue_map_sg: mapped gpa=00000000764e5aa0 at hva=0x7f0cae4e5aa0 for length=16, is_write=1 (out: errors, data_len, sense_len, residual)
  virtqueue_map_sg: mapped gpa=00000000764e5adc at hva=0x7f0cae4e5adc for length=1, is_write=1  (out: status)
  virtqueue_map_sg: mapped gpa=00000000764e5a90 at hva=0x7f0cae4e5a90 for length=16, is_write=0 (in: type, ioprio, sector)
  virtqueue_map_sg: mapped gpa=000000007ab80578 at hva=0x7f0cb2b80578 for length=6, is_write=0  (in: cmd)
  virtio_blk_handle_request: type=0x00000002
  virtqueue_fill: unmapping hva=0x7f0c24008000 for length=4, access_len=1, is_write=1
  Bad ram pointer 0x7f0c24008000

This looks related, in virtio_blk_handle_scsi():

    } else if (req->elem.in_num > 3) {
        /*
         * If we have more than 3 input segments the guest wants to actually
         * read data.
         */
        hdr.dxfer_direction = SG_DXFER_FROM_DEV;
        hdr.iovec_count = req->elem.in_num - 3;
        for (i = 0; i < hdr.iovec_count; i++)
            hdr.dxfer_len += req->elem.in_sg[i].iov_len;

        hdr.dxferp = req->elem.in_sg;
    } else {

This sets
- "hdr.iovec_count" to 1,
- "hdr.dxfer_len" to 4,
- "hdr.dxferp" as shown above,

For "struct sg_io_hdr" (which is the type of "hdr"), the typedef &
documentation are in <include/scsi/sg.h>:

    unsigned short iovec_count; /* [i] 0 implies no scatter gather */

    void __user *dxferp;        /* [i], [*io] points to data transfer memory
                                              or scatter gather list */

Now what we're seeing is a corruption of "req->elem.in_sg[0].iov_base",
whose address equals that of "req->elem.in_sg" (it's at offset 0 in the
struct at subscript #0 in the array).

  virtqueue_map_sg: mapped gpa=00000000790a9000 at hva=0x7f0cb10a9000 for length=4, is_write=1
  [...]
  virtio_blk_handle_request: type=0x00000002
  virtqueue_fill: unmapping hva=0x7f0c24008000 for length=4, access_len=1, is_write=1
  Bad ram pointer 0x7f0c24008000

First I don't understand how access_len can only be "1". But, in any
case, if the "req->elem.in_sg[0].iov_base" pointer is stored in
little-endian order, and the kernel (or iscsi_scsi_command_async()?) for
whatever reason misinterprets "hdr.dxferp" to point at an actual receive
buffer (instead of an iovec array), that would be consistent with the
symptoms:

  0x7f0cb10a9000 <--- original value of req->elem.in_sg[0].iov_base
  0x7f0c24008000 <--- corrupted value
        ^^^^^^^^ <--- 4 low bytes overwritten by SCSI data

Laszlo
ronniesahlberg@gmail.com - June 20, 2013, 3:31 p.m.
On Thu, Jun 20, 2013 at 7:47 AM, Laszlo Ersek <lersek@redhat.com> wrote:
> On 06/20/13 15:33, ronnie sahlberg wrote:
>> http://pastebin.com/EuwZPna1
>>
>> Last few thousand lines from the log with your patch.
>>
>>
>> The crash happens immediately after qemu has called out to iscsi_ioctl
>> with SG_IO to read the serial numbers vpd page.
>> We get the reply back from the target but as soon as ioctl_cb returns we crash.
>> If you comment out SG_IO in iscsi_ioctl then the crash does not happen
>> (but the qemu does nto get serial number either)
>>
>>
>> I will look more into it tonight.
>
>   virtqueue_map_sg: mapped gpa=00000000790a9000 at hva=0x7f0cb10a9000 for length=4, is_write=1  (out: data)
>   virtqueue_map_sg: mapped gpa=000000007726fc70 at hva=0x7f0caf26fc70 for length=96, is_write=1 (out: sense)
>   virtqueue_map_sg: mapped gpa=00000000764e5aa0 at hva=0x7f0cae4e5aa0 for length=16, is_write=1 (out: errors, data_len, sense_len, residual)
>   virtqueue_map_sg: mapped gpa=00000000764e5adc at hva=0x7f0cae4e5adc for length=1, is_write=1  (out: status)
>   virtqueue_map_sg: mapped gpa=00000000764e5a90 at hva=0x7f0cae4e5a90 for length=16, is_write=0 (in: type, ioprio, sector)
>   virtqueue_map_sg: mapped gpa=000000007ab80578 at hva=0x7f0cb2b80578 for length=6, is_write=0  (in: cmd)
>   virtio_blk_handle_request: type=0x00000002
>   virtqueue_fill: unmapping hva=0x7f0c24008000 for length=4, access_len=1, is_write=1
>   Bad ram pointer 0x7f0c24008000
>
> This looks related, in virtio_blk_handle_scsi():
>
>     } else if (req->elem.in_num > 3) {
>         /*
>          * If we have more than 3 input segments the guest wants to actually
>          * read data.
>          */
>         hdr.dxfer_direction = SG_DXFER_FROM_DEV;
>         hdr.iovec_count = req->elem.in_num - 3;
>         for (i = 0; i < hdr.iovec_count; i++)
>             hdr.dxfer_len += req->elem.in_sg[i].iov_len;
>
>         hdr.dxferp = req->elem.in_sg;
>     } else {
>
> This sets
> - "hdr.iovec_count" to 1,
> - "hdr.dxfer_len" to 4,
> - "hdr.dxferp" as shown above,
>
> For "struct sg_io_hdr" (which is the type of "hdr"), the typedef &
> documentation are in <include/scsi/sg.h>:
>
>     unsigned short iovec_count; /* [i] 0 implies no scatter gather */
>
>     void __user *dxferp;        /* [i], [*io] points to data transfer memory
>                                               or scatter gather list */
>
> Now what we're seeing is a corruption of "req->elem.in_sg[0].iov_base",
> whose address equals that of "req->elem.in_sg" (it's at offset 0 in the
> struct at subscript #0 in the array).
>
>   virtqueue_map_sg: mapped gpa=00000000790a9000 at hva=0x7f0cb10a9000 for length=4, is_write=1
>   [...]
>   virtio_blk_handle_request: type=0x00000002
>   virtqueue_fill: unmapping hva=0x7f0c24008000 for length=4, access_len=1, is_write=1
>   Bad ram pointer 0x7f0c24008000
>
> First I don't understand how access_len can only be "1". But, in any
> case, if the "req->elem.in_sg[0].iov_base" pointer is stored in
> little-endian order, and the kernel (or iscsi_scsi_command_async()?) for
> whatever reason misinterprets "hdr.dxferp" to point at an actual receive
> buffer (instead of an iovec array), that would be consistent with the
> symptoms:

Ah, that makes sense.

block.iscsi.c   (https://github.com/qemu/qemu/blob/master/block/iscsi.c)
does assume that ioh->dxferp is a pointer to the buffer and that there
is no scatter gather.
See lines  745-749.

I did not know that ioctl() could take a scatter/gather list.


I cant test now  but if I understand right then
lines 745-749 should be replaced with something that does

* check ioh->iovec_count IF if it zero then there is no scatter gather
and ioh->dxferp points to a buffer,  so just do what we do today.
* IF iovec_count is > 0  then dxferp is NOT a pointer to a buffer but
a pointer to an array of iovec then
traverse the iovec array and add these as buffers to the task just
like we do for readv. For example similar to the loop to add the
iovecs in lines 449-453


I will try this tonight.


>
>   0x7f0cb10a9000 <--- original value of req->elem.in_sg[0].iov_base
>   0x7f0c24008000 <--- corrupted value
>         ^^^^^^^^ <--- 4 low bytes overwritten by SCSI data
>
> Laszl
Laszlo Ersek - June 20, 2013, 3:47 p.m.
On 06/20/13 17:31, ronnie sahlberg wrote:
> On Thu, Jun 20, 2013 at 7:47 AM, Laszlo Ersek <lersek@redhat.com> wrote:

>> First I don't understand how access_len can only be "1". But, in any
>> case, if the "req->elem.in_sg[0].iov_base" pointer is stored in
>> little-endian order, and the kernel (or iscsi_scsi_command_async()?) for
>> whatever reason misinterprets "hdr.dxferp" to point at an actual receive
>> buffer (instead of an iovec array), that would be consistent with the
>> symptoms:
> 
> Ah, that makes sense.
> 
> block.iscsi.c   (https://github.com/qemu/qemu/blob/master/block/iscsi.c)
> does assume that ioh->dxferp is a pointer to the buffer and that there
> is no scatter gather.
> See lines  745-749.

How could I miss that? :) I stopped looking at the
iscsi_scsi_command_async() call on line 734. Sheesh.

> I did not know that ioctl() could take a scatter/gather list.
> 
> 
> I cant test now  but if I understand right then
> lines 745-749 should be replaced with something that does
> 
> * check ioh->iovec_count IF if it zero then there is no scatter gather
> and ioh->dxferp points to a buffer,  so just do what we do today.
> * IF iovec_count is > 0  then dxferp is NOT a pointer to a buffer but
> a pointer to an array of iovec then
> traverse the iovec array and add these as buffers to the task just
> like we do for readv. For example similar to the loop to add the
> iovecs in lines 449-453

Seems correct to me.

> 
> 
> I will try this tonight.

Thanks!
Laszlo

Patch

diff --git a/hw/block/virtio-blk.c b/hw/block/virtio-blk.c
index cf12469..14cf898 100644
--- a/hw/block/virtio-blk.c
+++ b/hw/block/virtio-blk.c
@@ -358,6 +358,7 @@  static void virtio_blk_handle_request(VirtIOBlockReq *req,
     req->in = (void *)req->elem.in_sg[req->elem.in_num - 1].iov_base;
 
     type = ldl_p(&req->out->type);
+    fprintf(stderr, "%s: type=0x%08" PRIx32 "\n", __FUNCTION__, type);
 
     if (type & VIRTIO_BLK_T_FLUSH) {
         virtio_blk_handle_flush(req, mrb);
diff --git a/hw/virtio/virtio.c b/hw/virtio/virtio.c
index 8176c14..0af31c5 100644
--- a/hw/virtio/virtio.c
+++ b/hw/virtio/virtio.c
@@ -240,6 +240,9 @@  void virtqueue_fill(VirtQueue *vq, const VirtQueueElement *elem,
     for (i = 0; i < elem->in_num; i++) {
         size_t size = MIN(len - offset, elem->in_sg[i].iov_len);
 
+        fprintf(stderr, "%s: unmapping hva=%p for length=%zu, "
+                "access_len=%zu, is_write=1\n", __FUNCTION__,
+                elem->in_sg[i].iov_base, elem->in_sg[i].iov_len, size);
         cpu_physical_memory_unmap(elem->in_sg[i].iov_base,
                                   elem->in_sg[i].iov_len,
                                   1, size);
@@ -248,6 +251,9 @@  void virtqueue_fill(VirtQueue *vq, const VirtQueueElement *elem,
     }
 
     for (i = 0; i < elem->out_num; i++)
+        fprintf(stderr, "%s: unmapping hva=%p for length=access_len=%zu, "
+                "is_write=0\n", __FUNCTION__,  elem->out_sg[i].iov_base,
+                elem->out_sg[i].iov_len);
         cpu_physical_memory_unmap(elem->out_sg[i].iov_base,
                                   elem->out_sg[i].iov_len,
                                   0, elem->out_sg[i].iov_len);
@@ -430,6 +436,9 @@  void virtqueue_map_sg(struct iovec *sg, hwaddr *addr,
             error_report("virtio: trying to map MMIO memory");
             exit(1);
         }
+        fprintf(stderr, "%s: mapped gpa=" TARGET_FMT_plx " at hva=%p "
+                "for length=%" HWADDR_PRIu ", is_write=%d\n", __FUNCTION__,
+                addr[i], sg[i].iov_base, len, is_write);
     }
 }