]> git.ipfire.org Git - thirdparty/open-vm-tools.git/commitdiff
Change for tools vmx logging. Added locking to handle race condition
authorOliver Kurth <okurth@vmware.com>
Wed, 29 Aug 2018 20:29:44 +0000 (13:29 -0700)
committerOliver Kurth <okurth@vmware.com>
Wed, 29 Aug 2018 20:29:44 +0000 (13:29 -0700)
and deadlocks.

While there, changing GStaticRecMutex to GRecMutex since
GStaticRecMutex is deprecated since glib 2.32, and we are now at
glib 2.48.

The requirement here is that on top of the existing logging mechanism,
toolsd also send logs to VMX according to VMX side setting for toolsd
log levels. The existing logging mechansim shall be preserved so that
if there is a problem sending a message to VMX, that message is saved
in the guest according to whatever exising setting in tools.conf
either to a local file or the guest syslog. In addition, if there is
an issue sending VMX the log message, additioinal logs about the error
can also be logged using the existing tools.conf based log mechansim.

In order to support both the new and the old RPCs and the existing
tools.conf settings, it is best to use static globals for the vmx
logging. This simplifies both design and coding, and make it easier
to reason about the state of the vmx guest logger.

There is also no need to split the new code into another file. The newly
added logic actually belong to vmtoolsLog.c which keeps track of the
global states of the log processing and then invokes each external
log handler. The newly added code shall be invoked from the existing
vmtoolsLog.c framework code and also uses/updates multiple existing
vmtoolsLog.c data structure.

The old VMX LogHandler shall be left alone for now, since not all guest
apps will move to the new code at the same time. Once every apps have changed,
the old VMX LogHandler can be removed. Also removed is the stoplogging
code from the old VMX LogHandler since it is already covered by the
caller VMToolsLog() in vmtoolsLog.c

The global logging state is initialized as early as possible. However,
it should be done after the first VMTools_ConfigLogging() call so
that if there is any errors during the initialization, we can use
the local logging system to log them.

For a compatibility with older hosts and older tools, this change
tries to make sure the old vmx handler settings shall still WORK.
This is the most challenging part.

In order to avoid sending logs to VMX twice, if the VMX handler setting
is specified in the tools.conf, the local logger shall replace it
with the default file logging. However, the vmx handler setting is
NOT ignored, it shall be honored and used if the host is old and does
not support the new guest.log.* RPCs. There, we shall enter a fallback
mode and use the old log RPCs and the VMX handler's level setting is
read and used.

Need to call the setup() code in multiple places.
1) Initial start up (this is to enable it as early as possible).
2) Set option for a host designated level change.
3) RPC channel reset.
4) Tools config change procssing from signal HUP or timer callback.

The setup code can use g_xxx() for logging, but the core log handler
VmxGuestLog() cannot, to avoid recursive g_xxx() calls. Instead,
it calls Debug()/Warning() suites just like RpcChannel code.

Before, the RpcChannel loggings are thrown away which is not good.
This change here fixed the issue by logging those using the internal
VMToolsLogInt() function which directly write to the file system logger.

This change also fixed a bug where the vmtoolsd domain logs are thrown
away at the beginnnig of the tools load up. Enabling those requires us
to add the username as part of the log file name, since both the vmsvc
and vmusr processes would have use the same file vmware-vmtoolsd.log
which would cause a permission problem. The g_get_user_name only
returns the user without the domain. This might be a concern if
there are the same user id in both the local accouts and in the
domain. This rare case needs to be handled, but I am leaving it out
for now since it is very rare use case, and the same problem exists
already with the existing code.

open-vm-tools/lib/include/vmware/guestrpc/tclodefs.h
open-vm-tools/lib/include/vmware/tools/guestrpc.h
open-vm-tools/lib/include/vmware/tools/log.h
open-vm-tools/lib/include/vmware/tools/utils.h
open-vm-tools/libvmtools/vmtoolsLog.c
open-vm-tools/libvmtools/vmxLogger.c
open-vm-tools/services/vmtoolsd/mainLoop.c
open-vm-tools/services/vmtoolsd/mainPosix.c
open-vm-tools/services/vmtoolsd/toolsCoreInt.h

index b884864bff42dd9351c59acd16000780e9e2d62c..c9288e0d98d86de45e96199ff804a9eedb0091d2 100644 (file)
 
 #define DESKTOP_AUTOLOCK_CMD        "Autolock_Desktop"
 
+/*
+ * Guest log commands.
+ */
+
+#define GUEST_LOG_STATE_CMD "guest.log.state"
+#define GUEST_LOG_TEXT_CMD "guest.log.text"
 
 /*
  * The max selection buffer length has to be less than the
index e6fee26d83fdb016b60ee99d94a7f7b59359431c..695fbb1b39929cb5e2dca2a939597da5a55bcc0b 100644 (file)
@@ -208,6 +208,9 @@ RpcChannel_New(void);
 void
 RpcChannel_SetBackdoorOnly(void);
 
+RpcChannel *
+BackdoorChannel_New(void);
+
 G_END_DECLS
 
 /** @} */
index 9d284284dbc5759964dd2ce37c5334591ce6cf36..4b4b9dcfefb40aa80bbd0d5a0e461cf505be9d05 100644 (file)
@@ -1,5 +1,5 @@
 /*********************************************************
- * Copyright (C) 2011-2016 VMware, Inc. All rights reserved.
+ * Copyright (C) 2011-2018 VMware, Inc. All rights reserved.
  *
  * This program is free software; you can redistribute it and/or modify it
  * under the terms of the GNU Lesser General Public License as published
@@ -325,6 +325,13 @@ VMTools_ConfigLogging(const gchar *defaultDomain,
                       gboolean force,
                       gboolean reset);
 
+void
+VMTools_UseVmxGuestLog(const gchar *appName);
+
+void
+VMTools_SetupVmxGuestLog(gboolean refreshRpcChannel, GKeyFile *cfg,
+                         const gchar *level);
+
 G_END_DECLS
 
 /** @} */
