Index: /trunk/src/VBox/Devices/Storage/DevVirtioSCSI.cpp =================================================================== --- /trunk/src/VBox/Devices/Storage/DevVirtioSCSI.cpp (revision 80521) +++ /trunk/src/VBox/Devices/Storage/DevVirtioSCSI.cpp (revision 80522) @@ -487,4 +487,42 @@ out[0] = 0x01; out[1] = target; out[2] = (lun >> 8) & 0x40; out[3] = lun & 0xff; *((uint16_t *)out + 4) = 0; +/** + * Do a hex dump of a buffer + * @param pv Pointer to array to dump + * @param cb Number of characters to dump + * @param uBase Base address of offset addresses displayed + * @param pszTitle Header line/title for the dump + * + */ +void virtioScsiHexDump(uint8_t *pv, size_t cb, uint32_t uBase, const char *pszTitle) { + if (pszTitle) + Log2(("%s [%d bytes]:\n", pszTitle, cb)); + for (uint32_t i = 0; i < RT_MAX(1, (cb / 16)); i++) + { + uint32_t uAddr = i * 16 + uBase; + Log2(("%x%x%x%x: ", (uAddr >> 12) & 0xf, (uAddr >> 8) & 0xf, (uAddr >> 4) & 0xf, uAddr & 0xf)); + for (int j = 0; j < 16; j++) + { + if (i * 16 + j >= cb) + Log2(("-- %s", (j + 1) % 8 ? "" : " ")); + else + { + uint8_t u8 = pv[i * 16 + j]; + Log2(("%x%x %s", u8 >> 4 & 0xf, u8 & 0xf, (j + 1) % 8 ? "" : " ")); + } + } + for (int j = 0; j < 16; j++ ) { + if (i * 16 + j >= cb) + Log2((" ")); + else + { + uint8_t u8 = pv[i * 16 + j]; + Log2(("%c", u8 >= 0x20 && u8 <= 0x7e ? u8 : '.')); + } + } + Log2(("\n")); + } + Log2(("\n")); +} DECLINLINE(const char *) virtioGetTMFTypeText(uint32_t uSubType) { @@ -567,4 +605,19 @@ } +uint8_t virtioScsiEstimateCdbLen(uint8_t uCmd, uint8_t cbMax) +{ + if (uCmd < 0x1f) + return 6; + else if (uCmd >= 0x20 && uCmd < 0x60) + return 10; + else if (uCmd >= 0x60 && uCmd < 0x80) + return cbMax; + else if (uCmd >= 0x80 && uCmd < 0xa0) + return 16; + else if (uCmd >= 0xa0 && uCmd < 0xC0) + return 12; + else + return cbMax; +} DECLINLINE(uint8_t) virtioScsiMapVerrToVirtio(uint32_t vboxRc) { @@ -818,5 +871,5 @@ * @returns virtual box status code */ -static int virtioScsiReqComplete(PVIRTIOSCSI pThis, uint16_t qIdx, uint32_t rcReq) +static int virtioScsiReqFinish(PVIRTIOSCSI pThis, uint16_t qIdx, uint32_t rcReq) { struct REQ_RESP_HDR respHdr; @@ -832,8 +885,9 @@ virtioQueueSync(pThis->hVirtio, qIdx); LogFunc(("Response code: %s\n", virtioGetReqRespText(respHdr.uResponse))); + Log(("---------------------------------------------------------------------------------\n")); return VINF_SUCCESS; } -static int virtioScsiR3ReqComplete(PVIRTIOSCSI pThis, PVIRTIOSCSIREQ pReq, int rcReq) +static int virtioScsiReqFinish(PVIRTIOSCSI pThis, PVIRTIOSCSIREQ pReq, int rcReq) { PVIRTIOSCSITARGET pTarget = pReq->pTarget; @@ -860,18 +914,25 @@ - LogFunc(("SCSI Status = %x (%s)\n", pReq->uStatus, virtioGetScsiStatusText(pReq->uStatus))); - LogFunc(("Response code: %s\n", virtioGetReqRespText(respHdr.uResponse))); + LogFunc(("Status: %s (0x%x%x) Response: %s (0x%x%x)\n", + virtioGetScsiStatusText(pReq->uStatus), pReq->uStatus >> 4 & 0xf, pReq->uStatus & 0xf, + virtioGetReqRespText(respHdr.uResponse), respHdr.uResponse >> 4 & 0xf, respHdr.uResponse & 0xf)); if (pReq->cbSense) - LogFunc(("Sense: %.*Rhxs\n", pReq->cbSense, pReq->pbSense)); + { + Log2Func(("Sense: %s\n", SCSISenseText(pReq->pbSense[2]))); + Log2Func(("Sense Ext3: %s\n", SCSISenseExtText(pReq->pbSense[12], pReq->pbSense[12]))); + virtioScsiHexDump( pReq->pbSense, pReq->cbSense, 0, "\nSense"); + } if (pReq->cbDataIn) - LogFunc(("Data In: %.*Rhxs\n", pReq->cbDataIn, pReq->pbDataIn)); + virtioScsiHexDump( pReq->pbDataIn, pReq->cbDataIn, 0, "\ndatain"); if (pReq->cbPiIn) - LogFunc(("Pi In: %.*Rhxs\n", pReq->cbPiIn, pReq->pbPiIn)); - - LogFunc(("Residual: %d\n", cbResidual)); - + virtioScsiHexDump( pReq->pbPiIn, pReq->cbPiIn, 0, "\nPi in"); + + if (cbResidual) + Log(("Residual: %d\n", cbResidual)); + + Log(("---------------------------------------------------------------------------------\n")); int cSegs = 0; RTSGSEG aReqSegs[4]; @@ -932,9 +993,9 @@ RT_NOREF(hIoReq); PVIRTIOSCSITARGET pTarget = RT_FROM_MEMBER(pInterface, VIRTIOSCSITARGET, IMediaExPort); - virtioScsiR3ReqComplete(pTarget->CTX_SUFF(pVirtioScsi), (PVIRTIOSCSIREQ)pvIoReqAlloc, rcReq); + virtioScsiReqFinish(pTarget->CTX_SUFF(pVirtioScsi), (PVIRTIOSCSIREQ)pvIoReqAlloc, rcReq); return VINF_SUCCESS; } -static int virtioScsiSubmitReq(PVIRTIOSCSI pThis, uint16_t qIdx, PRTSGBUF pInSgBuf, PRTSGBUF pOutSgBuf) +static int virtioScsiReqSubmit(PVIRTIOSCSI pThis, uint16_t qIdx, PRTSGBUF pInSgBuf, PRTSGBUF pOutSgBuf) { RT_NOREF(pInSgBuf); @@ -976,17 +1037,19 @@ uint32_t uLUN = (pVirtqReq->cmdHdr.uLUN[2] << 8 | pVirtqReq->cmdHdr.uLUN[3]) & 0x3fff; - LogFunc(("LUN: %.8Rhxs, (target:%d, lun:%d) id: %RX64, attr: %x, prio: %d, crn: %x\n" - " CDB: %.*Rhxs\n", - pVirtqReq->cmdHdr.uLUN, uTarget, uLUN, pVirtqReq->cmdHdr.uId, - pVirtqReq->cmdHdr.uTaskAttr, pVirtqReq->cmdHdr.uPrio, pVirtqReq->cmdHdr.uCrn, cbCdb, pbCdb)); + LogFunc(("[%s] (Target: %d LUN: %d) CDB: %.*Rhxs\n", + SCSICmdText(pbCdb[0]), uTarget, uLUN, + virtioScsiEstimateCdbLen(pbCdb[0], pThis->virtioScsiConfig.uCdbSize), pbCdb)); + + Log3Func((" id: %RX64, attr: %x, prio: %d, crn: %x\n", + pVirtqReq->cmdHdr.uId, pVirtqReq->cmdHdr.uTaskAttr, pVirtqReq->cmdHdr.uPrio, pVirtqReq->cmdHdr.uCrn)); if (uTarget >= pThis->cTargets) { - virtioScsiReqComplete(pThis, qIdx, VERR_IO_BAD_UNIT); + virtioScsiReqFinish(pThis, qIdx, VERR_IO_BAD_UNIT); return VINF_SUCCESS; } if (uLUN != 0) { - virtioScsiReqComplete(pThis, qIdx, VERR_IO_BAD_UNIT); + virtioScsiReqFinish(pThis, qIdx, VERR_IO_BAD_UNIT); return VINF_SUCCESS; } @@ -1015,8 +1078,9 @@ if (cbDataOut) - LogFunc(("dataout[]: %.*Rhxs\n", cbDataOut, pVirtqReq->uDataOut)); + virtioScsiHexDump( pVirtqReq->uDataOut, cbDataOut, 0, "\ndataout"); + if (cbPiOut) - LogFunc(("pi_out[]: %.*Rhxs\n", cbPiOut, pVirtqReq->uPiOut)); + virtioScsiHexDump(pVirtqReq->uPiOut, cbPiOut, 0, "\nPi out"); PDMMEDIAEXIOREQ hIoReq = NULL; @@ -1064,5 +1128,5 @@ } - LogFunc(("Submitting req (target=%d, LUN=%x) on %s\n", uTarget, uLUN, QUEUENAME(qIdx))); + Log3Func(("Submitting req on %s\n", uTarget, uLUN, QUEUENAME(qIdx))); rc = pIMediaEx->pfnIoReqSendScsiCmd(pIMediaEx, pReq->hIoReq, uLUN, pbCdb, cbCdb, @@ -1073,9 +1137,9 @@ { pIMediaEx->pfnIoReqFree(pIMediaEx, hIoReq); - virtioScsiReqComplete(pThis, qIdx, rc); + virtioScsiReqFinish(pThis, qIdx, rc); return VINF_SUCCESS; } } else { - virtioScsiReqComplete(pThis, qIdx, VERR_IO_NOT_READY); + virtioScsiReqFinish(pThis, qIdx, VERR_IO_NOT_READY); return VINF_SUCCESS; @@ -1180,5 +1244,5 @@ virtioGetControlAsyncMaskText(szTypeText, sizeof(szTypeText), pScsiCtrlAnQuery->uEventsRequested); - LogFunc(("%s, VirtIO LUN: %.8Rhxs\n%*sAsync Query, types: %s\n", + Log2Func(("%s, VirtIO LUN: %.8Rhxs\n%*sAsync Query, types: %s\n", QUEUENAME(qIdx), pScsiCtrlAnQuery->uLUN, CBQUEUENAME(qIdx) + 30, "", szTypeText)); @@ -1196,10 +1260,10 @@ if (pScsiCtrlAnSubscribe->uEventsRequested & ~SUBSCRIBABLE_EVENTS) - Log(("Unsupported bits in event subscription event mask: 0x%x\n", pScsiCtrlAnSubscribe->uEventsRequested)); + LogFunc(("Unsupported bits in event subscription event mask: 0x%x\n", pScsiCtrlAnSubscribe->uEventsRequested)); char szTypeText[128]; virtioGetControlAsyncMaskText(szTypeText, sizeof(szTypeText), pScsiCtrlAnSubscribe->uEventsRequested); - LogFunc(("%s, VirtIO LUN: %.8Rhxs\n%*sAsync Subscribe, types: %s\n", + Log2Func(("%s, VirtIO LUN: %.8Rhxs\n%*sAsync Subscribe, types: %s\n", QUEUENAME(qIdx), pScsiCtrlAnSubscribe->uLUN, CBQUEUENAME(qIdx) + 30, "", szTypeText)); @@ -1221,5 +1285,5 @@ } default: - Log(("Unknown control type extracted from %s: %d\n", QUEUENAME(qIdx), pScsiCtrl->uType)); + LogFunc(("Unknown control type extracted from %s: %d\n", QUEUENAME(qIdx), pScsiCtrl->uType)); uResponse = VIRTIOSCSI_S_FAILURE; @@ -1273,5 +1337,5 @@ if (!fNotificationSent) { - LogFunc(("%s worker sleeping...\n", QUEUENAME(qIdx))); + Log3Func(("%s worker sleeping...\n", QUEUENAME(qIdx))); Assert(ASMAtomicReadBool(&pWorker->fSleeping)); rc = SUPSemEventWaitNoResume(pThis->pSupDrvSession, pWorker->hEvtProcess, RT_INDEFINITE_WAIT); @@ -1279,14 +1343,14 @@ if (RT_UNLIKELY(pThread->enmState != PDMTHREADSTATE_RUNNING)) break; - LogFunc(("%s worker woken\n", QUEUENAME(qIdx))); + Log3Func(("%s worker woken\n", QUEUENAME(qIdx))); ASMAtomicWriteBool(&pWorker->fNotified, false); } ASMAtomicWriteBool(&pWorker->fSleeping, false); } - LogFunc(("fetching next descriptor chain from %s\n", QUEUENAME(qIdx))); + Log3Func(("fetching next descriptor chain from %s\n", QUEUENAME(qIdx))); rc = virtioQueueGet(pThis->hVirtio, qIdx, true, &pInSgBuf, &pOutSgBuf); if (rc == VERR_NOT_AVAILABLE) { - LogFunc(("Nothing found in %s\n", QUEUENAME(qIdx))); + Log2Func(("Nothing found in %s\n", QUEUENAME(qIdx))); continue; } @@ -1296,5 +1360,5 @@ virtioScsiCtrl(pThis, qIdx, pInSgBuf, pOutSgBuf); else - virtioScsiSubmitReq(pThis, qIdx, pInSgBuf, pOutSgBuf); + virtioScsiReqSubmit(pThis, qIdx, pInSgBuf, pOutSgBuf); } return VINF_SUCCESS; @@ -1505,5 +1569,5 @@ if (qIdx == CONTROLQ_IDX || IS_REQ_QUEUE(qIdx)) { - LogFunc(("%s has available data\n", QUEUENAME(qIdx))); + Log3Func(("%s has available data\n", QUEUENAME(qIdx))); /** Wake queue's worker thread up if sleeping */ if (!ASMAtomicXchgBool(&pWorker->fNotified, true)) @@ -1511,5 +1575,5 @@ if (ASMAtomicReadBool(&pWorker->fSleeping)) { - LogFunc(("waking %s worker.\n", QUEUENAME(qIdx))); + Log3Func(("waking %s worker.\n", QUEUENAME(qIdx))); int rc = SUPSemEventSignal(pThis->pSupDrvSession, pWorker->hEvtProcess); AssertRC(rc); @@ -1519,5 +1583,5 @@ else if (qIdx == EVENTQ_IDX) { - LogFunc(("Driver queued buffer(s) to %s\n")); + Log3Func(("Driver queued buffer(s) to %s\n")); if (ASMAtomicXchgBool(&pThis->fEventsMissed, false)) virtioScsiReportEventsMissed(pThis, 0); @@ -1529,5 +1593,4 @@ static DECLCALLBACK(void) virtioScsiStatusChanged(VIRTIOHANDLE hVirtio, void *pClient, bool fVirtioReady) { - LogFunc(("\n")); RT_NOREF(hVirtio); PVIRTIOSCSI pThis = (PVIRTIOSCSI)pClient; @@ -1535,5 +1598,5 @@ if (fVirtioReady) { - LogFunc(("VirtIO ready\n")); + LogFunc(("VirtIO ready\n---------------------------------------------------------------------------------")); uint64_t features = virtioGetNegotiatedFeatures(hVirtio); pThis->fHasT10pi = features & VIRTIO_SCSI_F_T10_PI; Index: /trunk/src/VBox/Devices/VirtIO/Virtio_1_0.cpp =================================================================== --- /trunk/src/VBox/Devices/VirtIO/Virtio_1_0.cpp (revision 80521) +++ /trunk/src/VBox/Devices/VirtIO/Virtio_1_0.cpp (revision 80522) @@ -81,10 +81,10 @@ if (pszDepiction[i] == ' ' && first++) pszDepiction[i] = '.'; - Log(("%s: Guest %s %s 0x%s\n", + Log3Func(("%s: Guest %s %s 0x%s\n", pszFunc, fWrite ? "wrote" : "read ", pszDepiction, pszFormattedVal)); } else /* odd number or oversized access, ... log inline hex-dump style */ { - Log(("%s: Guest %s %s%s[%d:%d]: %.*Rhxs\n", + Log3Func(("%s: Guest %s %s%s[%d:%d]: %.*Rhxs\n", pszFunc, fWrite ? "wrote" : "read ", pszMember, pszIdx, uOffset, uOffset + cb, cb, pv)); @@ -200,5 +200,5 @@ uint16_t uDescIdx = pDescChain->uHeadIdx; - Log2Func(("%s DESC CHAIN: (head) desc_idx=%u [avail_idx=%u]\n", + Log3Func(("%s DESC CHAIN: (head) desc_idx=%u [avail_idx=%u]\n", pVirtqProxy->szVirtqName, pDescChain->uHeadIdx, pVirtqProxy->uAvailIdx)); @@ -238,5 +238,5 @@ if (desc.fFlags & VIRTQ_DESC_F_WRITE) { - Log2Func(("%s IN desc_idx=%u seg=%u addr=%RGp cb=%u\n", + Log3Func(("%s IN desc_idx=%u seg=%u addr=%RGp cb=%u\n", QUEUENAME(qIdx), uDescIdx, pDescChain->cSegsIn, desc.pGcPhysBuf, desc.cb)); @@ -245,5 +245,5 @@ else { - Log2Func(("%s OUT desc_idx=%u seg=%u addr=%RGp cb=%u\n", + Log3Func(("%s OUT desc_idx=%u seg=%u addr=%RGp cb=%u\n", QUEUENAME(qIdx), uDescIdx, pDescChain->cSegsOut, desc.pGcPhysBuf, desc.cb)); pSeg = &(pDescChain->aSegsOut[pDescChain->cSegsOut++]); @@ -264,5 +264,5 @@ *ppOutSegs = &pVirtqProxy->outSgBuf; - Log2Func(("%s -- segs out: %u, segs in: %u --\n", + Log3Func(("%s -- segs out: %u, segs in: %u --\n", pVirtqProxy->szVirtqName, pDescChain->cSegsOut, pDescChain->cSegsIn)); @@ -290,8 +290,8 @@ size_t cbRemain = RTSgBufCalcTotalLength(pBufSrc); uint16_t uUsedIdx = virtioReadUsedRingIdx(pVirtio, qIdx); - Log2Func(("Copying client data to %s, desc chain (head desc_idx %d)\n", + Log3Func(("Copying client data to %s, desc chain (head desc_idx %d)\n", QUEUENAME(qIdx), uUsedIdx)); - while (cbRemain ) + while (cbRemain) { uint64_t dstSgStart = (uint64_t)pBufDst->paSegs[pBufDst->idxSeg].pvSeg; @@ -326,5 +326,5 @@ pDescChain->uHeadIdx, pDescChain->cSegsIn); - Log2Func(("Copied %u bytes to %u byte buffer\n Write ahead used_idx=%d, %s used_idx=%d\n", + Log3Func(("Copied %u bytes to %u byte buffer\n Write ahead used_idx=%d, %s used_idx=%d\n", cbWritten, cbInSgBuf, pVirtqProxy->uUsedIdx, QUEUENAME(qIdx), uUsedIdx)); return VINF_SUCCESS; @@ -345,5 +345,5 @@ uint16_t uIdx = virtioReadUsedRingIdx(pVirtio, qIdx); - Log2Func(("Updating %s used_idx from %u to %u\n", + Log3Func(("Updating %s used_idx from %u to %u\n", QUEUENAME(qIdx), uIdx, pVirtqProxy->uUsedIdx)); @@ -362,5 +362,5 @@ PVIRTQ_PROXY_T pVirtqProxy = &pVirtio->virtqProxy[qIdx]; - Log2Func(("%s\n", pVirtqProxy->szVirtqName)); + Log3Func(("%s\n", pVirtqProxy->szVirtqName)); @@ -392,5 +392,5 @@ return; } - Log2Func(("...skipping interrupt: VIRTIO_F_EVENT_IDX set but threshold not reached\n")); + Log3Func(("...skipping interrupt: VIRTIO_F_EVENT_IDX set but threshold not reached\n")); } else @@ -402,5 +402,5 @@ return; } - Log2Func(("...skipping interrupt. Guest flagged VIRTQ_AVAIL_F_NO_INTERRUPT for queue\n")); + Log3Func(("...skipping interrupt. Guest flagged VIRTQ_AVAIL_F_NO_INTERRUPT for queue\n")); } @@ -450,8 +450,8 @@ { if (uCause == VIRTIO_ISR_VIRTQ_INTERRUPT) - LogFlowFunc(("reason: buffer added to 'used' ring.\n")); + Log3Func(("reason: buffer added to 'used' ring.\n")); else if (uCause == VIRTIO_ISR_DEVICE_CONFIG) - LogFlowFunc(("reason: device config change\n")); + Log3Func(("reason: device config change\n")); pVirtio->uISR |= uCause; @@ -636,5 +636,5 @@ { pVirtio->uDeviceStatus = *(uint8_t *)pv; - Log2Func(("Guest wrote uDeviceStatus ................ (")); + Log3Func(("Guest wrote uDeviceStatus ................ (")); virtioLogDeviceStatus(pVirtio->uDeviceStatus); Log((")\n")); @@ -653,5 +653,5 @@ else /* Guest READ pCommonCfg->uDeviceStatus */ { - Log2Func(("Guest read uDeviceStatus ................ (")); + Log3Func(("Guest read uDeviceStatus ................ (")); *(uint32_t *)pv = pVirtio->uDeviceStatus; virtioLogDeviceStatus(pVirtio->uDeviceStatus); @@ -758,5 +758,5 @@ { ++pVirtio->uConfigGeneration; - Log2Func(("Bumped cfg. generation to %d because %s%s\n", + Log3Func(("Bumped cfg. generation to %d because %s%s\n", pVirtio->uConfigGeneration, fDevSpecificFieldChanged ? " " : "", @@ -775,10 +775,10 @@ { *(uint8_t *)pv = pVirtio->uISR; - Log2Func(("Read and clear ISR\n")); + Log3Func(("Read and clear ISR\n")); pVirtio->uISR = 0; /** VirtIO specification requires reads of ISR to clear it */ virtioLowerInterrupt(pVirtio); } else { - Log2Func(("Bad read access to mapped capabilities region:\n" + LogFunc(("Bad read access to mapped capabilities region:\n" " pVirtio=%#p GCPhysAddr=%RGp cb=%u\n", pVirtio, GCPhysAddr, pv, cb, pv, cb)); Index: /trunk/src/VBox/Devices/VirtIO/Virtio_1_0.h =================================================================== --- /trunk/src/VBox/Devices/VirtIO/Virtio_1_0.h (revision 80521) +++ /trunk/src/VBox/Devices/VirtIO/Virtio_1_0.h (revision 80522) @@ -320,3 +320,4 @@ bool fWrite, bool fHasIndex, uint32_t idx); + #endif /* !VBOX_INCLUDED_SRC_VirtIO_Virtio_1_0_h */ Index: /trunk/src/VBox/Devices/VirtIO/Virtio_1_0_impl.h =================================================================== --- /trunk/src/VBox/Devices/VirtIO/Virtio_1_0_impl.h (revision 80521) +++ /trunk/src/VBox/Devices/VirtIO/Virtio_1_0_impl.h (revision 80522) @@ -517,15 +517,15 @@ int primed = 0; if (status & VIRTIO_STATUS_ACKNOWLEDGE) - Log(("ACKNOWLEDGE", primed++)); + Log3(("ACKNOWLEDGE", primed++)); if (status & VIRTIO_STATUS_DRIVER) - Log(("%sDRIVER", primed++ ? " | " : "")); + Log3(("%sDRIVER", primed++ ? " | " : "")); if (status & VIRTIO_STATUS_FEATURES_OK) - Log(("%sFEATURES_OK", primed++ ? " | " : "")); + Log3(("%sFEATURES_OK", primed++ ? " | " : "")); if (status & VIRTIO_STATUS_DRIVER_OK) - Log(("%sDRIVER_OK", primed++ ? " | " : "")); + Log3(("%sDRIVER_OK", primed++ ? " | " : "")); if (status & VIRTIO_STATUS_FAILED) - Log(("%sFAILED", primed++ ? " | " : "")); + Log3(("%sFAILED", primed++ ? " | " : "")); if (status & VIRTIO_STATUS_DEVICE_NEEDS_RESET) - Log(("%sNEEDS_RESET", primed++ ? " | " : "")); + Log3(("%sNEEDS_RESET", primed++ ? " | " : "")); } }