Changeset 38113 in vbox

Timestamp:

Jul 22, 2011 1:57:35 PM (14 years ago)

Author:

vboxsync

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

73065

Message:

VBoxService/GuestCtrl: Fixed stability issues due to PID recycling, enhanced and unified debug logging along with thread names to stdout.

Location:

trunk/src/VBox/Additions/common/VBoxService

Files:

• VBoxService.cpp (modified) (4 diffs)
• VBoxServiceControlExec.cpp (modified) (37 diffs)
• VBoxServiceControlExecThread.cpp (modified) (9 diffs)
• VBoxServiceControlExecThread.h (modified) (1 diff)
• VBoxServiceInternal.h (modified) (3 diffs)
• VBoxServicePipeBuf.cpp (modified) (17 diffs)
• VBoxServicePipeBuf.h (modified) (2 diffs)

trunk/src/VBox/Additions/common/VBoxService/VBoxService.cpp

@@ -59 +59 @@
 /** The current verbosity level. */
 int g_cVerbosity = 0;
+/** Critical section for (debug) logging. */
+#ifdef DEBUG
+ RTCRITSECT g_csLog;
+#endif
 /** The default service interval (the -i | --interval) option). */
 uint32_t g_DefaultInterval = 0;
@@ -217 +221 @@
 void VBoxServiceVerbose(int iLevel, const char *pszFormat, ...)
 {
-    if (iLevel <= g_cVerbosity)
-    {
-        RTStrmPrintf(g_pStdOut, "%s: ", g_pszProgName);
-        va_list va;
-        va_start(va, pszFormat);
-        RTStrmPrintfV(g_pStdOut, pszFormat, va);
-        va_end(va);
-        va_start(va, pszFormat);
-        LogRel(("%s: %N", g_pszProgName, pszFormat, &va));
-        va_end(va);
-    }
+#ifdef DEBUG
+    int rc = RTCritSectEnter(&g_csLog);
+    if (RT_SUCCESS(rc))
+    {
+#endif
+        if (iLevel <= g_cVerbosity)
+        {
+#ifdef DEBUG
+            const char *pszThreadName = RTThreadSelfName();
+            AssertPtr(pszThreadName);
+            RTStrmPrintf(g_pStdOut, "%s [%s]: ",
+                         g_pszProgName, pszThreadName);
+#else
+            RTStrmPrintf(g_pStdOut, "%s: ", g_pszProgName);
+#endif
+            va_list va;
+            va_start(va, pszFormat);
+            RTStrmPrintfV(g_pStdOut, pszFormat, va);
+            va_end(va);
+            va_start(va, pszFormat);
+            LogRel(("%s: %N", g_pszProgName, pszFormat, &va));
+            va_end(va);
+        }
+#ifdef DEBUG
+        int rc2 = RTCritSectLeave(&g_csLog);
+        if (RT_SUCCESS(rc))
+            rc = rc2;
+    }
+#endif
 }
 
@@ -580 +602 @@
         return RTMsgInitFailure(rc);
     g_pszProgName = RTPathFilename(argv[0]);
+#ifdef DEBUG
+    rc = RTCritSectInit(&g_csLog);
+    AssertRC(rc);
+#endif
 
 #ifdef VBOXSERVICE_TOOLBOX
@@ -851 +877 @@
 
     VBoxServiceVerbose(0, "Ended.\n");
+
+#ifdef DEBUG
+    RTCritSectDelete(&g_csLog);
+#endif
     return rcExit;
 }

trunk/src/VBox/Additions/common/VBoxService/VBoxServiceControlExec.cpp

@@ -191 +191 @@
 
 /**
- * Handle pending output data/error on standard out or standard error.
+ * Handle pending output data/error on stdout or stderr.
  *
  * @return  IPRT status code.
@@ -206 +206 @@
     AssertPtrReturn(pBuf, VERR_INVALID_POINTER);
 
-#ifdef DEBUG
-    VBoxServiceVerbose(4, "ControlExec: HandleOutputEvent: fPollEvt=%#x, uHandle=%u\n",
-                       fPollEvt, uHandleId);
-#endif
-
     /*
      * Try drain the pipe before acting on any errors.
@@ -224 +219 @@
         rc = VBoxServicePipeBufWriteToBuf(pBuf, abBuf,
                                           cbRead, false /* Pending close */, &cbWritten);