index 127a49fb6b1ca005e1b0204fec279349711c2892..f31d2e690225b899f102fba26be5b47b42e05172 100644 (file)
@@ -176,12 +176,6 @@ VMTools_AcquireLogStateLock(void);
 void
 VMTools_ReleaseLogStateLock(void);
 
-void
-VMTools_StopLogging(void);
-
-void
-VMTools_RestartLogging(void);
-
 gchar *
 VMTools_GetTimeAsString(void);
 
index c0e4324292c25975ae59edf5cd4e6fb0268eb4e6..4722cfce020beb7f06f81db357f1b251c4e67a14 100644 (file)
@@ -54,6 +54,8 @@
 #include "str.h"
 #include "system.h"
 #include "vmware/tools/log.h"
+#include "vmware/tools/guestrpc.h"
+#include "vmware/guestrpc/tclodefs.h"
 #include "err.h"
 
 #define LOGGING_GROUP         "logging"
@@ -155,12 +157,97 @@ static LogHandler *gErrorData;
 static LogHandler *gErrorSyslog;
 static GPtrArray *gDomains = NULL;
 static gboolean gLogInitialized = FALSE;
-static GStaticRecMutex gLogStateMutex = G_STATIC_REC_MUTEX_INIT;
-static gboolean gLoggingStopped = FALSE;
+/* This lock protects the gGlibLoggingStopped and gLogHandlerEnabled flags */
+static GRecMutex gLogStateMutex;
+/* Whether to stop logging using glib logging functions */
+static gboolean gGlibLoggingStopped = FALSE;
+/* Whether to enable proxy messages to log handler */
+static gboolean gLogHandlerEnabled = TRUE;
+
 static gboolean gLogIOSuspended = FALSE;
 
+/* Data structures for the VMX guest logger */
+
+/*
+ * The gUseVmxGuestLog flag is turned on once and never modified later
+ * Therefore, the flag can be read without a lock.
+ */
+static gboolean gUseVmxGuestLog;
+static gchar *gAppName;
+
+/*
+ * This lock protects the gChannel, gLevelMask and gRpcMode
+ */
+static GRecMutex gVmxGuestLogMutex;
+static RpcChannel *gChannel; /* either NULL or allocated AND started */
+
+/*
+ * 1) VMX supports guest.log.* RPCs, use the query result of guest.log.state
+ * 2) Otherwise, use the tools.conf vmx handler level setting.
+ */
+static GLogLevelFlags gLevelMask;
+
+static enum RpcMode {
+   RPC_OFF = 0,
+   RPC_GUEST_LOG_TEXT,
+   RPC_LOG_FALLBACK
+} gRpcMode;
+
+
+/* Forward function declarations */
+
+static void VmxGuestLog(const gchar *domain,
+                        GLogLevelFlags level,
+                        const gchar *message);
+void Debug(const char *fmt, ...);
+
 /* Internal functions. */
 
+/**
+ * Convert log level flag to its string representation.
+ *
+ * @param[in] level        Log level.
+ *
+ * @return a string constant that corresponds to the log level.
+ *         Should NOT be g_free()'d.
+ */
+
+static const char *
+VMToolsLogLevelString(GLogLevelFlags level) {
+   const char *slevel;
+
+   switch (level & G_LOG_LEVEL_MASK) {
+   case G_LOG_LEVEL_ERROR:
+      slevel = "error";
+      break;
+
+   case G_LOG_LEVEL_CRITICAL:
+      slevel = "critical";
+      break;
+
+   case G_LOG_LEVEL_WARNING:
+      slevel = "warning";
+      break;
+
+   case G_LOG_LEVEL_MESSAGE:
+      slevel = "message";
+      break;
+
+   case G_LOG_LEVEL_INFO:
+      slevel = "info";
+      break;
+
+   case G_LOG_LEVEL_DEBUG:
+      slevel = "debug";
+      break;
+
+   default:
+      slevel = "unknown";
+   }
+
+   return slevel;
+}
+
 
 /**
  * Aborts the program, optionally creating a core dump.
@@ -310,34 +397,7 @@ VMToolsLogFormat(const gchar *message,
       message = "<null>";
    }
 
-   switch (level & G_LOG_LEVEL_MASK) {
-   case G_LOG_LEVEL_ERROR:
-      slevel = "error";
-      break;
-
-   case G_LOG_LEVEL_CRITICAL:
-      slevel = "critical";
-      break;
-
-   case G_LOG_LEVEL_WARNING:
-      slevel = "warning";
-      break;
-
-   case G_LOG_LEVEL_MESSAGE:
-      slevel = "message";
-      break;
-
-   case G_LOG_LEVEL_INFO:
-      slevel = "info";
-      break;
-
-   case G_LOG_LEVEL_DEBUG:
-      slevel = "debug";
-      break;
-
-   default:
-      slevel = "unknown";
-   }
+   slevel = VMToolsLogLevelString(level);
 
    if (data->logger != NULL) {
       shared = data->logger->shared;
@@ -455,7 +515,64 @@ VMToolsLogMsg(gpointer _data, gpointer userData)
 
 
 /**
- * Log handler function that does the common processing of log messages,
+ * This is called to avoid nested glib logging.
+ * For example the VMX logger calls RpcChannel code which calls
+ * Debug(), Warning() functions which calls the VMToolsLogWrapper()
+ * function. This variable controls whether the code path there can call
+ * glib logging function or not.
+ * Log messages can still be handled using lower level functions.
+ * NOTE: This must be called after acquiring LogState lock.
+ */
+
+static void
+StopGlibLogging(void)
+{
+   gGlibLoggingStopped = TRUE;
+}
+
+
+/**
+ * This is called to reset the state so that glib logging can be used again.
+ * NOTE: This must be called after acquiring LogState lock.
+ */
+
+static void
+RestartGlibLogging(void)
+{
+   gGlibLoggingStopped = FALSE;
+}
+
+
+/**
+ * This is called to avoid nested infinite logging loop.
+ * We set the flag in the log handler proxy function, Otherwise
+ * if there log handler might call another Debug()/Warning() function
+ * which would end up calling the log handler again, causing an infinite loop,
+ * eventually overflow the stack.
+ * NOTE: This must be called after acquiring LogState lock.
+ */
+
+static void
+DisableLogHandler(void)
+{
+   gLogHandlerEnabled = FALSE;
+}
+
+
+/**
+ * This is called to reset the state so that we can now call a log handler.
+ * NOTE: This must be called after acquiring LogState lock.
+ */
+
+static void
+EnableLogHandler(void)
+{
+   gLogHandlerEnabled = TRUE;
+}
+
+
+/**
+ * Internal Log handler function that does the common processing of logs,
  * and delegates the actual printing of the message to the given handler.
  *
  * @param[in] domain    Log domain.
@@ -465,13 +582,19 @@ VMToolsLogMsg(gpointer _data, gpointer userData)
  */
 
 static void
