improvements on interactive client

- add selective logging
- fix handling of exceptions

Change-Id: I7e2c2d4ed12302874c3bb2cc7bd707aa8e487341

secop/client/__init__.py

@@ -356,7 +356,7 @@ class SecopClient(ProxyClient):
         except ConnectionClosed:
             pass
         except Exception as e:
-            self.log.error('rxthread ended with %s' % e)
+            self.log.error('rxthread ended with %r', e)
         self._rxthread = None
         self.disconnect(False)
         if self._shutdown:
@@ -490,7 +490,7 @@ class SecopClient(ProxyClient):
 
     def _unhandled_message(self, action, ident, data):
         if not self.callback(None, 'unhandledMessage', action, ident, data):
-            self.log.warning('unhandled message: %s %s %r' % (action, ident, data))
+            self.log.warning('unhandled message: %s %s %r', action, ident, data)
 
     def _set_state(self, online, state=None):
         # remark: reconnecting is treated as online

secop/client/interactive.py

@@ -24,6 +24,7 @@
 import sys
 import time
 import json
+import re
 from queue import Queue
 from secop.client import SecopClient
 from secop.errors import SECoPError
@@ -58,10 +59,15 @@ class Logger:
             if lev == loglevel:
                 func = self.emit
             setattr(self, lev, func)
+        self._minute = 0
 
-    @staticmethod
-    def emit(fmt, *args, **kwds):
-        print(str(fmt) % args)
+    def emit(self, fmt, *args, **kwds):
+        now = time.time()
+        minute = now // 60
+        if minute != self._minute:
+            self._minute = minute
+            print(time.strftime('--- %H:%M:%S ---', time.localtime(now)))
+        print('%6.3f' % (now % 60.0), str(fmt) % args)
 
     @staticmethod
     def noop(fmt, *args, **kwds):
@@ -77,6 +83,8 @@ class PrettyFloat(float):
 
 
 class Module:
+    _log_pattern = re.compile('.*')
+
     def __init__(self, name, secnode):
         self._name = name
         self._secnode = secnode
@@ -174,6 +182,14 @@ class Module:
             '\n'.join(self._one_line(k, wid) for k in self._parameters),
             ', '.join(k + '()' for k in self._commands))
 
+    def logging(self, level='comlog', pattern='.*'):
+        self._log_pattern = re.compile(pattern)
+        self._secnode.request('logging', self._name, level)
+
+    def handle_log_message_(self, data):
+        if self._log_pattern.match(data):
+            self._secnode.log.info('%s: %r', self._name, data)
+
 
 class Param:
     def __init__(self, name, unit=None):
@@ -258,6 +274,17 @@ class Client(SecopClient):
             if 'status' in mobj._parameters:
                 self.register_callback((modname, 'status'), updateEvent=mobj._status_value_update)
                 self.register_callback((modname, 'value'), updateEvent=mobj._status_value_update)
-
             setattr(main, modname, mobj)
+        self.register_callback(None, self.unhandledMessage)
         self.log.info('%s', USAGE)
+
+    def unhandledMessage(self, action, ident, data):
+        """handle logging messages"""
+        if action == 'log':
+            modname = ident.split(':')[0]
+            modobj = getattr(main, modname, None)
+            if modobj:
+                modobj.handle_log_message_(data)
+                return
+            self.log.info('module %s not found', modname)
+        self.log.info('unhandled: %s %s %r', action, ident, data)