+#ifdef DEBUG_andy
+        VBoxServiceVerbose(4, "ControlExec: Written output event [%u %u], cbRead=%u, cbWritten=%u, rc=%Rrc, uHandleId=%u, fPollEvt=%#x\n",
+                           pBuf->uPID, pBuf->uPipeId, cbRead, cbWritten, rc, uHandleId, fPollEvt);
+#endif
         if (RT_SUCCESS(rc))
         {
@@ -257 +256 @@
                                                    PRTPIPE phNotificationPipeR, PRTPIPE phInputPipeW)
 {
-#ifdef DEBUG
+#ifdef DEBUG_andy
     VBoxServiceVerbose(4, "ControlExec: HandleStdInputNotify\n");
 #endif
@@ -317 +316 @@
     AssertPtr(pData);
 
-    /* Assign PID to thread data. */
-    pData->uPID = hProcess;
+    /*
+     * Assign PID to thread data.
+     * Also check if there already was a thread with the same PID and shut it down -- otherwise
+     * the first (stale) entry will be found and we get really weird results!
+     */
+    rc = VBoxServiceControlExecThreadAssignPID(pData, hProcess);
+    if (RT_FAILURE(rc))
+    {
+        VBoxServiceError("ControlExec: Unable to assign PID to new thread, rc=%Rrc\n", rc);
+        return rc;
+    }
 
     /*
@@ -324 +332 @@
      * and that it's now OK to send input to the process.
      */
-    VBoxServiceVerbose(3, "ControlExec: Process started: PID=%u, CID=%u, User=%s\n",
+    VBoxServiceVerbose(3, "ControlExec: [PID %u]: Process started, CID=%u, User=%s\n",
                        pData->uPID, pThread->uContextID, pData->pszUser);
     rc = VbglR3GuestCtrlExecReportStatus(pThread->uClientID, pThread->uContextID,
@@ -349 +357 @@
         if (RT_SUCCESS(rc2))
         {
-            VBoxServiceVerbose(4, "ControlExec: RTPollNoResume idPollHnd=%u\n", idPollHnd);
+            /*VBoxServiceVerbose(4, "ControlExec: [PID %u}: RTPollNoResume idPollHnd=%u\n",
+                                 pData->uPID, idPollHnd);*/
             switch (idPollHnd)
             {
@@ -370 +379 @@
 
                 case VBOXSERVICECTRLPIPEID_STDOUT:
+#ifdef DEBUG
+                    VBoxServiceVerbose(4, "ControlExec: [PID %u]: StdOut fPollEvt=%#x\n",
+                                       pData->uPID, fPollEvt);
+#endif
                     rc = VBoxServiceControlExecProcHandleOutputEvent(hPollSet, fPollEvt, phStdOutR,
                                                                      VBOXSERVICECTRLPIPEID_STDOUT, &pData->stdOut);
+// TEST!!!
+VBoxServicePipeBufIsEnabled(&pData->stdOut);
                     break;
 
                 case VBOXSERVICECTRLPIPEID_STDERR:
+#ifdef DEBUG
+                    VBoxServiceVerbose(4, "ControlExec: [PID %u]: StdErr: fPollEvt=%#x\n",
+                                       pData->uPID, fPollEvt);
+#endif
                     rc = VBoxServiceControlExecProcHandleOutputEvent(hPollSet, fPollEvt, phStdErrR,
                                                                      VBOXSERVICECTRLPIPEID_STDERR, &pData->stdErr);
@@ -380 +399 @@
 
                 default:
-                    AssertMsgFailed(("idPollHnd=%u fPollEvt=%#x\n", idPollHnd, fPollEvt));
+                    AssertMsgFailed(("PID=%u idPollHnd=%u fPollEvt=%#x\n",
+                                     pData->uPID, idPollHnd, fPollEvt));
                     break;
             }
@@ -428 +448 @@
             if (cMsElapsed >= cMsTimeout)
             {
-                VBoxServiceVerbose(3, "ControlExec: Process timed out (%ums elapsed > %ums timeout), killing ...", cMsElapsed, cMsTimeout);
+                VBoxServiceVerbose(3, "ControlExec: [PID %u]: Timed out (%ums elapsed > %ums timeout), killing ...",
+                                   pData->uPID, cMsElapsed, cMsTimeout);
 
                 fProcessTimedOut = true;
@@ -463 +484 @@
         if (MsProcessKilled == UINT64_MAX)
         {
-            VBoxServiceVerbose(3, "ControlExec: Process (PID=%u) is still alive and not killed yet\n",
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Is still alive and not killed yet\n",
                                pData->uPID);
 
@@ -473 +494 @@
         for (size_t i = 0; i < 10; i++)
         {
-            VBoxServiceVerbose(4, "ControlExec: Kill attempt %d/10: Waiting for process (PID=%u) exit ...\n",
-                               i + 1, pData->uPID);
+            VBoxServiceVerbose(4, "ControlExec: [PID %u]: Kill attempt %d/10: Waiting to exit ...\n",
+                               pData->uPID, i + 1);
             rc2 = RTProcWait(hProcess, RTPROCWAIT_FLAGS_NOBLOCK, &ProcessStatus);
             if (RT_SUCCESS(rc2))
             {
-                VBoxServiceVerbose(4, "ControlExec: Kill attempt %d/10: Process (PID=%u) exited\n",
-                                   i + 1, pData->uPID);
+                VBoxServiceVerbose(4, "ControlExec: [PID %u]: Kill attempt %d/10: Exited\n",
+                                   pData->uPID, i + 1);
                 fProcessAlive = false;
                 break;
@@ -485 +506 @@
             if (i >= 5)
             {
-                VBoxServiceVerbose(4, "ControlExec: Kill attempt %d/10: Try to terminate (PID=%u) ...\n",
-                                   i + 1, pData->uPID);
+                VBoxServiceVerbose(4, "ControlExec: [PID %u]: Kill attempt %d/10: Trying to terminate ...\n",
+                                   pData->uPID, i + 1);
                 RTProcTerminate(hProcess);
             }
@@ -493 +514 @@
 
         if (fProcessAlive)
-            VBoxServiceVerbose(3, "ControlExec: Process (PID=%u) could not be killed\n", pData->uPID);
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Could not be killed\n", pData->uPID);
     }
 
     /*
-     * If we don't have a client problem (RT_FAILURE(rc) we'll reply to the
+     * If we don't have a client problem (RT_FAILURE(rc)) we'll reply to the
      * clients exec packet now.
      */
@@ -516 +537 @@
         if (     fProcessTimedOut  && !fProcessAlive && MsProcessKilled != UINT64_MAX)
         {
-            VBoxServiceVerbose(3, "ControlExec: Process timed out and got killed\n");
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Timed out and got killed\n",
+                               pData->uPID);
             uStatus = PROC_STS_TOK;
         }
         else if (fProcessTimedOut  &&  fProcessAlive && MsProcessKilled != UINT64_MAX)
         {
-            VBoxServiceVerbose(3, "ControlExec: Process timed out and did *not* get killed\n");
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Timed out and did *not* get killed\n",
+                               pData->uPID);
             uStatus = PROC_STS_TOA;
         }
         else if (pThread->fShutdown && (fProcessAlive || MsProcessKilled != UINT64_MAX))
         {
-            VBoxServiceVerbose(3, "ControlExec: Process got terminated because system/service is about to shutdown\n");
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Got terminated because system/service is about to shutdown\n",
+                               pData->uPID);
             uStatus = PROC_STS_DWN; /* Service is stopping, process was killed. */
             uFlags = pData->uFlags; /* Return handed-in execution flags back to the host. */
@@ -532 +556 @@
         else if (fProcessAlive)
         {
-            VBoxServiceError("ControlExec: Process is alive when it should not!\n");
+            VBoxServiceError("ControlExec: [PID %u]: Is alive when it should not!\n",
+                             pData->uPID);
         }
         else if (MsProcessKilled != UINT64_MAX)
         {
-            VBoxServiceError("ControlExec: Process has been killed when it should not!\n");
+            VBoxServiceError("ControlExec: [PID %u]: Has been killed when it should not!\n",
+                             pData->uPID);
         }
         else if (ProcessStatus.enmReason == RTPROCEXITREASON_NORMAL)
         {
-            VBoxServiceVerbose(3, "ControlExec: Process ended with RTPROCEXITREASON_NORMAL (%u)\n",
-                               ProcessStatus.iStatus);
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Ended with RTPROCEXITREASON_NORMAL (%u)\n",
+                               pData->uPID, ProcessStatus.iStatus);
 
             uStatus = PROC_STS_TEN;
@@ -548 +574 @@
         else if (ProcessStatus.enmReason == RTPROCEXITREASON_SIGNAL)
         {
-            VBoxServiceVerbose(3, "ControlExec: Process ended with RTPROCEXITREASON_SIGNAL (%u)\n",
-                               ProcessStatus.iStatus);
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Ended with RTPROCEXITREASON_SIGNAL (%u)\n",
+                               pData->uPID, ProcessStatus.iStatus);
 
             uStatus = PROC_STS_TES;
@@ -556 +582 @@
         else if (ProcessStatus.enmReason == RTPROCEXITREASON_ABEND)
         {
-            VBoxServiceVerbose(3, "ControlExec: Process ended with RTPROCEXITREASON_ABEND (%u)\n",
-                               ProcessStatus.iStatus);
+            VBoxServiceVerbose(3, "ControlExec: [PID %u]: Ended with RTPROCEXITREASON_ABEND (%u)\n",
+                               pData->uPID, ProcessStatus.iStatus);
 
             uStatus = PROC_STS_TEA;
@@ -563 +589 @@
         }
         else
-        {
-            VBoxServiceError("ControlExec: Process has reached an undefined status!\n");
-        }
-
-        VBoxServiceVerbose(3, "ControlExec: Process ended: PID=%u, CID=%u, Status=%u, Flags=%u\n",
+            VBoxServiceError("ControlExec: [PID %u]: Reached an undefined state!\n",
+                             pData->uPID);
+
+        VBoxServiceVerbose(3, "ControlExec: [PID %u]: Ended, CID=%u, Status=%u, Flags=%u\n",
                            pData->uPID, pThread->uContextID, uStatus, uFlags);
         rc = VbglR3GuestCtrlExecReportStatus(pThread->uClientID, pThread->uContextID,
                                              pData->uPID, uStatus, uFlags,
                                              NULL /* pvData */, 0 /* cbData */);
-        VBoxServiceVerbose(3, "ControlExec: Process loop ended with rc=%Rrc\n", rc);
+        VBoxServiceVerbose(3, "ControlExec: [PID %u]: Process loop ended with rc=%Rrc\n",
+                           pData->uPID, rc);
 
         /*
@@ -580 +606 @@
         if (g_cVerbosity >= 5)
         {
-            VBoxServiceVerbose(5, "StdOut of process (PID %u):\n", pData->uPID);
+            VBoxServiceVerbose(5, "[PID %u]: StdOut:\n", pData->uPID);
 
             uint8_t szBuf[_64K];
@@ -589 +615 @@
                    && cbRead)
             {
-                RTStrmWrite(g_pStdOut, szBuf, cbRead);
                 cbOffset += cbRead;
                 if (!cbLeft)
@@ -599 +624 @@
     }
     else
-        VBoxServiceError("ControlExec: Process loop failed with rc=%Rrc\n", rc);
+        VBoxServiceError("ControlExec: [PID %u]: Loop failed with rc=%Rrc\n",
+                         pData->uPID, rc);
     return rc;
 }
@@ -883 +909 @@
                 uProcFlags |= RTPROC_FLAGS_SERVICE;
 #ifdef DEBUG
-            VBoxServiceVerbose(3, "Command: %s\n", szExecExp);
+            VBoxServiceVerbose(3, "ControlExec: Command: %s\n", szExecExp);
             for (size_t i = 0; papszArgsExp[i]; i++)
-                VBoxServiceVerbose(3, "\targv[%ld]: %s\n", i, papszArgsExp[i]);
+                VBoxServiceVerbose(3, "ControlExec:\targv[%ld]: %s\n", i, papszArgsExp[i]);
 #endif
             /* Do normal execution. */
@@ -1020 +1046 @@
                                      * So, NIL the handles to avoid closing them again.
                                      */
-                                    if (RT_FAILURE(RTPollSetQueryHandle(hPollSet, 0 /* stdin */, NULL)))
+                                    if (RT_FAILURE(RTPollSetQueryHandle(hPollSet, VBOXSERVICECTRLPIPEID_STDIN_WRITABLE, NULL)))
                                         pData->pipeStdInW = NIL_RTPIPE;
-                                    if (RT_FAILURE(RTPollSetQueryHandle(hPollSet, 1 /* stdout */, NULL)))
+                                    if (RT_FAILURE(RTPollSetQueryHandle(hPollSet, VBOXSERVICECTRLPIPEID_STDIN_INPUT_NOTIFY, NULL)))
+                                        pData->stdIn.hNotificationPipeR = NIL_RTPIPE;
+                                    if (RT_FAILURE(RTPollSetQueryHandle(hPollSet, VBOXSERVICECTRLPIPEID_STDOUT, NULL)))
                                         hStdOutR = NIL_RTPIPE;
-                                    if (RT_FAILURE(RTPollSetQueryHandle(hPollSet, 2 /* stderr */, NULL)))
+                                    if (RT_FAILURE(RTPollSetQueryHandle(hPollSet, VBOXSERVICECTRLPIPEID_STDERR, NULL)))
                                         hStdErrR = NIL_RTPIPE;
                                 }
@@ -1041 +1069 @@
                             }
                             RTPollSetDestroy(hPollSet);
+                            RTPipeClose(pData->stdIn.hNotificationPipeR);
                         }
                         RTPipeClose(hStdErrR);
@@ -1056 +1085 @@
 
     VbglR3GuestCtrlDisconnect(pThread->uClientID);
-    VBoxServiceVerbose(3, "ControlExec: Thread of process \"%s\" (PID: %u) ended with rc=%Rrc\n",
-                       pData->pszCmd, pData->uPID, rc);
+    VBoxServiceVerbose(3, "ControlExec: [PID %u]: Thread of process \"%s\" ended with rc=%Rrc\n",
+                       pData->uPID, pData->pszCmd, rc);
 
     /*
@@ -1122 +1151 @@
         if (RT_SUCCESS(rc))
         {
+            static uint32_t uCtrlExecThread = 0;
+            char szThreadName[32];
+            if (!RTStrPrintf(szThreadName, sizeof(szThreadName), "controlexec%ld", uCtrlExecThread++))
+                AssertMsgFailed(("Unable to create unique control exec thread name!\n"));
+
             rc = RTThreadCreate(&pThread->Thread, VBoxServiceControlExecThread,
                                 (void *)(PVBOXSERVICECTRLTHREAD*)pThread, 0,
-                                RTTHREADTYPE_DEFAULT, RTTHREADFLAGS_WAITABLE, "Exec");
+                                RTTHREADTYPE_DEFAULT, RTTHREADFLAGS_WAITABLE, szThreadName);
             if (RT_FAILURE(rc))
             {
@@ -1135 +1169 @@
 
                 /* Wait for the thread to initialize. */
-                RTThreadUserWait(pThread->Thread, 60 * 1000);
+                RTThreadUserWait(pThread->Thread, 60 * 1000 /* 60 seconds max. */);
                 if (pThread->fShutdown)
                 {
@@ -1220 +1254 @@
     else
         VBoxServiceError("ControlExec: Failed to retrieve exec start command! Error: %Rrc\n", rc);
-    VBoxServiceVerbose(3, "ControlExec: VBoxServiceControlExecHandleCmdStartProcess returned with %Rrc\n", rc);
     return rc;
 }
@@ -1256 +1289 @@
     if (RT_FAILURE(rc))
     {
-        VBoxServiceError("ControlExec: Failed to retrieve exec input command! Error: %Rrc\n", rc);
+        VBoxServiceError("ControlExec: [PID %u]: Failed to retrieve exec input command! Error: %Rrc\n",
+                         uPID, rc);
     }
     else if (cbSize >  cbMaxBufSize)
     {
-        VBoxServiceError("ControlExec: Maximum input buffer size is too small! cbSize=%u, cbMaxBufSize=%u\n",
-                         cbSize, cbMaxBufSize);
+        VBoxServiceError("ControlExec: [PID %u]: Maximum input buffer size is too small! cbSize=%u, cbMaxBufSize=%u\n",
+                         uPID, cbSize, cbMaxBufSize);
         rc = VERR_INVALID_PARAMETER;
     }
@@ -1273 +1307 @@
         {
             fPendingClose = true;
-            VBoxServiceVerbose(4, "ControlExec: Got last input block (PID %u) of size %u ...\n",
+            VBoxServiceVerbose(4, "ControlExec: [PID %u]: Got last input block of size %u ...\n",
                                uPID, cbSize);
         }
@@ -1279 +1313 @@
         rc = VBoxServiceControlExecThreadSetInput(uPID, fPendingClose, pabBuffer,
                                                   cbSize, &cbWritten);
-        VBoxServiceVerbose(4, "ControlExec: Written input (PID %u): rc=%Rrc, uFlags=0x%x, fPendingClose=%d, cbSize=%u, cbWritten=%u\n",
+        VBoxServiceVerbose(4, "ControlExec: [PID %u]: Written input, rc=%Rrc, uFlags=0x%x, fPendingClose=%d, cbSize=%u, cbWritten=%u\n",
                            uPID, rc, uFlags, fPendingClose, cbSize, cbWritten);
         if (RT_SUCCESS(rc))
@@ -1311 +1345 @@
     Assert(uStatus > INPUT_STS_UNDEFINED);
 
-    VBoxServiceVerbose(3, "ControlExec: Input processed (PID %u), Status=%u, Flags=0x%x, cbWritten=%u\n",
+    VBoxServiceVerbose(3, "ControlExec: [PID %u]: Input processed, uStatus=%u, uFlags=0x%x, cbWritten=%u\n",
                        uPID, uStatus, uFlags, cbWritten);
 
@@ -1321 +1355 @@
 
     if (RT_FAILURE(rc))
-        VBoxServiceError("ControlExec: Failed to report input status! Error: %Rrc\n", rc);
+        VBoxServiceError("ControlExec: [PID %u]: Failed to report input status! Error: %Rrc\n",
+                         uPID, rc);
     return rc;
 }
@@ -1345 +1380 @@
     if (RT_SUCCESS(rc))
     {
-        uint32_t cbRead;
+        uint32_t cbRead = 0;
         uint8_t *pBuf = (uint8_t*)RTMemAlloc(_64K);
         if (pBuf)
@@ -1352 +1387 @@
                                                        pBuf, _64K /* cbSize */, &cbRead);
             if (RT_SUCCESS(rc))
-            {
-                VBoxServiceVerbose(3, "ControlExec: Got output (PID %u), read=%u, handle=%u, flags=%u\n",
+                VBoxServiceVerbose(3, "ControlExec: [PID %u]: Got output, cbRead=%u, uHandle=%u, uFlags=%u\n",
                                    uPID, cbRead, uHandleID, uFlags);
-
-                /* Note: Since the context ID is unique the request *has* to be completed here,
-                 *       regardless whether we got data or not! Otherwise the progress object
-                 *       on the host never will get completed! */
-                /* cbRead now contains actual size. */
-                rc = VbglR3GuestCtrlExecSendOut(u32ClientId, uContextID, uPID, uHandleID, uFlags,
-                                                pBuf, cbRead);
-            }
             else
-                VBoxServiceError("ControlExec: Failed to retrieve output (PID %u), rc=%Rrc\n",
-                                 uPID, rc);
+                VBoxServiceError("ControlExec: [PID %u]: Failed to retrieve output, uHandle=%u, rc=%Rrc\n",
+                                 uPID, uHandleID, rc);
+
+            /* Note: Since the context ID is unique the request *has* to be completed here,
+             *       regardless whether we got data or not! Otherwise the progress object
+             *       on the host never will get completed! */
+            /* cbRead now contains actual size. */
+            int rc2 = VbglR3GuestCtrlExecSendOut(u32ClientId, uContextID, uPID, uHandleID, uFlags,
+                                                 pBuf, cbRead);
+            if (RT_SUCCESS(rc))
+                rc = rc2;
             RTMemFree(pBuf);
         }
@@ -1371 +1406 @@
             rc = VERR_NO_MEMORY;
     }
-    else
-        VBoxServiceError("ControlExec: Failed to retrieve exec output command! Error: %Rrc\n", rc);
-    return rc;
-}
-
+
+    if (RT_FAILURE(rc))
+        VBoxServiceError("ControlExec: [PID %u]: Failed to handle output command! Error: %Rrc\n",
+                         uPID, rc);
+    return rc;
+}
+

trunk/src/VBox/Additions/common/VBoxService/VBoxServiceControlExecThread.cpp

@@ -36 +36 @@
 extern RTCRITSECT g_GuestControlExecThreadsCritSect;
 
+const PVBOXSERVICECTRLTHREAD vboxServiceControlExecThreadGetByPID(uint32_t uPID);
 
 /**
@@ -134 +135 @@
 
         /* Init buffers. */
-        rc = VBoxServicePipeBufInit(&pData->stdOut, false /*fNeedNotificationPipe*/);
+        rc = VBoxServicePipeBufInit(&pData->stdOut, VBOXSERVICECTRLPIPEID_STDOUT,
+                                    false /*fNeedNotificationPipe*/);
         if (RT_SUCCESS(rc))
         {
-            rc = VBoxServicePipeBufInit(&pData->stdErr, false /*fNeedNotificationPipe*/);
+            rc = VBoxServicePipeBufInit(&pData->stdErr, VBOXSERVICECTRLPIPEID_STDERR,
+                                        false /*fNeedNotificationPipe*/);
             if (RT_SUCCESS(rc))
-                rc = VBoxServicePipeBufInit(&pData->stdIn, true /*fNeedNotificationPipe*/);
+                rc = VBoxServicePipeBufInit(&pData->stdIn, VBOXSERVICECTRLPIPEID_STDIN,
+                                            true /*fNeedNotificationPipe*/);
+        }
+
+        if (RT_SUCCESS(rc))
+        {
+            pThread->enmType = kVBoxServiceCtrlThreadDataExec;
+            pThread->pvData = pData;
         }
     }
 
     if (RT_FAILURE(rc))
-    {
         VBoxServiceControlExecThreadDestroy(pData);
-    }
-    else
-    {
-        pThread->enmType = kVBoxServiceCtrlThreadDataExec;
-        pThread->pvData = pData;
-    }
     return rc;
 }
