Add tracing for more received packet types, cbw_state changes, and some more SCSI callbacks. These were useful in debugging relaxed packet ordering support.
Reviewed-by: Philippe Mathieu-Daudé <phi...@linaro.org> Signed-off-by: Nicholas Piggin <npig...@gmail.com> --- hw/usb/dev-storage.c | 61 +++++++++++++++++++++++++++++++++----------- hw/usb/trace-events | 11 +++++++- 2 files changed, 56 insertions(+), 16 deletions(-) diff --git a/hw/usb/dev-storage.c b/hw/usb/dev-storage.c index f421bd1f8dd..79f857de599 100644 --- a/hw/usb/dev-storage.c +++ b/hw/usb/dev-storage.c @@ -185,6 +185,21 @@ static const USBDesc desc = { .str = desc_strings, }; + +static void usb_msd_change_cbw_state(MSDState *s, USBMSDCBWState cbw_state) +{ + g_assert(s->cbw_state != cbw_state); + s->cbw_state = cbw_state; + trace_usb_msd_cbw_state(s->cbw_state); +} + +static void usb_msd_set_cbw_state(MSDState *s, USBMSDCBWState cbw_state) +{ + if (s->cbw_state != cbw_state) { + usb_msd_change_cbw_state(s, cbw_state); + } +} + static void usb_msd_data_packet_complete(MSDState *s, int status) { USBPacket *p = s->data_packet; @@ -194,7 +209,7 @@ static void usb_msd_data_packet_complete(MSDState *s, int status) * because another request may be issued before usb_packet_complete * returns. */ - trace_usb_msd_packet_complete(); + trace_usb_msd_data_packet_complete(); s->data_packet = NULL; p->status = status; usb_packet_complete(&s->dev, p); @@ -209,7 +224,7 @@ static void usb_msd_csw_packet_complete(MSDState *s, int status) * because another request may be issued before usb_packet_complete * returns. */ - trace_usb_msd_packet_complete(); + trace_usb_msd_csw_packet_complete(); s->csw_in_packet = NULL; p->status = status; usb_packet_complete(&s->dev, p); @@ -238,7 +253,11 @@ static void usb_msd_fatal_error(MSDState *s) static void usb_msd_copy_data(MSDState *s, USBPacket *p) { uint32_t len; + len = p->iov.size - p->actual_length; + + trace_usb_msd_copy_data(s->req->tag, len); + if (len > s->scsi_len) len = s->scsi_len; usb_packet_copy(p, scsi_req_get_buf(s->req) + s->scsi_off, len); @@ -271,6 +290,8 @@ void usb_msd_transfer_data(SCSIRequest *req, uint32_t len) MSDState *s = DO_UPCAST(MSDState, dev.qdev, req->bus->qbus.parent); USBPacket *p = s->data_packet; + trace_usb_msd_transfer_data(req->tag, len); + if (s->cbw_state == USB_MSD_CBW_DATAIN) { if (req->cmd.mode == SCSI_XFER_TO_DEV) { usb_msd_fatal_error(s); @@ -333,19 +354,19 @@ void usb_msd_command_complete(SCSIRequest *req, size_t resid) s->data_len -= len; } if (s->data_len == 0) { - s->cbw_state = USB_MSD_CBW_CSW; + usb_msd_change_cbw_state(s, USB_MSD_CBW_CSW); } /* USB_RET_SUCCESS status clears previous ASYNC status */ usb_msd_data_packet_complete(s, USB_RET_SUCCESS); } else if (s->data_len == 0) { - s->cbw_state = USB_MSD_CBW_CSW; + usb_msd_change_cbw_state(s, USB_MSD_CBW_CSW); } if (s->cbw_state == USB_MSD_CBW_CSW) { p = s->csw_in_packet; if (p) { usb_msd_send_status(s, p); - s->cbw_state = USB_MSD_CBW_NONE; + usb_msd_change_cbw_state(s, USB_MSD_CBW_NONE); /* USB_RET_SUCCESS status clears previous ASYNC status */ usb_msd_csw_packet_complete(s, USB_RET_SUCCESS); } @@ -388,7 +409,7 @@ void usb_msd_handle_reset(USBDevice *dev) } memset(&s->csw, 0, sizeof(s->csw)); - s->cbw_state = USB_MSD_CBW_NONE; + usb_msd_set_cbw_state(s, USB_MSD_CBW_NONE); s->needs_reset = false; } @@ -439,6 +460,8 @@ static void usb_msd_cancel_io(USBDevice *dev, USBPacket *p) { MSDState *s = USB_STORAGE_DEV(dev); + trace_usb_msd_cancel_io(); + if (p == s->data_packet) { s->data_packet = NULL; if (s->req) { @@ -491,11 +514,14 @@ static void usb_msd_handle_data_out(USBDevice *dev, USBPacket *p) SCSIDevice *scsi_dev; int len; + trace_usb_msd_data_out(p->iov.size, s->data_len); + switch (s->cbw_state) { case USB_MSD_CBW_NONE: if (!try_get_valid_cbw(p, &cbw)) { goto fail; } + trace_usb_msd_cbw_out(); scsi_dev = scsi_device_find(&s->bus, 0, 0, cbw.lun); if (scsi_dev == NULL) { qemu_log_mask(LOG_GUEST_ERROR, "usb-msd: Bad CBW LUN %d\n", @@ -505,11 +531,11 @@ static void usb_msd_handle_data_out(USBDevice *dev, USBPacket *p) tag = le32_to_cpu(cbw.tag); s->data_len = le32_to_cpu(cbw.data_len); if (s->data_len == 0) { - s->cbw_state = USB_MSD_CBW_NODATA; + usb_msd_change_cbw_state(s, USB_MSD_CBW_NODATA); } else if (cbw.flags & 0x80) { - s->cbw_state = USB_MSD_CBW_DATAIN; + usb_msd_change_cbw_state(s, USB_MSD_CBW_DATAIN); } else { - s->cbw_state = USB_MSD_CBW_DATAOUT; + usb_msd_change_cbw_state(s, USB_MSD_CBW_DATAOUT); } if (s->unknown_in_packet) { if (s->cbw_state == USB_MSD_CBW_DATAIN) { @@ -540,7 +566,6 @@ static void usb_msd_handle_data_out(USBDevice *dev, USBPacket *p) break; case USB_MSD_CBW_DATAOUT: - trace_usb_msd_data_out(p->iov.size, s->data_len); if (s->unknown_in_packet) { error_report("usb-msd: unknown_in_packet in DATAOUT state"); goto fail; @@ -562,7 +587,7 @@ static void usb_msd_handle_data_out(USBDevice *dev, USBPacket *p) } s->data_len -= len; if (s->data_len == 0) { - s->cbw_state = USB_MSD_CBW_CSW; + usb_msd_change_cbw_state(s, USB_MSD_CBW_CSW); } } } @@ -579,6 +604,7 @@ static void usb_msd_handle_data_out(USBDevice *dev, USBPacket *p) return; fail: + trace_usb_msd_bad_packet(); p->status = USB_RET_STALL; } @@ -587,8 +613,11 @@ static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p) MSDState *s = (MSDState *)dev; int len; + trace_usb_msd_data_in(p->iov.size, s->data_len, s->scsi_len); + switch (s->cbw_state) { case USB_MSD_CBW_NONE: + trace_usb_msd_unknown_in(p->iov.size); if (s->unknown_in_packet) { qemu_log_mask(LOG_GUEST_ERROR, "usb-msd: second IN packet was" "received before CBW\n"); @@ -602,12 +631,13 @@ static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p) case USB_MSD_CBW_NODATA: case USB_MSD_CBW_DATAOUT: if (s->unknown_in_packet) { - error_report("usb-msd: unknown_in_packet in DATAOUT state"); + error_report("usb-msd: unknown_in_packet in DATAOUT/NODATA state"); goto fail; } if (!check_valid_csw(p)) { goto fail; } + trace_usb_msd_csw_in(); if (s->data_len != 0) { qemu_log_mask(LOG_GUEST_ERROR, "usb-msd: CSW received before " "all data was sent\n"); @@ -621,6 +651,7 @@ static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p) break; case USB_MSD_CBW_CSW: + trace_usb_msd_csw_in(); if (s->unknown_in_packet) { error_report("usb-msd: unknown_in_packet in CSW state"); goto fail; @@ -636,12 +667,11 @@ static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p) p->status = USB_RET_ASYNC; } else { usb_msd_send_status(s, p); - s->cbw_state = USB_MSD_CBW_NONE; + usb_msd_change_cbw_state(s, USB_MSD_CBW_NONE); } break; case USB_MSD_CBW_DATAIN: - trace_usb_msd_data_in(p->iov.size, s->data_len, s->scsi_len); if (s->unknown_in_packet) { error_report("usb-msd: unknown_in_packet in DATAIN state"); goto fail; @@ -658,7 +688,7 @@ static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p) } s->data_len -= len; if (s->data_len == 0) { - s->cbw_state = USB_MSD_CBW_CSW; + usb_msd_change_cbw_state(s, USB_MSD_CBW_CSW); } } } @@ -676,6 +706,7 @@ static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p) return; fail: + trace_usb_msd_bad_packet(); p->status = USB_RET_STALL; } diff --git a/hw/usb/trace-events b/hw/usb/trace-events index dd04f14add1..851ba9986c3 100644 --- a/hw/usb/trace-events +++ b/hw/usb/trace-events @@ -264,12 +264,21 @@ usb_msd_maxlun(unsigned maxlun) "%d" usb_msd_send_status(unsigned status, unsigned tag, size_t size) "status %d, tag 0x%x, len %zd" usb_msd_data_in(unsigned packet, unsigned remaining, unsigned total) "%d/%d (scsi %d)" usb_msd_data_out(unsigned packet, unsigned remaining) "%d/%d" +usb_msd_unknown_in(unsigned packet) "%d" +usb_msd_cbw_out(void) "" +usb_msd_csw_in(void) "" usb_msd_packet_async(void) "" -usb_msd_packet_complete(void) "" +usb_msd_data_packet_complete(void) "" +usb_msd_csw_packet_complete(void) "" +usb_msd_bad_packet(void) "" usb_msd_cmd_submit(unsigned lun, unsigned tag, unsigned flags, unsigned len, unsigned data_len) "lun %u, tag 0x%x, flags 0x%08x, len %d, data-len %d" usb_msd_cmd_complete(unsigned status, unsigned tag) "status %d, tag 0x%x" +usb_msd_copy_data(unsigned tag, unsigned len) "tag 0x%x len %d" +usb_msd_transfer_data(unsigned tag, unsigned len) "tag 0x%x len %d" usb_msd_cmd_cancel(unsigned tag) "tag 0x%x" +usb_msd_cancel_io(void) "" usb_msd_fatal_error(void) "" +usb_msd_cbw_state(unsigned cbw_state) "cbw-state %d" # dev-uas.c usb_uas_reset(int addr) "dev %d" -- 2.47.1