Changeset 108371 in vbox

Timestamp:

Feb 25, 2025 1:57:42 PM (8 weeks ago)

Author:

vboxsync

svn:sync-xref-src-repo-rev:

167732

Message:

UsbNet: Minor logging enhancements, including packet dumping/numbering bugref:10779

File:

• trunk/src/VBox/Devices/Network/UsbNet.cpp (modified) (26 diffs)

trunk/src/VBox/Devices/Network/UsbNet.cpp

@@ -422 +422 @@
     STAMCOUNTER                         StatTransmitBytes;
 
+    uint32_t                            u32PktNo;
     /**
      * LUN\#0 data.
@@ -1133 +1134 @@
 static int usbNetCompleteOk(PUSBNET pThis, PVUSBURB pUrb, size_t cbData)
 {
-    LogFunc(("/#%u/ pUrb=%p:%s cbData=%#zx\n", pThis->pUsbIns->iInstance, pUrb, pUrb->pszDesc, cbData));
+    LogFlowFunc(("/#%u/ pUrb=%p:%s cbData=%#zx\n", pThis->pUsbIns->iInstance, pUrb, pUrb->pszDesc, cbData));
 
     pUrb->enmStatus = VUSBSTATUS_OK;
@@ -1149 +1150 @@
 static void usbNetCompleteNotificationOk(PUSBNET pThis, PVUSBURB pUrb, const void *pSrc, size_t cbSrc)
 {
-    LogFunc(("/#%u/ pUrb=%p:%s (cbData=%#x) cbSrc=%#zx\n", pThis->pUsbIns->iInstance, pUrb, pUrb->pszDesc, pUrb->cbData, cbSrc));
+    LogFlowFunc(("/#%u/ pUrb=%p:%s (cbData=%#x) cbSrc=%#zx\n", pThis->pUsbIns->iInstance, pUrb, pUrb->pszDesc, pUrb->cbData, cbSrc));
 
     pUrb->enmStatus = VUSBSTATUS_OK;
@@ -1164 +1165 @@
         memcpy(pDst, pSrc, cbCopy);
         pUrb->cbData = (uint32_t)cbCopy;
-        Log(("Copied %zu bytes to pUrb->abData, source had %zu bytes\n", cbCopy, cbSrc));
+        Log2Func(("/#%u/ Copied %zu bytes to pUrb->abData, source had %zu bytes\n", pThis->pUsbIns->iInstance, cbCopy, cbSrc));
 
         /*
@@ -1267 +1268 @@
 }
 
+#ifdef LOG_ENABLED
+
+DECLINLINE(void) usbNetProtocolDump(const uint8_t *cpPacket, uint32_t cb)
+{
+    RT_NOREF(cb);
+    uint8_t  protocol;
+    uint16_t offset = sizeof(RTNETETHERHDR);
+    uint16_t uEthType = RT_N2H_U16(*(uint16_t*)(cpPacket+12));
+    if (uEthType == RTNET_ETHERTYPE_VLAN)
+    {
+        uEthType = RT_N2H_U16(*(uint16_t*)(cpPacket+16));
+        offset += 4;
+    }
+    if (uEthType == RTNET_ETHERTYPE_ARP)
+    {
+        Log4(("\tARP\n"));
+        return;
+    }
+    else if (uEthType == RTNET_ETHERTYPE_IPV4)
+    {
+        PRTNETIPV4 pHdr = (PRTNETIPV4)(cpPacket + offset);
+        offset += pHdr->ip_hl * 4;
+        protocol = pHdr->ip_p;
+        Log4(("\tIPv4: %RTnaipv4 => %RTnaipv4\n", pHdr->ip_src, pHdr->ip_dst));
+    }
+    else if (uEthType == RTNET_ETHERTYPE_IPV6)
+    {
+        PRTNETIPV6 pHdr = (PRTNETIPV6)(cpPacket + offset);
+        protocol = pHdr->ip6_nxt;
+        offset += sizeof(RTNETIPV6);
+        if (protocol == 0 || protocol == 60)
+        {
+            /* Skip hop-by-hop and destination options */
+            while (cpPacket[offset] == 0 || cpPacket[offset] == 60)
+                offset += 8 * (1 + cpPacket[offset+1]);
+            protocol = cpPacket[offset];
+            offset += 8 * (1 + cpPacket[offset+1]);
+        }
+        Log4(("\tIPv6: %RTnaipv6 => %RTnaipv6\n", pHdr->ip6_src, pHdr->ip6_dst));
+    }
+    else
+    {
+        Log4(("\tEthernet: 0x%04x\n", uEthType));
+        return;
+    }     
+    switch (protocol)
+    {
+        case 1: Log4(("\tICMP\n")); break;
+        case 2: Log4(("\tIGMP\n")); break;
+        case 58: Log4(("\tICMPv6\n")); break;
+
+        case 6:
+            {
+                PRTNETTCP pTcp = (PRTNETTCP)(cpPacket + offset);
+                Log4(("\tTCP: %u => %u, seq=%u ack=%u\n", RT_N2H_U16(pTcp->th_sport), RT_N2H_U16(pTcp->th_dport),
+                      RT_N2H_U32(pTcp->th_seq), RT_N2H_U32(pTcp->th_ack)));
+            }
+            break;
+        case 17:
+            {
+                PRTNETUDP pUdp = (PRTNETUDP)(cpPacket + offset);
+                Log4(("\tUDP: %u => %u\n", RT_N2H_U16(pUdp->uh_sport), RT_N2H_U16(pUdp->uh_dport)));
+            }
+            break;
+        default:
+            Log4(("\tUnknown (%u)", protocol));
+            break;
+    }
+}
+
+DECLINLINE(void) usbNetPacketDump(PUSBNET pThis, const void *pvBuf, size_t cb, const char *pcszText)
+{
+    const uint8_t *cpPacket = (const uint8_t *)pvBuf;
+    if (cb < 14)
+        Log3(("/#%u/ %s packet #%d is too small (%u bytes):\n%.*Rhxd\n",
+              pThis->pUsbIns->iInstance, pcszText, ++pThis->u32PktNo, (uint32_t)cb, (uint32_t)cb, cpPacket));
+    else
+    {
+        Log3(("/#%u/ %s packet #%d, %u bytes, %RTmac => %RTmac\n",
+              pThis->pUsbIns->iInstance, pcszText, ++pThis->u32PktNo, (uint32_t)cb, cpPacket+6, cpPacket));
+        if (LogIs4Enabled())
+            usbNetProtocolDump(cpPacket, (uint32_t)cb);
+        Log5(("%.*Rhxd\n", (uint32_t)cb, cpPacket));
+    }
+}
+
+#else
+#define usbNetPacketDump(pUsbIns, pvBuf, cb, pcszText)
+#endif
 
 /**
@@ -1309 +1399 @@
         return VINF_SUCCESS;
     }
+
+    usbNetPacketDump(pThis, pvBuf, cb, "<-- Rx");
 
     PUSBNCMNTH16 pNth16 = (PUSBNCMNTH16)&pUrb->abData[0];
@@ -1468 +1560 @@
 
     if (pUrb)
-        LogFunc(("/#%u/ pUrb=%p:%s\n", pUsbIns->iInstance, pUrb, pUrb->pszDesc));
+        Log2Func(("/#%u/ pUrb=%p:%s\n", pUsbIns->iInstance, pUrb, pUrb->pszDesc));
     return pUrb;
 }
@@ -1525 +1617 @@
     if (pUrb->cbData < sizeof(*pNth16))
     {
-        Log(("UsbNet: Bad NTH16: cbData=%#x < min=%#x\n", pUrb->cbData, sizeof(*pNth16) ));
+        LogFunc(("/#%u/ Bad NTH16: cbData=%#x < min=%#x\n", pThis->pUsbIns->iInstance, pUrb->cbData, sizeof(*pNth16) ));
         return usbNetCompleteStall(pThis, NULL, pUrb, "BAD NTH16");
     }
     if (pNth16->dwSignature != USBNCMNTH16_SIGNATURE)
     {
-        Log(("UsbNet: NTH16: Invalid dwSignature value: %#x\n", pNth16->dwSignature));
+        LogFunc(("/#%u/ NTH16: Invalid dwSignature value: %#x\n", pNth16->dwSignature));
         return usbNetCompleteStall(pThis, NULL, pUrb, "Bad NTH16");
     }
-    Log(("UsbNet: NTH16: wHeaderLength=%#x wSequence=%#x wBlockLength=%#x wNdpIndex=%#x cbData=%#x fShortNotOk=%RTbool\n",
-         pNth16->wHeaderLength, pNth16->wSequence, pNth16->wBlockLength, pNth16->wNdpIndex, pUrb->cbData, pUrb->fShortNotOk));
+    Log2Func(("/#%u/ NTH16: wHeaderLength=%#x wSequence=%#x wBlockLength=%#x wNdpIndex=%#x cbData=%#x fShortNotOk=%RTbool\n", pThis->pUsbIns->iInstance,
+              pNth16->wHeaderLength, pNth16->wSequence, pNth16->wBlockLength, pNth16->wNdpIndex, pUrb->cbData, pUrb->fShortNotOk));
     if (pNth16->wHeaderLength != sizeof(*pNth16))
     {
-        Log(("UsbNet: NTH16: Bad wHeaderLength value: %#x\n", pNth16->wHeaderLength));
+        LogFunc(("/#%u/ NTH16: Bad wHeaderLength value: %#x\n", pThis->pUsbIns->iInstance, pNth16->wHeaderLength));
         return usbNetCompleteStall(pThis, NULL, pUrb, "Bad NTH16");
 
@@ -1543 +1635 @@
     if (pNth16->wBlockLength > pUrb->cbData)
     {
-        Log(("UsbNet: NTH16: Bad wBlockLength value: %#x\n", pNth16->wBlockLength));
+        LogFunc(("/#%u/ NTH16: Bad wBlockLength value: %#x\n", pThis->pUsbIns->iInstance, pNth16->wBlockLength));
         return usbNetCompleteStall(pThis, NULL, pUrb, "Bad NTH16");
     }
@@ -1549 +1641 @@
     if (pNth16->wNdpIndex < sizeof(*pNth16))
     {
-        Log(("UsbNet: NTH16: wNdpIndex is too small: %#x (%u), at least required %#x\n",
+        LogFunc(("/#%u/ NTH16: wNdpIndex is too small: %#x (%u), at least required %#x\n", pThis->pUsbIns->iInstance,
              pNth16->wNdpIndex, pNth16->wNdpIndex, sizeof(*pNth16) ));
         return usbNetCompleteStall(pThis, NULL, pUrb, "Bad NTH16");
@@ -1560 +1652 @@
         if (offNdp16Next >= pUrb->cbData)
         {
-            Log(("UsbNet: Bad NDP16: offNdp16Next=%#x >= cbData=%#x\n", offNdp16Next, pUrb->cbData));
+            LogFunc(("/#%u/ Bad NDP16: offNdp16Next=%#x >= cbData=%#x\n", pThis->pUsbIns->iInstance, offNdp16Next, pUrb->cbData));
             return usbNetCompleteStall(pThis, NULL, pUrb, "BAD NDP16");
         }
@@ -1568 +1660 @@
         if (cbNdpMax < sizeof(*pNdp16))
         {
-            Log(("UsbNet: Bad NDP16: cbNdpMax=%#x < min=%#x\n", cbNdpMax, sizeof(*pNdp16) ));
+            LogFunc(("/#%u/ Bad NDP16: cbNdpMax=%#x < min=%#x\n", pThis->pUsbIns->iInstance, cbNdpMax, sizeof(*pNdp16) ));
             return usbNetCompleteStall(pThis, NULL, pUrb, "BAD NDP16");
         }
@@ -1575 +1667 @@
             && pNdp16->dwSignature != USBNCMNDP16_SIGNATURE_NCM1)
         {
-            Log(("UsbNet: NDP16: Invalid dwSignature value: %#x\n", pNdp16->dwSignature));
+            LogFunc(("/#%u/ NDP16: Invalid dwSignature value: %#x\n", pThis->pUsbIns->iInstance, pNdp16->dwSignature));
             return usbNetCompleteStall(pThis, NULL, pUrb, "Bad NDP16");
         }
@@ -1583 +1675 @@
             || pNdp16->wLength > cbNdpMax)
         {
-            Log(("UsbNet: NDP16: Invalid size value: %#x, req. (min %#x max %#x)\n",
+            LogFunc(("/#%u/ NDP16: Invalid size value: %#x, req. (min %#x max %#x)\n", pThis->pUsbIns->iInstance,
                  pNdp16->wLength, sizeof(*pNdp16), cbNdpMax));
             return usbNetCompleteStall(pThis, NULL, pUrb, "Bad NDP16");
@@ -1607 +1699 @@
                     || pDGram->wDatagramIndex >= pUrb->cbData)
                 {
-                    Log(("UsbNet: DGRAM16: Invalid wDatagramIndex value: %#x\n", pDGram->wDatagramIndex));
+                    LogFunc(("/#%u/ DGRAM16: Invalid wDatagramIndex value: %#x\n", pThis->pUsbIns->iInstance, pDGram->wDatagramIndex));
                     return usbNetCompleteStall(pThis, NULL, pUrb, "Bad DGRAM16");
                 }
@@ -1613 +1705 @@
                 if (pUrb->cbData - pDGram->wDatagramIndex < pDGram->wDatagramLength)
                 {
-                    Log(("UsbNet: DGRAM16: Invalid wDatagramLength value: %#x (max %#x)\n",
+                    LogFunc(("/#%u/ DGRAM16: Invalid wDatagramLength value: %#x (max %#x)\n", pThis->pUsbIns->iInstance,
                          pDGram->wDatagramLength, pUrb->cbData - pDGram->wDatagramIndex));
                     return usbNetCompleteStall(pThis, NULL, pUrb, "Bad DGRAM16");
@@ -1624 +1716 @@
                     uint8_t *pbBuf = pSgBuf ? (uint8_t *)pSgBuf->aSegs[0].pvSeg : NULL;
                     memcpy(pbBuf, &pUrb->abData[pDGram->wDatagramIndex], pDGram->wDatagramLength);
+                    usbNetPacketDump(pThis, pbBuf, pDGram->wDatagramLength, "--> Tx");
                     pSgBuf->cbUsed = pDGram->wDatagramLength;
                     rc = pThis->Lun0.pINetwork->pfnSendBuf(pThis->Lun0.pINetwork, pSgBuf, true /* fOnWorkerThread */);
