[Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Denis V. Lunev]

There are 2 cases I have spotted so far:
1) IDE ATAPI read processing. Actually this was reported from field
2) QEMU IO hmp command (found during evaluation of (1))

SCSI code checks during access that blk_is_available(). These patches add
same checks on different code paths.

Pls decide whether these patches should go through sub-system trees or via
block tree.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
CC: John Snow <jsnow@redhat.com>
CC: Kevin Wolf <kwolf@redhat.com>
CC: Stefan Hajnoczi <stefanha@redhat.com>

[Qemu-devel] [PATCH 1/2] hmp: block qemu-io command for device without media

[Denis V. Lunev]

In this case blk->bs == NULL and the code will just crash. Emulate error
on that path.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
CC: Kevin Wolf <kwolf@redhat.com>
CC: Stefan Hajnoczi <stefanha@redhat.com>
---
 hmp.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/hmp.c b/hmp.c
index 35a7041824..cfd1d9ab29 100644
--- a/hmp.c
+++ b/hmp.c
@@ -2336,6 +2336,9 @@ void hmp_qemu_io(Monitor *mon, const QDict *qdict)
         } else {
             goto fail;
         }
+    } else if (!blk_is_available(blk)) {
+        error_setg(&err, "No media in the device '%s'", device);
+        goto fail;
     }
 
     aio_context = blk_get_aio_context(blk);
-- 
2.11.0

Re: [Qemu-devel] [PATCH 1/2] hmp: block qemu-io command for device without media

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 463 bytes --]

On Tue, Nov 28, 2017 at 03:10:54PM +0300, Denis V. Lunev wrote:
> In this case blk->bs == NULL and the code will just crash. Emulate error
> on that path.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
> CC: Kevin Wolf <kwolf@redhat.com>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> ---
>  hmp.c | 3 +++
>  1 file changed, 3 insertions(+)

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 455 bytes --]

[Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[Denis V. Lunev]

There is the following crash reported from the field in QEMU 2.9:
    bdrv_inc_in_flight (bs=bs@entry=0x0)
    blk_aio_prwv
    blk_aio_preadv
    ide_buffered_readv
    cd_read_sector
    ide_data_readw
    portio_read
    memory_region_read_accessor
    access_with_adjusted_size
    memory_region_dispatch_read1
    memory_region_dispatch_read
    address_space_read_continue
    address_space_read_full
    address_space_read
    address_space_rw
    kvm_handle_io
    kvm_cpu_exec
    qemu_kvm_cpu_thread_fn
    start_thread
    clone
Indeed, the CDROM device without media has blk->bs == NULL. We should
check that the media is really available for the device like has been done
in SCSI code.

May be the patch adds a bit more check than necessary, but this is not be
the problem. We should always stay on the safe side.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: John Snow <jsnow@redhat.com>
CC: Kevin Wolf <kwolf@redhat.com>
CC: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/ide/atapi.c | 32 ++++++++++++++++++++++++++++----
 hw/ide/core.c  |  4 ++--
 2 files changed, 30 insertions(+), 6 deletions(-)

diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
index c0509c8bf5..fa50c0ccf6 100644
--- a/hw/ide/atapi.c
+++ b/hw/ide/atapi.c
@@ -119,6 +119,11 @@ cd_read_sector_sync(IDEState *s)
 
     trace_cd_read_sector_sync(s->lba);
 
+    if (!blk_is_available(s->blk)) {
+        ret = -ENOMEDIUM;
+        goto fail;
+    }
+
     switch (s->cd_sector_size) {
     case 2048:
         ret = blk_pread(s->blk, (int64_t)s->lba << ATAPI_SECTOR_BITS,
@@ -132,8 +137,8 @@ cd_read_sector_sync(IDEState *s)
         }
         break;
     default:
-        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
-        return -EIO;
+        ret = -EIO;
+        goto fail;
     }
 
     if (ret < 0) {
@@ -145,6 +150,10 @@ cd_read_sector_sync(IDEState *s)
     }
 
     return ret;
+
+fail:
+    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
+    return ret;
 }
 
 static void cd_read_sector_cb(void *opaque, int ret)
@@ -174,9 +183,15 @@ static void cd_read_sector_cb(void *opaque, int ret)
 
 static int cd_read_sector(IDEState *s)
 {
+    int err;
+
     if (s->cd_sector_size != 2048 && s->cd_sector_size != 2352) {
-        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
-        return -EINVAL;
+        err = -EINVAL;
+        goto fail;
+    }
+    if (!blk_is_available(s->blk)) {
+        err = -ENOMEDIUM;
+        goto fail;
     }
 
     s->iov.iov_base = (s->cd_sector_size == 2352) ?
@@ -195,6 +210,10 @@ static int cd_read_sector(IDEState *s)
 
     s->status |= BUSY_STAT;
     return 0;
+
+fail:
+    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
+    return err;
 }
 
 void ide_atapi_cmd_ok(IDEState *s)
@@ -404,6 +423,11 @@ static void ide_atapi_cmd_read_dma_cb(void *opaque, int ret)
         goto eot;
     }
 