-VMToolsLog(const gchar *domain,
-           GLogLevelFlags level,
-           const gchar *message,
-           gpointer _data)
+VMToolsLogInt(const gchar *domain,
+              GLogLevelFlags level,
+              const gchar *message,
+              gpointer _data)
 {
    LogHandler *data = _data;
 
+   if (!gLogHandlerEnabled) {
+      return;
+   }
+
+   DisableLogHandler();
+
    if (SHOULD_LOG(level, data)) {
       LogEntry *entry;
 
@@ -549,6 +672,71 @@ exit:
    if (IS_FATAL(level)) {
       VMToolsLogPanic();
    }
+
+   EnableLogHandler();
+}
+
+
+/**
+ * Log handler function that glib invokes on each g_xxx(...) invocation.
+ *
+ * @param[in] domain    Log domain.
+ * @param[in] level     Log level.
+ * @param[in] message   Message to log.
+ * @param[in] _data     LogHandler pointer.
+ */
+
+static void
+VMToolsLog(const gchar *domain,
+           GLogLevelFlags level,
+           const gchar *message,
+           gpointer _data)
+{
+   if (!gLogEnabled) {
+      return;
+   }
+   /*
+    * To avoid nested logging inside of RpcChannel, we need to disable
+    * logging here. See bug 1069390.
+    * This actually stop the glib based logging only. However,
+    * log messages are saved directly to the file system using a lower
+    * level function.
+    */
+   VMTools_AcquireLogStateLock();
+   StopGlibLogging();
+
+   if (gUseVmxGuestLog) {
+
+      /*
+       * Protect the RPC channel and friends data race
+       * Other thread might call g_xxx() or reinitialize the vmx guest logger.
+       *
+       * Recursive mutex is required as the set up function might calls
+       * g_xxx() functions to log messages which would call this function here.
+       *
+       * Always acquire the log state mutex first followed by
+       * the vmxGuestLog mutex to avoid a deadlock.
+       *
+       * This is because Debug()/Warning() functions call VMToolsLogWrapper()
+       * which acquire the log state mutex and call g_xxx function which ends
+       * up here.
+       *
+       * If the order is reversed here, we could end up deadlock
+       * between two threads, one calling g_xxx(), and the other calling
+       * Debug()/Warning()
+       */
+
+      g_rec_mutex_lock(&gVmxGuestLogMutex);
+      VmxGuestLog(NULL == domain ? gLogDomain : domain,
+                  level, message);
+      g_rec_mutex_unlock(&gVmxGuestLogMutex);
+   }
+
+   /* Proxy to the LogHandler object pointed by _data. */
+   VMToolsLogInt(domain, level, message, _data);
+
+   RestartGlibLogging();
+   VMTools_ReleaseLogStateLock();
 }
 
 
@@ -574,11 +762,15 @@ VMToolsDefaultLogFilePath(const gchar *domain)
 
    Win32U_ExpandEnvironmentStrings(DEFAULT_LOGFILE_DIR,
                                    (LPSTR) winDir, sizeof winDir);
-   path = g_strdup_printf("%s%sTemp%s%s-%s.log",
+   path = g_strdup_printf("%s%sTemp%s%s-%s-%s.log",
                           winDir, DIRSEPS, DIRSEPS,
-                          DEFAULT_LOGFILE_NAME_PREFIX, domain);
+                          DEFAULT_LOGFILE_NAME_PREFIX,
+                          domain,
+                          g_get_user_name());
 #else
-   path = g_strdup_printf("%s-%s.log", DEFAULT_LOGFILE_NAME_PREFIX, domain);
+   path = g_strdup_printf("%s-%s-%s.log", DEFAULT_LOGFILE_NAME_PREFIX,
+                          domain,
+                          g_get_user_name());
 #endif
    return path;
 }
@@ -767,6 +959,33 @@ VMToolsGetLogHandler(const gchar *handler,
 }
 
 