@@ -1640 +1733 @@
         else
         {
-            Log(("UsbNet: NDP16: Not implemented\n"));
+            LogFunc(("/#%u/ NDP16: Not implemented\n", pThis->pUsbIns->iInstance));
             return usbNetCompleteStall(pThis, NULL, pUrb, "Bad NDP16");
         }
@@ -1754 +1847 @@
                 if (pSetup->bmRequestType != (VUSB_TO_DEVICE | VUSB_REQ_STANDARD | VUSB_DIR_TO_HOST))
                 {
-                    Log(("UsbNet: Bad GET_DESCRIPTOR req: bmRequestType=%#x\n", pSetup->bmRequestType));
+                    LogFunc(("/#%u/ Bad GET_DESCRIPTOR req: bmRequestType=%#x\n", pThis->pUsbIns->iInstance, pSetup->bmRequestType));
                     return usbNetCompleteStall(pThis, pEp, pUrb, "Bad GET_DESCRIPTOR");
                 }
@@ -1763 +1856 @@
 
                     case VUSB_DT_STRING:
-                        Log(("UsbNet: GET_DESCRIPTOR DT_STRING wValue=%#x wIndex=%#x\n", pSetup->wValue, pSetup->wIndex));
+                        LogFunc(("/#%u/ GET_DESCRIPTOR DT_STRING wValue=%#x wIndex=%#x\n", pThis->pUsbIns->iInstance, pSetup->wValue, pSetup->wIndex));
                         break;
                     case VUSB_DT_DEVICE_QUALIFIER:
