Changeset 91012 in vbox for trunk/src

Timestamp:

Aug 30, 2021 7:44:20 PM (3 years ago)

Author:

vboxsync

Message:

Audio/Validation Kit: More (verbose) releasing logging for the TCP transport layer of VKAT. ​bugref:10008

File:

• trunk/src/VBox/Devices/Audio/AudioTestServiceTcp.cpp (modified) (27 diffs)

trunk/src/VBox/Devices/Audio/AudioTestServiceTcp.cpp

@@ -131 +131 @@
     if (pClient->hTcpClient != NIL_RTSOCKET)
     {
+        LogRelFlowFunc(("Disconnecting client %RTsock\n", pClient->hTcpClient));
+
         int rc;
         if (pClient->fFromServer)
@@ -150 +152 @@
  * Sets the current client socket in a safe manner.
  *
- * @returns NIL_RTSOCKET if consumed, other wise hTcpClient.
+ * @returns NIL_RTSOCKET if consumed, otherwise hTcpClient.
  * @param   pThis           Transport instance.
  * @param   pClient         Client to set the socket for.
@@ -163 +165 @@
         && !pThis->fStopConnecting)
     {
-        LogFunc(("New client connected\n"));
+        LogRelFlowFunc(("New client %RTsock connected (fFromServer=%RTbool)\n", hTcpClient, fFromServer));
 
         pClient->fFromServer = fFromServer;
@@ -206 +208 @@
     /** @todo Implement cancellation support for using pConnCtx->msTimeout. */
 
+    LogRelFlowFuncEnter();
+
     RTSOCKET hTcpClient;
     int rc = RTTcpServerListen2(pThis->pTcpServer, &hTcpClient);
@@ -214 +218 @@
     }
 
+    LogRelFlowFuncLeaveRC(rc);
     return rc;
 }
@@ -233 +238 @@
     uint64_t msStartTs = RTTimeMilliTS();
 
+    LogRelFlowFuncEnter();
+
     for (;;)
     {
@@ -259 +266 @@
             && RTTimeMilliTS() - msStartTs >= pConnCtx->msTimeout)
         {
+            LogRelFlowFunc(("Timed out (%RU32ms)\n", pConnCtx->msTimeout));
             return VERR_TIMEOUT;
         }
@@ -265 +273 @@
         RTThreadUserWait(hSelf, 1536);
     }
+
+    LogRelFlowFuncLeave();
     return VINF_SUCCESS;
 }
@@ -279 +289 @@
     int rcRet = VINF_SUCCESS;
 
+    LogRelFlowFuncEnter();
+
     if (pThis->hThreadConnect != NIL_RTTHREAD)
     {
@@ -301 +313 @@
         }
     }
+
+    LogRelFlowFuncLeaveRC(rcRet);
     return rcRet;
 }
@@ -314 +328 @@
     int rc;
 
-    LogFunc(("msTimeout=%RU32, enmConnMode=%#x\n", msTimeout, pThis->enmConnMode));
+    LogRelFlowFunc(("msTimeout=%RU32, enmConnMode=%#x\n", msTimeout, pThis->enmConnMode));
 
     uint64_t msStartTs = RTTimeMilliTS();
@@ -324 +338 @@
         pClient->fFromServer = true;
         rc = RTTcpServerListen2(pThis->pTcpServer, &pClient->hTcpClient);
-        LogFunc(("RTTcpServerListen2 -> %Rrc\n", rc));
+        LogRelFlowFunc(("RTTcpServerListen2 -> %Rrc\n", rc));
     }
     else if (pThis->enmConnMode == ATSCONNMODE_CLIENT)
@@ -331 +345 @@
         for (;;)
         {
-            Log2Func(("Calling RTTcpClientConnect(%s, %u,)...\n", pThis->szConnectAddr, pThis->uConnectPort));
+            LogRelFlowFunc(("Calling RTTcpClientConnect(%s, %u,)...\n", pThis->szConnectAddr, pThis->uConnectPort));
             rc = RTTcpClientConnect(pThis->szConnectAddr, pThis->uConnectPort, &pClient->hTcpClient);
-            LogFunc(("RTTcpClientConnect -> %Rrc\n", rc));
+            LogRelFlowFunc(("RTTcpClientConnect -> %Rrc\n", rc));
             if (RT_SUCCESS(rc) || atsTcpIsFatalClientConnectStatus(rc))
                 break;
@@ -422 +436 @@
     }
 
