Improved logging in python

-- Reworked the way developer logging happens when using the openweave wrappers for python.
With this change, all WeaveLog...() calls in C++ code result in a callback to a logging
function in python.  The default implementation of this function directs log messages to a
standard python logger object associated with the python WeaveStack object.  By default, the
python logger is configured to output messages to stdout, in a format identical to that used
by the C++ code.  However, developers are free to reconfigure the logger object, or replace
it altogether, giving them complete control over the handling of C++ generated logs in
python applications.

-- Added support for dynamic logging behavior.  Modified the standard implementation of
nl::Weave::Logging::Log() so that the default logging behavior can be overridden at runtime.
Applications can now use the SetLogFunct() function to specify a pointer to a function to be
called for every logged message.  Setting the function pointer to NULL (the default value)
results in the original behavior of logging to stdout via printf().

Author: Jay Logue

src/device-manager/python/WeaveDeviceManager-ScriptBinding.cpp

@@ -29,6 +29,7 @@
 #include <errno.h>
 #include <unistd.h>
 #include <fcntl.h>
+#include <sys/time.h>
 
 #include <SystemLayer/SystemLayer.h>
 #include <SystemLayer/SystemError.h>
@@ -69,6 +70,7 @@ using DeviceDescription::IdentifyDeviceCriteria;
 extern "C" {
 typedef void * (*GetBleEventCBFunct)(void);
 typedef void (*ConstructBytesArrayFunct)(const uint8_t *dataBuf, uint32_t dataLen);
+typedef void (*LogMessageFunct)(uint64_t time, uint64_t timeUS, const char *moduleName, uint8_t category, const char *msg);
 }
 
 enum BleEventType