@@ -165 +168 @@
     if (pData)
     {
+        VBoxServiceVerbose(3, "ControlExec: [PID %u]: Destroying thread ...\n",
+                           pData->uPID);
+
         RTStrFree(pData->pszCmd);
         if (pData->uNumEnvVars)
@@ -186 +192 @@
 
 
+int VBoxServiceControlExecThreadAssignPID(PVBOXSERVICECTRLTHREADDATAEXEC pData, uint32_t uPID)
+{
+    AssertPtrReturn(pData, VERR_INVALID_POINTER);
+    AssertReturn(uPID, VERR_INVALID_PARAMETER);
+
+    int rc = RTCritSectEnter(&g_GuestControlExecThreadsCritSect);
+    if (RT_SUCCESS(rc))
+    {
+        /* Search an old thread using the desired PID and shut it down completely -- it's
+         * not used anymore. */
+        const PVBOXSERVICECTRLTHREAD pOldThread = vboxServiceControlExecThreadGetByPID(uPID);
+        if (   pOldThread
+            && pOldThread->pvData != pData)
+        {
+            VBoxServiceVerbose(3, "ControlExec: PID %u was used before, shutting down stale exec thread ...\n",
+                               uPID);
+            AssertPtr(pOldThread->pvData);
+            VBoxServiceControlExecThreadDestroy((PVBOXSERVICECTRLTHREADDATAEXEC)pOldThread->pvData);
+        }
+        /** @todo Remove node from thread list! */
+
+        /* Assign PID to current thread. */
+        pData->uPID = uPID;
+        VBoxServicePipeBufSetPID(&pData->stdIn, pData->uPID);
+        VBoxServicePipeBufSetPID(&pData->stdOut, pData->uPID);
+        VBoxServicePipeBufSetPID(&pData->stdErr, pData->uPID);
+
+        int rc2 = RTCritSectLeave(&g_GuestControlExecThreadsCritSect);
+        if (RT_SUCCESS(rc))
+            rc = rc2;
+    }
+
+    return rc;
+}
+
+
 /**
  * Finds a (formerly) started process given by its PID.
@@ -193 +235 @@
  * @param   uPID                        PID to search for.
  */
-PVBOXSERVICECTRLTHREAD vboxServiceControlExecThreadGetByPID(uint32_t uPID)
+const PVBOXSERVICECTRLTHREAD vboxServiceControlExecThreadGetByPID(uint32_t uPID)
 {
     PVBOXSERVICECTRLTHREAD pNode = NULL;
@@ -236 +278 @@
             if (VBoxServicePipeBufIsEnabled(&pData->stdIn))
             {
-                uint32_t cbWritten;
                 /*
                  * Feed the data to the pipe.
                  */
+                uint32_t cbWritten;
                 rc = VBoxServicePipeBufWriteToBuf(&pData->stdIn, pBuf,
                                                   cbSize, fPendingClose, &cbWritten);
@@ -279 +321 @@
     if (RT_SUCCESS(rc))
     {
-        PVBOXSERVICECTRLTHREAD pNode = vboxServiceControlExecThreadGetByPID(uPID);
+        const PVBOXSERVICECTRLTHREAD pNode = vboxServiceControlExecThreadGetByPID(uPID);
         if (pNode)
         {
-            PVBOXSERVICECTRLTHREADDATAEXEC pData = (PVBOXSERVICECTRLTHREADDATAEXEC)pNode->pvData;
+            const PVBOXSERVICECTRLTHREADDATAEXEC pData = (PVBOXSERVICECTRLTHREADDATAEXEC)pNode->pvData;
             AssertPtr(pData);
 
-            PVBOXSERVICECTRLEXECPIPEBUF pPipeBuf;
+            PVBOXSERVICECTRLEXECPIPEBUF pPipeBuf = NULL;
             switch (uHandleId)
             {
@@ -293 +335 @@
 
                 case OUTPUT_HANDLE_ID_STDOUT: /* StdOut */
+                    pPipeBuf = &pData->stdOut;
+                    break;
+
                 default:
-                    pPipeBuf = &pData->stdOut;
-                    break;
-            }
-            AssertPtr(pPipeBuf);
-
+                    AssertReleaseMsgFailed(("Unknown output handle ID (%u)\n", uHandleId));
+                    break;
+            }
+            if (!pPipeBuf)
+                return VERR_INVALID_PARAMETER;
+
+#ifdef DEBUG_andy
+            VBoxServiceVerbose(4, "ControlExec: [PID %u]: Getting output from pipe buffer %u ...\n",
+                               uPID, pPipeBuf->uPipeId);
+#endif
             /* If the stdout pipe buffer is enabled (that is, still could be filled by a running
              * process) wait for the signal to arrive so that we don't return without any actual
              * data read. */
-            if (VBoxServicePipeBufIsEnabled(pPipeBuf))
+            bool fEnabled = VBoxServicePipeBufIsEnabled(pPipeBuf);
+            if (fEnabled)
+            {
+#ifdef DEBUG_andy
+                VBoxServiceVerbose(4, "ControlExec: [PID %u]: Waiting for pipe buffer %u\n",
+                                   uPID, pPipeBuf->uPipeId);
+#endif
                 rc = VBoxServicePipeBufWaitForEvent(pPipeBuf, uTimeout);
-
+            }
             if (RT_SUCCESS(rc))
             {
@@ -311 +367 @@
                 if (RT_SUCCESS(rc))
                 {
+                    if (fEnabled && !cbRead)
+                        AssertMsgFailed(("Waited for pipe buffer %u, but nothing read!\n",
+                                         pPipeBuf->uPipeId));
                     if (pcbRead)
                         *pcbRead = cbRead;
                 }
+                else
+                    VBoxServiceError("ControlExec: [PID %u]: Unable to read from pipe buffer %u, rc=%Rrc\n",
+                                     uPID, pPipeBuf->uPipeId, rc);
             }
         }

trunk/src/VBox/Additions/common/VBoxService/VBoxServiceControlExecThread.h

@@ -27 +27 @@
                                       const char *pszEnv, uint32_t cbEnv, uint32_t uNumEnvVars,
                                       const char *pszUser, const char *pszPassword, uint32_t uTimeLimitMS);
+int VBoxServiceControlExecThreadAssignPID(PVBOXSERVICECTRLTHREADDATAEXEC pData, uint32_t uPID);
 void VBoxServiceControlExecThreadDestroy(PVBOXSERVICECTRLTHREADDATAEXEC pData);
 int VBoxServiceControlExecThreadSetInput(uint32_t uPID, bool fPendingClose, uint8_t *pBuf,

trunk/src/VBox/Additions/common/VBoxService/VBoxServiceInternal.h

@@ -102 +102 @@
 # define VBOXSERVICE_FRIENDLY_NAME  "VirtualBox Guest Additions Service"
 /** The service description (only W2K+ atm) */
-# define VBOXSERVICE_DESCRIPTION    "Manages VM runtime information, time synchronization, remote sysprep execution and miscellaneous utilities for guest operating systems."
+# define VBOXSERVICE_DESCRIPTION    "Manages VM runtime information, time synchronization, guest control execution and miscellaneous utilities for guest operating systems."
 /** The following constant may be defined by including NtStatus.h. */
 # define STATUS_SUCCESS             ((NTSTATUS)0x00000000L)
@@ -116 +116 @@
 typedef enum VBOXSERVICECTRLPIPEID
 {
-    VBOXSERVICECTRLPIPEID_STDIN_ERROR  = 0,
+    VBOXSERVICECTRLPIPEID_STDIN = 0,
+    VBOXSERVICECTRLPIPEID_STDIN_ERROR,
     VBOXSERVICECTRLPIPEID_STDIN_WRITABLE,
     VBOXSERVICECTRLPIPEID_STDIN_INPUT_NOTIFY,
@@ -128 +129 @@
 typedef struct
 {
+    /** The PID the pipe is assigned to. */
+    uint32_t    uPID;
+    /** The pipe's Id of enum VBOXSERVICECTRLPIPEID. */
+    uint8_t     uPipeId;
     /** The data buffer. */
     uint8_t    *pbData;

trunk/src/VBox/Additions/common/VBoxService/VBoxServicePipeBuf.cpp

@@ -28 +28 @@
 #include "VBoxServicePipeBuf.h"
 
-
 /**
  * Initializes a pipe buffer.
@@ -34 +33 @@
  * @returns IPRT status code.
  * @param   pBuf                    The pipe buffer to initialize.
+ * @param   uId                     The pipe's ID handle.
  * @param   fNeedNotificationPipe   Whether the buffer needs a notification
  *                                  pipe or not.
  */
-int VBoxServicePipeBufInit(PVBOXSERVICECTRLEXECPIPEBUF pBuf, bool fNeedNotificationPipe)
+int VBoxServicePipeBufInit(PVBOXSERVICECTRLEXECPIPEBUF pBuf, uint8_t uId, bool fNeedNotificationPipe)
 {
     AssertPtrReturn(pBuf, VERR_INVALID_POINTER);
 
     /** @todo Add allocation size as function parameter! */
+    pBuf->uPID = 0; /* We don't have the PID yet. */
+    pBuf->uPipeId = uId;
     pBuf->pbData = (uint8_t *)RTMemAlloc(_64K); /* Start with a 64k buffer. */
     AssertReturn(pBuf->pbData, VERR_NO_MEMORY);
@@ -59 +61 @@
         rc = RTCritSectInit(&pBuf->CritSect);
         if (RT_SUCCESS(rc) && fNeedNotificationPipe)
-        {
             rc = RTPipeCreate(&pBuf->hNotificationPipeR, &pBuf->hNotificationPipeW, 0);
-            if (RT_FAILURE(rc))
-            {
-                RTCritSectDelete(&pBuf->CritSect);
-                if (pBuf->hEventSem != NIL_RTSEMEVENT)
-                    RTSemEventDestroy(pBuf->hEventSem);
-            }
-        }
+    }
+
+    if (RT_FAILURE(rc))
+    {
+        if (RTCritSectIsInitialized(&pBuf->CritSect))
+            RTCritSectDelete(&pBuf->CritSect);
+        if (pBuf->hEventSem != NIL_RTSEMEVENT)
+            RTSemEventDestroy(pBuf->hEventSem);
     }
     return rc;
@@ -96 +98 @@
     {
         Assert(pBuf->cbSize >= pBuf->cbOffset);
-        if (*pcbToRead > pBuf->cbSize - pBuf->cbOffset)
-            *pcbToRead = pBuf->cbSize - pBuf->cbOffset;
-
-        if (*pcbToRead > cbBuffer)
-            *pcbToRead = cbBuffer;
-
-        if (*pcbToRead > 0)
-        {
-            memcpy(pbBuffer, pBuf->pbData + pBuf->cbOffset, *pcbToRead);
-            pBuf->cbOffset += *pcbToRead;
+        uint32_t cbToRead = *pcbToRead;
+
+        if (cbToRead > pBuf->cbSize - pBuf->cbOffset)
+            cbToRead = pBuf->cbSize - pBuf->cbOffset;
+
+        if (cbToRead > cbBuffer)
+            cbToRead = cbBuffer;
+
+        if (cbToRead)
+        {
+            memcpy(pbBuffer, &pBuf->pbData[pBuf->cbOffset], cbToRead);
+            pBuf->cbOffset += cbToRead;
 
             if (pBuf->hEventSem != NIL_RTSEMEVENT)
@@ -114 +118 @@
 
 #ifdef DEBUG_andy
-            VBoxServiceVerbose(4, "PipeBuf[0x%p]: read=%u, size=%u, alloc=%u, off=%u\n",
-                                   pBuf, *pcbToRead, pBuf->cbSize, pBuf->cbAllocated, pBuf->cbOffset);
+            VBoxServiceVerbose(4, "Pipe [%u %u 0x%p %s] read pcbToRead=%u, cbSize=%u, cbAlloc=%u, cbOff=%u\n",
+                               pBuf->uPID, pBuf->uPipeId, pBuf, pBuf->fEnabled ? "EN" : "DIS", cbToRead, pBuf->cbSize, pBuf->cbAllocated, pBuf->cbOffset);
 #endif
+            *pcbToRead = cbToRead;
         }
         else
         {
-            pbBuffer = NULL;
             *pcbToRead = 0;
         }
@@ -132 +136 @@
 
 
+/**
+ * Peeks for buffer data without moving the buffer's offset
+ * or touching any other internal data.
+ *
+ * @return  IPRT status code.
+ * @param   pBuf                        Pointer to pipe buffer to read the data from.
+ * @param   pbBuffer                    Pointer to buffer to store the read out data.
+ * @param   cbBuffer                    Size (in bytes) of the buffer where to store the data.
+ * @param   cbOffset                    Offset (in bytes) where to start reading.
+ * @param   pcbRead                     Pointer to desired amount (in bytes) of data to read,
+ *                                      will reflect the actual amount read on return.
+ * @param   pcbLeft                     Pointer to bytes left in buffer after the current read
+ *                                      operation.
+ */
 int VBoxServicePipeBufPeek(PVBOXSERVICECTRLEXECPIPEBUF pBuf,
                            uint8_t *pbBuffer, uint32_t cbBuffer,
@@ -140 +158 @@
     AssertPtrReturn(pbBuffer, VERR_INVALID_POINTER);
     AssertReturn(cbBuffer, VERR_INVALID_PARAMETER);
-
-    int rc = RTCritSectEnter(&pBuf->CritSect);
-    if (RT_SUCCESS(rc))
-    {
-        Assert(pBuf->cbSize >= pBuf->cbOffset);
+    AssertReturn(pBuf->cbSize >= pBuf->cbOffset, VERR_BUFFER_OVERFLOW);
+
+    int rc = RTCritSectEnter(&pBuf->CritSect);
+    if (RT_SUCCESS(rc))
+    {
         if (cbOffset > pBuf->cbSize)
             cbOffset = pBuf->cbSize;
@@ -152 +170 @@
         if (cbToRead)
         {
-            memcpy(pbBuffer, pBuf->pbData + cbOffset, cbToRead);
+            memcpy(pbBuffer, &pBuf->pbData[cbOffset], cbToRead);
             pbBuffer[cbBuffer - 1] = '\0';
         }
@@ -183 +201 @@
 {
     AssertPtrReturn(pBuf, VERR_INVALID_POINTER);
-
-    int rc = RTCritSectEnter(&pBuf->CritSect);
-    if (RT_SUCCESS(rc))
-    {
-        AssertPtrReturn(pbData, VERR_INVALID_POINTER);
+    AssertPtrReturn(pbData, VERR_INVALID_POINTER);
+
+    int rc = RTCritSectEnter(&pBuf->CritSect);
+    if (RT_SUCCESS(rc))
+    {
         if (pBuf->fEnabled)
         {
@@ -269 +287 @@
                     *pcbWritten = cbData;
 
-                if (pBuf->hEventSem != NIL_RTSEMEVENT)
+                /* Only trigger signal if we really wrote something. */
+                if (   cbData
+                    && pBuf->hEventSem != NIL_RTSEMEVENT)
                 {
                     rc = RTSemEventSignal(pBuf->hEventSem);
@@ -276 +296 @@
 
 #ifdef DEBUG_andy
-                VBoxServiceVerbose(4, "PipeBuf[0x%p]: written=%u, size=%u, alloc=%u, off=%u\n",
-                                   pBuf, cbData, pBuf->cbSize, pBuf->cbAllocated, pBuf->cbOffset);
+                VBoxServiceVerbose(4, "Pipe [%u %u 0x%p %s] written cbData=%u, cbSize=%u, cbAlloc=%u, cbOff=%u\n",
+                                   pBuf->uPID, pBuf->uPipeId, pBuf, pBuf->fEnabled ? "EN" : "DIS", cbData, pBuf->cbSize, pBuf->cbAllocated, pBuf->cbOffset);
 #endif
             }
@@ -349 +369 @@
             {
                 *pcbWritten = 0;
-                pBuf->fEnabled = false;
+                /* Don't set pBuf->fEnabled to false here! We just didn't write
+                 * anything -- that doesn't mean this buffer is disabled (again). */
             }
         }
@@ -377 +398 @@
 
     bool fEnabled = false;
-    if (   RTCritSectIsInitialized(&pBuf->CritSect)
-        && RT_SUCCESS(RTCritSectEnter(&pBuf->CritSect)))
+    int rc = RTCritSectEnter(&pBuf->CritSect);
+    if (RT_SUCCESS(rc))
     {
         fEnabled = pBuf->fEnabled;
@@ -400 +421 @@
     AssertPtrReturn(pBuf, false);
 
+    if (!RTCritSectIsInitialized(&pBuf->CritSect))
+        return false;
+
     bool fClosing = false;
-    if (   RTCritSectIsInitialized(&pBuf->CritSect)
-        && RT_SUCCESS(RTCritSectEnter(&pBuf->CritSect)))
+    if (RT_SUCCESS(RTCritSectEnter(&pBuf->CritSect)))
     {
         fClosing = pBuf->fPendingClose;
@@ -425 +448 @@
     if (RT_SUCCESS(rc))
     {
+        bool fEnabledOld = pBuf->fEnabled;
         pBuf->fEnabled = fEnabled;
-        /* Let waiter know that something has changed ... */
-        if (pBuf->hEventSem)
+        if (   pBuf->fEnabled != fEnabledOld
+            && pBuf->hEventSem)
+        {
+            /* Let waiter know that something has changed ... */
             RTSemEventSignal(pBuf->hEventSem);
+        }
         rc = RTCritSectLeave(&pBuf->CritSect);
     }
@@ -435 +462 @@
 
 
+/**
+ * Assigns a PID to the specified pipe buffer. Does not allow
+ * setting a new PID after a PID already was set.
+ *
+ * @return  IPRT status code.
+ * @param   pBuf            The pipe buffer.
+ * @param   uPID            PID to assign.
+ */
+int VBoxServicePipeBufSetPID(PVBOXSERVICECTRLEXECPIPEBUF pBuf, uint32_t uPID)
+{
+    AssertPtrReturn(pBuf, VERR_INVALID_POINTER);
+
+    int rc = RTCritSectEnter(&pBuf->CritSect);
+    if (RT_SUCCESS(rc))
+    {
+        if (!pBuf->uPID)
+            pBuf->uPID = uPID;
+        rc = RTCritSectLeave(&pBuf->CritSect);
+    }
+    return rc;
+}
+
+
+/**
+ * Waits for the pipe buffer to get notified when something changed, like
+ * new data was written to or the buffer was disabled, i.e. not used anymore.
+ *
+ * @return  IPRT status code.
+ * @param   pBuf            The pipe buffer.
+ * @param   cMillies        The maximum time (in ms) to wait for the event.
+ */
 int VBoxServicePipeBufWaitForEvent(PVBOXSERVICECTRLEXECPIPEBUF pBuf, RTMSINTERVAL cMillies)
 {
@@ -455 +513 @@
 void VBoxServicePipeBufDestroy(PVBOXSERVICECTRLEXECPIPEBUF pBuf)
 {
-    AssertPtr(pBuf);
+    AssertPtrReturnVoid(pBuf);
+
     if (pBuf->pbData)
     {
-        RTMemFree(pBuf->pbData);
-        pBuf->pbData = NULL;
+        pBuf->uPID = 0;
+        pBuf->uPipeId = 0;
         pBuf->cbAllocated = 0;
         pBuf->cbSize = 0;
         pBuf->cbOffset = 0;
-    }
-
-    RTPipeClose(pBuf->hNotificationPipeR);
-    pBuf->hNotificationPipeR = NIL_RTPIPE;
-    RTPipeClose(pBuf->hNotificationPipeW);
-    pBuf->hNotificationPipeW = NIL_RTPIPE;
-
-    RTCritSectDelete(&pBuf->CritSect);
-    if (pBuf->hEventSem != NIL_RTSEMEVENT)
-        RTSemEventDestroy(pBuf->hEventSem);
-}
-
+
+        RTPipeClose(pBuf->hNotificationPipeR);
+        pBuf->hNotificationPipeR = NIL_RTPIPE;
+        RTPipeClose(pBuf->hNotificationPipeW);
+        pBuf->hNotificationPipeW = NIL_RTPIPE;
+
+        if (RTCritSectIsInitialized(&pBuf->CritSect))
+            RTCritSectDelete(&pBuf->CritSect);
+        if (pBuf->hEventSem != NIL_RTSEMEVENT)
+            RTSemEventDestroy(pBuf->hEventSem);
+
+        RTMemFree(pBuf->pbData);
+        pBuf->pbData = NULL;
+    }
+}
+

trunk/src/VBox/Additions/common/VBoxService/VBoxServicePipeBuf.h

@@ -21 +21 @@
 #include "VBoxServiceInternal.h"
 
-int  VBoxServicePipeBufInit(PVBOXSERVICECTRLEXECPIPEBUF pBuf, bool fNeedNotificationPipe);
+int  VBoxServicePipeBufInit(PVBOXSERVICECTRLEXECPIPEBUF pBuf, uint8_t uId, bool fNeedNotificationPipe);
 int  VBoxServicePipeBufRead(PVBOXSERVICECTRLEXECPIPEBUF pBuf,
                             uint8_t *pbBuffer, uint32_t cbBuffer, uint32_t *pcbToRead);
@@ -34 +34 @@
 bool VBoxServicePipeBufIsEnabled(PVBOXSERVICECTRLEXECPIPEBUF pBuf);
 bool VBoxServicePipeBufIsClosing(PVBOXSERVICECTRLEXECPIPEBUF pBuf);
+int  VBoxServicePipeBufSetPID(PVBOXSERVICECTRLEXECPIPEBUF pBuf, uint32_t uPID);
 int  VBoxServicePipeBufSetStatus(PVBOXSERVICECTRLEXECPIPEBUF pBuf, bool fEnabled);
 int  VBoxServicePipeBufWaitForEvent(PVBOXSERVICECTRLEXECPIPEBUF pBuf, RTMSINTERVAL cMillies);