+    if (!blk_is_available(s->blk)) {
+        ide_atapi_cmd_read_dma_cb(s, -ENOMEDIUM);
+        return;
+    }
+
     s->io_buffer_index = 0;
     if (s->cd_sector_size == 2352) {
         n = 1;
diff --git a/hw/ide/core.c b/hw/ide/core.c
index 471d0c928b..71780fc9d1 100644
--- a/hw/ide/core.c
+++ b/hw/ide/core.c
@@ -758,7 +758,7 @@ static void ide_sector_read(IDEState *s)
 
     trace_ide_sector_read(sector_num, n);
 
-    if (!ide_sect_range_ok(s, sector_num, n)) {
+    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
         ide_rw_error(s);
         block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
         return;
@@ -1023,7 +1023,7 @@ static void ide_sector_write(IDEState *s)
 
     trace_ide_sector_write(sector_num, n);
 
-    if (!ide_sect_range_ok(s, sector_num, n)) {
+    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
         ide_rw_error(s);
         block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
         return;
-- 
2.11.0

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[Kevin Wolf]

Am 28.11.2017 um 13:10 hat Denis V. Lunev geschrieben:
> There is the following crash reported from the field in QEMU 2.9:
>     bdrv_inc_in_flight (bs=bs@entry=0x0)
>     blk_aio_prwv
>     blk_aio_preadv
>     ide_buffered_readv
>     cd_read_sector
>     ide_data_readw
>     portio_read
>     memory_region_read_accessor
>     access_with_adjusted_size
>     memory_region_dispatch_read1
>     memory_region_dispatch_read
>     address_space_read_continue
>     address_space_read_full
>     address_space_read
>     address_space_rw
>     kvm_handle_io
>     kvm_cpu_exec
>     qemu_kvm_cpu_thread_fn
>     start_thread
>     clone
> Indeed, the CDROM device without media has blk->bs == NULL. We should
> check that the media is really available for the device like has been done
> in SCSI code.
> 
> May be the patch adds a bit more check than necessary, but this is not be
> the problem. We should always stay on the safe side.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: John Snow <jsnow@redhat.com>
> CC: Kevin Wolf <kwolf@redhat.com>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> ---
>  hw/ide/atapi.c | 32 ++++++++++++++++++++++++++++----
>  hw/ide/core.c  |  4 ++--
>  2 files changed, 30 insertions(+), 6 deletions(-)
> 
> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
> index c0509c8bf5..fa50c0ccf6 100644
> --- a/hw/ide/atapi.c
> +++ b/hw/ide/atapi.c
> @@ -119,6 +119,11 @@ cd_read_sector_sync(IDEState *s)
>  
>      trace_cd_read_sector_sync(s->lba);
>  
> +    if (!blk_is_available(s->blk)) {
> +        ret = -ENOMEDIUM;
> +        goto fail;
> +    }
> +
>      switch (s->cd_sector_size) {
>      case 2048:
>          ret = blk_pread(s->blk, (int64_t)s->lba << ATAPI_SECTOR_BITS,
> @@ -132,8 +137,8 @@ cd_read_sector_sync(IDEState *s)
>          }
>          break;
>      default:
> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
> -        return -EIO;
> +        ret = -EIO;
> +        goto fail;
>      }
>  
>      if (ret < 0) {
> @@ -145,6 +150,10 @@ cd_read_sector_sync(IDEState *s)
>      }
>  
>      return ret;
> +
> +fail:
> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
> +    return ret;
>  }

I'm not sure if we can do anything about blk_aio_* in the short time
that we have until 2.11, so maybe we need to fix some callers like IDE
(we won't catch all of them anyway), but at least the synchronous one
should be easily handled in blk_prwv() by returning -ENOMEDIUM before we
access blk_bs(blk).

AIO is trickier because we need to schedule a BH, and blk_drain() can't
execute that BH yet unless we increase bs->in_flight - which we
obviously can't do for a NULL bs->in_flight. The proper solution
involves a separate blk->in_flight counter for the BB and a blk_drain()
implementation that considers it.

Kevin

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[Denis V. Lunev]

On 11/28/2017 07:56 PM, Kevin Wolf wrote:
> Am 28.11.2017 um 13:10 hat Denis V. Lunev geschrieben:
>> There is the following crash reported from the field in QEMU 2.9:
>>     bdrv_inc_in_flight (bs=bs@entry=0x0)
>>     blk_aio_prwv
>>     blk_aio_preadv
>>     ide_buffered_readv
>>     cd_read_sector
>>     ide_data_readw
>>     portio_read
>>     memory_region_read_accessor
>>     access_with_adjusted_size
>>     memory_region_dispatch_read1
>>     memory_region_dispatch_read
>>     address_space_read_continue
>>     address_space_read_full
>>     address_space_read
>>     address_space_rw
>>     kvm_handle_io
>>     kvm_cpu_exec
>>     qemu_kvm_cpu_thread_fn
>>     start_thread
>>     clone
>> Indeed, the CDROM device without media has blk->bs == NULL. We should
>> check that the media is really available for the device like has been done
>> in SCSI code.
>>
>> May be the patch adds a bit more check than necessary, but this is not be
>> the problem. We should always stay on the safe side.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: John Snow <jsnow@redhat.com>
>> CC: Kevin Wolf <kwolf@redhat.com>
>> CC: Stefan Hajnoczi <stefanha@redhat.com>
>> ---
>>  hw/ide/atapi.c | 32 ++++++++++++++++++++++++++++----
>>  hw/ide/core.c  |  4 ++--
>>  2 files changed, 30 insertions(+), 6 deletions(-)
>>
>> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
>> index c0509c8bf5..fa50c0ccf6 100644
>> --- a/hw/ide/atapi.c
>> +++ b/hw/ide/atapi.c
>> @@ -119,6 +119,11 @@ cd_read_sector_sync(IDEState *s)
>>  
>>      trace_cd_read_sector_sync(s->lba);
>>  
>> +    if (!blk_is_available(s->blk)) {
>> +        ret = -ENOMEDIUM;
>> +        goto fail;
>> +    }
>> +
>>      switch (s->cd_sector_size) {
>>      case 2048:
>>          ret = blk_pread(s->blk, (int64_t)s->lba << ATAPI_SECTOR_BITS,
>> @@ -132,8 +137,8 @@ cd_read_sector_sync(IDEState *s)
>>          }
>>          break;
>>      default:
>> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>> -        return -EIO;
>> +        ret = -EIO;
>> +        goto fail;
>>      }
>>  
>>      if (ret < 0) {
>> @@ -145,6 +150,10 @@ cd_read_sector_sync(IDEState *s)
>>      }
>>  
>>      return ret;
>> +
>> +fail:
>> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>> +    return ret;
>>  }
> I'm not sure if we can do anything about blk_aio_* in the short time
> that we have until 2.11, so maybe we need to fix some callers like IDE
> (we won't catch all of them anyway), but at least the synchronous one
> should be easily handled in blk_prwv() by returning -ENOMEDIUM before we
> access blk_bs(blk).
>
> AIO is trickier because we need to schedule a BH, and blk_drain() can't
> execute that BH yet unless we increase bs->in_flight - which we
> obviously can't do for a NULL bs->in_flight. The proper solution
> involves a separate blk->in_flight counter for the BB and a blk_drain()
> implementation that considers it.
>
> Kevin
I have double checked that SCSI code is correct.
AHCI comes through IDE thus with this patch applied
we will be safe at emulation layer.

Den

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[John Snow]

On 11/28/2017 07:10 AM, Denis V. Lunev wrote:
> There is the following crash reported from the field in QEMU 2.9:
>     bdrv_inc_in_flight (bs=bs@entry=0x0)
>     blk_aio_prwv
>     blk_aio_preadv
>     ide_buffered_readv
>     cd_read_sector

Is ide_atapi_cmd_reply_end missing from the call stack here for some
reason? ide_data_readw /should/ have end_transfer_func set to that if it
was processing an ATAPI command; otherwise it shouldn't be able to get
here under normal circumstances...

>     ide_data_readw

How do we get here? ide_is_pio_out ought to be false here; do you know
what command was being processed? Do you have a reproducer?

Knowing both the ATA and ATAPI commands under consideration here would
be helpful.

>     portio_read
>     memory_region_read_accessor
>     access_with_adjusted_size
>     memory_region_dispatch_read1
>     memory_region_dispatch_read
>     address_space_read_continue
>     address_space_read_full
>     address_space_read
>     address_space_rw
>     kvm_handle_io
>     kvm_cpu_exec
>     qemu_kvm_cpu_thread_fn
>     start_thread
>     clone

The thing that looks to be incongruent here is that we appear to be
servicing a ATAPI reply; that reply is either the kind that uses
preformatted data in a buffer, or the kind that buffers a read.

If it buffers a read, it should require CHECK_READY which requires a medium.

If it does not buffer a read, it should not be able to invoke
cd_read_sector or any bdrv function from ide_data_readw.

If it neither serves preformatted data nor buffers a read, it should not
allow ide_data_readw to perform any action at all.

> Indeed, the CDROM device without media has blk->bs == NULL. We should
> check that the media is really available for the device like has been done
> in SCSI code.
> 
> May be the patch adds a bit more check than necessary, but this is not be
> the problem. We should always stay on the safe side.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: John Snow <jsnow@redhat.com>
> CC: Kevin Wolf <kwolf@redhat.com>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> ---
>  hw/ide/atapi.c | 32 ++++++++++++++++++++++++++++----
>  hw/ide/core.c  |  4 ++--
>  2 files changed, 30 insertions(+), 6 deletions(-)
> 
> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
> index c0509c8bf5..fa50c0ccf6 100644
> --- a/hw/ide/atapi.c
> +++ b/hw/ide/atapi.c
> @@ -119,6 +119,11 @@ cd_read_sector_sync(IDEState *s)
>  
>      trace_cd_read_sector_sync(s->lba);
>  
> +    if (!blk_is_available(s->blk)) {
> +        ret = -ENOMEDIUM;
> +        goto fail;
> +    }
> +
>      switch (s->cd_sector_size) {
>      case 2048:
>          ret = blk_pread(s->blk, (int64_t)s->lba << ATAPI_SECTOR_BITS,
> @@ -132,8 +137,8 @@ cd_read_sector_sync(IDEState *s)
>          }
>          break;
>      default:
> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
> -        return -EIO;
> +        ret = -EIO;
> +        goto fail;
>      }
>  
>      if (ret < 0) {
> @@ -145,6 +150,10 @@ cd_read_sector_sync(IDEState *s)
>      }
>  
>      return ret;
> +
> +fail:
> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
> +    return ret;
>  }
>  
>  static void cd_read_sector_cb(void *opaque, int ret)
> @@ -174,9 +183,15 @@ static void cd_read_sector_cb(void *opaque, int ret)
>  
>  static int cd_read_sector(IDEState *s)
>  {
> +    int err;
> +
>      if (s->cd_sector_size != 2048 && s->cd_sector_size != 2352) {
> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
> -        return -EINVAL;
> +        err = -EINVAL;
> +        goto fail;
> +    }
> +    if (!blk_is_available(s->blk)) {
> +        err = -ENOMEDIUM;
> +        goto fail;
>      }
>  
>      s->iov.iov_base = (s->cd_sector_size == 2352) ?
> @@ -195,6 +210,10 @@ static int cd_read_sector(IDEState *s)
>  
>      s->status |= BUSY_STAT;
>      return 0;
> +
> +fail:
> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
> +    return err;
>  }
>  
>  void ide_atapi_cmd_ok(IDEState *s)
> @@ -404,6 +423,11 @@ static void ide_atapi_cmd_read_dma_cb(void *opaque, int ret)
>          goto eot;
>      }
>  
> +    if (!blk_is_available(s->blk)) {
> +        ide_atapi_cmd_read_dma_cb(s, -ENOMEDIUM);
> +        return;
> +    }
> +

I'm not sure this is OK, because it's an error but not setting the sense
code or raising an IRQ; it's only calling ide_set_inactive, so this
might be a problem. Normally the error code from the data read is
handled earlier in the call by ide_handle_rw_error which can set the
proper codes.

>      s->io_buffer_index = 0;
>      if (s->cd_sector_size == 2352) {
>          n = 1;
> diff --git a/hw/ide/core.c b/hw/ide/core.c
> index 471d0c928b..71780fc9d1 100644
> --- a/hw/ide/core.c
> +++ b/hw/ide/core.c
> @@ -758,7 +758,7 @@ static void ide_sector_read(IDEState *s)
>  
>      trace_ide_sector_read(sector_num, n);
>  
> -    if (!ide_sect_range_ok(s, sector_num, n)) {
> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>          ide_rw_error(s);
>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>          return;
> @@ -1023,7 +1023,7 @@ static void ide_sector_write(IDEState *s)
>  
>      trace_ide_sector_write(sector_num, n);
>  
> -    if (!ide_sect_range_ok(s, sector_num, n)) {
> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>          ide_rw_error(s);
>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
>          return;
> 

Since it's not a new regression (this is being reported against 2.9) I
am somewhat hesitant to rush it into 2.11-rc3 without a little more info.

That said, here's a list of the ATAPI commands we service that either
return or CAN return data, but do not enforce CHECK_READY:

    [ 0x03 ] = { cmd_request_sense,                 ALLOW_UA },
    [ 0x12 ] = { cmd_inquiry,                       ALLOW_UA },
    [ 0x46 ] = { cmd_get_configuration,             ALLOW_UA },
    [ 0x4a ] = { cmd_get_event_status_notification, ALLOW_UA },
    [ 0x5a ] = { cmd_mode_sense, /* (10) */         0 },
    [ 0xbd ] = { cmd_mechanism_status,              0 },

These six all invoke ide_atapi_cmd_reply in some way (which allows the
guest to begin reading the reply via PIO mechanisms if DMA is not set):

cmd_request_sense:     ide_atapi_cmd_reply(s, 18, max_len);
cmd_inquiry:           ide_atapi_cmd_reply(s, idx, max_len);
cmd_get_configuration: ide_atapi_cmd_reply(s, len, max_len);
cmd_get_event_status_notification:
                       ide_atapi_cmd_reply(s, used_len, max_len);
cmd_mode_sense:        ide_atapi_cmd_reply(s, 16, max_len);
                       ide_atapi_cmd_reply(s, 24, max_len);
                       ide_atapi_cmd_reply(s, 30, max_len);
cmd_mechanism_status:  ide_atapi_cmd_reply(s, 8, max_len);

ide_atapi_cmd_reply itself sets lba to -1, which should inform
ide_atapi_cmd_reply_end not to attempt to buffer any new data. These
*should* be safe. The reply sizes are also all small enough that they
are almost certainly getting buffered in one single transfer without
attempting to buffer more data.

In the normative PIO case then, reads will consume from this buffer
until empty, then we'll call ide_atapi_cmd_reply_end through
end_transfer_func and hit the end of transfer logic.

I'm not sure I see how this crash is happening; it doesn't look like
this path allows for invoking the block read functions and everything
else is guarded by NONDATA or CHECK_READY.

Unless this is an interesting interaction with ide_atapi_cmd_reply
setting the DRQ bit which may trick the pio read function to allow PIO
reads to come in during this time?

Hypothetically:

cmd_packet sets end_transfer_func to ide_atapi_cmd so it can process
further once that PIO is completed. (The PIO may be emulated
synchronously, in the case of AHCI.) In the true PIO case, it may be
asynchronous.

Now, in the AHCI case, the guest has control back and the CDROM is now
executing a command to, perhaps, read data via DMA. Then,
simultaneously, the guest issues a PIO read and because the DRQ bit is
set for DMA, the PIO read also goes through.

This still requires a media, though... and a very broken guest doing
something naughty on purpose.

I can't quite connect the dots to see how this crash is possible in
general... it'd help to have:

- The ATAPI command being processed at the time
- The IDE command being processed at the time
- s->status

as a minimum, and then perhaps optionally some of the ATAPI loop
variables, like packet_transfer_size, elementary_transfer_size, and
io_buffer_index. Or a reproducer!

Sorry I'm not more help and I wrote too much again :(

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[Denis V. Lunev]

On 11/29/2017 02:50 AM, John Snow wrote:
>
> On 11/28/2017 07:10 AM, Denis V. Lunev wrote:
>> There is the following crash reported from the field in QEMU 2.9:
>>     bdrv_inc_in_flight (bs=bs@entry=0x0)
>>     blk_aio_prwv
>>     blk_aio_preadv
>>     ide_buffered_readv
>>     cd_read_sector
> Is ide_atapi_cmd_reply_end missing from the call stack here for some
> reason? ide_data_readw /should/ have end_transfer_func set to that if it
> was processing an ATAPI command; otherwise it shouldn't be able to get
> here under normal circumstances...
this is my fault. I have lost this line while removing unnecessary into
from callstack. Here if the full one.

(gdb) bt
#0  bdrv_inc_in_flight (bs=bs@entry=0x0) at block/io.c:561
#1  0x000055b224160d37 in blk_aio_prwv (blk=0x55b2265405a0,
    offset=offset@entry=285122560, bytes=2048,
qiov=qiov@entry=0x55b22a31de20,
    co_entry=co_entry@entry=0x55b224160400 <blk_aio_read_entry>,
    flags=flags@entry=0, cb=cb@entry=0x55b224048e00
<ide_buffered_readv_cb>,
    opaque=opaque@entry=0x55b22a31de00) at block/block-backend.c:1151
#2  0x000055b224160db5 in blk_aio_preadv (blk=<optimized out>,
    offset=offset@entry=285122560, qiov=qiov@entry=0x55b22a31de20,
    flags=flags@entry=0, cb=cb@entry=0x55b224048e00
<ide_buffered_readv_cb>,
    opaque=opaque@entry=0x55b22a31de00) at block/block-backend.c:1256
#3  0x000055b22404bd8d in ide_buffered_readv (s=s@entry=0x55b22a712a68,
    sector_num=556880, iov=iov@entry=0x55b22a712d60,
    nb_sectors=nb_sectors@entry=4,
    cb=cb@entry=0x55b22404f2a0 <cd_read_sector_cb>,
    opaque=opaque@entry=0x55b22a712a68) at hw/ide/core.c:637
#4  0x000055b22404e2c1 in cd_read_sector (s=0x55b22a712a68)
    at hw/ide/atapi.c:198
#5  ide_atapi_cmd_reply_end (s=0x55b22a712a68) at hw/ide/atapi.c:272
#6  0x000055b224049704 in ide_data_readw (opaque=<optimized out>,
    addr=<optimized out>) at hw/ide/core.c:2263
#7  0x000055b223edd7f0 in portio_read (opaque=0x55b22a836000, addr=0,
size=2)
    at /usr/src/debug/qemu-2.9.0/ioport.c:180
#8  0x000055b223ee8e3b in memory_region_read_accessor (mr=0x55b22a836000,
    addr=0, value=0x7f843b5be7c0, size=2, shift=0, mask=65535, attrs=...)
    at /usr/src/debug/qemu-2.9.0/memory.c:435
#9  0x000055b223ee6369 in access_with_adjusted_size (addr=addr@entry=0,
    value=value@entry=0x7f843b5be7c0, size=size@entry=2,
    access_size_min=<optimized out>, access_size_max=<optimized out>,
    access=access@entry=0x55b223ee8e10 <memory_region_read_accessor>,
    mr=mr@entry=0x55b22a836000, attrs=attrs@entry=...)
    at /usr/src/debug/qemu-2.9.0/memory.c:592
#10 0x000055b223ee9d36 in memory_region_dispatch_read1 (attrs=..., size=2,
    pval=0x7f843b5be7c0, addr=0, mr=0x55b22a836000)
    at /usr/src/debug/qemu-2.9.0/memory.c:1238
#11 memory_region_dispatch_read (mr=mr@entry=0x55b22a836000,
    addr=addr@entry=0, pval=pval@entry=0x7f843b5be7c0, size=size@entry=2,
    attrs=attrs@entry=...) at /usr/src/debug/qemu-2.9.0/memory.c:1269
#12 0x000055b223e9bdb2 in address_space_read_continue (
    as=as@entry=0x55b2247db8c0 <address_space_io>, addr=addr@entry=496,
---Type <return> to continue, or q <return> to quit---
    attrs=..., attrs@entry=...,
    buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
    len=len@entry=2, addr1=0, l=2, mr=0x55b22a836000)
    at /usr/src/debug/qemu-2.9.0/exec.c:2844
#13 0x000055b223e9be67 in address_space_read_full (
    as=0x55b2247db8c0 <address_space_io>, addr=addr@entry=496, attrs=...,
    buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
    len=2, len@entry=602521191) at /usr/src/debug/qemu-2.9.0/exec.c:2895
#14 0x000055b223e9bfce in address_space_read (len=602521191,
    buf=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>, attrs=...,
    addr=496, as=<optimized out>)
    at /usr/src/debug/qemu-2.9.0/include/exec/memory.h:1718
#15 address_space_rw (as=<optimized out>, addr=addr@entry=496, attrs=...,
    attrs@entry=...,
    buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
    len=len@entry=2, is_write=is_write@entry=false)
    at /usr/src/debug/qemu-2.9.0/exec.c:2909