@@ -257,6 +259,7 @@ extern "C" {
     NL_DLL_EXPORT WEAVE_ERROR nl_Weave_Stack_Shutdown();
     NL_DLL_EXPORT const char *nl_Weave_Stack_ErrorToString(WEAVE_ERROR err);
     NL_DLL_EXPORT const char *nl_Weave_Stack_StatusReportToString(uint32_t profileId, uint16_t statusCode);
+    NL_DLL_EXPORT void nl_Weave_Stack_SetLogFunct(LogMessageFunct logFunct);
 #if WEAVE_CONFIG_DATA_MANAGEMENT_CLIENT_EXPERIMENTAL
     NL_DLL_EXPORT WEAVE_ERROR nl_Weave_WdmClient_Init();
     NL_DLL_EXPORT WEAVE_ERROR nl_Weave_WdmClient_Shutdown();
@@ -1217,14 +1220,93 @@ WEAVE_ERROR nl_Weave_Stack_Shutdown()
 
 const char *nl_Weave_Stack_ErrorToString(WEAVE_ERROR err)
 {
-        return nl::ErrorStr(err);
+    return nl::ErrorStr(err);
 }
 
 const char *nl_Weave_Stack_StatusReportToString(uint32_t profileId, uint16_t statusCode)
 {
     return nl::StatusReportStr(profileId, statusCode);
 }
 
+#if WEAVE_LOG_ENABLE_DYNAMIC_LOGING_FUNCTION
+
+// A pointer to the python logging function.
+static LogMessageFunct sLogMessageFunct = NULL;
+
+// This function is called by the Weave logging code whenever a developer message
+// is logged.  It serves as glue to adapt the logging arguments to what is expected
+// by the python code.
+// NOTE that this function MUST be thread-safe.
+static void LogMessageToPython(uint8_t module, uint8_t category, const char *msg, va_list ap)
+{
+    if (IsCategoryEnabled(category))
+    {
+        // Capture the timestamp of the log message.
+        struct timeval tv;
+        gettimeofday(&tv, NULL);
+
+        // Get the module name
+        char moduleName[nlWeaveLoggingModuleNameLen + 1];
+        ::nl::Weave::Logging::GetModuleName(moduleName, module);
+
+        // Format the log message into a dynamic memory buffer, growing the
+        // buffer as needed to fit the message.
+        char * msgBuf = NULL;
+        size_t msgBufSize = 0;
+        size_t msgSize = 0;
+        constexpr size_t kInitialBufSize = 120;
+        do
+        {
+            va_list apCopy;
+            va_copy(apCopy, ap);
+
+            msgBufSize = max(msgSize+1, kInitialBufSize);
+            msgBuf = (char *)realloc(msgBuf, msgBufSize);
+            if (msgBuf == NULL)
+            {
+                return;
+            }
+
+            int res = vsnprintf(msgBuf, msgBufSize, msg, apCopy);
+            if (res < 0)
+            {
+                return;
+            }
+            msgSize = (size_t)res;
+
+            va_end(apCopy);
+        } while (msgSize >= msgBufSize);
+
+        // Call the configured python logging function.
+        sLogMessageFunct((int64_t)tv.tv_sec, (int64_t)tv.tv_usec, moduleName, category, msgBuf);
+
+        // Release the message buffer.
+        free(msgBuf);
+    }
+}
+
+void nl_Weave_Stack_SetLogFunct(LogMessageFunct logFunct)
+{
+    if (logFunct != NULL)
+    {
+        sLogMessageFunct = logFunct;
+        ::nl::Weave::Logging::SetLogFunct(LogMessageToPython);
+    }
+    else
+    {
+        sLogMessageFunct = NULL;
+        ::nl::Weave::Logging::SetLogFunct(NULL);
+    }
+}
+
+#else // WEAVE_LOG_ENABLE_DYNAMIC_LOGING_FUNCTION
+
+void nl_Weave_Stack_SetLogFunct(LogMessageFunct logFunct)
+{
+}
+
+#endif // WEAVE_LOG_ENABLE_DYNAMIC_LOGING_FUNCTION
+
 #if WEAVE_CONFIG_DATA_MANAGEMENT_CLIENT_EXPERIMENTAL
 static void EngineEventCallback(void * const aAppState,
                                 SubscriptionEngine::EventID aEvent,

src/device-manager/python/openweave/WeaveStack.py

@@ -36,6 +36,7 @@
 import glob
 import platform
 import ast
+import logging
 from threading import Thread, Lock, Event
 from ctypes import *
 from .WeaveUtility import WeaveUtility
@@ -90,8 +91,57 @@ def __init__(self, profileId, statusCode, systemErrorCode, msg=None):
     def __str__(self):
         return "Device Error: " + self.message
 
+class LogCategory(object):
+    '''Debug logging categories used by openweave.'''
+    
+    # NOTE: These values must correspond to those used in the openweave C++ code.
+    Disabled    = 0
+    Error       = 1
+    Progress    = 2
+    Detail      = 3
+    Retain      = 4
+
+    @staticmethod
+    def categoryToLogLevel(cat):
+        if cat == LogCategory.Error:
+            return logging.ERROR
+        elif cat == LogCategory.Progress:
+            return logging.INFO
+        elif cat == LogCategory.Detail:
+            return logging.DEBUG
+        elif cat == LogCategory.Retain:
+            return logging.CRITICAL
+        else:
+            return logging.NOTSET
+
+class WeaveLogFormatter(logging.Formatter):
+    '''A custom logging.Formatter for logging openweave library messages.'''
+    def __init__(self, datefmt=None, logModule=True, logLevel=False, logTimestamp=False, logMSecs=True):
+        fmt = '%(message)s'
+        if logModule:
+            fmt = 'WEAVE:%(weave-module)s: ' + fmt
+        if logLevel:
+            fmt = '%(levelname)s:' + fmt
+        if datefmt is not None or logTimestamp:
+            fmt = '%(asctime)s ' + fmt
+        super(WeaveLogFormatter, self).__init__(fmt=fmt, datefmt=datefmt)
+        self.logMSecs = logMSecs
+        
+    def formatTime(self, record, datefmt=None):
+        timestamp = record.__dict__.get('timestamp', time.time())
+        timestamp = time.localtime(timestamp)
+        if datefmt is None:
+            datefmt = '%Y-%m-%d %H:%M:%S%z'
+        timestampStr = time.strftime('%Y-%m-%d %H:%M:%S%z')
+        if self.logMSecs:
+            timestampUS = record.__dict__.get('timestamp-usec', 0)
+            timestampStr = '%s.%03ld' % (timestampStr, timestampUS / 1000)
+        return timestampStr
+
+
 _CompleteFunct                              = CFUNCTYPE(None, c_void_p, c_void_p)
 _ErrorFunct                                 = CFUNCTYPE(None, c_void_p, c_void_p, c_ulong, POINTER(DeviceStatusStruct))
+_LogMessageFunct                            = CFUNCTYPE(None, c_int64, c_int64, c_char_p, c_uint8, c_char_p)
 
 @_singleton
 class WeaveStack(object):
@@ -102,8 +152,33 @@ def __init__(self):
         self._weaveDLLPath = None
         self.devMgr = None
         self.callbackRes = None
+        self._activeLogFunct = None
 
-        self._InitLib()
+        # Locate and load the openweave shared library.
+        self._loadLib()
+
+        # By default, configure the openweave library to log to a python logger object with the
+        # name 'openweave.WeaveStack'.  If this logger has not already been initialized by
+        # the application, automatically configure it to log to stdout. 
+        #
+        # Applications can override this behavior in any one the following ways:
+        #     - Setting self.logger to a different python logger object.
+        #     - Replacing the StreamHandler on self.logger with a different handler object.
+        #     - Setting a different Formatter object on the existing StreamHandler object.
+        #     - Reconfiguring the existing LogMessageFormatter object, e.g. to enable logging
+        #       of timestamps.
+        #     - Configuring openwave to call an application-specific logging function by
+        #       calling self.setLogFunct().
+        #     - Calling self.setLogFunct(None), which will configure the openweave library
+        #       to log directly to stdout, bypassing python altogether.
+        #
+        self.logger = logging.getLogger(__name__)
+        if len(self.logger.handlers) == 0:
+            logHandler = logging.StreamHandler(stream=sys.stdout)
+            logHandler.setFormatter(WeaveLogFormatter())
+            self.logger.addHandler(logHandler)
+            self.logger.setLevel(logging.DEBUG)
+        self.setLogFunct(self.defaultLogFunct)
 
         def HandleComplete(appState, reqState):
             self.callbackRes = True
@@ -117,6 +192,49 @@ def HandleError(appState, reqState, err, devStatusPtr):
         self.cbHandleError = _ErrorFunct(HandleError)
         self.blockingCB = None # set by other modules(BLE) that require service by thread while thread blocks.
 
+        # Initialize the openweave library
+        res = self._weaveStackLib.nl_Weave_Stack_Init()
+        if (res != 0):
+            raise self._weaveStack.ErrorToException(res)
+
+    @property
+    def defaultLogFunct(self):
+        '''Returns a python callable which, when called, logs a message to the python logger object
+           currently associated with the WeaveStack object.
+           The returned function is suitable for passing to the setLogFunct() method.'''
+        def logFunct(timestamp, timestampUSec, moduleName, logCat, message):
+            moduleName = WeaveUtility.CStringToString(moduleName)
+            message = WeaveUtility.CStringToString(message)
+            logLevel = LogCategory.categoryToLogLevel(logCat)
+            msgAttrs = { 
+                'weave-module' : moduleName,
+                'timestamp' : timestamp,
+                'timestamp-usec' : timestampUSec
+            }
+            self.logger.log(logLevel, message, extra=msgAttrs)
+        return logFunct
+
+    def setLogFunct(self, logFunct):
+        '''Set the function used by the openweave library to log messages.
+           The supplied object must be a python callable that accepts the following
+           arguments:
+              timestamp (integer)
+              timestampUS (integer)
+              module name (encoded UTF-8 string)
+              log category (integer)
+              message (encoded UTF-8 string)
+           Specifying None configures the openweave library to log directly to stdout.'''
+        if logFunct is None:
+            logFunct = 0
+        if not isinstance(logFunct, _LogMessageFunct):
+            logFunct = _LogMessageFunct(logFunct)
+        with self.networkLock:
+            # NOTE: WeaveStack must hold a reference to the CFUNCTYPE object while it is
+            # set. Otherwise it may get garbage collected, and logging calls from the
+            # openweave library will fail.
+            self._activeLogFunct = logFunct
+            self._weaveStackLib.nl_Weave_Stack_SetLogFunct(logFunct)
+
     def Shutdown(self):
         self._weaveStack.Call(
             lambda: self._dmLib.nl_Weave_Stack_Shutdown()
@@ -208,7 +326,7 @@ def _AllDirsToRoot(self, dir):
                 break
             dir = parent
 
-    def _InitLib(self):
+    def _loadLib(self):
         if (self._weaveStackLib == None):
             self._weaveStackLib = CDLL(self.LocateWeaveDLL())
             self._weaveStackLib.nl_Weave_Stack_Init.argtypes = [ ]
@@ -219,7 +337,5 @@ def _InitLib(self):
             self._weaveStackLib.nl_Weave_Stack_StatusReportToString.restype = c_char_p
             self._weaveStackLib.nl_Weave_Stack_ErrorToString.argtypes = [ c_uint32 ]
             self._weaveStackLib.nl_Weave_Stack_ErrorToString.restype = c_char_p
-
-        res = self._weaveStackLib.nl_Weave_Stack_Init()
-        if (res != 0):
-            raise self._weaveStack.ErrorToException(res)
+            self._weaveStackLib.nl_Weave_Stack_SetLogFunct.argtypes = [ _LogMessageFunct ]
+            self._weaveStackLib.nl_Weave_Stack_SetLogFunct.restype = c_uint32