+    if (RT_FAILURE(rc))
+        LogRelFunc(("Failed with %Rrc\n", rc));
+
     return rc;
 }
@@ -430 +447 @@
 static DECLCALLBACK(void) atsTcpNotifyReboot(PATSTRANSPORTINST pThis)
 {
-    LogFunc(("RTTcpServerDestroy(%p)\n", pThis->pTcpServer));
+    LogRelFlowFuncEnter();
     if (pThis->pTcpServer)
     {
         int rc = RTTcpServerDestroy(pThis->pTcpServer);
         if (RT_FAILURE(rc))
-            LogRel(("RTTcpServerDestroy failed in atsTcpNotifyReboot: %Rrc", rc));
+            LogRelFunc(("RTTcpServerDestroy failed, rc=%Rrc", rc));
         pThis->pTcpServer = NULL;
     }
+    LogRelFlowFuncLeave();
 }
 
@@ -475 +493 @@
      * Disconnect the client.
      */
-    LogFunc(("atsTcpDisconnectClient(%RTsock) (RTTcpWrite rc=%Rrc)\n", pClient->hTcpClient, rc));
+    LogRelFlowFunc(("atsTcpDisconnectClient(%RTsock) (RTTcpWrite rc=%Rrc)\n", pClient->hTcpClient, rc));
     atsTcpDisconnectClient(pThis, pClient);
 }
@@ -493 +511 @@
     Log3Func(("%RU32 -> %zu\n", pPktHdr->cb, cbToSend));
 
-    Log3Func(("Header:\n"
-              "%.*Rhxd\n", RT_MIN(sizeof(ATSPKTHDR), cbToSend), pPktHdr));
+    LogRelFlowFunc(("Header:\n"
+                    "%.*Rhxd\n", RT_MIN(sizeof(ATSPKTHDR), cbToSend), pPktHdr));
 
     if (cbToSend > sizeof(ATSPKTHDR))
-        Log3Func(("Payload:\n"
-                  "%.*Rhxd\n",
-                  RT_MIN(64, cbToSend - sizeof(ATSPKTHDR)), (uint8_t *)pPktHdr + sizeof(ATSPKTHDR)));
+        LogRelFlowFunc(("Payload:\n"
+                        "%.*Rhxd\n",
+                        RT_MIN(64, cbToSend - sizeof(ATSPKTHDR)), (uint8_t *)pPktHdr + sizeof(ATSPKTHDR)));
 
     int rc = RTTcpWrite(pClient->hTcpClient, pPktHdr, cbToSend);
@@ -506 +524 @@
     {
         /* assume fatal connection error. */
-        LogFunc(("RTTcpWrite -> %Rrc -> atsTcpDisconnectClient(%RTsock)\n", rc, pClient->hTcpClient));
+        LogRelFunc(("RTTcpWrite -> %Rrc -> atsTcpDisconnectClient(%RTsock)\n", rc, pClient->hTcpClient));
         atsTcpDisconnectClient(pThis, pClient);
     }
