remote logging (issue 46)

Change-Id: Id92e66280811b1f871157b5c2ceca65085d2c15b
Reviewed-on: https://forge.frm2.tum.de/review/c/sine2020/secop/playground/+/27346
Tested-by: Jenkins Automated Tests <pedersen+jenkins@frm2.tum.de>
Reviewed-by: Enrico Faulhaber <enrico.faulhaber@frm2.tum.de>
Reviewed-by: Markus Zolliker <markus.zolliker@psi.ch>

secop/logging.py

@@ -0,0 +1,66 @@
+#!/usr/bin/env python
+#  -*- coding: utf-8 -*-
+# *****************************************************************************
+# This program is free software; you can redistribute it and/or modify it under
+# the terms of the GNU General Public License as published by the Free Software
+# Foundation; either version 2 of the License, or (at your option) any later
+# version.
+#
+# This program is distributed in the hope that it will be useful, but WITHOUT
+# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
+# FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
+# details.
+#
+# You should have received a copy of the GNU General Public License along with
+# this program; if not, write to the Free Software Foundation, Inc.,
+# 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
+#
+# Module authors:
+#   Markus Zolliker <markus.zolliker@psi.ch>
+# *****************************************************************************
+
+
+from logging import LoggerAdapter
+from mlzlog import LOGLEVELS
+
+OFF = 99
+LOG_LEVELS = dict(LOGLEVELS, off=OFF)
+LEVEL_NAMES = {v: k for k, v in LOG_LEVELS.items()}
+
+
+def check_level(level):
+    try:
+        if isinstance(level, str):
+            return LOG_LEVELS[level.lower()]
+        if level in LEVEL_NAMES:
+            return level
+    except KeyError:
+        pass
+    raise ValueError('%r is not a valid level' % level)
+
+
+class Adapter(LoggerAdapter):
+    def __init__(self, modobj):
+        super().__init__(modobj.log, {})
+        self.subscriptions = {}  # dict [conn] of level
+        self.modobj = modobj
+
+    def log(self, level, msg, *args, **kwargs):
+        super().log(level, msg, *args, **kwargs)
+        for conn, lev in self.subscriptions.items():
+            if level >= lev:
+                self.modobj.DISPATCHER.send_log_msg(
+                    conn, self.modobj.name, LEVEL_NAMES[level], msg % args)
+
+    def set_log_level(self, conn, level):
+        level = check_level(level)
+        if level == OFF:
+            self.subscriptions.pop(conn, None)
+        else:
+            self.subscriptions[conn] = level
+
+
+def set_log_level(modobj, conn, level):
+    if not isinstance(modobj.log, Adapter):
+        modobj.log = Adapter(modobj)
+    modobj.log.set_log_level(conn, level)

secop/protocol/dispatcher.py

@@ -45,9 +45,11 @@ from time import time as currenttime
 from secop.errors import NoSuchCommandError, NoSuchModuleError, \
     NoSuchParameterError, ProtocolError, ReadOnlyError, SECoPServerError
 from secop.params import Parameter
+from secop.logging import set_log_level
 from secop.protocol.messages import COMMANDREPLY, DESCRIPTIONREPLY, \
     DISABLEEVENTSREPLY, ENABLEEVENTSREPLY, ERRORPREFIX, EVENTREPLY, \
-    HEARTBEATREPLY, IDENTREPLY, IDENTREQUEST, READREPLY, WRITEREPLY
+    HEARTBEATREPLY, IDENTREPLY, IDENTREQUEST, READREPLY, WRITEREPLY, \
+    LOGGING_REPLY, LOG_EVENT
 
 
 def make_update(modulename, pobj):
@@ -129,6 +131,7 @@ class Dispatcher:
             self._connections.remove(conn)
         for _evt, conns in list(self._subscriptions.items()):
             conns.discard(conn)
+        self.set_all_log_levels(conn, 'off')
         self._active_connections.discard(conn)
 
     def register_module(self, moduleobj, modulename, export=True):
@@ -372,3 +375,19 @@ class Dispatcher:
             self._active_connections.discard(conn)
             # XXX: also check all entries in self._subscriptions?
         return (DISABLEEVENTSREPLY, None, None)
+
+    def send_log_msg(self, conn, modname, level, msg):
+        """send log message """
+        if conn in self._connections:
+            conn.send_reply((LOG_EVENT, '%s:%s' % (modname, level), msg))
+
+    def set_all_log_levels(self, conn, level):
+        for modobj in self._modules.values():
+            set_log_level(modobj, conn, level)
+
+    def handle_logging(self, conn, specifier, level):
+        if specifier and specifier != '.':
+            set_log_level(self._modules[specifier], conn, level)
+        else:
+            self.set_all_log_levels(conn, level)
+        return LOGGING_REPLY, specifier, level

secop/protocol/messages.py

@@ -65,6 +65,13 @@ ERRORPREFIX = 'error_'  # + specifier + json_extended_info(error_report)
 HELPREQUEST = 'help'  # literal
 HELPREPLY = 'helping'  # +line number +json_text
 