#16 0x000055b223ee5271 in kvm_handle_io (count=512, size=2,
    direction=<optimized out>, data=<optimized out>, attrs=..., port=496)
    at /usr/src/debug/qemu-2.9.0/kvm-all.c:1828
#17 kvm_cpu_exec (cpu=cpu@entry=0x55b229032000)
    at /usr/src/debug/qemu-2.9.0/kvm-all.c:2058
#18 0x000055b223ed1c22 in qemu_kvm_cpu_thread_fn (arg=0x55b229032000)
    at /usr/src/debug/qemu-2.9.0/cpus.c:1119
#19 0x00007f8443993e25 in start_thread (arg=0x7f843b5bf700)
    at pthread_create.c:308
#20 0x00007f84436c134d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113



>>     ide_data_readw
> How do we get here? ide_is_pio_out ought to be false here; do you know
> what command was being processed? Do you have a reproducer?
>
> Knowing both the ATA and ATAPI commands under consideration here would
> be helpful.
>

if you prefer, I can upload core/binary to some storage.
Here is the state.

(gdb) p *s
$3 = {bus = 0x55b22a7129f0, unit = 0 '\000', drive_kind = IDE_CD,
  cylinders = 0, heads = 0, sectors = 0, chs_trans = 0, nb_sectors =
11588488,
  mult_sectors = 16, identify_set = 1,
  identify_data = "\300\205", '\000' <repeats 18 times>, "MQ0000 1", ' '
<repeats 12 times>, "\003\000\000\002\004\000.2+5    EQUMD DVR-MO", ' '
<repeats 28 times>,
"\000\000\001\000\000\003\000\000\000\000\000\000\a", '\000' <repeats 17
times>,
"\a\000\a\000\003\000\264\000\264\000,\001\264\000\000\000\000\000\036\000\036",
'\000' <repeats 15 times>, "\036", '\000' <repeats 15 times>, "? ",
'\000' <repeats 333 times>, drive_serial = 1,
  drive_serial_str = "QM00001", '\000' <repeats 13 times>,
  drive_model_str = "QEMU DVD-ROM", '\000' <repeats 28 times>, wwn = 0,
  feature = 0 '\000', error = 0 '\000', nsector = 2, sector = 0 '\000',
  lcyl = 0 '\000', hcyl = 8 '\b', hob_feature = 0 '\000',
  hob_nsector = 3 '\003', hob_sector = 0 '\000', hob_lcyl = 0 '\000',
  hob_hcyl = 8 '\b', select = 32 ' ', status = 80 'P', lba48 = 0 '\000',
  blk = 0x55b2265405a0, version = "2.5+\000\000\000\000", events = {
    eject_request = false, new_media = false}, sense_key = 0 '\000',
  asc = 0 '\000', tray_open = false, tray_locked = false,
  cdrom_changed = 0 '\000', packet_transfer_size = 55296,
  elementary_transfer_size = 0, io_buffer_index = 2048, lba = 139220,
  cd_sector_size = 2048, atapi_dma = 0, acct = {bytes = 2048,
    start_time_ns = 433417215764666, type = BLOCK_ACCT_READ}, pio_aiocb
= 0x0,
  iov = {iov_base = 0x55b22a8ae000, iov_len = 2048}, qiov = {
    iov = 0x55b22a712d50, niov = 1, nalloc = -1, size = 2048},
  buffered_requests = {lh_first = 0x0}, io_buffer_offset = 0,
  io_buffer_size = 0, sg = {sg = 0x0, nsg = 0, nalloc = 0, size = 0,
    dev = 0x0, as = 0x0}, req_nb_sectors = 0,
  end_transfer_func = 0x55b22404e190 <ide_atapi_cmd_reply_end>,
  data_ptr = 0x55b22a8ae800 "", data_end = 0x55b22a8ae800 "",
  io_buffer = 0x55b22a8ae000
")8\"\t\031\"\232\vx.\311l\301\270o$\335\025\257\064F\271\rI,R\342\032\315\nԆV\341od\251\023>\024\370\323\060A\256\337\300텋\024\233\201U\221T^\202\303\036\"E%\262\230\367ξ\fW\302\360\277\347\334\022\253\a\025\216\rj\334z\355>)\230/\021\255%a^\306\001\032",

  io_buffer_total_len = 131076, cur_io_buffer_offset = 0,
  cur_io_buffer_len = 0, end_transfer_fn_idx = 0 '\000',
  sector_write_timer = 0x55b22a45d5c0, irq_count = 0, ext_error = 0 '\000',
  mdata_size = 0, mdata_storage = 0x0, media_changed = 0,
  dma_cmd = IDE_DMA_READ, smart_enabled = 1 '\001', smart_autosave = 1
'\001',
  smart_errors = 0, smart_selftest_count = 0 '\000',
---Type <return> to continue, or q <return> to quit---
  smart_selftest_data = 0x55b22a827000 "", ncq_queues = 0}
(gdb)

In general, I can upload the binary and core to the location
you want. Send it to me in person. By the way. I am staring to
receive these crashes in number. 2-3 in a day BUT from one
specific host. This could be important.

>>     portio_read
>>     memory_region_read_accessor
>>     access_with_adjusted_size
>>     memory_region_dispatch_read1
>>     memory_region_dispatch_read
>>     address_space_read_continue
>>     address_space_read_full
>>     address_space_read
>>     address_space_rw
>>     kvm_handle_io
>>     kvm_cpu_exec
>>     qemu_kvm_cpu_thread_fn
>>     start_thread
>>     clone
> The thing that looks to be incongruent here is that we appear to be
> servicing a ATAPI reply; that reply is either the kind that uses
> preformatted data in a buffer, or the kind that buffers a read.
>
> If it buffers a read, it should require CHECK_READY which requires a medium.
>
> If it does not buffer a read, it should not be able to invoke
> cd_read_sector or any bdrv function from ide_data_readw.
>
> If it neither serves preformatted data nor buffers a read, it should not
> allow ide_data_readw to perform any action at all.
the guest could misbehave! This is not a reason to crash.
For example there is a race or something like this. What
if the guest will execute read from the device without
ANY sanity checks? QEMU should not crash. This is the point
and this is the approach taken in the original patch.


>> Indeed, the CDROM device without media has blk->bs == NULL. We should
>> check that the media is really available for the device like has been done
>> in SCSI code.
>>
>> May be the patch adds a bit more check than necessary, but this is not be
>> the problem. We should always stay on the safe side.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: John Snow <jsnow@redhat.com>
>> CC: Kevin Wolf <kwolf@redhat.com>
>> CC: Stefan Hajnoczi <stefanha@redhat.com>
>> ---
>>  hw/ide/atapi.c | 32 ++++++++++++++++++++++++++++----
>>  hw/ide/core.c  |  4 ++--
>>  2 files changed, 30 insertions(+), 6 deletions(-)
>>
>> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
>> index c0509c8bf5..fa50c0ccf6 100644
>> --- a/hw/ide/atapi.c
>> +++ b/hw/ide/atapi.c
>> @@ -119,6 +119,11 @@ cd_read_sector_sync(IDEState *s)
>>  
>>      trace_cd_read_sector_sync(s->lba);
>>  
>> +    if (!blk_is_available(s->blk)) {
>> +        ret = -ENOMEDIUM;
>> +        goto fail;
>> +    }
>> +
>>      switch (s->cd_sector_size) {
>>      case 2048:
>>          ret = blk_pread(s->blk, (int64_t)s->lba << ATAPI_SECTOR_BITS,
>> @@ -132,8 +137,8 @@ cd_read_sector_sync(IDEState *s)
>>          }
>>          break;
>>      default:
>> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>> -        return -EIO;
>> +        ret = -EIO;
>> +        goto fail;
>>      }
>>  
>>      if (ret < 0) {
>> @@ -145,6 +150,10 @@ cd_read_sector_sync(IDEState *s)
>>      }
>>  
>>      return ret;
>> +
>> +fail:
>> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>> +    return ret;
>>  }
>>  
>>  static void cd_read_sector_cb(void *opaque, int ret)
>> @@ -174,9 +183,15 @@ static void cd_read_sector_cb(void *opaque, int ret)
>>  
>>  static int cd_read_sector(IDEState *s)
>>  {
>> +    int err;
>> +
>>      if (s->cd_sector_size != 2048 && s->cd_sector_size != 2352) {
>> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>> -        return -EINVAL;
>> +        err = -EINVAL;
>> +        goto fail;
>> +    }
>> +    if (!blk_is_available(s->blk)) {
>> +        err = -ENOMEDIUM;
>> +        goto fail;
>>      }
>>  
>>      s->iov.iov_base = (s->cd_sector_size == 2352) ?
>> @@ -195,6 +210,10 @@ static int cd_read_sector(IDEState *s)
>>  
>>      s->status |= BUSY_STAT;
>>      return 0;
>> +
>> +fail:
>> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>> +    return err;
>>  }
>>  
>>  void ide_atapi_cmd_ok(IDEState *s)
>> @@ -404,6 +423,11 @@ static void ide_atapi_cmd_read_dma_cb(void *opaque, int ret)
>>          goto eot;
>>      }
>>  
>> +    if (!blk_is_available(s->blk)) {
>> +        ide_atapi_cmd_read_dma_cb(s, -ENOMEDIUM);
>> +        return;
>> +    }
>> +
> I'm not sure this is OK, because it's an error but not setting the sense
> code or raising an IRQ; it's only calling ide_set_inactive, so this
> might be a problem. Normally the error code from the data read is
> handled earlier in the call by ide_handle_rw_error which can set the
> proper codes.
>
this follows the approach used by the error handling in this call.
I this code is not made worse. We can hit to the same processing
with the different error upper.