@@ -561 +579 @@
         if (cbRead == 0)
         {
-            LogFunc(("RTTcpRead -> %Rrc / cbRead=0 -> VERR_NET_NOT_CONNECTED (#1)\n", rc));
+            LogRelFunc(("RTTcpRead -> %Rrc / cbRead=0 -> VERR_NET_NOT_CONNECTED (#1)\n", rc));
             rc = VERR_NET_NOT_CONNECTED;
             break;
@@ -601 +619 @@
                     if (cbRead == 0)
                     {
-                        LogFunc(("RTTcpRead -> %Rrc / cbRead=0 -> VERR_NET_NOT_CONNECTED (#2)\n", rc));
+                        LogRelFunc(("RTTcpRead -> %Rrc / cbRead=0 -> VERR_NET_NOT_CONNECTED (#2)\n", rc));
                         rc = VERR_NET_NOT_CONNECTED;
                         break;
@@ -609 +627 @@
                 }
 
-                Log3Func(("Header:\n"
-                          "%.*Rhxd\n", sizeof(ATSPKTHDR), pbData));
+                LogRelFlowFunc(("Header:\n"
+                                "%.*Rhxd\n", sizeof(ATSPKTHDR), pbData));
 
                 if (   RT_SUCCESS(rc)
                     && cbData > sizeof(ATSPKTHDR))
-                    Log3Func(("Payload:\n"
-                              "%.*Rhxd\n", RT_MIN(64, cbData - sizeof(ATSPKTHDR)), (uint8_t *)pbData + sizeof(ATSPKTHDR)));
+                    LogRelFlowFunc(("Payload:\n"
+                                    "%.*Rhxd\n", RT_MIN(64, cbData - sizeof(ATSPKTHDR)), (uint8_t *)pbData + sizeof(ATSPKTHDR)));
             }
         }
@@ -643 +661 @@
 
             /* assume fatal connection error. */
-            LogFunc(("RTTcpRead -> %Rrc -> atsTcpDisconnectClient(%RTsock)\n", rc, pClient->hTcpClient));
+            LogRelFunc(("RTTcpRead -> %Rrc -> atsTcpDisconnectClient(%RTsock)\n", rc, pClient->hTcpClient));
             atsTcpDisconnectClient(pThis, pClient);
         }
@@ -684 +702 @@
 static DECLCALLBACK(void) atsTcpTerm(PATSTRANSPORTINST pThis)
 {
+    LogRelFlowFuncEnter();
+
     /* Signal thread */
     if (RTCritSectIsInitialized(&pThis->CritSect))
@@ -701 +721 @@
     if (pThis->pTcpServer)
     {
-        LogFunc(("Destroying server...\n"));
+        LogRelFlowFunc(("Destroying server...\n"));
         int rc = RTTcpServerDestroy(pThis->pTcpServer);
         if (RT_FAILURE(rc))
-            LogRel(("RTTcpServerDestroy failed in atsTcpTerm: %Rrc", rc));
+            LogRelFunc(("RTTcpServerDestroy failed with %Rrc", rc));
         pThis->pTcpServer        = NULL;
     }
@@ -711 +731 @@
     atsTcpConnectWaitOnThreads(pThis, 15000);
 
-    LogFunc(("Done\n"));
+    LogRelFlowFuncLeave();
 }
 
@@ -759 +779 @@
             if (rc == VERR_NET_DOWN)
             {
-                LogRel2(("RTTcpServerCreateEx(%s, %u,) failed: %Rrc, retrying for 20 seconds...\n",
-                         pThis->szBindAddr[0] ? pThis->szBindAddr : NULL, pThis->uBindPort, rc));
+                LogRelFunc(("RTTcpServerCreateEx(%s, %u,) failed: %Rrc, retrying for 20 seconds...\n",
+                            pThis->szBindAddr[0] ? pThis->szBindAddr : NULL, pThis->uBindPort, rc));
                 uint64_t StartMs = RTTimeMilliTS();
                 do
@@ -769 +789 @@
                          && RTTimeMilliTS() - StartMs < 20000);
                 if (RT_SUCCESS(rc))
-                    LogRel2(("RTTcpServerCreateEx succceeded\n"));
+                    LogRelFunc(("RTTcpServerCreateEx succceeded\n"));
             }
 
             if (RT_FAILURE(rc))
             {
-                LogRel(("RTTcpServerCreateEx(%s, %u,) failed: %Rrc\n",
-                        pThis->szBindAddr[0] ? pThis->szBindAddr : NULL, pThis->uBindPort, rc));
+                LogRelFunc(("RTTcpServerCreateEx(%s, %u,) failed: %Rrc\n",
+                            pThis->szBindAddr[0] ? pThis->szBindAddr : NULL, pThis->uBindPort, rc));
             }
         }