-                        Log(("UsbNet: GET_DESCRIPTOR DT_DEVICE_QUALIFIER wValue=%#x wIndex=%#x\n", pSetup->wValue, pSetup->wIndex));
+                        LogFunc(("/#%u/ GET_DESCRIPTOR DT_DEVICE_QUALIFIER wValue=%#x wIndex=%#x\n", pThis->pUsbIns->iInstance, pSetup->wValue, pSetup->wIndex));
                         /* Returned data is written after the setup message. */
                         cbCopy = pUrb->cbData - sizeof(*pSetup);
@@ -1773 +1866 @@
                         return usbNetCompleteOk(pThis, pUrb, cbCopy + sizeof(*pSetup));
                     case VUSB_DT_BOS:
-                        Log(("UsbNet: GET_DESCRIPTOR DT_BOS wValue=%#x wIndex=%#x\n", pSetup->wValue, pSetup->wIndex));
+                        LogFunc(("/#%u/ GET_DESCRIPTOR DT_BOS wValue=%#x wIndex=%#x\n", pThis->pUsbIns->iInstance, pSetup->wValue, pSetup->wIndex));
                         /* Returned data is written after the setup message. */
                         cbCopy = pUrb->cbData - sizeof(*pSetup);
@@ -1780 +1873 @@
                         return usbNetCompleteOk(pThis, pUrb, cbCopy + sizeof(*pSetup));
                     default:
-                        Log(("UsbNet: GET_DESCRIPTOR, huh? wValue=%#x wIndex=%#x\n", pSetup->wValue, pSetup->wIndex));
+                        LogFunc(("/#%u/ GET_DESCRIPTOR, huh? wValue=%#x wIndex=%#x\n", pThis->pUsbIns->iInstance, pSetup->wValue, pSetup->wIndex));
                         break;
                 }
@@ -1854 +1947 @@
 
         /** @todo implement this. */
-        Log(("UsbNet: Implement standard request: bmRequestType=%#x bRequest=%#x wValue=%#x wIndex=%#x wLength=%#x\n",
+        LogFunc(("/#%u/ Implement standard request: bmRequestType=%#x bRequest=%#x wValue=%#x wIndex=%#x wLength=%#x\n", pThis->pUsbIns->iInstance,
              pSetup->bmRequestType, pSetup->bRequest, pSetup->wValue, pSetup->wIndex, pSetup->wLength));
 
@@ -1867 +1960 @@
                 if (pSetup->bmRequestType != (VUSB_TO_INTERFACE | VUSB_REQ_CLASS | VUSB_DIR_TO_HOST))
                 {
-                    Log(("UsbNet: Bad GET_NTB_PARAMETERS req: bmRequestType=%#x\n", pSetup->bmRequestType));
+                    LogFunc(("/#%u/ Bad GET_NTB_PARAMETERS req: bmRequestType=%#x\n", pThis->pUsbIns->iInstance, pSetup->bmRequestType));
                     return usbNetCompleteStall(pThis, pEp, pUrb, "Bad GET_NTB_PARAMETERS");
                 }
@@ -1900 +1993 @@
     else
     {
-        Log(("UsbNet: Unknown control msg: bmRequestType=%#x bRequest=%#x wValue=%#x wIndex=%#x wLength=%#x\n",
+        LogFunc(("/#%u/ Unknown control msg: bmRequestType=%#x bRequest=%#x wValue=%#x wIndex=%#x wLength=%#x\n", pThis->pUsbIns->iInstance,
              pSetup->bmRequestType, pSetup->bRequest, pSetup->wValue, pSetup->wIndex, pSetup->wLength));
         return usbNetCompleteStall(pThis, pEp, pUrb, "Unknown control msg");
@@ -2216 +2309 @@
     LogFlowFunc(("/#%u/\n", iInstance));
 
+    pThis->u32PktNo = 1;
     /*
      * Perform the basic structure initialization first so the destructor