Changeset 80522 in vbox for trunk/src

Timestamp:

Aug 31, 2019 9:19:08 PM (5 years ago)

Author:

vboxsync

Message:

Storage/DevVirtioSCSI.cpp: Changes to logging to by default just log the SCSI Commands and Response, and format them to be legible. Still trying to understand the SCSI dialog the logging shows. See bugref:9440, Comment #62 for a log out the exchanges and comments

Location:

trunk/src/VBox/Devices

Files:

• Storage/DevVirtioSCSI.cpp (modified) (21 diffs)
• VirtIO/Virtio_1_0.cpp (modified) (16 diffs)
• VirtIO/Virtio_1_0.h (modified) (1 diff)
• VirtIO/Virtio_1_0_impl.h (modified) (1 diff)

trunk/src/VBox/Devices/Storage/DevVirtioSCSI.cpp

@@ -487 +487 @@
      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 +605 @@
 }
 
+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 +871 @@
  * @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 +885 @@
     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 +914 @@
 
 
-    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 +993 @@
     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 +1037 @@
     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 +1078 @@
 
     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 +1128 @@
         }
 
-        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 +1137 @@
         {
             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 +1244 @@
             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 +1260 @@
 
             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 +1285 @@
         }
         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 +1337 @@
             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 +1343 @@
                 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 +1360 @@
             virtioScsiCtrl(pThis, qIdx, pInSgBuf, pOutSgBuf);
         else
-            virtioScsiSubmitReq(pThis, qIdx, pInSgBuf, pOutSgBuf);
+            virtioScsiReqSubmit(pThis, qIdx, pInSgBuf, pOutSgBuf);
     }
     return VINF_SUCCESS;
@@ -1505 +1569 @@
     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 +1575 @@
             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 +1583 @@
     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 +1593 @@
 static DECLCALLBACK(void) virtioScsiStatusChanged(VIRTIOHANDLE hVirtio, void *pClient,  bool fVirtioReady)
 {
-    LogFunc(("\n"));
     RT_NOREF(hVirtio);
     PVIRTIOSCSI pThis = (PVIRTIOSCSI)pClient;
@@ -1535 +1598 @@
     if (fVirtioReady)
     {
-        LogFunc(("VirtIO ready\n"));
+        LogFunc(("VirtIO ready\n---------------------------------------------------------------------------------"));
         uint64_t features = virtioGetNegotiatedFeatures(hVirtio);
         pThis->fHasT10pi     = features & VIRTIO_SCSI_F_T10_PI;

trunk/src/VBox/Devices/VirtIO/Virtio_1_0.cpp

@@ -81 +81 @@
             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 +200 @@
     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 +238 @@
         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 +245 @@
         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 +264 @@
         *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 +290 @@
     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 +326 @@
                         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 +345 @@
 
     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 +362 @@
 
     PVIRTQ_PROXY_T pVirtqProxy = &pVirtio->virtqProxy[qIdx];
-    Log2Func(("%s\n", pVirtqProxy->szVirtqName));
+    Log3Func(("%s\n", pVirtqProxy->szVirtqName));
 
 
@@ -392 +392 @@
                 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 +402 @@
                 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 +450 @@
 {
    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 +636 @@
         {
             pVirtio->uDeviceStatus = *(uint8_t *)pv;
-            Log2Func(("Guest wrote uDeviceStatus ................ ("));
+            Log3Func(("Guest wrote uDeviceStatus ................ ("));
             virtioLogDeviceStatus(pVirtio->uDeviceStatus);
             Log((")\n"));
@@ -653 +653 @@
         else /* Guest READ pCommonCfg->uDeviceStatus */
         {
-            Log2Func(("Guest read  uDeviceStatus ................ ("));
+            Log3Func(("Guest read  uDeviceStatus ................ ("));
             *(uint32_t *)pv = pVirtio->uDeviceStatus;
             virtioLogDeviceStatus(pVirtio->uDeviceStatus);
@@ -758 +758 @@
         {
             ++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 ? "<dev cfg changed> " : "",
@@ -775 +775 @@
     {
         *(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));

trunk/src/VBox/Devices/VirtIO/Virtio_1_0.h

@@ -320 +320 @@
                             bool fWrite, bool fHasIndex, uint32_t idx);
 
+
 #endif /* !VBOX_INCLUDED_SRC_VirtIO_Virtio_1_0_h */

trunk/src/VBox/Devices/VirtIO/Virtio_1_0_impl.h

@@ -517 +517 @@
         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++ ? " | " : ""));
     }
 }