>>      s->io_buffer_index = 0;
>>      if (s->cd_sector_size == 2352) {
>>          n = 1;
>> diff --git a/hw/ide/core.c b/hw/ide/core.c
>> index 471d0c928b..71780fc9d1 100644
>> --- a/hw/ide/core.c
>> +++ b/hw/ide/core.c
>> @@ -758,7 +758,7 @@ static void ide_sector_read(IDEState *s)
>>  
>>      trace_ide_sector_read(sector_num, n);
>>  
>> -    if (!ide_sect_range_ok(s, sector_num, n)) {
>> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>>          ide_rw_error(s);
>>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>          return;
>> @@ -1023,7 +1023,7 @@ static void ide_sector_write(IDEState *s)
>>  
>>      trace_ide_sector_write(sector_num, n);
>>  
>> -    if (!ide_sect_range_ok(s, sector_num, n)) {
>> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>>          ide_rw_error(s);
>>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
>>          return;
>>
> Since it's not a new regression (this is being reported against 2.9) I
> am somewhat hesitant to rush it into 2.11-rc3 without a little more info.
>
> That said, here's a list of the ATAPI commands we service that either
> return or CAN return data, but do not enforce CHECK_READY:
>
>     [ 0x03 ] = { cmd_request_sense,                 ALLOW_UA },
>     [ 0x12 ] = { cmd_inquiry,                       ALLOW_UA },
>     [ 0x46 ] = { cmd_get_configuration,             ALLOW_UA },
>     [ 0x4a ] = { cmd_get_event_status_notification, ALLOW_UA },
>     [ 0x5a ] = { cmd_mode_sense, /* (10) */         0 },
>     [ 0xbd ] = { cmd_mechanism_status,              0 },
>
> These six all invoke ide_atapi_cmd_reply in some way (which allows the
> guest to begin reading the reply via PIO mechanisms if DMA is not set):
>
> cmd_request_sense:     ide_atapi_cmd_reply(s, 18, max_len);
> cmd_inquiry:           ide_atapi_cmd_reply(s, idx, max_len);
> cmd_get_configuration: ide_atapi_cmd_reply(s, len, max_len);
> cmd_get_event_status_notification:
>                        ide_atapi_cmd_reply(s, used_len, max_len);
> cmd_mode_sense:        ide_atapi_cmd_reply(s, 16, max_len);
>                        ide_atapi_cmd_reply(s, 24, max_len);
>                        ide_atapi_cmd_reply(s, 30, max_len);
> cmd_mechanism_status:  ide_atapi_cmd_reply(s, 8, max_len);
>
> ide_atapi_cmd_reply itself sets lba to -1, which should inform
> ide_atapi_cmd_reply_end not to attempt to buffer any new data. These
> *should* be safe. The reply sizes are also all small enough that they
> are almost certainly getting buffered in one single transfer without
> attempting to buffer more data.
>
> In the normative PIO case then, reads will consume from this buffer
> until empty, then we'll call ide_atapi_cmd_reply_end through
> end_transfer_func and hit the end of transfer logic.
>
> I'm not sure I see how this crash is happening; it doesn't look like
> this path allows for invoking the block read functions and everything
> else is guarded by NONDATA or CHECK_READY.
>
> Unless this is an interesting interaction with ide_atapi_cmd_reply
> setting the DRQ bit which may trick the pio read function to allow PIO
> reads to come in during this time?
>
> Hypothetically:
>
> cmd_packet sets end_transfer_func to ide_atapi_cmd so it can process
> further once that PIO is completed. (The PIO may be emulated
> synchronously, in the case of AHCI.) In the true PIO case, it may be
> asynchronous.
>
> Now, in the AHCI case, the guest has control back and the CDROM is now
> executing a command to, perhaps, read data via DMA. Then,
> simultaneously, the guest issues a PIO read and because the DRQ bit is
> set for DMA, the PIO read also goes through.
>
> This still requires a media, though... and a very broken guest doing
> something naughty on purpose.
>
> I can't quite connect the dots to see how this crash is possible in
> general... it'd help to have:
>
> - The ATAPI command being processed at the time
> - The IDE command being processed at the time
> - s->status
>
> as a minimum, and then perhaps optionally some of the ATAPI loop
> variables, like packet_transfer_size, elementary_transfer_size, and
> io_buffer_index. Or a reproducer!
>
> Sorry I'm not more help and I wrote too much again :(
imho this does not matter. Once again - the guest can misbehave.
This is not the reason to crash. You can consider this as CVE.

Den

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[John Snow]

Hi Den, the long email about IDE stuff:

On 11/30/2017 07:01 AM, Denis V. Lunev wrote:
> On 11/29/2017 02:50 AM, John Snow wrote:
>>
>> On 11/28/2017 07:10 AM, Denis V. Lunev wrote:
>>> There is the following crash reported from the field in QEMU 2.9:
>>>     bdrv_inc_in_flight (bs=bs@entry=0x0)
>>>     blk_aio_prwv
>>>     blk_aio_preadv
>>>     ide_buffered_readv
>>>     cd_read_sector
>> Is ide_atapi_cmd_reply_end missing from the call stack here for some
>> reason? ide_data_readw /should/ have end_transfer_func set to that if it
>> was processing an ATAPI command; otherwise it shouldn't be able to get
>> here under normal circumstances...
> this is my fault. I have lost this line while removing unnecessary into
> from callstack. Here if the full one.
> 

Well, at least we're back on terra firma here.

I'm going to talk myself through what the problem looks like here, and I
have some questions for you at the bottom of the email, so you can just
skim if you're not interested in the details.

> (gdb) bt
> #0  bdrv_inc_in_flight (bs=bs@entry=0x0) at block/io.c:561
> #1  0x000055b224160d37 in blk_aio_prwv (blk=0x55b2265405a0,
>     offset=offset@entry=285122560, bytes=2048,
> qiov=qiov@entry=0x55b22a31de20,
>     co_entry=co_entry@entry=0x55b224160400 <blk_aio_read_entry>,
>     flags=flags@entry=0, cb=cb@entry=0x55b224048e00
> <ide_buffered_readv_cb>,
>     opaque=opaque@entry=0x55b22a31de00) at block/block-backend.c:1151
> #2  0x000055b224160db5 in blk_aio_preadv (blk=<optimized out>,
>     offset=offset@entry=285122560, qiov=qiov@entry=0x55b22a31de20,
>     flags=flags@entry=0, cb=cb@entry=0x55b224048e00
> <ide_buffered_readv_cb>,
>     opaque=opaque@entry=0x55b22a31de00) at block/block-backend.c:1256
> #3  0x000055b22404bd8d in ide_buffered_readv (s=s@entry=0x55b22a712a68,
>     sector_num=556880, iov=iov@entry=0x55b22a712d60,
>     nb_sectors=nb_sectors@entry=4,
>     cb=cb@entry=0x55b22404f2a0 <cd_read_sector_cb>,
>     opaque=opaque@entry=0x55b22a712a68) at hw/ide/core.c:637
> #4  0x000055b22404e2c1 in cd_read_sector (s=0x55b22a712a68)
>     at hw/ide/atapi.c:198
> #5  ide_atapi_cmd_reply_end (s=0x55b22a712a68) at hw/ide/atapi.c:272
> #6  0x000055b224049704 in ide_data_readw (opaque=<optimized out>,
>     addr=<optimized out>) at hw/ide/core.c:2263
> #7  0x000055b223edd7f0 in portio_read (opaque=0x55b22a836000, addr=0,
> size=2)
>     at /usr/src/debug/qemu-2.9.0/ioport.c:180
> #8  0x000055b223ee8e3b in memory_region_read_accessor (mr=0x55b22a836000,
>     addr=0, value=0x7f843b5be7c0, size=2, shift=0, mask=65535, attrs=...)
>     at /usr/src/debug/qemu-2.9.0/memory.c:435
> #9  0x000055b223ee6369 in access_with_adjusted_size (addr=addr@entry=0,
>     value=value@entry=0x7f843b5be7c0, size=size@entry=2,
>     access_size_min=<optimized out>, access_size_max=<optimized out>,
>     access=access@entry=0x55b223ee8e10 <memory_region_read_accessor>,
>     mr=mr@entry=0x55b22a836000, attrs=attrs@entry=...)
>     at /usr/src/debug/qemu-2.9.0/memory.c:592
> #10 0x000055b223ee9d36 in memory_region_dispatch_read1 (attrs=..., size=2,
>     pval=0x7f843b5be7c0, addr=0, mr=0x55b22a836000)
>     at /usr/src/debug/qemu-2.9.0/memory.c:1238
> #11 memory_region_dispatch_read (mr=mr@entry=0x55b22a836000,
>     addr=addr@entry=0, pval=pval@entry=0x7f843b5be7c0, size=size@entry=2,
>     attrs=attrs@entry=...) at /usr/src/debug/qemu-2.9.0/memory.c:1269
> #12 0x000055b223e9bdb2 in address_space_read_continue (
>     as=as@entry=0x55b2247db8c0 <address_space_io>, addr=addr@entry=496,
> ---Type <return> to continue, or q <return> to quit---
>     attrs=..., attrs@entry=...,
>     buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
>     len=len@entry=2, addr1=0, l=2, mr=0x55b22a836000)
>     at /usr/src/debug/qemu-2.9.0/exec.c:2844
> #13 0x000055b223e9be67 in address_space_read_full (
>     as=0x55b2247db8c0 <address_space_io>, addr=addr@entry=496, attrs=...,
>     buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
>     len=2, len@entry=602521191) at /usr/src/debug/qemu-2.9.0/exec.c:2895
> #14 0x000055b223e9bfce in address_space_read (len=602521191,
>     buf=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>, attrs=...,
>     addr=496, as=<optimized out>)
>     at /usr/src/debug/qemu-2.9.0/include/exec/memory.h:1718
> #15 address_space_rw (as=<optimized out>, addr=addr@entry=496, attrs=...,
>     attrs@entry=...,
>     buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
>     len=len@entry=2, is_write=is_write@entry=false)
>     at /usr/src/debug/qemu-2.9.0/exec.c:2909
> #16 0x000055b223ee5271 in kvm_handle_io (count=512, size=2,
>     direction=<optimized out>, data=<optimized out>, attrs=..., port=496)
>     at /usr/src/debug/qemu-2.9.0/kvm-all.c:1828
> #17 kvm_cpu_exec (cpu=cpu@entry=0x55b229032000)
>     at /usr/src/debug/qemu-2.9.0/kvm-all.c:2058
> #18 0x000055b223ed1c22 in qemu_kvm_cpu_thread_fn (arg=0x55b229032000)
>     at /usr/src/debug/qemu-2.9.0/cpus.c:1119
> #19 0x00007f8443993e25 in start_thread (arg=0x7f843b5bf700)
>     at pthread_create.c:308
> #20 0x00007f84436c134d in clone ()
>     at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
> 
> 
> 
>>>     ide_data_readw
>> How do we get here? ide_is_pio_out ought to be false here; do you know
>> what command was being processed? Do you have a reproducer?
>>
>> Knowing both the ATA and ATAPI commands under consideration here would
>> be helpful.
>>
> 
> if you prefer, I can upload core/binary to some storage.
> Here is the state.
> 

This might be helpful for me to poke around at, but unfortunately it
looks like I can't see the ATAPI command that was being processed from
the trace given. I don't think there's a way for me to retrieve it from
a core, either.

> (gdb) p *s
> $3 = {bus = 0x55b22a7129f0, unit = 0 '\000', drive_kind = IDE_CD,
>   cylinders = 0, heads = 0, sectors = 0, chs_trans = 0, nb_sectors =
> 11588488,
>   mult_sectors = 16, identify_set = 1,
>   identify_data = "\300\205", '\000' <repeats 18 times>, "MQ0000 1", ' '
> <repeats 12 times>, "\003\000\000\002\004\000.2+5    EQUMD DVR-MO", ' '
> <repeats 28 times>,
> "\000\000\001\000\000\003\000\000\000\000\000\000\a", '\000' <repeats 17
> times>,
> "\a\000\a\000\003\000\264\000\264\000,\001\264\000\000\000\000\000\036\000\036",
> '\000' <repeats 15 times>, "\036", '\000' <repeats 15 times>, "? ",
> '\000' <repeats 333 times>, drive_serial = 1,
>   drive_serial_str = "QM00001", '\000' <repeats 13 times>,
>   drive_model_str = "QEMU DVD-ROM", '\000' <repeats 28 times>, wwn = 0,
>   feature = 0 '\000', error = 0 '\000', nsector = 2, sector = 0 '\000',
>   lcyl = 0 '\000', hcyl = 8 '\b', hob_feature = 0 '\000',
>   hob_nsector = 3 '\003', hob_sector = 0 '\000', hob_lcyl = 0 '\000',
>   hob_hcyl = 8 '\b', select = 32 ' ', status = 80 'P', lba48 = 0 '\000',

status = BUSY_STAT
nsector = ATAPI_INT_REASON_IO (set in ide_atapi_cmd_reply_end)
byte_count_limit = 2048 (hcyl << 8)

>   blk = 0x55b2265405a0, version = "2.5+\000\000\000\000", events = {
>     eject_request = false, new_media = false}, sense_key = 0 '\000',
>   asc = 0 '\000', tray_open = false, tray_locked = false,
>   cdrom_changed = 0 '\000', packet_transfer_size = 55296,
>   elementary_transfer_size = 0, io_buffer_index = 2048, lba = 139220,

packet_transfer_size = 55296, (27 cd sectors)
elementary_transfer_size = 0,
io_buffer_index = 2048,
lba = 139220, or 0x021fd4


This is either an initial read request, or a rebuffering.
In the normative case, initial reads look like this:

IDE:
ide_ioport_write
  ide_exec_cmd (0xA0)
    cmd_packet
      ide_transfer_start
        s->end_transfer_func = ide_atapi_cmd
        [data_ptr and data_end set to meaningful values]
[Return to guest, await PIO write of scsi cdb]
ide_data_writew
  ide_atapi_cmd
    [soft error if !blk->bs]
    cmd_read_cd
      ide_atapi_cmd_read
        ide_atapi_cmd_read_pio
          ide_atapi_cmd_reply_end
            cd_read_sector
              [segv if !blk->bs]

AHCI:
handle_reg_h2d_fis
  [scsi CDB is copied into s->io_buffer]
  ide_exec_cmd
    cmd_packet
      ide_transfer_start
        [data_ptr and data_end set to transfer scsi cdb]
          ahci_start_transfer
            [shortcut, no transfer]
            s->data_ptr set to s->data_end [*]
              ide_atapi_cmd

* (but data_end likely is still != s->io_buffer)

from here the callback is the same as above: we'll wind up at
cd_read_sector. Neither of these cases match your traceback.

If it was the initial buffering, it would have occurred synchronously
with receipt of the SCSI CDB, but your traces place it as a consequence
of an attempt to read data, so that makes me suspect it's a rebuffering
attempt, and the data in s->io_buffer is... cd data? I guess? did you
have a CD in here at one point?

>   cd_sector_size = 2048, atapi_dma = 0, acct = {bytes = 2048,

So we're using PIO paths when applicable. The s->feature register being
0 seems to agree.

>     start_time_ns = 433417215764666, type = BLOCK_ACCT_READ}, pio_aiocb
> = 0x0,
>   iov = {iov_base = 0x55b22a8ae000, iov_len = 2048}, qiov = {
>     iov = 0x55b22a712d50, niov = 1, nalloc = -1, size = 2048},
>   buffered_requests = {lh_first = 0x0}, io_buffer_offset = 0,
>   io_buffer_size = 0, sg = {sg = 0x0, nsg = 0, nalloc = 0, size = 0,
>     dev = 0x0, as = 0x0}, req_nb_sectors = 0,
>   end_transfer_func = 0x55b22404e190 <ide_atapi_cmd_reply_end>,
>   data_ptr = 0x55b22a8ae800 "", data_end = 0x55b22a8ae800 "",
>   io_buffer = 0x55b22a8ae000

s->data_ptr  = 0x55b22a8ae800
s->data_end  = 0x55b22a8ae800
s->io_buffer = 0x55b22a8ae000
s->io_buffer_offset = 0

Uh, hm. This does not look like an in-progress PIO transfer of any kind...

This says to me that ide_dummy_transfer_stop was called at some point
and nothing has started up in its place.

This seems to conflict with the trace, which looks like a rebuffering.
This looks like... undefined behavior entirely. I am not sure I have a
good guess as to what's happening.

> ")8\"\t\031\"\232\vx.\311l\301\270o$\335\025\257\064F\271\rI,R\342\032\315\nԆV\341od\251\023>\024\370\323\060A\256\337\300텋\024\233\201U\221T^\202\303\036\"E%\262\230\367ξ\fW\302\360\277\347\334\022\253\a\025\216\rj\334z\355>)\230/\021\255%a^\306\001\032",

... hmm

0x29 56 34 09 19

0x29 is... almost a read command (0x28) but it isn't. 0x29 shouldn't map
to anything, actually. So this must be data we've buffered, or something
left over from god knows what.

> 
>   io_buffer_total_len = 131076, cur_io_buffer_offset = 0,
>   cur_io_buffer_len = 0, end_transfer_fn_idx = 0 '\000',
>   sector_write_timer = 0x55b22a45d5c0, irq_count = 0, ext_error = 0 '\000',
>   mdata_size = 0, mdata_storage = 0x0, media_changed = 0,
>   dma_cmd = IDE_DMA_READ, smart_enabled = 1 '\001', smart_autosave = 1
> '\001',
>   smart_errors = 0, smart_selftest_count = 0 '\000',
> ---Type <return> to continue, or q <return> to quit---
>   smart_selftest_data = 0x55b22a827000 "", ncq_queues = 0}
> (gdb)
> 
> In general, I can upload the binary and core to the location
> you want. Send it to me in person. By the way. I am staring to
> receive these crashes in number. 2-3 in a day BUT from one
> specific host. This could be important.
> 
>>>     portio_read
>>>     memory_region_read_accessor
>>>     access_with_adjusted_size
>>>     memory_region_dispatch_read1
>>>     memory_region_dispatch_read
>>>     address_space_read_continue
>>>     address_space_read_full
>>>     address_space_read
>>>     address_space_rw
>>>     kvm_handle_io
>>>     kvm_cpu_exec
>>>     qemu_kvm_cpu_thread_fn
>>>     start_thread
>>>     clone
>> The thing that looks to be incongruent here is that we appear to be
>> servicing a ATAPI reply; that reply is either the kind that uses
>> preformatted data in a buffer, or the kind that buffers a read.
>>
>> If it buffers a read, it should require CHECK_READY which requires a medium.
>>
>> If it does not buffer a read, it should not be able to invoke
>> cd_read_sector or any bdrv function from ide_data_readw.
>>
>> If it neither serves preformatted data nor buffers a read, it should not
>> allow ide_data_readw to perform any action at all.
> the guest could misbehave! This is not a reason to crash.
> For example there is a race or something like this. What
> if the guest will execute read from the device without
> ANY sanity checks? QEMU should not crash. This is the point
> and this is the approach taken in the original patch.
> 