+LOGGING_REQUEST = 'logging'
+LOGGING_REPLY = 'logging'
+# + [module] + json string (loglevel)
+
+LOG_EVENT = 'log'
+# + [module:level] + json_string (message)
+
 # helper mapping to find the REPLY for a REQUEST
 # do not put IDENTREQUEST/IDENTREPLY here, as this needs anyway extra treatment
 REQUEST2REPLY = {
@@ -77,6 +84,7 @@ REQUEST2REPLY = {
     READREQUEST:          READREPLY,
     HEARTBEATREQUEST:     HEARTBEATREPLY,
     HELPREQUEST:          HELPREPLY,
+    LOGGING_REQUEST:      LOGGING_REPLY,
 }
 
 
@@ -89,6 +97,8 @@ HelpMessage = """Try one of the following:
             '%s <nonce>' to request a heartbeat response
             '%s' to activate async updates
             '%s' to deactivate updates
+            '%s [<module>] <loglevel>' to activate logging events
             """ % (IDENTREQUEST, DESCRIPTIONREQUEST, READREQUEST,
                    WRITEREQUEST, COMMANDREQUEST, HEARTBEATREQUEST,
-                   ENABLEEVENTSREQUEST, DISABLEEVENTSREQUEST)
+                   ENABLEEVENTSREQUEST, DISABLEEVENTSREQUEST,
+                   LOGGING_REQUEST)

test/test_logging.py

@@ -0,0 +1,140 @@
+#  -*- coding: utf-8 -*-
+# *****************************************************************************
+#
+# This program is free software; you can redistribute it and/or modify it under
+# the terms of the GNU General Public License as published by the Free Software
+# Foundation; either version 2 of the License, or (at your option) any later
+# version.
+#
+# This program is distributed in the hope that it will be useful, but WITHOUT
+# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
+# FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
+# details.
+#
+# You should have received a copy of the GNU General Public License along with
+# this program; if not, write to the Free Software Foundation, Inc.,
+# 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
+#
+# Module authors:
+#   Markus Zolliker <markus.zolliker@psi.ch>
+#
+# *****************************************************************************
+
+
+from mlzlog import MLZLogger, Handler, INFO, DEBUG
+from secop.modules import Module
+from secop.protocol.dispatcher import Dispatcher
+
+
+class LogHandler(Handler):
+    def __init__(self, result):
+        super().__init__()
+        self.result = result
+
+    def emit(self, record):
+        self.result.append('%s:%s' % (record.levelname, record.getMessage()))
+
+
+class LogRecorder(MLZLogger):
+    def __init__(self, result):
+        super().__init__('root')
+        self.setLevel(INFO)
+        self.addHandler(LogHandler(result))
+
+
+class ServerStub:
+    restart = None
+    shutdown = None
+
+
+class Connection:
+    def __init__(self, dispatcher):
+        self.result = []
+        dispatcher.add_connection(self)
+
+    def send_reply(self, msg):
+        self.result.append(msg)
+
+    def check(self, *args):
+        assert self.result == list(args)
+        self.result[:] = []
+
+    def send(self, *request):
+        assert srv.dispatcher.handle_request(self, request) == request
+
+
+class Mod(Module):
+    def __init__(self, name):
+        self.result = []
+        super().__init__(name, LogRecorder(self.result), {'.description': ''}, srv)
+        srv.dispatcher.register_module(self, name, name)
+
+    def check(self, *args):
+        assert self.result == list(args)
+        self.result[:] = []
+
+
+srv = ServerStub()
+srv.dispatcher = Dispatcher('', LogRecorder([]), {}, srv)
+conn1 = Connection(srv.dispatcher)
+conn2 = Connection(srv.dispatcher)
+o1 = Mod('o1')
+o2 = Mod('o2')
+
+
+def test_logging1():
+    # test normal logging
+    o1.log.setLevel(INFO)
+    o2.log.setLevel(DEBUG)
+
+    o1.log.info('i1')
+    o1.log.debug('d1')
+    o2.log.info('i2')
+    o2.log.debug('d2')
+
+    o1.check('INFO:i1')
+    o2.check('INFO:i2', 'DEBUG:d2')
+    conn1.check()
+    conn2.check()
+
+    # test remote logging on
+    conn1.send('logging', 'o1', 'debug')
+    conn2.send('logging', 'o1', 'info')
+    conn2.send('logging', 'o2', 'debug')
+
+    o1.log.info('i1')
+    o1.log.debug('d1')
+    o2.log.info('i2')
+    o2.log.debug('d2')
+
+    o1.check('INFO:i1')
+    o2.check('INFO:i2', 'DEBUG:d2')
+    conn1.check(('log', 'o1:info', 'i1'), ('log', 'o1:debug', 'd1'))
+    conn2.check(('log', 'o1:info', 'i1'), ('log', 'o2:info', 'i2'), ('log', 'o2:debug', 'd2'))
+
+    # test all remote logging
+    conn1.send('logging', '', 'off')
+    conn2.send('logging', '', 'off')
+
+    o1.log.info('i1')
+    o1.log.debug('d1')
+    o2.log.info('i2')
+    o2.log.debug('d2')
+
+    o1.check('INFO:i1')
+    o2.check('INFO:i2', 'DEBUG:d2')
+    conn1.check()
+    conn2.check()
+
+    # test all modules on, warning level
+    conn2.send('logging', '', 'warning')
+
+    o1.log.info('i1')
+    o1.log.warning('w1')
+    o2.log.info('i2')
+    o2.log.warning('w2')
+
+    o1.check('INFO:i1', 'WARNING:w1')
+    o2.check('INFO:i2', 'WARNING:w2')
+    conn1.check()
+    conn2.check(('log', 'o1:warning', 'w1'), ('log', 'o2:warning', 'w2'))