Merge pull request #556 from openweave/feature/improved-python-logging

Improved logging in python

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,20 +91,115 @@ 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):
-    def __init__(self):
+    def __init__(self, installDefaultLogHandler=True):
         self.networkLock = Lock()
         self.completeEvent = Event()
         self._weaveStackLib = None
         self._weaveDLLPath = None
         self.devMgr = None
         self.callbackRes = None
+        self._activeLogFunct = None
+
+        # Locate and load the openweave shared library.
+        self._loadLib()
+
+        # Arrange to log output from the openweave library to a python logger object with the
+        # name 'openweave.WeaveStack'.  If desired, applications can override this behavior by
+        # setting self.logger to a different python logger object, or by calling setLogFunct()
+        # with their own logging function.
+        self.logger = logging.getLogger(__name__)
+        self.setLogFunct(self.defaultLogFunct)
+
+        # Determine if there are already handlers installed for the logger.  Python 3.5+
+        # has a method for this; on older versions the check has to be done manually.  
+        if hasattr(self.logger, 'hasHandlers'):
+            hasHandlers = self.logger.hasHandlers()
+        else:
+            hasHandlers = False
+            logger = self.logger
+            while logger is not None:
+                if len(logger.handlers) > 0:
+                    hasHandlers = True
+                    break
+                if not logger.propagate:
+                    break
+                logger = logger.parent
 
-        self._InitLib()
+        # If a logging handler has not already been initialized for 'openweave.WeaveStack',
+        # or any one of its parent loggers, automatically configure a handler to log to
+        # stdout.  This maintains compatibility with a number of applications which expect
+        # openweave log output to go to stdout by default.
+        #
+        # This behavior can be overridden in a variety of ways:
+        #     - Initialize a different log handler before WeaveStack is initialized.
+        #     - Pass installDefaultLogHandler=False when initializing WeaveStack.
+        #     - Replace the StreamHandler on self.logger with a different handler object.
+        #     - Set a different Formatter object on the existing StreamHandler object.
+        #     - Reconfigure the existing WeaveLogFormatter object.
+        #     - Configure openweave to call an application-specific logging function by
+        #       calling self.setLogFunct().
+        #     - Call self.setLogFunct(None), which will configure the openweave library
+        #       to log directly to stdout, bypassing python altogether.
+        #
+        if installDefaultLogHandler and not hasHandlers:
+            logHandler = logging.StreamHandler(stream=sys.stdout)
+            logHandler.setFormatter(WeaveLogFormatter())
+            self.logger.addHandler(logHandler)
+            self.logger.setLevel(logging.DEBUG)
 
         def HandleComplete(appState, reqState):
             self.callbackRes = True
@@ -117,6 +213,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 +347,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 +358,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