The stuff quoted above isn't participatory, it's mandatory. I don't know
how we're bypassing CHECK_READY. I want to understand what's happening
before I pepper in sanity checks.

in 2.9.0, you have this code:

    if ((cmd->flags & CHECK_READY) &&
        (!media_present(s) || !blk_is_inserted(s->blk)))
    {
        ide_atapi_cmd_error(s, NOT_READY, ASC_MEDIUM_NOT_PRESENT);
        return;
    }

with media_present defined as:

static inline int media_present(IDEState *s)
{
    return !s->tray_open && s->nb_sectors > 0;
}

... however, from your gdb output, we do have:

tray_open = false
nb_sectors = 11588488

but blk_is_inserted is still going to check for the presence of 'bs'
attached to the Block Backend, so this check should still prevent us
from executing a read command out of the gate.

Is the guest executing a read and then are we racing with the removal of
the bds? Do you expect a CD to be inserted on this guest?

nb_sectors I would expect to be 0; based on ide_cd_change_cb:

    blk_get_geometry(s->blk, &nb_sectors);

this should set nb_sectors to 0 if there's no blk->bs.

I'm sort of lost, I can't really easily construct what exactly happened
here.

> 
>>> Indeed, the CDROM device without media has blk->bs == NULL. We should
>>> check that the media is really available for the device like has been done
>>> in SCSI code.
>>>
>>> May be the patch adds a bit more check than necessary, but this is not be
>>> the problem. We should always stay on the safe side.
>>>
>>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>>> CC: John Snow <jsnow@redhat.com>
>>> CC: Kevin Wolf <kwolf@redhat.com>
>>> CC: Stefan Hajnoczi <stefanha@redhat.com>
>>> ---
>>>  hw/ide/atapi.c | 32 ++++++++++++++++++++++++++++----
>>>  hw/ide/core.c  |  4 ++--
>>>  2 files changed, 30 insertions(+), 6 deletions(-)
>>>
>>> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
>>> index c0509c8bf5..fa50c0ccf6 100644
>>> --- a/hw/ide/atapi.c
>>> +++ b/hw/ide/atapi.c
>>> @@ -119,6 +119,11 @@ cd_read_sector_sync(IDEState *s)
>>>  
>>>      trace_cd_read_sector_sync(s->lba);
>>>  
>>> +    if (!blk_is_available(s->blk)) {
>>> +        ret = -ENOMEDIUM;
>>> +        goto fail;
>>> +    }
>>> +
>>>      switch (s->cd_sector_size) {
>>>      case 2048:
>>>          ret = blk_pread(s->blk, (int64_t)s->lba << ATAPI_SECTOR_BITS,
>>> @@ -132,8 +137,8 @@ cd_read_sector_sync(IDEState *s)
>>>          }
>>>          break;
>>>      default:
>>> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>> -        return -EIO;
>>> +        ret = -EIO;
>>> +        goto fail;
>>>      }
>>>  
>>>      if (ret < 0) {
>>> @@ -145,6 +150,10 @@ cd_read_sector_sync(IDEState *s)
>>>      }
>>>  
>>>      return ret;
>>> +
>>> +fail:
>>> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>> +    return ret;
>>>  }
>>>  
>>>  static void cd_read_sector_cb(void *opaque, int ret)
>>> @@ -174,9 +183,15 @@ static void cd_read_sector_cb(void *opaque, int ret)
>>>  
>>>  static int cd_read_sector(IDEState *s)
>>>  {
>>> +    int err;
>>> +
>>>      if (s->cd_sector_size != 2048 && s->cd_sector_size != 2352) {
>>> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>> -        return -EINVAL;
>>> +        err = -EINVAL;
>>> +        goto fail;
>>> +    }
>>> +    if (!blk_is_available(s->blk)) {
>>> +        err = -ENOMEDIUM;
>>> +        goto fail;
>>>      }
>>>  
>>>      s->iov.iov_base = (s->cd_sector_size == 2352) ?
>>> @@ -195,6 +210,10 @@ static int cd_read_sector(IDEState *s)
>>>  
>>>      s->status |= BUSY_STAT;
>>>      return 0;
>>> +
>>> +fail:
>>> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>> +    return err;
>>>  }
>>>  
>>>  void ide_atapi_cmd_ok(IDEState *s)
>>> @@ -404,6 +423,11 @@ static void ide_atapi_cmd_read_dma_cb(void *opaque, int ret)
>>>          goto eot;
>>>      }
>>>  
>>> +    if (!blk_is_available(s->blk)) {
>>> +        ide_atapi_cmd_read_dma_cb(s, -ENOMEDIUM);
>>> +        return;
>>> +    }
>>> +
>> I'm not sure this is OK, because it's an error but not setting the sense
>> code or raising an IRQ; it's only calling ide_set_inactive, so this
>> might be a problem. Normally the error code from the data read is
>> handled earlier in the call by ide_handle_rw_error which can set the
>> proper codes.
>>
> this follows the approach used by the error handling in this call.
> I this code is not made worse. We can hit to the same processing
> with the different error upper.
> 
>>>      s->io_buffer_index = 0;
>>>      if (s->cd_sector_size == 2352) {
>>>          n = 1;
>>> diff --git a/hw/ide/core.c b/hw/ide/core.c
>>> index 471d0c928b..71780fc9d1 100644
>>> --- a/hw/ide/core.c
>>> +++ b/hw/ide/core.c
>>> @@ -758,7 +758,7 @@ static void ide_sector_read(IDEState *s)
>>>  
>>>      trace_ide_sector_read(sector_num, n);
>>>  
>>> -    if (!ide_sect_range_ok(s, sector_num, n)) {
>>> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>>>          ide_rw_error(s);
>>>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>>          return;
>>> @@ -1023,7 +1023,7 @@ static void ide_sector_write(IDEState *s)
>>>  
>>>      trace_ide_sector_write(sector_num, n);
>>>  
>>> -    if (!ide_sect_range_ok(s, sector_num, n)) {
>>> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>>>          ide_rw_error(s);
>>>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
>>>          return;
>>>
>> Since it's not a new regression (this is being reported against 2.9) I
>> am somewhat hesitant to rush it into 2.11-rc3 without a little more info.
>>
>> That said, here's a list of the ATAPI commands we service that either
>> return or CAN return data, but do not enforce CHECK_READY:
>>
>>     [ 0x03 ] = { cmd_request_sense,                 ALLOW_UA },
>>     [ 0x12 ] = { cmd_inquiry,                       ALLOW_UA },
>>     [ 0x46 ] = { cmd_get_configuration,             ALLOW_UA },
>>     [ 0x4a ] = { cmd_get_event_status_notification, ALLOW_UA },
>>     [ 0x5a ] = { cmd_mode_sense, /* (10) */         0 },
>>     [ 0xbd ] = { cmd_mechanism_status,              0 },
>>
>> These six all invoke ide_atapi_cmd_reply in some way (which allows the
>> guest to begin reading the reply via PIO mechanisms if DMA is not set):
>>
>> cmd_request_sense:     ide_atapi_cmd_reply(s, 18, max_len);
>> cmd_inquiry:           ide_atapi_cmd_reply(s, idx, max_len);
>> cmd_get_configuration: ide_atapi_cmd_reply(s, len, max_len);
>> cmd_get_event_status_notification:
>>                        ide_atapi_cmd_reply(s, used_len, max_len);
>> cmd_mode_sense:        ide_atapi_cmd_reply(s, 16, max_len);
>>                        ide_atapi_cmd_reply(s, 24, max_len);
>>                        ide_atapi_cmd_reply(s, 30, max_len);
>> cmd_mechanism_status:  ide_atapi_cmd_reply(s, 8, max_len);
>>
>> ide_atapi_cmd_reply itself sets lba to -1, which should inform
>> ide_atapi_cmd_reply_end not to attempt to buffer any new data. These
>> *should* be safe. The reply sizes are also all small enough that they
>> are almost certainly getting buffered in one single transfer without
>> attempting to buffer more data.
>>
>> In the normative PIO case then, reads will consume from this buffer
>> until empty, then we'll call ide_atapi_cmd_reply_end through
>> end_transfer_func and hit the end of transfer logic.
>>
>> I'm not sure I see how this crash is happening; it doesn't look like
>> this path allows for invoking the block read functions and everything
>> else is guarded by NONDATA or CHECK_READY.
>>
>> Unless this is an interesting interaction with ide_atapi_cmd_reply
>> setting the DRQ bit which may trick the pio read function to allow PIO
>> reads to come in during this time?
>>
>> Hypothetically:
>>
>> cmd_packet sets end_transfer_func to ide_atapi_cmd so it can process
>> further once that PIO is completed. (The PIO may be emulated
>> synchronously, in the case of AHCI.) In the true PIO case, it may be
>> asynchronous.
>>
>> Now, in the AHCI case, the guest has control back and the CDROM is now
>> executing a command to, perhaps, read data via DMA. Then,
>> simultaneously, the guest issues a PIO read and because the DRQ bit is
>> set for DMA, the PIO read also goes through.
>>
>> This still requires a media, though... and a very broken guest doing
>> something naughty on purpose.
>>
>> I can't quite connect the dots to see how this crash is possible in
>> general... it'd help to have:
>>
>> - The ATAPI command being processed at the time
>> - The IDE command being processed at the time
>> - s->status
>>
>> as a minimum, and then perhaps optionally some of the ATAPI loop
>> variables, like packet_transfer_size, elementary_transfer_size, and
>> io_buffer_index. Or a reproducer!
>>
>> Sorry I'm not more help and I wrote too much again :(
> imho this does not matter. Once again - the guest can misbehave.

I never said that if a guest acting out of spec was the problem I
wouldn't fix it. I just want to find the root cause.

If this has been broken since 2.9, 2.11-rc3 is too late for a bandaid
applied to something I can't diagnose. Let's discuss this for 2.12 and I
will keep trying to figure out what the root cause is.


Some questions for you:

(1) Is the guest Linux? Do we know why this one machine might be
tripping up QEMU? (Is it running a fuzzer, a weird OS, etc...?)
(2) Does the VM actually have a CDROM inserted at some point? Is it
possible we're racing on some kind of eject or graph manipulation failure?
(3) Is this using AHCI or IDE?


If I can't figure it out within a week or so from here I'll just check
in the band-aid with some /* FIXME */ comments attached.

--js

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[Denis V. Lunev]

On 12/13/2017 02:40 AM, John Snow wrote:
> Hi Den, the long email about IDE stuff:
>
> On 11/30/2017 07:01 AM, Denis V. Lunev wrote:
>> On 11/29/2017 02:50 AM, John Snow wrote:
>>> On 11/28/2017 07:10 AM, Denis V. Lunev wrote:
>>>> There is the following crash reported from the field in QEMU 2.9:
>>>>     bdrv_inc_in_flight (bs=bs@entry=0x0)
>>>>     blk_aio_prwv
>>>>     blk_aio_preadv
>>>>     ide_buffered_readv
>>>>     cd_read_sector
>>> Is ide_atapi_cmd_reply_end missing from the call stack here for some
>>> reason? ide_data_readw /should/ have end_transfer_func set to that if it
>>> was processing an ATAPI command; otherwise it shouldn't be able to get
>>> here under normal circumstances...
>> this is my fault. I have lost this line while removing unnecessary into
>> from callstack. Here if the full one.
>>
> Well, at least we're back on terra firma here.
>
> I'm going to talk myself through what the problem looks like here, and I
> have some questions for you at the bottom of the email, so you can just
> skim if you're not interested in the details.
>
>> (gdb) bt
>> #0  bdrv_inc_in_flight (bs=bs@entry=0x0) at block/io.c:561
>> #1  0x000055b224160d37 in blk_aio_prwv (blk=0x55b2265405a0,
>>     offset=offset@entry=285122560, bytes=2048,
>> qiov=qiov@entry=0x55b22a31de20,
>>     co_entry=co_entry@entry=0x55b224160400 <blk_aio_read_entry>,
>>     flags=flags@entry=0, cb=cb@entry=0x55b224048e00
>> <ide_buffered_readv_cb>,
>>     opaque=opaque@entry=0x55b22a31de00) at block/block-backend.c:1151
>> #2  0x000055b224160db5 in blk_aio_preadv (blk=<optimized out>,
>>     offset=offset@entry=285122560, qiov=qiov@entry=0x55b22a31de20,
>>     flags=flags@entry=0, cb=cb@entry=0x55b224048e00
>> <ide_buffered_readv_cb>,
>>     opaque=opaque@entry=0x55b22a31de00) at block/block-backend.c:1256
>> #3  0x000055b22404bd8d in ide_buffered_readv (s=s@entry=0x55b22a712a68,
>>     sector_num=556880, iov=iov@entry=0x55b22a712d60,
>>     nb_sectors=nb_sectors@entry=4,
>>     cb=cb@entry=0x55b22404f2a0 <cd_read_sector_cb>,
>>     opaque=opaque@entry=0x55b22a712a68) at hw/ide/core.c:637
>> #4  0x000055b22404e2c1 in cd_read_sector (s=0x55b22a712a68)
>>     at hw/ide/atapi.c:198
>> #5  ide_atapi_cmd_reply_end (s=0x55b22a712a68) at hw/ide/atapi.c:272
>> #6  0x000055b224049704 in ide_data_readw (opaque=<optimized out>,
>>     addr=<optimized out>) at hw/ide/core.c:2263
>> #7  0x000055b223edd7f0 in portio_read (opaque=0x55b22a836000, addr=0,
>> size=2)
>>     at /usr/src/debug/qemu-2.9.0/ioport.c:180
>> #8  0x000055b223ee8e3b in memory_region_read_accessor (mr=0x55b22a836000,
>>     addr=0, value=0x7f843b5be7c0, size=2, shift=0, mask=65535, attrs=...)
>>     at /usr/src/debug/qemu-2.9.0/memory.c:435
>> #9  0x000055b223ee6369 in access_with_adjusted_size (addr=addr@entry=0,
>>     value=value@entry=0x7f843b5be7c0, size=size@entry=2,
>>     access_size_min=<optimized out>, access_size_max=<optimized out>,
>>     access=access@entry=0x55b223ee8e10 <memory_region_read_accessor>,
>>     mr=mr@entry=0x55b22a836000, attrs=attrs@entry=...)
>>     at /usr/src/debug/qemu-2.9.0/memory.c:592
>> #10 0x000055b223ee9d36 in memory_region_dispatch_read1 (attrs=..., size=2,
>>     pval=0x7f843b5be7c0, addr=0, mr=0x55b22a836000)
>>     at /usr/src/debug/qemu-2.9.0/memory.c:1238
>> #11 memory_region_dispatch_read (mr=mr@entry=0x55b22a836000,
>>     addr=addr@entry=0, pval=pval@entry=0x7f843b5be7c0, size=size@entry=2,
>>     attrs=attrs@entry=...) at /usr/src/debug/qemu-2.9.0/memory.c:1269
>> #12 0x000055b223e9bdb2 in address_space_read_continue (
>>     as=as@entry=0x55b2247db8c0 <address_space_io>, addr=addr@entry=496,
>> ---Type <return> to continue, or q <return> to quit---
>>     attrs=..., attrs@entry=...,
>>     buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
>>     len=len@entry=2, addr1=0, l=2, mr=0x55b22a836000)
>>     at /usr/src/debug/qemu-2.9.0/exec.c:2844
>> #13 0x000055b223e9be67 in address_space_read_full (
>>     as=0x55b2247db8c0 <address_space_io>, addr=addr@entry=496, attrs=...,
>>     buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
>>     len=2, len@entry=602521191) at /usr/src/debug/qemu-2.9.0/exec.c:2895
>> #14 0x000055b223e9bfce in address_space_read (len=602521191,
>>     buf=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>, attrs=...,
>>     addr=496, as=<optimized out>)
>>     at /usr/src/debug/qemu-2.9.0/include/exec/memory.h:1718
>> #15 address_space_rw (as=<optimized out>, addr=addr@entry=496, attrs=...,
>>     attrs@entry=...,
>>     buf=buf@entry=0x7f844dc103fe <Address 0x7f844dc103fe out of bounds>,
>>     len=len@entry=2, is_write=is_write@entry=false)
>>     at /usr/src/debug/qemu-2.9.0/exec.c:2909
>> #16 0x000055b223ee5271 in kvm_handle_io (count=512, size=2,
>>     direction=<optimized out>, data=<optimized out>, attrs=..., port=496)
>>     at /usr/src/debug/qemu-2.9.0/kvm-all.c:1828
>> #17 kvm_cpu_exec (cpu=cpu@entry=0x55b229032000)
>>     at /usr/src/debug/qemu-2.9.0/kvm-all.c:2058
>> #18 0x000055b223ed1c22 in qemu_kvm_cpu_thread_fn (arg=0x55b229032000)
>>     at /usr/src/debug/qemu-2.9.0/cpus.c:1119
>> #19 0x00007f8443993e25 in start_thread (arg=0x7f843b5bf700)
>>     at pthread_create.c:308
>> #20 0x00007f84436c134d in clone ()
>>     at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
>>
>>
>>
>>>>     ide_data_readw
>>> How do we get here? ide_is_pio_out ought to be false here; do you know
>>> what command was being processed? Do you have a reproducer?
>>>
>>> Knowing both the ATA and ATAPI commands under consideration here would
>>> be helpful.
>>>
>> if you prefer, I can upload core/binary to some storage.
>> Here is the state.
>>
> This might be helpful for me to poke around at, but unfortunately it
> looks like I can't see the ATAPI command that was being processed from
> the trace given. I don't think there's a way for me to retrieve it from
> a core, either.
>
>> (gdb) p *s
>> $3 = {bus = 0x55b22a7129f0, unit = 0 '\000', drive_kind = IDE_CD,
>>   cylinders = 0, heads = 0, sectors = 0, chs_trans = 0, nb_sectors =
>> 11588488,
>>   mult_sectors = 16, identify_set = 1,
>>   identify_data = "\300\205", '\000' <repeats 18 times>, "MQ0000 1", ' '
>> <repeats 12 times>, "\003\000\000\002\004\000.2+5    EQUMD DVR-MO", ' '
>> <repeats 28 times>,
>> "\000\000\001\000\000\003\000\000\000\000\000\000\a", '\000' <repeats 17
>> times>,
>> "\a\000\a\000\003\000\264\000\264\000,\001\264\000\000\000\000\000\036\000\036",
>> '\000' <repeats 15 times>, "\036", '\000' <repeats 15 times>, "? ",
>> '\000' <repeats 333 times>, drive_serial = 1,
>>   drive_serial_str = "QM00001", '\000' <repeats 13 times>,
>>   drive_model_str = "QEMU DVD-ROM", '\000' <repeats 28 times>, wwn = 0,
>>   feature = 0 '\000', error = 0 '\000', nsector = 2, sector = 0 '\000',
>>   lcyl = 0 '\000', hcyl = 8 '\b', hob_feature = 0 '\000',
>>   hob_nsector = 3 '\003', hob_sector = 0 '\000', hob_lcyl = 0 '\000',
>>   hob_hcyl = 8 '\b', select = 32 ' ', status = 80 'P', lba48 = 0 '\000',
> status = BUSY_STAT
> nsector = ATAPI_INT_REASON_IO (set in ide_atapi_cmd_reply_end)
> byte_count_limit = 2048 (hcyl << 8)
>
>>   blk = 0x55b2265405a0, version = "2.5+\000\000\000\000", events = {
>>     eject_request = false, new_media = false}, sense_key = 0 '\000',
>>   asc = 0 '\000', tray_open = false, tray_locked = false,
>>   cdrom_changed = 0 '\000', packet_transfer_size = 55296,
>>   elementary_transfer_size = 0, io_buffer_index = 2048, lba = 139220,
> packet_transfer_size = 55296, (27 cd sectors)
> elementary_transfer_size = 0,
> io_buffer_index = 2048,
> lba = 139220, or 0x021fd4
>
>
> This is either an initial read request, or a rebuffering.
> In the normative case, initial reads look like this:
>
> IDE:
> ide_ioport_write
>   ide_exec_cmd (0xA0)
>     cmd_packet
>       ide_transfer_start
>         s->end_transfer_func = ide_atapi_cmd
>         [data_ptr and data_end set to meaningful values]
> [Return to guest, await PIO write of scsi cdb]
> ide_data_writew
>   ide_atapi_cmd
>     [soft error if !blk->bs]
>     cmd_read_cd
>       ide_atapi_cmd_read
>         ide_atapi_cmd_read_pio
>           ide_atapi_cmd_reply_end
>             cd_read_sector
>               [segv if !blk->bs]
>
> AHCI:
> handle_reg_h2d_fis
>   [scsi CDB is copied into s->io_buffer]
>   ide_exec_cmd
>     cmd_packet
>       ide_transfer_start
>         [data_ptr and data_end set to transfer scsi cdb]
>           ahci_start_transfer
>             [shortcut, no transfer]
>             s->data_ptr set to s->data_end [*]
>               ide_atapi_cmd
>
> * (but data_end likely is still != s->io_buffer)
>
> from here the callback is the same as above: we'll wind up at
> cd_read_sector. Neither of these cases match your traceback.
>
> If it was the initial buffering, it would have occurred synchronously
> with receipt of the SCSI CDB, but your traces place it as a consequence
> of an attempt to read data, so that makes me suspect it's a rebuffering
> attempt, and the data in s->io_buffer is... cd data? I guess? did you
> have a CD in here at one point?
>
>>   cd_sector_size = 2048, atapi_dma = 0, acct = {bytes = 2048,
> So we're using PIO paths when applicable. The s->feature register being
> 0 seems to agree.
>
>>     start_time_ns = 433417215764666, type = BLOCK_ACCT_READ}, pio_aiocb
>> = 0x0,
>>   iov = {iov_base = 0x55b22a8ae000, iov_len = 2048}, qiov = {
>>     iov = 0x55b22a712d50, niov = 1, nalloc = -1, size = 2048},
>>   buffered_requests = {lh_first = 0x0}, io_buffer_offset = 0,
>>   io_buffer_size = 0, sg = {sg = 0x0, nsg = 0, nalloc = 0, size = 0,
>>     dev = 0x0, as = 0x0}, req_nb_sectors = 0,
>>   end_transfer_func = 0x55b22404e190 <ide_atapi_cmd_reply_end>,
>>   data_ptr = 0x55b22a8ae800 "", data_end = 0x55b22a8ae800 "",
>>   io_buffer = 0x55b22a8ae000
> s->data_ptr  = 0x55b22a8ae800
> s->data_end  = 0x55b22a8ae800
> s->io_buffer = 0x55b22a8ae000
> s->io_buffer_offset = 0
>
> Uh, hm. This does not look like an in-progress PIO transfer of any kind...
>
> This says to me that ide_dummy_transfer_stop was called at some point
> and nothing has started up in its place.
>
> This seems to conflict with the trace, which looks like a rebuffering.
> This looks like... undefined behavior entirely. I am not sure I have a
> good guess as to what's happening.
>
>> ")8\"\t\031\"\232\vx.\311l\301\270o$\335\025\257\064F\271\rI,R\342\032\315\nԆV\341od\251\023>\024\370\323\060A\256\337\300텋\024\233\201U\221T^\202\303\036\"E%\262\230\367ξ\fW\302\360\277\347\334\022\253\a\025\216\rj\334z\355>)\230/\021\255%a^\306\001\032",
> ... hmm
>
> 0x29 56 34 09 19
>
> 0x29 is... almost a read command (0x28) but it isn't. 0x29 shouldn't map
> to anything, actually. So this must be data we've buffered, or something
> left over from god knows what.
>
>>   io_buffer_total_len = 131076, cur_io_buffer_offset = 0,
>>   cur_io_buffer_len = 0, end_transfer_fn_idx = 0 '\000',
>>   sector_write_timer = 0x55b22a45d5c0, irq_count = 0, ext_error = 0 '\000',
>>   mdata_size = 0, mdata_storage = 0x0, media_changed = 0,
>>   dma_cmd = IDE_DMA_READ, smart_enabled = 1 '\001', smart_autosave = 1
>> '\001',
>>   smart_errors = 0, smart_selftest_count = 0 '\000',
>> ---Type <return> to continue, or q <return> to quit---
>>   smart_selftest_data = 0x55b22a827000 "", ncq_queues = 0}
>> (gdb)
>>
>> In general, I can upload the binary and core to the location
>> you want. Send it to me in person. By the way. I am staring to
>> receive these crashes in number. 2-3 in a day BUT from one
>> specific host. This could be important.
>>
>>>>     portio_read
>>>>     memory_region_read_accessor
>>>>     access_with_adjusted_size
>>>>     memory_region_dispatch_read1
>>>>     memory_region_dispatch_read
>>>>     address_space_read_continue
>>>>     address_space_read_full
>>>>     address_space_read
>>>>     address_space_rw
>>>>     kvm_handle_io
>>>>     kvm_cpu_exec
>>>>     qemu_kvm_cpu_thread_fn
>>>>     start_thread
>>>>     clone
>>> The thing that looks to be incongruent here is that we appear to be
>>> servicing a ATAPI reply; that reply is either the kind that uses
>>> preformatted data in a buffer, or the kind that buffers a read.
>>>
>>> If it buffers a read, it should require CHECK_READY which requires a medium.
>>>
>>> If it does not buffer a read, it should not be able to invoke
>>> cd_read_sector or any bdrv function from ide_data_readw.
>>>
>>> If it neither serves preformatted data nor buffers a read, it should not
>>> allow ide_data_readw to perform any action at all.
>> the guest could misbehave! This is not a reason to crash.
>> For example there is a race or something like this. What
>> if the guest will execute read from the device without
>> ANY sanity checks? QEMU should not crash. This is the point
>> and this is the approach taken in the original patch.
>>
> The stuff quoted above isn't participatory, it's mandatory. I don't know
> how we're bypassing CHECK_READY. I want to understand what's happening
> before I pepper in sanity checks.
>
> in 2.9.0, you have this code:
>
>     if ((cmd->flags & CHECK_READY) &&
>         (!media_present(s) || !blk_is_inserted(s->blk)))
>     {
>         ide_atapi_cmd_error(s, NOT_READY, ASC_MEDIUM_NOT_PRESENT);
>         return;
>     }
>
> with media_present defined as:
>
> static inline int media_present(IDEState *s)
> {
>     return !s->tray_open && s->nb_sectors > 0;
> }
>
> ... however, from your gdb output, we do have:
>
> tray_open = false
> nb_sectors = 11588488
>
> but blk_is_inserted is still going to check for the presence of 'bs'
> attached to the Block Backend, so this check should still prevent us
> from executing a read command out of the gate.
>
> Is the guest executing a read and then are we racing with the removal of
> the bds? Do you expect a CD to be inserted on this guest?
>
> nb_sectors I would expect to be 0; based on ide_cd_change_cb:
>
>     blk_get_geometry(s->blk, &nb_sectors);
>
> this should set nb_sectors to 0 if there's no blk->bs.
>
> I'm sort of lost, I can't really easily construct what exactly happened
> here.
>
>>>> Indeed, the CDROM device without media has blk->bs == NULL. We should
>>>> check that the media is really available for the device like has been done
>>>> in SCSI code.
>>>>
>>>> May be the patch adds a bit more check than necessary, but this is not be
>>>> the problem. We should always stay on the safe side.
>>>>
>>>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>>>> CC: John Snow <jsnow@redhat.com>
>>>> CC: Kevin Wolf <kwolf@redhat.com>
>>>> CC: Stefan Hajnoczi <stefanha@redhat.com>
>>>> ---
>>>>  hw/ide/atapi.c | 32 ++++++++++++++++++++++++++++----
>>>>  hw/ide/core.c  |  4 ++--
>>>>  2 files changed, 30 insertions(+), 6 deletions(-)
>>>>
>>>> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
>>>> index c0509c8bf5..fa50c0ccf6 100644
>>>> --- a/hw/ide/atapi.c
>>>> +++ b/hw/ide/atapi.c
>>>> @@ -119,6 +119,11 @@ cd_read_sector_sync(IDEState *s)
>>>>  
>>>>      trace_cd_read_sector_sync(s->lba);
>>>>  
>>>> +    if (!blk_is_available(s->blk)) {
>>>> +        ret = -ENOMEDIUM;
>>>> +        goto fail;
>>>> +    }
>>>> +
>>>>      switch (s->cd_sector_size) {
>>>>      case 2048:
>>>>          ret = blk_pread(s->blk, (int64_t)s->lba << ATAPI_SECTOR_BITS,
>>>> @@ -132,8 +137,8 @@ cd_read_sector_sync(IDEState *s)
>>>>          }
>>>>          break;
>>>>      default:
>>>> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>>> -        return -EIO;
>>>> +        ret = -EIO;
>>>> +        goto fail;
>>>>      }
>>>>  
>>>>      if (ret < 0) {
>>>> @@ -145,6 +150,10 @@ cd_read_sector_sync(IDEState *s)
>>>>      }
>>>>  
>>>>      return ret;
>>>> +
>>>> +fail:
>>>> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>>> +    return ret;
>>>>  }
>>>>  
>>>>  static void cd_read_sector_cb(void *opaque, int ret)
>>>> @@ -174,9 +183,15 @@ static void cd_read_sector_cb(void *opaque, int ret)
>>>>  
>>>>  static int cd_read_sector(IDEState *s)
>>>>  {
>>>> +    int err;
>>>> +
>>>>      if (s->cd_sector_size != 2048 && s->cd_sector_size != 2352) {
>>>> -        block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>>> -        return -EINVAL;
>>>> +        err = -EINVAL;
>>>> +        goto fail;
>>>> +    }
>>>> +    if (!blk_is_available(s->blk)) {
>>>> +        err = -ENOMEDIUM;
>>>> +        goto fail;
>>>>      }
>>>>  
>>>>      s->iov.iov_base = (s->cd_sector_size == 2352) ?
>>>> @@ -195,6 +210,10 @@ static int cd_read_sector(IDEState *s)
>>>>  
>>>>      s->status |= BUSY_STAT;
>>>>      return 0;
>>>> +
>>>> +fail:
>>>> +    block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>>> +    return err;
>>>>  }
>>>>  
>>>>  void ide_atapi_cmd_ok(IDEState *s)
>>>> @@ -404,6 +423,11 @@ static void ide_atapi_cmd_read_dma_cb(void *opaque, int ret)
>>>>          goto eot;
>>>>      }
>>>>  
>>>> +    if (!blk_is_available(s->blk)) {
>>>> +        ide_atapi_cmd_read_dma_cb(s, -ENOMEDIUM);
>>>> +        return;
>>>> +    }
>>>> +
>>> I'm not sure this is OK, because it's an error but not setting the sense
>>> code or raising an IRQ; it's only calling ide_set_inactive, so this
>>> might be a problem. Normally the error code from the data read is
>>> handled earlier in the call by ide_handle_rw_error which can set the
>>> proper codes.
>>>
>> this follows the approach used by the error handling in this call.
>> I this code is not made worse. We can hit to the same processing
>> with the different error upper.
>>
>>>>      s->io_buffer_index = 0;
>>>>      if (s->cd_sector_size == 2352) {
>>>>          n = 1;
>>>> diff --git a/hw/ide/core.c b/hw/ide/core.c
>>>> index 471d0c928b..71780fc9d1 100644
>>>> --- a/hw/ide/core.c
>>>> +++ b/hw/ide/core.c
>>>> @@ -758,7 +758,7 @@ static void ide_sector_read(IDEState *s)
>>>>  
>>>>      trace_ide_sector_read(sector_num, n);
>>>>  
>>>> -    if (!ide_sect_range_ok(s, sector_num, n)) {
>>>> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>>>>          ide_rw_error(s);
>>>>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_READ);
>>>>          return;
>>>> @@ -1023,7 +1023,7 @@ static void ide_sector_write(IDEState *s)
>>>>  
>>>>      trace_ide_sector_write(sector_num, n);
>>>>  
>>>> -    if (!ide_sect_range_ok(s, sector_num, n)) {
>>>> +    if (!ide_sect_range_ok(s, sector_num, n) || !blk_is_available(s->blk)) {
>>>>          ide_rw_error(s);
>>>>          block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
>>>>          return;
>>>>
>>> Since it's not a new regression (this is being reported against 2.9) I
>>> am somewhat hesitant to rush it into 2.11-rc3 without a little more info.
>>>
>>> That said, here's a list of the ATAPI commands we service that either
>>> return or CAN return data, but do not enforce CHECK_READY:
>>>
>>>     [ 0x03 ] = { cmd_request_sense,                 ALLOW_UA },
>>>     [ 0x12 ] = { cmd_inquiry,                       ALLOW_UA },
>>>     [ 0x46 ] = { cmd_get_configuration,             ALLOW_UA },
>>>     [ 0x4a ] = { cmd_get_event_status_notification, ALLOW_UA },
>>>     [ 0x5a ] = { cmd_mode_sense, /* (10) */         0 },
>>>     [ 0xbd ] = { cmd_mechanism_status,              0 },
>>>
>>> These six all invoke ide_atapi_cmd_reply in some way (which allows the
>>> guest to begin reading the reply via PIO mechanisms if DMA is not set):
>>>
>>> cmd_request_sense:     ide_atapi_cmd_reply(s, 18, max_len);
>>> cmd_inquiry:           ide_atapi_cmd_reply(s, idx, max_len);
>>> cmd_get_configuration: ide_atapi_cmd_reply(s, len, max_len);
>>> cmd_get_event_status_notification:
>>>                        ide_atapi_cmd_reply(s, used_len, max_len);
>>> cmd_mode_sense:        ide_atapi_cmd_reply(s, 16, max_len);
>>>                        ide_atapi_cmd_reply(s, 24, max_len);
>>>                        ide_atapi_cmd_reply(s, 30, max_len);
>>> cmd_mechanism_status:  ide_atapi_cmd_reply(s, 8, max_len);
>>>
>>> ide_atapi_cmd_reply itself sets lba to -1, which should inform
>>> ide_atapi_cmd_reply_end not to attempt to buffer any new data. These
>>> *should* be safe. The reply sizes are also all small enough that they
>>> are almost certainly getting buffered in one single transfer without
>>> attempting to buffer more data.
>>>
>>> In the normative PIO case then, reads will consume from this buffer
>>> until empty, then we'll call ide_atapi_cmd_reply_end through
>>> end_transfer_func and hit the end of transfer logic.
>>>
>>> I'm not sure I see how this crash is happening; it doesn't look like
>>> this path allows for invoking the block read functions and everything
>>> else is guarded by NONDATA or CHECK_READY.
>>>
>>> Unless this is an interesting interaction with ide_atapi_cmd_reply
>>> setting the DRQ bit which may trick the pio read function to allow PIO
>>> reads to come in during this time?
>>>
>>> Hypothetically:
>>>
>>> cmd_packet sets end_transfer_func to ide_atapi_cmd so it can process
>>> further once that PIO is completed. (The PIO may be emulated
>>> synchronously, in the case of AHCI.) In the true PIO case, it may be
>>> asynchronous.
>>>
>>> Now, in the AHCI case, the guest has control back and the CDROM is now
>>> executing a command to, perhaps, read data via DMA. Then,
>>> simultaneously, the guest issues a PIO read and because the DRQ bit is
>>> set for DMA, the PIO read also goes through.
>>>
>>> This still requires a media, though... and a very broken guest doing
>>> something naughty on purpose.
>>>
>>> I can't quite connect the dots to see how this crash is possible in
>>> general... it'd help to have:
>>>
>>> - The ATAPI command being processed at the time
>>> - The IDE command being processed at the time
>>> - s->status
>>>
>>> as a minimum, and then perhaps optionally some of the ATAPI loop
>>> variables, like packet_transfer_size, elementary_transfer_size, and
>>> io_buffer_index. Or a reproducer!
>>>
>>> Sorry I'm not more help and I wrote too much again :(
>> imho this does not matter. Once again - the guest can misbehave.
> I never said that if a guest acting out of spec was the problem I
> wouldn't fix it. I just want to find the root cause.
>
> If this has been broken since 2.9, 2.11-rc3 is too late for a bandaid
> applied to something I can't diagnose. Let's discuss this for 2.12 and I
> will keep trying to figure out what the root cause is.
I have read the entire letter in 2 subsequent attempts, but
unfortunately I can not say much more additionally :(

>
> Some questions for you:
>
> (1) Is the guest Linux? Do we know why this one machine might be
> tripping up QEMU? (Is it running a fuzzer, a weird OS, etc...?)
This is running by the end-user by our customer and we do not have
access to that machine and customer. This is anonymized crash report
from the node. This is not a single crash. We observe 1-2 reports with
this crash in a day.

> (2) Does the VM actually have a CDROM inserted at some point? Is it
> possible we're racing on some kind of eject or graph manipulation failure?
unclear but IMHO probable.

> (3) Is this using AHCI or IDE?
IDE. This is known 120%. We do not provide ability to enable AHCI
without manual tweaking.

>
> If I can't figure it out within a week or so from here I'll just check
> in the band-aid with some /* FIXME */ comments attached.
No prob. We are going to ship my band-aid and see to report statistics.

Thank you in advance,
    Den

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[John Snow]

On 12/14/2017 06:29 AM, Denis V. Lunev wrote:
>> If this has been broken since 2.9, 2.11-rc3 is too late for a bandaid
>> applied to something I can't diagnose. Let's discuss this for 2.12 and I
>> will keep trying to figure out what the root cause is.
> I have read the entire letter in 2 subsequent attempts, but
> unfortunately I can not say much more additionally :(
> 

No problem, sometimes I don't understand myself. And the IDE code isn't
exactly the nicest stuff to read. If I was smart enough I'd refactor the
whole thing, but without breaking migration it's a little hard :(

>> Some questions for you:
>>
>> (1) Is the guest Linux? Do we know why this one machine might be
>> tripping up QEMU? (Is it running a fuzzer, a weird OS, etc...?)
> This is running by the end-user by our customer and we do not have
> access to that machine and customer. This is anonymized crash report
> from the node. This is not a single crash. We observe 1-2 reports with
> this crash in a day.
> 

Yikes. Is this still on a 2.9-based VM, or have you upgraded to 2.10 or
2.11 at this point?

(From memory this was a problem with a 2.9 based machine)

>> (2) Does the VM actually have a CDROM inserted at some point? Is it
>> possible we're racing on some kind of eject or graph manipulation failure?
> unclear but IMHO probable.
> 

If they're using a 2.10+ based VM, could you look at some trace points?

either:
trace_ide_atapi_cmd (just scsi byte 0), or
trace_ide_atapi_cmd_packet (the entire scsi cdb)

and

trace_ide_exec_cmd

the actual command bytes never get saved in the state struct, so it's
hard to tell from traces what commands were being processed, but these
traces help.

>> (3) Is this using AHCI or IDE?
> IDE. This is known 120%. We do not provide ability to enable AHCI
> without manual tweaking.
> 

At least that helps narrow down the path...

>> If I can't figure it out within a week or so from here I'll just check
>> in the band-aid with some /* FIXME */ comments attached.
> No prob. We are going to ship my band-aid and see to report statistics.
> 
> Thank you in advance,
>     Den

I'll stage the band-aid with some FIXME comments, and maybe some scary
error_report prints with some information in them. I'll send it to the list.

Re: [Qemu-devel] [PATCH 2/2] ide: fix crash in IDE cdrom read

[Denis V. Lunev]

sorry, I have caught this latter tooo late.

On 12/18/2017 08:49 PM, John Snow wrote:
>
> On 12/14/2017 06:29 AM, Denis V. Lunev wrote:
>>> If this has been broken since 2.9, 2.11-rc3 is too late for a bandaid
>>> applied to something I can't diagnose. Let's discuss this for 2.12 and I
>>> will keep trying to figure out what the root cause is.
>> I have read the entire letter in 2 subsequent attempts, but
>> unfortunately I can not say much more additionally :(
>>
> No problem, sometimes I don't understand myself. And the IDE code isn't
> exactly the nicest stuff to read. If I was smart enough I'd refactor the
> whole thing, but without breaking migration it's a little hard :(
>
>>> Some questions for you:
>>>
>>> (1) Is the guest Linux? Do we know why this one machine might be
>>> tripping up QEMU? (Is it running a fuzzer, a weird OS, etc...?)
>> This is running by the end-user by our customer and we do not have
>> access to that machine and customer. This is anonymized crash report
>> from the node. This is not a single crash. We observe 1-2 reports with
>> this crash in a day.
>>
> Yikes. Is this still on a 2.9-based VM, or have you upgraded to 2.10 or
> 2.11 at this point?
>
> (From memory this was a problem with a 2.9 based machine)
the problem is with 2.9

>>> (2) Does the VM actually have a CDROM inserted at some point? Is it
>>> possible we're racing on some kind of eject or graph manipulation failure?
>> unclear but IMHO probable.
>>
> If they're using a 2.10+ based VM, could you look at some trace points?
>
> either:
> trace_ide_atapi_cmd (just scsi byte 0), or
> trace_ide_atapi_cmd_packet (the entire scsi cdb)
>
> and
>
> trace_ide_exec_cmd
>
> the actual command bytes never get saved in the state struct, so it's
> hard to tell from traces what commands were being processed, but these
> traces help.
unfortunately I do not have access to the crashing node :(
that is the problem.


>>> (3) Is this using AHCI or IDE?
>> IDE. This is known 120%. We do not provide ability to enable AHCI
>> without manual tweaking.
>>
> At least that helps narrow down the path...
>
>>> If I can't figure it out within a week or so from here I'll just check
>>> in the band-aid with some /* FIXME */ comments attached.
>> No prob. We are going to ship my band-aid and see to report statistics.
>>
>> Thank you in advance,
>>     Den
> I'll stage the band-aid with some FIXME comments, and maybe some scary
> error_report prints with some information in them. I'll send it to the list.
I do not see them merged. Have you?

For now I have merged my patch downstream. I do not see that it could be
wrong. The release is scheduled late this spring and if crashes
will stop to happen - I'll let you know.

Den

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Kevin Wolf]

Am 28.11.2017 um 13:10 hat Denis V. Lunev geschrieben:
> There are 2 cases I have spotted so far:
> 1) IDE ATAPI read processing. Actually this was reported from field
> 2) QEMU IO hmp command (found during evaluation of (1))
> 
> SCSI code checks during access that blk_is_available(). These patches add
> same checks on different code paths.
> 
> Pls decide whether these patches should go through sub-system trees or via
> block tree.

Why does this always come up in the last minute? :-(

The real fix shouldn't be in the devices, but blk_aio_*() needs to
handle empty drives gracefully. We already made a similar fix before the
last release in commit 4da97120d, and I already didn't like it back
then.

Of course, we should have used the time to fix this properly, but as you
can see, nothing has happened and we're running out of time again.

Kevin

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Denis V. Lunev]

On 11/28/2017 07:08 PM, Kevin Wolf wrote:
> Am 28.11.2017 um 13:10 hat Denis V. Lunev geschrieben:
>> There are 2 cases I have spotted so far:
>> 1) IDE ATAPI read processing. Actually this was reported from field
>> 2) QEMU IO hmp command (found during evaluation of (1))
>>
>> SCSI code checks during access that blk_is_available(). These patches add
>> same checks on different code paths.
>>
>> Pls decide whether these patches should go through sub-system trees or via
>> block tree.
> Why does this always come up in the last minute? :-(
>
> The real fix shouldn't be in the devices, but blk_aio_*() needs to
> handle empty drives gracefully. We already made a similar fix before the
> last release in commit 4da97120d, and I already didn't like it back
> then.
>
> Of course, we should have used the time to fix this properly, but as you
> can see, nothing has happened and we're running out of time again.
>
> Kevin
I see.

We have started ABRT report collection program a week ago. This
is the first result for QEMU from the real customer running
his own workload :(

What else can I say?

Den

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[John Snow]

On 11/28/2017 11:29 AM, Denis V. Lunev wrote:
> On 11/28/2017 07:08 PM, Kevin Wolf wrote:
>> Am 28.11.2017 um 13:10 hat Denis V. Lunev geschrieben:
>>> There are 2 cases I have spotted so far:
>>> 1) IDE ATAPI read processing. Actually this was reported from field
>>> 2) QEMU IO hmp command (found during evaluation of (1))
>>>
>>> SCSI code checks during access that blk_is_available(). These patches add
>>> same checks on different code paths.
>>>
>>> Pls decide whether these patches should go through sub-system trees or via
>>> block tree.
>> Why does this always come up in the last minute? :-(
>>
>> The real fix shouldn't be in the devices, but blk_aio_*() needs to
>> handle empty drives gracefully. We already made a similar fix before the
>> last release in commit 4da97120d, and I already didn't like it back
>> then.
>>
>> Of course, we should have used the time to fix this properly, but as you
>> can see, nothing has happened and we're running out of time again.
>>
>> Kevin
> I see.
> 
> We have started ABRT report collection program a week ago. This
> is the first result for QEMU from the real customer running
> his own workload :(
> 
> What else can I say?
> 
> Den
> 

It's not your fault, it's mine for letting this go for a release. It's
just unfortunate timing. I'm looking at (at least) the IDE portion of
this and the underlying cause in block-backend today.

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Peter Maydell]

On 28 November 2017 at 17:01, John Snow <jsnow@redhat.com> wrote:
> It's not your fault, it's mine for letting this go for a release. It's
> just unfortunate timing. I'm looking at (at least) the IDE portion of
> this and the underlying cause in block-backend today.

If it's not a regression, and nobody reported it for the whole release
cycle, we might choose to not fix it in 2.11...

thanks
-- PMM

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Denis V. Lunev]

On 11/28/2017 08:28 PM, Peter Maydell wrote:
> On 28 November 2017 at 17:01, John Snow <jsnow@redhat.com> wrote:
>> It's not your fault, it's mine for letting this go for a release. It's
>> just unfortunate timing. I'm looking at (at least) the IDE portion of
>> this and the underlying cause in block-backend today.
> If it's not a regression, and nobody reported it for the whole release
> cycle, we might choose to not fix it in 2.11...
>
> thanks
> -- PMM
may be this is related report
https://patchwork.kernel.org/patch/9779795/

Anyway, I will be fine with any decision.

Den

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Denis V. Lunev]

On 11/28/2017 03:10 PM, Denis V. Lunev wrote:
> There are 2 cases I have spotted so far:
> 1) IDE ATAPI read processing. Actually this was reported from field
> 2) QEMU IO hmp command (found during evaluation of (1))
>
> SCSI code checks during access that blk_is_available(). These patches add
> same checks on different code paths.
>
> Pls decide whether these patches should go through sub-system trees or via
> block tree.
>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
> CC: John Snow <jsnow@redhat.com>
> CC: Kevin Wolf <kwolf@redhat.com>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
>
any decision on this?

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[John Snow]