+/**
+ * Determine if the domain can only use vmx logging.
+ * Some domain such as vmvss cannot use file logger since the disk
+ * is frozen.
+ *
+ * @param[in]  domain      Name of domain being configured.
+ * @return     TRUE if the domain can only use vmx logging.
+ *             FALSE otherwise.
+ */
+
+static gboolean
+IsDomainVmxLoggingOnly(const gchar *domain)
+{
+   static const gchar *restricted[] = { "vmvss",
+                                       NULL };
+   unsigned int i;
+
+   for(i = 0; restricted[i] != NULL; ++i) {
+      if (strcmp(restricted[i], domain) == 0) {
+         return TRUE;
+      }
+   }
+
+   return FALSE;
+}
+
+
 /**
  * Configures the given log domain based on the data provided in the given
  * dictionary. If the log domain being configured doesn't match the default, and
@@ -821,6 +1040,25 @@ VMToolsConfigLogDomain(const gchar *domain,
    g_snprintf(key, sizeof key, "%s.data", domain);
    confData = g_key_file_get_string(cfg, LOGGING_GROUP, key, NULL);
 
+   /*
+    * Disable the old vmx handler if we are setting up the vmx guest logger
+    * This avoids sending duplicate messages to VMX and also makes the
+    * file logger always available, e.g. logging errors when we cannot
+    * send a message over the vmx guest logger.
+    * Make an exception for vmvss where it might not be able to use a file
+    * system log handler at all, e.g. dllhost.exe.
+    * TBD: Create a no-op LogHandler type so as not to send vmx logs
+    * twice for vmvss.
+    */
+   if (gUseVmxGuestLog && handler != NULL &&
+       !IsDomainVmxLoggingOnly(domain) &&
+       strcmp(handler, "vmx") == 0) {
+      g_free(handler);
+      handler = g_strdup(DEFAULT_HANDLER);
+      g_info("Switched %s log handler from vmx to " DEFAULT_HANDLER ".\n",
+             domain);
+   }
+
    if (handler == NULL && isDefault) {
       /*
        * If no handler defined and we're configuring the default domain,
@@ -1016,6 +1254,22 @@ VMTools_AttachConsole(void)
 #endif
 
 
+/**
+ * Mark log system initialized.
+ *
+ * Also initialize the log state lock.
+ */
+
+static void
+MarkLogInitialized(void)
+{
+   if (!gLogInitialized) {
+      gLogInitialized = TRUE;
+      g_rec_mutex_init(&gLogStateMutex);
+   }
+}
+
+
 /**
  * Configures the logging system to log to the STDIO.
  *
@@ -1044,13 +1298,10 @@ VMTools_ConfigLogToStdio(const gchar *domain)
 
    g_log_set_handler(gLogDomain, ~0, VMToolsLog, gStdLogHandler);
 
-   if (!gLogInitialized) {
-      gLogInitialized = TRUE;
-      g_static_rec_mutex_init(&gLogStateMutex);
-   }
-
    gLogEnabled = TRUE;
 
+   MarkLogInitialized();
+
 exit:
    g_key_file_free(cfg);
 }
@@ -1155,10 +1406,7 @@ VMTools_ConfigLogging(const gchar *defaultDomain,
     * can also log messages.
     */
    gLogEnabled |= force;
-   if (!gLogInitialized) {
-      gLogInitialized = TRUE;
-      g_static_rec_mutex_init(&gLogStateMutex);
-   }
+   MarkLogInitialized();
 
    gMaxCacheEntries = g_key_file_get_integer(cfg, LOGGING_GROUP,
                                              "maxCacheEntries", &err);
@@ -1268,7 +1516,10 @@ VMTools_ConfigLogging(const gchar *defaultDomain,
 
 /* Wrappers for VMware's logging functions. */
 
-/**
+/*
+ *******************************************************************************
+ * VMToolsLogWrapper --                                                   */ /**
+ *
  * Generic wrapper for VMware log functions.
  *
  * CoreDump_CoreDump() may log, and glib doesn't like recursive log calls. So
@@ -1277,6 +1528,8 @@ VMTools_ConfigLogging(const gchar *defaultDomain,
  * @param[in]  level    Log level.
  * @param[in]  fmt      Message format.
  * @param[in]  args     Message arguments.
+ *
+ *******************************************************************************
  */
 
 static void
@@ -1294,71 +1547,370 @@ VMToolsLogWrapper(GLogLevelFlags level,
    }
 
    VMTools_AcquireLogStateLock();
-   if (gLoggingStopped) {
-      /* This is to avoid nested logging in vmxLogger */
-      VMTools_ReleaseLogStateLock();
-      return;
-   }
-   VMTools_ReleaseLogStateLock();
 
    if (gPanicCount == 0) {
       char *msg = Str_Vasprintf(NULL, fmt, args);
+
       if (msg != NULL) {
-         g_log(gLogDomain, level, "%s", msg);
+
+         if (gGlibLoggingStopped) {
+            /*
+             * Stop logging using glib logging functions such as g_log()
+             * This is to avoid nested logging in vmxLogger
+             * However, we should still directly call the lower level
+             * primitive to directly write to the guest file system.
+             */
+            VMToolsLogInt(gLogDomain, level, msg, gDefaultData);
+         } else {
+            g_log(gLogDomain, level, "%s", msg);
+         }
+
          free(msg);
       }
    } else {
       /* Try to avoid malloc() since we're aborting. */
       gchar msg[256];
       Str_Vsnprintf(msg, sizeof msg, fmt, args);
-      VMToolsLog(gLogDomain, level, msg, gDefaultData);
+      VMToolsLogInt(gLogDomain, level, msg, gDefaultData);
    }
+
+   VMTools_ReleaseLogStateLock();
 }
 
 
-/**
- * Acquire the log state lock.
+/*
+ *******************************************************************************
+ * CreateRpcChannel --                                                    */ /**
+ *
+ * Create the dedicated RPCI channel for querying the guest level setting
+ * and sending logs.
+ *
+ * @return TRUE if the RPCI channel is ready.
+ *         FALSE otherwise.
+ *
+ *******************************************************************************
  */
 
-void
-VMTools_AcquireLogStateLock(void)
+static gboolean
+CreateRpcChannel(void)
 {
-   g_static_rec_mutex_lock(&gLogStateMutex);
+   if (NULL != gChannel) {
+      return TRUE; // already created and started
+   }
+
+   gChannel = BackdoorChannel_New();
+   if (NULL == gChannel) {
+      g_warning("Failed to create the RPCI channel for logging.\n");
+      return FALSE;
+   }
+
+   if (!RpcChannel_Start(gChannel)) {
+      g_warning("Failed to start the RPCI channel for logging.\n");
+      RpcChannel_Destroy(gChannel);
+      gChannel = NULL;
+      return FALSE;
+   }
+
+   g_debug("RPCI Channel for logging is created successfully.\n");
+
+   return TRUE;
 }
 
 
-/**
- * Release the log state lock.
+/*
+ *******************************************************************************
+ * DestroyRpcChannel --                                                   */ /**
+ *
+ * Destroy the dedicated RPCI channel.
+ *
+ *******************************************************************************
  */
 
-void
-VMTools_ReleaseLogStateLock(void)
+static void
+DestroyRpcChannel(void)
+{
+   if (NULL == gChannel) {
+      return;
+   }
+
+   RpcChannel_Stop(gChannel);
+   RpcChannel_Destroy(gChannel);
+
+   gChannel = NULL;
+
+   g_debug("RPCI Channel for logging is destroyed successfully.\n");
+}
+
+
+/*
+ *******************************************************************************
+ * LevelMask --                                                           */ /**
+ *
+ * Convert level string to a level mask value.
+ *
+ * @return the level mask
+ *
+ *******************************************************************************
+ */
+
+static GLogLevelFlags
+LevelMask(const gchar *level)
+{
+   GLogLevelFlags result;
+
+   /* level to glib log mask translation */
+
+   if (strcmp(level, "error") == 0) {
+      result = G_LOG_LEVEL_ERROR | G_LOG_LEVEL_CRITICAL;
+   } else if (strcmp(level, "warning") == 0) {
+      result = G_LOG_LEVEL_ERROR |
+         G_LOG_LEVEL_CRITICAL |
+         G_LOG_LEVEL_WARNING;
+   } else if (strcmp(level, "notice") == 0 ||
+              strcmp(level, "info") == 0 ||
+              strcmp(level, "message") == 0) {
+      result = G_LOG_LEVEL_ERROR |
+         G_LOG_LEVEL_CRITICAL |
+         G_LOG_LEVEL_WARNING |
+         G_LOG_LEVEL_MESSAGE |
+         G_LOG_LEVEL_INFO;
+   } else if (strcmp(level, "verbose") == 0 ||
+              strcmp(level, "debug") == 0 ||
+              strcmp(level, "trivia") == 0) {
+      result = G_LOG_LEVEL_MASK;
+   } else {
+      /* treated as off */
+      result = 0;
+   }
+
+   return result;
+}
+
+
+/*
+ *******************************************************************************
+ * LoadFallbackSetting --                                                 */ /**
+ *
+ * Load the log fallback setting from a tools config object.
+ *
+ * TBD: Extend this function load the vmx handler setting into a dictionary
+ * of [domain, level] mapping instead of just a single level from the default
+ * domain. The Log handler code can use the dictonary vs a single level mask.
+ * The VMX side can also be extended to return an dictionary of [domain, level]
+ * mapping as well. For now, let us stick with the simple.
+ *
+ * @param [in] cfg    a tools config object.
+ *
+ *******************************************************************************
+ */
+
+static void
+LoadFallbackSetting(GKeyFile *cfg)
+{
+   gchar *handler;
+   gchar *level;
+   gchar key[128];
+
+   ASSERT(NULL != cfg);
+
+   g_snprintf(key, sizeof key, "%s.handler", gLogDomain);
+   handler = g_key_file_get_string(cfg, LOGGING_GROUP, key, NULL);
+
+   if (NULL == handler) {
+      g_debug("%s.handler not present in config file.\n", gLogDomain);
+      return;
+   }
+
+   if (strcmp(handler, "vmx") != 0) {
+      g_debug("%s.handler is not a vmx handler in config file.\n", gLogDomain);
+      g_free(handler);
+      return;
+   }
+
+   g_free(handler);
+
+   /* The tools.conf use the vmx handler, let us continue to load the level */
+   g_snprintf(key, sizeof key, "%s.level", gLogDomain);
+   level = g_key_file_get_string(cfg, LOGGING_GROUP, key, NULL);
+   if (NULL == level) {
+      level = g_strdup(VMTOOLS_LOGGING_LEVEL_DEFAULT);
+   }
+
+   gLevelMask = LevelMask(level);
+
+   g_free(level);
+
+   if (gLevelMask != 0) {
+      gRpcMode = RPC_LOG_FALLBACK;
+   } else {
+      gRpcMode = RPC_OFF;
+   }
+}
+
+
+/*
+ *******************************************************************************
+ * SetupLogLevelAndRpcMode --                                             */ /**
+ *
+ * Query the host to set up the log level and the RPC mode.
+ * If the host does not support the guest.log.state guest RPC, we fallback
+ * load the config and use the log RPC.
+ *
+ * @param[in/opt]  cfg                  tools config file object.
+ * @param[in/opt]  level                log level string from vmx
+ * @return         TRUE  if RPC channel is created and ready to send log.
+ *                 FALSE otherwise.
+ *
+ *******************************************************************************
+ */
+
+static gboolean
+SetupLogLevelAndRpcMode(GKeyFile *cfg,
+                        const gchar *level)
+{
+   gRpcMode = RPC_OFF;
+
+   if (NULL == gChannel) {
+      /*
+       * Channel could be broken due to a VMX channel reinitialize
+       * This needs to be tolerated, but we cannot log right now...
+       * A later reset handler would refresh the channel.
+       */
+      g_info("The LOG RPC channel is not up, skip query log state.\n");
+      goto done;
+   }
+
+   if (NULL == level) {
+      char *result = NULL;
+      size_t resultLen;
+
+      if (!RpcChannel_Send(gChannel, GUEST_LOG_STATE_CMD,
+                           sizeof GUEST_LOG_STATE_CMD,
+                           &result, &resultLen)) {
+         g_warning("Failed to send " GUEST_LOG_STATE_CMD " command to VMX.\n");
+         LoadFallbackSetting(cfg);
+         RpcChannel_Free(result);
+         goto done;
+      }
+
+      /* The RpcChannel_Send() NULL terminate the response */
+      g_info("Received host log level '%s'.\n", result);
+
+      gLevelMask = LevelMask(result);
+
+      RpcChannel_Free(result);
+   } else {
+      gLevelMask = LevelMask(level);
+   }
+
+   if (gLevelMask != 0) {
+      gRpcMode = RPC_GUEST_LOG_TEXT;
+   } else {
+      gRpcMode = RPC_OFF;
+   }
+
+done:
+
+   if (RPC_OFF == gRpcMode || NULL == gChannel) {
+      /*
+       * No need to keep around the RPC channel,
+       * VMX can give it to other apps.
+       */
+      DestroyRpcChannel();
+      return FALSE;
+   }
+
+   return TRUE;
+}
+
+
+/*
+ *******************************************************************************
+ * VmxGuestLog --                                                         */ /**
+ *
+ * Logs a message to the VMX using RpcChannel.
+ *
+ * @param[in] domain    Unused.
+ * @param[in] level     Log level.
+ * @param[in] message   Message to log.
+ *
+ *******************************************************************************
+ */
+
+static void
+VmxGuestLog(const gchar *domain,
+            GLogLevelFlags level,
+            const gchar *message)
 {
-   g_static_rec_mutex_unlock(&gLogStateMutex);
+   if (!(gLevelMask & level)) { /* level is not sufficient */
+      return;
+   }
+
+   if (NULL == gChannel) {
+      /* This could happen upon a toolsd reset, e.g. vMotion */
+      Debug("The LOG RPC channel is not up, skip logging.\n");
+      return;
+   }
+
+   if (RPC_GUEST_LOG_TEXT == gRpcMode) {
+      gchar *msg = NULL;
+      gint len = VMToolsAsprintf(&msg, GUEST_LOG_TEXT_CMD
+                                 " [%s] [%s] [%s] %s", gAppName,
+                                 VMToolsLogLevelString(level), domain, message);
+      if (NULL == msg) {
+         VMToolsLogPanic();
+      }
+
+      if (!RpcChannel_Send(gChannel, msg, len, NULL, NULL)) {
+         Warning("Failed to send " GUEST_LOG_TEXT_CMD " command to VMX.\n");
+         /* Transition to the fallback mode */
+         gRpcMode = RPC_LOG_FALLBACK;
+      }
+      g_free(msg);
+   }
+
+   if (RPC_LOG_FALLBACK == gRpcMode) {
+      gchar *msg = NULL;
+      gint len = VMToolsAsprintf(&msg,
+                                 "log [%s] [%s] %s",
+                                 VMToolsLogLevelString(level), domain, message);
+      if (NULL == msg) {
+         VMToolsLogPanic();
+      }
+
+      if (!RpcChannel_Send(gChannel, msg, len, NULL, NULL)) {
+         Warning("Failed to send log command to VMX.\n");
+         /*
+          * VMX might have done a channel reset. This needs to be tolerated.
+          * Transition to the off mode, let the tools reset handle the rest
+          */
+         gRpcMode = RPC_OFF;
+         DestroyRpcChannel();
+      }
+      g_free(msg);
+   }
 }
 
 
 /**
- * This is called to avoid nested logging in vmxLogger.
- * NOTE: This must be called after acquiring LogState lock.
+ * Acquire the log state lock.
  */
 
 void
-VMTools_StopLogging(void)
+VMTools_AcquireLogStateLock(void)
 {
-   gLoggingStopped = TRUE;
+   g_rec_mutex_lock(&gLogStateMutex);
 }
 
 
 /**
- * This is called to reset logging in vmxLogger.
- * NOTE: This must be called after acquiring LogState lock.
+ * Release the log state lock.
  */
 
 void
-VMTools_RestartLogging(void)
+VMTools_ReleaseLogStateLock(void)
 {
-   gLoggingStopped = FALSE;
+   g_rec_mutex_unlock(&gLogStateMutex);
 }
 
 
@@ -1521,12 +2073,17 @@ LogV(uint32 routing,
 }
 
 
-/**
+/*
+ *******************************************************************************
+ * Panic --                                                               */ /**
+ *
  * Logs a message using the G_LOG_LEVEL_ERROR level. In the default
  * configuration, this will cause the application to terminate and,
  * if enabled, to dump core.
  *
  * @param[in] fmt Log message format.
+ *
+ *******************************************************************************
  */
 
 void
@@ -1569,10 +2126,15 @@ Panic(const char *fmt, ...)
 }
 
 
