Changeset 69987 in vbox

Timestamp:

Dec 7, 2017 4:02:40 PM (7 years ago)

Author:

vboxsync

Message:

VBoxService: Added "/VirtualBox/GuestAdd/VBoxService/--timesync-verbosity" guest property to make the time syncing service more verbose. Untested.

Location:

trunk/src/VBox/Additions/common/VBoxService

Files:

• VBoxService.cpp (modified) (3 diffs)
• VBoxServiceInternal.h (modified) (1 diff)
• VBoxServiceTimeSync.cpp (modified) (13 diffs)

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

@@ -334 +334 @@
 
 
+/**
+ * Logs a verbose message.
+ *
+ * @param   pszFormat   The message text.
+ * @param   ...         Format arguments.
+ */
+void VGSvcLog(const char *pszFormat, ...)
+{
+#ifdef DEBUG
+    int rc = RTCritSectEnter(&g_csLog);
+    if (RT_SUCCESS(rc))
+    {
+#endif
+        va_list args;
+        va_start(args, pszFormat);
+        char *psz = NULL;
+        RTStrAPrintfV(&psz, pszFormat, args);
+        va_end(args);
+
+        AssertPtr(psz);
+        LogRel(("%s", psz));
+
+        RTStrFree(psz);
+#ifdef DEBUG
+        RTCritSectLeave(&g_csLog);
+    }
+#endif
+}
+
+
+/**
+ * Destroys the currently active logging instance.
+ */
 void VGSvcLogDestroy(void)
 {
@@ -415 +448 @@
 
 /**
- * Displays a verbose message.
+ * Displays a verbose message based on the currently
+ * set global verbosity level.
  *
  * @param   iLevel      Minimum log level required to display this message.
@@ -425 +459 @@
     if (iLevel <= g_cVerbosity)
     {
-#ifdef DEBUG
-        int rc = RTCritSectEnter(&g_csLog);
-        if (RT_SUCCESS(rc))
-        {
-#endif
-            va_list args;
-            va_start(args, pszFormat);
-            char *psz = NULL;
-            RTStrAPrintfV(&psz, pszFormat, args);
-            va_end(args);
-
-            AssertPtr(psz);
-            LogRel(("%s", psz));
-
-            RTStrFree(psz);
-#ifdef DEBUG
-            RTCritSectLeave(&g_csLog);
-        }
-#endif
+        va_list args;
+        va_start(args, pszFormat);
+
+        VGSvcLog(pszFormat, args);
+
+        va_end(args);
     }
 }

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

@@ -185 +185 @@
 extern void                     VGSvcVerbose(unsigned iLevel, const char *pszFormat, ...);
 extern int                      VGSvcLogCreate(const char *pszLogFile);
+extern void                     VGSvcLog(const char *pszFormat, ...);
 extern void                     VGSvcLogDestroy(void);
 extern int                      VGSvcArgUInt32(int argc, char **argv, const char *psz, int *pi, uint32_t *pu32,

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

@@ -131 +131 @@
 /** Whether to set the time when the VM was restored. */
 static bool             g_fTimeSyncSetOnRestore = true;
+/** The logging verbosity.
+ *  This uses the global verbosity level by default. */
+static unsigned         g_uTimeSyncVerbosity = 0;
 
 /** Current error count. Used to knowing when to bitch and when not to. */
@@ -158 +161 @@
 static DECLCALLBACK(int) vgsvcTimeSyncPreInit(void)
 {
+    /* Use global verbosity as default. */
+    g_uTimeSyncVerbosity = g_cVerbosity;
+
 #ifdef VBOX_WITH_GUEST_PROPS
     /** @todo Merge this function with vgsvcTimeSyncOption() to generalize
@@ -219 +225 @@
                 g_fTimeSyncSetOnRestore = !!value;
         }
-
+        if (   RT_SUCCESS(rc)
+            || rc == VERR_NOT_FOUND)
+        {
+            uint32_t value;
+            rc = VGSvcReadPropUInt32(uGuestPropSvcClientID, "/VirtualBox/GuestAdd/VBoxService/--timesync-verbosity",
+                                     &value, 0, 255);
+            if (RT_SUCCESS(rc))
+                g_uTimeSyncVerbosity = (unsigned)value;
+        }
         VbglR3GuestPropDisconnect(uGuestPropSvcClientID);
     }
@@ -230 +244 @@
     return VINF_SUCCESS;
 #endif
+}
+
+
+/**
+ * Displays a verbose message based on the currently
+ * set timesync verbosity level.
+ *
+ * @param   iLevel      Minimum log level required to display this message.
+ * @param   pszFormat   The message text.
+ * @param   ...         Format arguments.
+ */
+static void vgsvcTimeSyncLog(unsigned iLevel, const char *pszFormat, ...)
+{
+    if (iLevel <= g_uTimeSyncVerbosity)
+    {
+        va_list args;
+        va_start(args, pszFormat);
+
+        VGSvcLog(pszFormat, args);
+
+        va_end(args);
+    }
 }
 
@@ -336 +372 @@
 
     if (GetSystemTimeAdjustment(&g_dwWinTimeAdjustment, &g_dwWinTimeIncrement, &g_bWinTimeAdjustmentDisabled))
-        VGSvcVerbose(3, "vgsvcTimeSyncInit: Initially %ld (100ns) units per %ld (100 ns) units interval, disabled=%d\n",
-                     g_dwWinTimeAdjustment, g_dwWinTimeIncrement, g_bWinTimeAdjustmentDisabled ? 1 : 0);
+        vgsvcTimeSyncLog(3, "vgsvcTimeSyncInit: Initially %ld (100ns) units per %ld (100 ns) units interval, disabled=%d\n",
+                         g_dwWinTimeAdjustment, g_dwWinTimeIncrement, g_bWinTimeAdjustmentDisabled ? 1 : 0);
     else
     {
@@ -394 +430 @@
         }
 
-        VGSvcVerbose(3, "vgsvcTimeSyncAdjust: Drift=%lldms\n", RTTimeSpecGetMilli(pDrift));
-        VGSvcVerbose(3, "vgsvcTimeSyncAdjust: OrgTA=%ld, CurTA=%ld, NewTA=%ld, DiffNew=%ld, DiffMax=%ld\n",
-                     g_dwWinTimeAdjustment, dwWinTimeAdjustment, dwWinNewTimeAdjustment, dwDiffNew, dwDiffMax);
+        vgsvcTimeSyncLog(3, "vgsvcTimeSyncAdjust: Drift=%lldms\n", RTTimeSpecGetMilli(pDrift));
+        vgsvcTimeSyncLog(3, "vgsvcTimeSyncAdjust: OrgTA=%ld, CurTA=%ld, NewTA=%ld, DiffNew=%ld, DiffMax=%ld\n",
+                         g_dwWinTimeAdjustment, dwWinTimeAdjustment, dwWinNewTimeAdjustment, dwDiffNew, dwDiffMax);
         if (SetSystemTimeAdjustment(dwWinNewTimeAdjustment, FALSE /* Periodic adjustments enabled. */))
         {
@@ -421 +457 @@
     {
         if (g_cVerbosity >= 1)
-            VGSvcVerbose(1, "vgsvcTimeSyncAdjust: adjtime by %RDtimespec\n", pDrift);
+            vgsvcTimeSyncLog(1, "vgsvcTimeSyncAdjust: adjtime by %RDtimespec\n", pDrift);
         g_cTimeSyncErrors = 0;
         return true;
@@ -445 +481 @@
         return;
     if (SetSystemTimeAdjustment(0, TRUE /* Periodic adjustments disabled. */))
-        VGSvcVerbose(3, "vgsvcTimeSyncCancelAdjust: Windows Time Adjustment is now disabled.\n");
+        vgsvcTimeSyncLog(3, "vgsvcTimeSyncCancelAdjust: Windows Time Adjustment is now disabled.\n");
     else if (g_cTimeSyncErrors++ < 10)
         VGSvcError("vgsvcTimeSyncCancelAdjust: SetSystemTimeAdjustment(,disable) failed, error=%u\n", GetLastError());
@@ -475 +511 @@
             char        sz[64];
             RTTIME      Time;
-            VGSvcVerbose(1, "time set to %s\n", RTTimeToString(RTTimeExplode(&Time, &NewGuestTime), sz, sizeof(sz)));
+            vgsvcTimeSyncLog(1, "time set to %s\n", RTTimeToString(RTTimeExplode(&Time, &NewGuestTime), sz, sizeof(sz)));
 #ifdef DEBUG
             RTTIMESPEC  Tmp;
             if (g_cVerbosity >= 3)
-                VGSvcVerbose(3, "        now %s\n", RTTimeToString(RTTimeExplode(&Time, RTTimeNow(&Tmp)), sz, sizeof(sz)));
+                vgsvcTimeSyncLog(3, "        now %s\n", RTTimeToString(RTTimeExplode(&Time, RTTimeNow(&Tmp)), sz, sizeof(sz)));
 #endif
         }
@@ -556 +592 @@
                     && idNewSession != g_idTimeSyncSession)
                 {
-                    VGSvcVerbose(3, "vgsvcTimeSyncWorker: The VM session ID changed, forcing resync.\n");
+                    vgsvcTimeSyncLog(3, "vgsvcTimeSyncWorker: The VM session ID changed, forcing resync.\n");
                     g_idTimeSyncSession  = idNewSession;
                     TimeSyncSetThreshold = 0;
@@ -577 +613 @@
                 if (g_cVerbosity >= 3)
                 {
-                    VGSvcVerbose(3, "vgsvcTimeSyncWorker: Host:    %s    (MinAdjust: %RU32 ms)\n",
-                                 RTTimeToString(RTTimeExplode(&Time, &HostNow), sz, sizeof(sz)), MinAdjust);
-                    VGSvcVerbose(3, "vgsvcTimeSyncWorker: Guest: - %s => %RDtimespec drift\n",
-                                 RTTimeToString(RTTimeExplode(&Time, &GuestNow), sz, sizeof(sz)), &Drift);
+                    vgsvcTimeSyncLog(3, "vgsvcTimeSyncWorker: Host:    %s    (MinAdjust: %RU32 ms)\n",
+                                     RTTimeToString(RTTimeExplode(&Time, &HostNow), sz, sizeof(sz)), MinAdjust);
+                    vgsvcTimeSyncLog(3, "vgsvcTimeSyncWorker: Guest: - %s => %RDtimespec drift\n",
+                                     RTTimeToString(RTTimeExplode(&Time, &GuestNow), sz, sizeof(sz)), &Drift);
                 }
 
@@ -605 +641 @@
                     int64_t cNsHostDelta = RTTimeSpecGetNano(&HostNow) - RTTimeSpecGetNano(&HostLast);
                     if ((uint64_t)RT_ABS(cNsHostDelta) > RT_NS_1HOUR / 2)
-                        VGSvcVerbose(0, "vgsvcTimeSyncWorker: Radical host time change: %'RI64ns (HostNow=%RDtimespec HostLast=%RDtimespec)\n",
-                                     cNsHostDelta, &HostNow, &HostLast);
+                        vgsvcTimeSyncLog(0, "vgsvcTimeSyncWorker: Radical host time change: %'RI64ns (HostNow=%RDtimespec HostLast=%RDtimespec)\n",
+                                         cNsHostDelta, &HostNow, &HostLast);
                 }
                 else
@@ -613 +649 @@
                 break;
             }
-            VGSvcVerbose(3, "vgsvcTimeSyncWorker: %RDtimespec: latency too high (%RDtimespec, max %ums) sleeping 1s\n",
-                         &GuestNow, &GuestElapsed, g_cMsTimeSyncMaxLatency);
+            vgsvcTimeSyncLog(3, "vgsvcTimeSyncWorker: %RDtimespec: latency too high (%RDtimespec, max %ums) sleeping 1s\n",
+                             &GuestNow, &GuestElapsed, g_cMsTimeSyncMaxLatency);
             RTThreadSleep(1000);
         } while (--cTries > 0);