On 12/11/2017 05:24 AM, Denis V. Lunev wrote:
> On 11/28/2017 03:10 PM, Denis V. Lunev wrote:
>> There are 2 cases I have spotted so far:
>> 1) IDE ATAPI read processing. Actually this was reported from field
>> 2) QEMU IO hmp command (found during evaluation of (1))
>>
>> SCSI code checks during access that blk_is_available(). These patches add
>> same checks on different code paths.
>>
>> Pls decide whether these patches should go through sub-system trees or via
>> block tree.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
>> CC: John Snow <jsnow@redhat.com>
>> CC: Kevin Wolf <kwolf@redhat.com>
>> CC: Stefan Hajnoczi <stefanha@redhat.com>
>>
> any decision on this?
> 

Hi Den, I was investigating it and had a long reply typed out but I
didn't want to bore you to tears with my badly written novel. I'll send
it shortly.

I couldn't reproduce the problem and I can't see how the behavior you
are seeing is possible, so I am concerned about the root cause of what's
wrong.

I will accept the hotfix before 2.12-rc0 or 2.11.1, but I want to try
and see what's going wrong in the meantime.

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[John Snow]

On 11/28/2017 07:10 AM, Denis V. Lunev wrote:
> There are 2 cases I have spotted so far:
> 1) IDE ATAPI read processing. Actually this was reported from field
> 2) QEMU IO hmp command (found during evaluation of (1))
> 
> SCSI code checks during access that blk_is_available(). These patches add
> same checks on different code paths.
> 
> Pls decide whether these patches should go through sub-system trees or via
> block tree.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
> CC: John Snow <jsnow@redhat.com>
> CC: Kevin Wolf <kwolf@redhat.com>
> CC: Stefan Hajnoczi <stefanha@redhat.com>
> 
> 