-/**
+/*
+ *******************************************************************************
+ * Warning --                                                             */ /**
+ *
  * Logs a message using the G_LOG_LEVEL_WARNING level.
  *
  * @param[in] fmt Log message format.
+ *
+ *******************************************************************************
  */
 
 void
@@ -1595,9 +2157,8 @@ Warning(const char *fmt, ...)
 
 
 /*
- *----------------------------------------------------------------------
- *
- * VMTools_ChangeLogFilePath --
+ *******************************************************************************
+ * VMTools_ChangeLogFilePath --                                           */ /**
  *
  *     This function gets the log file location given in the config file
  *     and appends the string provided just before the delimiter specified.
@@ -1621,7 +2182,7 @@ Warning(const char *fmt, ...)
  * Side effects:
  *     Appends a string into the log file location.
  *
- *----------------------------------------------------------------------
+ *******************************************************************************
  */
 
 gboolean
@@ -1671,3 +2232,145 @@ exit:
 
    return retVal;
 }
+
+
+/*
+ *******************************************************************************
+ * VMTools_UseVmxGuestLog --                                              */ /**
+ *
+ * Set up a global flag that indicates we shall use the vmx guest logger.
+ * You might wonder why this function and the VMTools_SetVmxGuestLog() are NOT
+ * one. This is because we need to call VMTools_SetupVmxGuestLog() after
+ * VMTools_ConfigLogging() since if we failed to setup the vmx guest logger,
+ * we can leverage the file system logging facility to log those setup failures.
+ * However, VMTools_ConfigLogging() code path needs to know whether to disable
+ * the old vmx log handler or not. Not all tools app have migrated to the new
+ * vmx guest logger. To keep the compatibility we should not mess up with
+ * the VMTools_ConfigLogging() code path by restructuring it yet.
+ *
+ * @param[in]   appName   the application name, also serves as a routing tag
+ *                        of the log message for the host side.
+ *
+ *******************************************************************************
+ */
+
+void
+VMTools_UseVmxGuestLog(const gchar *appName)
+{
+   if (!gUseVmxGuestLog) {
+      gAppName = g_strdup(appName);
+      g_rec_mutex_init(&gVmxGuestLogMutex);
+      gUseVmxGuestLog = TRUE;
+   }
+}
+
+
+/*
+ *******************************************************************************
+ * SetupVmxGuestLogInt --                                                 */ /**
+ *
+ * Initialize the Vmx Guest Logging.
+ * If the guest.log.* RPC is supported, set the level from the RPC query.
+ * Otherwise, check the vmx handler setting from the cfg.
+ *
+ * @param[in]      refreshRpcChannel    whether to create a new RPC channel.
+ * @param[in]      cfg                  tools config file object.
+ * @param[in/opt]  level                log level string from vmx
+ *
+ *******************************************************************************
+ */
+
+
+static void
+SetupVmxGuestLogInt(gboolean refreshRpcChannel,   // IN
+                    GKeyFile *cfg,                // IN
+                    const gchar *level)           // IN
+{
+   gboolean disabled = g_key_file_get_boolean(cfg, LOGGING_GROUP,
+                                             "vmxGuestLogDisabled", NULL);
+
+   if (disabled) {
+      g_info("Vmx guest logger is disabled in tools configuration");
+      gRpcMode = RPC_OFF;
+      DestroyRpcChannel();
+      return;
+   }
+
+   if (refreshRpcChannel) {
+      DestroyRpcChannel();
+   }
+
+   if (CreateRpcChannel() && SetupLogLevelAndRpcMode(cfg, level)) {
+      g_info("Initialized the vmx guest logger.\n");
+   }
+}
+
+
+/*
+ *******************************************************************************
+ * VMTools_SetupVmxGuestLog --                                            */ /**
+ *
+ * Initialize the Vmx Guest Logging.
+ * If the guest.log.* RPC is supported, set the level from the RPC query.
+ * Otherwise, read tools.conf for the vmx handler setting.
+ * This function is called from the tools initialization, tools reset,
+ * and the tools options handler code path.
+ *
+ * @param[in]      refreshRpcChannel    whether to create a new RPC channel.
+ * @param[in/opt]  cfg                  tools config file object.
+ * @param[in/opt]  level                log level string from vmx
+ *
+ *******************************************************************************
+ */
+
+void
+VMTools_SetupVmxGuestLog(gboolean refreshRpcChannel,   // IN
+                         GKeyFile *cfg,                // IN
+                         const gchar *level)           // IN
+{
+   /*
+    * Callers need to call VMTools_UseVmxGuestLog() first.
+    * See the function header of VMTools_UseVmxGuestLog for details.
+    */
+
+   VERIFY(gUseVmxGuestLog);
+
+   /*
+    * Always acquire the log state mutex first followed by
+    * the vmxGuestLog mutex to avoid a deadlock.
+    * This is because Debug()/Warning() functions call VMToolsLogWrapper()
+    * which acquire the log state mutex and call g_xxx function.
+    *
+    * If the order is reversed here, we could end up deadlock between
+    * two threads, one calling this function, and the other calling
+    * Debug()/Warning()
+    *
+    */
+   VMTools_AcquireLogStateLock();
+
+   /*
+    * Recursive mutex is required as the set up function might call
+    * g_xxx() functions to log messages which would call VMToolsLog()
+    * which acquires the same mutex.
+    */
+   g_rec_mutex_lock(&gVmxGuestLogMutex);
+
+   /* Load config for the kill switch in tools.conf */
+   if (NULL == cfg) {
+      if (!VMTools_LoadConfig(NULL, G_KEY_FILE_NONE, &cfg, NULL)) {
+         g_warning("Failed to load the tools config file.\n");
+         goto done;
+      }
+
+      SetupVmxGuestLogInt(refreshRpcChannel, cfg, level);
+      g_key_file_free(cfg);
+      goto done;
+   }
+
+   SetupVmxGuestLogInt(refreshRpcChannel, cfg, level);
+
+done:
+   g_rec_mutex_unlock(&gVmxGuestLogMutex);
+
+   VMTools_ReleaseLogStateLock();
+}
index 113c55c1af0bc2df865af4517aaf0edee1f07ab3..b73546bc34fc881023c0cc778de2c0f31a0cab10 100644 (file)
@@ -59,14 +59,6 @@ VMXLoggerLog(const gchar *domain,
 {
    VMXLoggerData *logger = data;
 
-   VMTools_AcquireLogStateLock();
-   /*
-    * To avoid nested logging inside of RpcChannel, we need to disable logging
-    * here. See bug 1069390.
-    */
-
-   VMTools_StopLogging();
-
    if (RpcChannel_Start(logger->chan)) {
       gchar *msg;
       gint cnt = VMToolsAsprintf(&msg, "log %s", message);
@@ -76,9 +68,6 @@ VMXLoggerLog(const gchar *domain,
       g_free(msg);
       RpcChannel_Stop(logger->chan);
    }
-
-   VMTools_RestartLogging();
-   VMTools_ReleaseLogStateLock();
 }
 
 
index eaab9a13ca14a8880971819b49b201a8a7f84ae2..88d18fd9f46a4ed0dee3e1dd09f95801c855b196 100644 (file)
@@ -1,5 +1,5 @@
 /*********************************************************
- * Copyright (C) 2008-2017 VMware, Inc. All rights reserved.
+ * Copyright (C) 2008-2018 VMware, Inc. All rights reserved.
  *
  * This program is free software; you can redistribute it and/or modify it
  * under the terms of the GNU Lesser General Public License as published
@@ -255,6 +255,79 @@ ToolsCoreReportVersionData(ToolsServiceState *state)
 }
 
 
+/*
+ ******************************************************************************
+ * ToolsCoreSetOptionSignalCb --
+ *
+ *  The SET_OPTION signal callback. The signal was triggered from
+ *  ToolsCoreRpcSetOption. This function is needed to safely run code
+ *  outside of the TCLO RPC handler.
+ *
+ *  Check for TOOLSOPTION_GUEST_LOG_LEVEL,
+ *  and reinitialize the Vmx Guest Logger.
+ *
+ * @param[in]  src      The source object.
+ * @param[in]  ctx      The ToolsAppCtx for passing config.
+ * @param[in]  option   The option key.
+ * @param[in]  value    The option value.
+ * @param[in]  data     Unused.
+ *
+ * Result:
+ *      TRUE on success.
+ *
+ * Side-effects:
+ *      None
+ *
+ ******************************************************************************
+ */
+
+static gboolean
+ToolsCoreSetOptionSignalCb(gpointer src,               // IN
+                           ToolsAppCtx *ctx,           // IN
+                           const gchar *option,        // IN
+                           const gchar *value,         // IN
+                           gpointer data)              // IN
+{
+   if (strcmp(option, TOOLSOPTION_GUEST_LOG_LEVEL) == 0) {
+      ASSERT(value); /* Caller ensures */
+      g_info("Received the tools set option for the guest log level '%s'.\n",
+             value);
+
+      /* Reuse the existing RPC channel */
+      VMTools_SetupVmxGuestLog(FALSE, ctx->config, value);
+   }
+
+   return TRUE;
+}
+
+
+/*
+ ******************************************************************************
+ *
+ * ToolsCoreResetSignalCb --
+ *  The RESET signal callback. The signal was triggered from
+ *  ToolsCoreCheckReset. This function is needed to safely run code
+ *  outside of the RPC Channel reset code.
+ *
+ *  Reinitialize the Vmx Guest Logger.
+ *
+ * @param[in]  src      The source object.
+ * @param[in]  ctx      The ToolsAppCtx for passing the config.
+ * @param[in]  data     Unused.
+ *
+ ******************************************************************************
+ */
+
+static void
+ToolsCoreResetSignalCb(gpointer src,          // IN
+                       ToolsAppCtx *ctx,      // IN
+                       gpointer data)         // IN
+{
+   g_info("Reinitialize the Vmx Guest Logger with a new RPC channel.\n");
+   VMTools_SetupVmxGuestLog(TRUE, ctx->config, NULL); /* New RPC channel */
+}
+
+
 /*
  ******************************************************************************
  * ToolsCoreRunLoop --                                                  */ /**
@@ -330,6 +403,22 @@ ToolsCoreRunLoop(ToolsServiceState *state)
                           state);
       }
 
+      if (g_signal_lookup(TOOLS_CORE_SIG_SET_OPTION,
+                          G_OBJECT_TYPE(state->ctx.serviceObj)) != 0) {
+         g_signal_connect(state->ctx.serviceObj,
+                          TOOLS_CORE_SIG_SET_OPTION,
+                          G_CALLBACK(ToolsCoreSetOptionSignalCb),
+                          NULL);
+      }
+
+      if (g_signal_lookup(TOOLS_CORE_SIG_RESET,
+                          G_OBJECT_TYPE(state->ctx.serviceObj)) != 0) {
+         g_signal_connect(state->ctx.serviceObj,
+                          TOOLS_CORE_SIG_RESET,
+                          G_CALLBACK(ToolsCoreResetSignalCb),
+                          NULL);
+      }
+
       state->configCheckTask = g_timeout_add(CONF_POLL_TIME * 1000,
                                              ToolsCoreConfFileCb,
                                              state);
@@ -467,6 +556,14 @@ ToolsCore_ReloadConfig(ToolsServiceState *state,
                             state->ctx.config,
                             TRUE,
                             reset);
+
+      /*
+       * Reinitialize the level setting of the VMX Guest Logger
+       * since either the config is changing or we are forcing a reload
+       * of the tools logging subsystem.
+       * However, reuse the RPC channel since it is not affected.
+       */
+      VMTools_SetupVmxGuestLog(FALSE, state->ctx.config, NULL);
    }
 }
 