Denis, I was never able to figure this out, but Stefan added a more
rigorous block-wide fix that should prevent these crashes. If you see
any anomalies in the ATAPI device again please let me know.

Sorry I wasn't able to help any faster.

Re: [Qemu-devel] [PATCH for 2.11 0/2] QEMU crashes with CD device without media

[Denis V. Lunev]

On 03/13/2018 08:18 PM, John Snow wrote:
>
> On 11/28/2017 07:10 AM, Denis V. Lunev wrote:
>> There are 2 cases I have spotted so far:
>> 1) IDE ATAPI read processing. Actually this was reported from field
>> 2) QEMU IO hmp command (found during evaluation of (1))
>>
>> SCSI code checks during access that blk_is_available(). These patches add
>> same checks on different code paths.
>>
>> Pls decide whether these patches should go through sub-system trees or via
>> block tree.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
>> CC: John Snow <jsnow@redhat.com>
>> CC: Kevin Wolf <kwolf@redhat.com>
>> CC: Stefan Hajnoczi <stefanha@redhat.com>
>>
>>
> Denis, I was never able to figure this out, but Stefan added a more
> rigorous block-wide fix that should prevent these crashes. If you see
> any anomalies in the ATAPI device again please let me know.
>
> Sorry I wasn't able to help any faster.
ok, no prob. Thank you for a feedback

Den