index cf200103b112e7707f537391486374c1f442ba0e..4a2fa2bcdd7890d62ca97ee6b3c73709e9522d39 100644 (file)
@@ -1,5 +1,5 @@
 /*********************************************************
- * Copyright (C) 2008-2016 VMware, Inc. All rights reserved.
+ * Copyright (C) 2008-2018 VMware, Inc. All rights reserved.
  *
  * This program is free software; you can redistribute it and/or modify it
  * under the terms of the GNU Lesser General Public License as published
@@ -183,7 +183,11 @@ main(int argc,
    }
 
    setlocale(LC_ALL, "");
-   VMTools_ConfigLogging(G_LOG_DOMAIN, NULL, FALSE, FALSE);
+
+   VMTools_UseVmxGuestLog(VMTOOLS_APP_NAME);
+   VMTools_ConfigLogging(G_LOG_DOMAIN, NULL, TRUE, FALSE);
+   VMTools_SetupVmxGuestLog(FALSE, NULL, NULL);
+
    VMTools_BindTextDomain(VMW_TEXT_DOMAIN, NULL, NULL);
 
    if (!ToolsCore_ParseCommandLine(&gState, argc, argvCopy)) {
index 6d304a716c0452b9ba1c847be8791ef65c76039e..3095fd4180ed8b75173dbb1658313160d6c338a8 100644 (file)
@@ -49,6 +49,8 @@
 #  define G_MODULE_SUFFIX "dylib"
 #endif
 
+#define VMTOOLS_APP_NAME "vmtools"
+
 /** State of app providers. */
 typedef enum {
    TOOLS_PROVIDER_IDLE,