diff --git a/bin/secop-server b/bin/secop-server index 50f6f3d..6866b34 100755 --- a/bin/secop-server +++ b/bin/secop-server @@ -27,12 +27,11 @@ import sys import argparse from os import path -import mlzlog - # Add import path for inplace usage sys.path.insert(0, path.abspath(path.join(path.dirname(__file__), '..'))) from secop.lib import generalConfig +from secop.logging import logger from secop.server import Server @@ -87,9 +86,9 @@ def main(argv=None): loglevel = 'debug' if args.verbose else ('error' if args.quiet else 'info') generalConfig.init(args.gencfg) - mlzlog.initLogging('frappy', loglevel, generalConfig.logdir) + logger.init(loglevel) - srv = Server(args.name, mlzlog.log, cfgfiles=args.cfgfiles, interface=args.port, testonly=args.test) + srv = Server(args.name, logger.log, cfgfiles=args.cfgfiles, interface=args.port, testonly=args.test) if args.daemonize: srv.start() diff --git a/secop/io.py b/secop/io.py index 90e0717..8fa4d36 100644 --- a/secop/io.py +++ b/secop/io.py @@ -57,6 +57,7 @@ class HasIodev(Module): if not ioname: ioname = iodev or name + '_iodev' iodev = self.iodevClass(ioname, srv.log.getChild(ioname), opts, srv) + iodev.callingModule = [] srv.modules[ioname] = iodev self.iodevDict[self.uri] = ioname self.iodev = ioname @@ -71,8 +72,13 @@ class HasIodev(Module): pass super().initModule() - def sendRecv(self, command): - return self._iodev.communicate(command) + def communicate(self, *args): + return self._iodev.communicate(*args) + + def multicomm(self, *args): + return self._iodev.multicomm(*args) + + sendRecv = communicate # TODO: remove legacy stuff class IOBase(Communicator): @@ -154,6 +160,9 @@ class IOBase(Communicator): if removeme: self._reconnectCallbacks.pop(key) + def communicate(self, command): + return NotImplementedError + class StringIO(IOBase): """line oriented communicator @@ -234,15 +243,15 @@ class StringIO(IOBase): if garbage is None: # read garbage only once garbage = self._conn.flush_recv() if garbage: - self.log.debug('garbage: %r', garbage) + self.comLog('garbage: %r', garbage) self._conn.send(cmd + self._eol_write) - self.log.debug('send: %s', cmd + self._eol_write) + self.comLog('> %s', cmd.decode(self.encoding)) reply = self._conn.readline(self.timeout) except ConnectionClosed as e: self.closeConnection() raise CommunicationFailedError('disconnected') from None reply = reply.decode(self.encoding) - self.log.debug('recv: %s', reply) + self.comLog('< %s', reply) return reply except Exception as e: if str(e) == self._last_error: @@ -291,6 +300,10 @@ def make_bytes(string): return bytes([int(c, 16) if HEX_CODE.match(c) else ord(c) for c in string.split()]) +def hexify(bytes_): + return ' '.join('%02x' % r for r in bytes_) + + class BytesIO(IOBase): identification = Property( """identification @@ -330,14 +343,14 @@ class BytesIO(IOBase): time.sleep(self.wait_before) garbage = self._conn.flush_recv() if garbage: - self.log.debug('garbage: %r', garbage) + self.comLog('garbage: %r', garbage) self._conn.send(request) - self.log.debug('send: %r', request) + self.comLog('> %s', hexify(request)) reply = self._conn.readbytes(replylen, self.timeout) except ConnectionClosed as e: self.closeConnection() raise CommunicationFailedError('disconnected') from None - self.log.debug('recv: %r', reply) + self.comLog('< %s', hexify(reply)) return self.getFullReply(request, reply) except Exception as e: if str(e) == self._last_error: @@ -346,6 +359,15 @@ class BytesIO(IOBase): self.log.error(self._last_error) raise + @Command((ArrayOf(TupleOf(BLOBType(), IntRange(0)))), result=ArrayOf(BLOBType())) + def multicomm(self, requests): + """communicate multiple request/replies in one row""" + replies = [] + with self._lock: + for request in requests: + replies.append(self.communicate(*request)) + return replies + def readBytes(self, nbytes): """read bytes diff --git a/secop/lib/__init__.py b/secop/lib/__init__.py index 646502e..c0c21c7 100644 --- a/secop/lib/__init__.py +++ b/secop/lib/__init__.py @@ -94,10 +94,28 @@ class GeneralConfig: except KeyError: return default + def getint(self, key, default=None): + try: + return int(self.__getitem__(key)) + except KeyError: + return default + def __getattr__(self, key): """goodie: use generalConfig. instead of generalConfig.get('')""" return self.get(key) + def __setattr__(self, key, value): + if key == '_config': + super().__setattr__(key, value) + return + if hasattr(type(self), key): + raise AttributeError('can not set generalConfig.%s' % key) + self._config[key] = value # for test purposes + + @property + def initialized(self): + return bool(self._config) + generalConfig = GeneralConfig() diff --git a/secop/logging.py b/secop/logging.py index 77f0722..2b3291e 100644 --- a/secop/logging.py +++ b/secop/logging.py @@ -20,11 +20,20 @@ # ***************************************************************************** -from logging import LoggerAdapter -from mlzlog import LOGLEVELS +import os +from os.path import dirname, join +from logging import DEBUG, INFO, addLevelName +import mlzlog + +from secop.lib import generalConfig +from secop.datatypes import BoolType +from secop.properties import Property OFF = 99 -LOG_LEVELS = dict(LOGLEVELS, off=OFF) +COMLOG = 15 +addLevelName(COMLOG, 'COMLOG') +assert DEBUG < COMLOG < INFO +LOG_LEVELS = dict(mlzlog.LOGLEVELS, off=OFF, comlog=COMLOG) LEVEL_NAMES = {v: k for k, v in LOG_LEVELS.items()} @@ -39,28 +48,120 @@ def check_level(level): 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 +class RemoteLogHandler(mlzlog.Handler): + """handler for remote logging""" + def __init__(self): + super().__init__() + self.subscriptions = {} # dict[modname] of tuple(mobobj, dict [conn] of level) - 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 emit(self, record): + """unused""" - def set_log_level(self, conn, level): + def handle(self, record): + modname = record.name.split('.')[-1] + try: + modobj, subscriptions = self.subscriptions[modname] + except KeyError: + return + for conn, lev in subscriptions.items(): + if record.levelno >= lev: + modobj.DISPATCHER.send_log_msg( + conn, modobj.name, LEVEL_NAMES[record.levelno], + record.getMessage()) + + def set_conn_level(self, modobj, conn, level): level = check_level(level) + modobj, subscriptions = self.subscriptions.setdefault(modobj.name, (modobj, {})) if level == OFF: - self.subscriptions.pop(conn, None) + subscriptions.pop(conn, None) else: - self.subscriptions[conn] = level + subscriptions[conn] = level + + def __repr__(self): + return 'RemoteLogHandler()' -def set_log_level(modobj, conn, level): - if not isinstance(modobj.log, Adapter): - modobj.log = Adapter(modobj) - modobj.log.set_log_level(conn, level) +class LogfileHandler(mlzlog.LogfileHandler): + + def __init__(self, logdir, rootname, max_days=0): + self.logdir = logdir + self.rootname = rootname + self.max_days = max_days + super().__init__(logdir, rootname) + + def emit(self, record): + if record.levelno != COMLOG: + super().emit(record) + + def doRollover(self): + super().doRollover() + if self.max_days: + # keep only the last max_days files + with os.scandir(dirname(self.baseFilename)) as it: + files = sorted(entry.path for entry in it if entry.name != 'current') + for filepath in files[-self.max_days:]: + os.remove(filepath) + + +class ComLogfileHandler(LogfileHandler): + """handler for logging communication""" + + def format(self, record): + return '%s %s' % (self.formatter.formatTime(record), record.getMessage()) + + +class HasComlog: + """mixin for modules with comlog""" + comlog = Property('whether communication is logged ', BoolType(), + default=True, export=False) + _comLog = None + + def earlyInit(self): + super().earlyInit() + if self.comlog and generalConfig.initialized and generalConfig.comlog: + self._comLog = mlzlog.Logger('COMLOG.%s' % self.name) + self._comLog.handlers[:] = [] + directory = join(logger.logdir, logger.rootname, 'comlog', self.DISPATCHER.name) + self._comLog.addHandler(ComLogfileHandler( + directory, self.name, max_days=generalConfig.getint('comlog_days', 7))) + return + + def comLog(self, msg, *args, **kwds): + self.log.log(COMLOG, msg, *args, **kwds) + if self._comLog: + self._comLog.info(msg, *args) + + +class MainLogger: + def __init__(self): + self.log = None + self.logdir = None + self.rootname = None + self.console_handler = None + + def init(self, console_level='info'): + self.rootname = generalConfig.get('logger_root', 'frappy') + # set log level to minimum on the logger, effective levels on the handlers + # needed also for RemoteLogHandler + # modified from mlzlog.initLogging + mlzlog.setLoggerClass(mlzlog.MLZLogger) + assert self.log is None + self.log = mlzlog.log = mlzlog.MLZLogger(self.rootname) + + self.log.setLevel(DEBUG) + self.log.addHandler(mlzlog.ColoredConsoleHandler()) + + self.logdir = generalConfig.get('logdir', '/tmp/log') + if self.logdir: + logfile_days = generalConfig.getint('logfile_days') + logfile_handler = LogfileHandler(self.logdir, self.rootname, max_days=logfile_days) + if generalConfig.logfile_days: + logfile_handler.max_days = int(generalConfig.logfile_days) + logfile_handler.setLevel(LOG_LEVELS[generalConfig.get('logfile_level', 'info')]) + self.log.addHandler(logfile_handler) + + self.log.addHandler(RemoteLogHandler()) + self.log.handlers[0].setLevel(LOG_LEVELS[console_level]) + + +logger = MainLogger() diff --git a/secop/modules.py b/secop/modules.py index 5947f61..1cdca29 100644 --- a/secop/modules.py +++ b/secop/modules.py @@ -36,6 +36,7 @@ from secop.lib.enum import Enum from secop.params import Accessible, Command, Parameter from secop.poller import BasicPoller, Poller from secop.properties import HasProperties, Property +from secop.logging import RemoteLogHandler, HasComlog Done = object() #: a special return value for a read/write function indicating that the setter is triggered already @@ -124,20 +125,22 @@ class HasAccessibles(HasProperties): def wrapped_rfunc(self, pname=pname, rfunc=rfunc): if rfunc: - self.log.debug("calling %r" % rfunc) + self.log.debug("call read_%s" % pname) try: value = rfunc(self) - self.log.debug("rfunc(%s) returned %r" % (pname, value)) if value is Done: # the setter is already triggered - return getattr(self, pname) + value = getattr(self, pname) + self.log.debug("read_%s returned Done (%r)" % (pname, value)) + return value + self.log.debug("read_%s returned %r" % (pname, value)) except Exception as e: - self.log.debug("rfunc(%s) failed %r" % (pname, e)) + self.log.debug("read_%s failed %r" % (pname, e)) self.announceUpdate(pname, None, e) raise else: # return cached value - self.log.debug("rfunc(%s): return cached value" % pname) value = self.accessibles[pname].value + self.log.debug("return cached %s = %r" % (pname, value)) setattr(self, pname, value) # important! trigger the setter return value @@ -158,16 +161,18 @@ class HasAccessibles(HasProperties): if not wrapped: def wrapped_wfunc(self, value, pname=pname, wfunc=wfunc): - self.log.debug("check validity of %s = %r" % (pname, value)) pobj = self.accessibles[pname] - value = pobj.datatype(value) if wfunc: - self.log.debug('calling %s %r(%r)' % (wfunc.__name__, wfunc, value)) + self.log.debug("check and call write_%s(%r)" % (pname, value)) + value = pobj.datatype(value) returned_value = wfunc(self, value) if returned_value is Done: # the setter is already triggered return getattr(self, pname) if returned_value is not None: # goodie: accept missing return value value = returned_value + else: + self.log.debug("check %s = %r" % (pname, value)) + value = pobj.datatype(value) setattr(self, pname, value) return value @@ -266,6 +271,7 @@ class Module(HasAccessibles): self.earlyInitDone = False self.initModuleDone = False self.startModuleDone = False + self.remoteLogHandler = None errors = [] # handle module properties @@ -585,6 +591,16 @@ class Module(HasAccessibles): if started_callback: started_callback() + def setRemoteLogging(self, conn, level): + if self.remoteLogHandler is None: + for handler in self.log.handlers: + if isinstance(handler, RemoteLogHandler): + self.remoteLogHandler = handler + break + else: + raise ValueError('remote handler not found') + self.remoteLogHandler.set_conn_level(self, conn, level) + class Readable(Module): """basic readable module""" @@ -700,7 +716,7 @@ class Drivable(Writable): """cease driving, go to IDLE state""" -class Communicator(Module): +class Communicator(HasComlog, Module): """basic abstract communication module""" @Command(StringType(), result=StringType()) diff --git a/secop/protocol/dispatcher.py b/secop/protocol/dispatcher.py index 33b4f15..0505f25 100644 --- a/secop/protocol/dispatcher.py +++ b/secop/protocol/dispatcher.py @@ -45,7 +45,6 @@ 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, \ @@ -84,6 +83,7 @@ class Dispatcher: # eventname is or : self._subscriptions = {} self._lock = threading.RLock() + self.name = name self.restart = srv.restart self.shutdown = srv.shutdown @@ -378,16 +378,16 @@ class Dispatcher: 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)) + 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) + modobj.setRemoteLogging(conn, level) def handle_logging(self, conn, specifier, level): if specifier and specifier != '.': - set_log_level(self._modules[specifier], conn, level) + modobj = self._modules[specifier] + modobj.setRemoteLogging(conn, level) else: self.set_all_log_levels(conn, level) return LOGGING_REPLY, specifier, level diff --git a/secop_psi/ls370res.py b/secop_psi/ls370res.py index 50fb478..91cea8a 100644 --- a/secop_psi/ls370res.py +++ b/secop_psi/ls370res.py @@ -71,6 +71,7 @@ class Main(HasIodev, Drivable): _channels = None # dict of def earlyInit(self): + super().earlyInit() self._channels = {} def register_channel(self, modobj): @@ -166,6 +167,7 @@ class ResChannel(HasIodev, Readable): _trigger_read = False def initModule(self): + super().initModule() self._main = self.DISPATCHER.get_module(self.main) self._main.register_channel(self) @@ -228,7 +230,7 @@ class ResChannel(HasIodev, Readable): if autorange: result['autorange'] = 'hard' # else: do not change autorange - self.log.info('%s range %r %r %r' % (self.name, rng, autorange, self.autorange)) + self.log.debug('%s range %r %r %r' % (self.name, rng, autorange, self.autorange)) if excoff: result.update(iexc=0, vexc=0) elif iscur: diff --git a/secop_psi/ls370sim.py b/secop_psi/ls370sim.py index e0dbf08..cde2d64 100644 --- a/secop_psi/ls370sim.py +++ b/secop_psi/ls370sim.py @@ -37,6 +37,7 @@ class Ls370Sim(Communicator): ] def earlyInit(self): + super().earlyInit() self._data = dict(self.OTHER_COMMANDS) for fmt, v in self.CHANNEL_COMMANDS: for chan in range(1,17): @@ -44,6 +45,7 @@ class Ls370Sim(Communicator): # mkthread(self.run) def communicate(self, command): + self.comLog('> %s' % command) # simulation part, time independent for channel in range(1,17): _, _, _, _, excoff = self._data['RDGRNG?%d' % channel].split(',') @@ -68,6 +70,6 @@ class Ls370Sim(Communicator): if qcmd in self._data: self._data[qcmd] = arg break - #if command.startswith('R'): - # print('> %s\t< %s' % (command, reply)) - return ';'.join(reply) + reply = ';'.join(reply) + self.comLog('< %s' % reply) + return reply diff --git a/secop_psi/ppms.py b/secop_psi/ppms.py index 8846e2f..53a9f47 100644 --- a/secop_psi/ppms.py +++ b/secop_psi/ppms.py @@ -100,8 +100,9 @@ class Main(Communicator): def communicate(self, command): """GPIB command""" with self.lock: + self.comLog('> %s' % command) reply = self._ppms_device.send(command) - self.log.debug("%s|%s", command, reply) + self.comLog("< %s", reply) return reply def read_data(self): diff --git a/test/test_logging.py b/test/test_logging.py index 0351f23..a8577a0 100644 --- a/test/test_logging.py +++ b/test/test_logging.py @@ -20,121 +20,256 @@ # # ***************************************************************************** - -from mlzlog import MLZLogger, Handler, INFO, DEBUG +import pytest +import mlzlog 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)) +from secop.protocol.interface import encode_msg_frame, decode_msg +import secop.logging +from secop.logging import logger, generalConfig, HasComlog class ServerStub: restart = None shutdown = None + def __init__(self): + self.dispatcher = Dispatcher('', logger.log.getChild('dispatcher'), {}, self) + class Connection: - def __init__(self, dispatcher): - self.result = [] + def __init__(self, name, dispatcher, result): + self.result = result + self.dispatcher = dispatcher + self.name = name dispatcher.add_connection(self) def send_reply(self, msg): - self.result.append(msg) + self.result.append(encode_msg_frame(*msg).strip().decode()) - def check(self, *args): - assert self.result == list(args) - self.result[:] = [] - - def send(self, *request): - assert srv.dispatcher.handle_request(self, request) == request + def send(self, msg): + request = decode_msg(msg.encode()) + assert self.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) +@pytest.fixture(name='init') +def init_(monkeypatch): + logger.__init__() - def check(self, *args): - assert self.result == list(args) - self.result[:] = [] + class Playground: + def __init__(self, console_level='debug', comlog=True, com_module=True): + self.result_dict = result_dict = dict( + console=[], comlog=[], conn1=[], conn2=[]) + + class ConsoleHandler(mlzlog.Handler): + def __init__(self, *args, **kwds): + super().__init__() + self.result = result_dict['console'] + + def emit(self, record): + if record.name != 'frappy.dispatcher': + self.result.append('%s %s %s' % (record.name, record.levelname, record.getMessage())) + + class ComLogHandler(mlzlog.Handler): + def __init__(self, *args, **kwds): + super().__init__() + self.result = result_dict['comlog'] + + def emit(self, record): + self.result.append('%s %s' % (record.name.split('.')[1], record.getMessage())) + + class LogfileHandler(mlzlog.Handler): + def __init__(self, *args, **kwds): + super().__init__() + + def noop(self, *args): + pass + + close = flush = emit = noop + + monkeypatch.setattr(mlzlog, 'ColoredConsoleHandler', ConsoleHandler) + monkeypatch.setattr(secop.logging, 'ComLogfileHandler', ComLogHandler) + monkeypatch.setattr(secop.logging, 'LogfileHandler', LogfileHandler) + + class Mod(Module): + result = [] + + def __init__(self, name, srv, **kwds): + kwds['description'] = '' + super().__init__(name or 'mod', logger.log.getChild(name), kwds, srv) + srv.dispatcher.register_module(self, name, name) + self.result[:] = [] + + def earlyInit(self): + pass + + class Com(HasComlog, Mod): + def __init__(self, name, srv, **kwds): + super().__init__(name, srv, **kwds) + self.earlyInit() + self.log.handlers[-1].result = result_dict['comlog'] + + def communicate(self, request): + self.comLog('> %s', request) + + generalConfig.init() + generalConfig.comlog = comlog + logger.init(console_level) + self.srv = ServerStub() + + self.conn1 = Connection('conn1', self.srv.dispatcher, self.result_dict['conn1']) + self.conn2 = Connection('conn2', self.srv.dispatcher, self.result_dict['conn2']) + self.mod = Mod('mod', self.srv) + self.com = Com('com', self.srv, comlog=com_module) + for item in self.result_dict.values(): + assert item == [] + + def check(self, both=None, **expected): + if both: + expected['conn1'] = expected['conn2'] = both + assert self.result_dict['console'] == expected.get('console', []) + assert self.result_dict['comlog'] == expected.get('comlog', []) + assert self.result_dict['conn1'] == expected.get('conn1', []) + assert self.result_dict['conn2'] == expected.get('conn2', []) + for item in self.result_dict.values(): + item[:] = [] + + def comlog(self, flag): + logger.comlog = flag + + yield Playground + # revert settings + generalConfig.__init__() + logger.__init__() -srv = ServerStub() -srv.dispatcher = Dispatcher('', LogRecorder([]), {}, srv) -conn1 = Connection(srv.dispatcher) -conn2 = Connection(srv.dispatcher) -o1 = Mod('o1') -o2 = Mod('o2') +def test_mod_info(init): + p = init() + p.mod.log.info('i') + p.check(console=['frappy.mod INFO i']) + p.conn1.send('logging mod "debug"') + p.conn2.send('logging mod "info"') + p.mod.log.info('i') + p.check(console=['frappy.mod INFO i'], both=['log mod:info "i"']) -def test_logging1(): - # test normal logging - o1.log.setLevel(INFO) - o2.log.setLevel(DEBUG) +def test_mod_debug(init): + p = init() + p.mod.log.debug('d') + p.check(console=['frappy.mod DEBUG d']) + p.conn1.send('logging mod "debug"') + p.conn2.send('logging mod "info"') + p.mod.log.debug('d') + p.check(console=['frappy.mod DEBUG d'], conn1=['log mod:debug "d"']) - 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() +def test_com_info(init): + p = init() + p.com.log.info('i') + p.check(console=['frappy.com INFO i']) + p.conn1.send('logging com "info"') + p.conn2.send('logging com "debug"') + p.com.log.info('i') + p.check(console=['frappy.com INFO i'], both=['log com:info "i"']) - # 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') +def test_com_debug(init): + p = init() + p.com.log.debug('d') + p.check(console=['frappy.com DEBUG d']) + p.conn2.send('logging com "debug"') + p.com.log.debug('d') + p.check(console=['frappy.com DEBUG d'], conn2=['log com:debug "d"']) - 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') +def test_com_com(init): + p = init() + p.com.communicate('x') + p.check(console=['frappy.com COMLOG > x'], comlog=['com > x']) + p.conn1.send('logging mod "debug"') + p.conn2.send('logging mod "info"') + p.conn2.send('logging com "debug"') + p.com.communicate('x') + p.check(console=['frappy.com COMLOG > x'], comlog=['com > x'], conn2=['log com:comlog "> x"']) - 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() +def test_main_info(init): + p = init(console_level='info') + p.mod.log.debug('d') + p.com.communicate('x') + p.check(comlog=['com > x']) + p.conn1.send('logging mod "debug"') + p.conn2.send('logging mod "info"') + p.conn2.send('logging com "debug"') + p.com.communicate('x') + p.check(comlog=['com > x'], conn2=['log com:comlog "> x"']) - # 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') +def test_comlog_off(init): + p = init(console_level='info', comlog=False) + p.mod.log.debug('d') + p.com.communicate('x') + p.check() - o1.check('INFO:i1', 'WARNING:w1') - o2.check('INFO:i2', 'WARNING:w2') - conn1.check() - conn2.check(('log', 'o1:warning', 'w1'), ('log', 'o2:warning', 'w2')) + +def test_comlog_module_off(init): + p = init(console_level='info', com_module=False) + p.mod.log.debug('d') + p.com.communicate('x') + p.check() + + +def test_remote_all_off(init): + p = init() + p.conn1.send('logging mod "debug"') + p.conn2.send('logging mod "info"') + p.conn2.send('logging com "debug"') + p.mod.log.debug('d') + p.com.communicate('x') + p.mod.log.info('i') + checks = dict( + console=['frappy.mod DEBUG d', 'frappy.com COMLOG > x', 'frappy.mod INFO i'], + comlog=['com > x'], + conn1=['log mod:debug "d"', 'log mod:info "i"'], + conn2=['log com:comlog "> x"', 'log mod:info "i"']) + p.check(**checks) + p.conn1.send('logging "off"') + p.mod.log.debug('d') + p.com.communicate('x') + p.mod.log.info('i') + checks.pop('conn1') + p.check(**checks) + p.conn2.send('logging . "off"') + p.mod.log.debug('d') + p.com.communicate('x') + p.mod.log.info('i') + checks.pop('conn2') + p.check(**checks) + + +def test_remote_single_off(init): + p = init() + p.conn1.send('logging mod "debug"') + p.conn2.send('logging mod "info"') + p.conn2.send('logging com "debug"') + p.mod.log.debug('d') + p.com.communicate('x') + p.mod.log.info('i') + checks = dict( + console=['frappy.mod DEBUG d', 'frappy.com COMLOG > x', 'frappy.mod INFO i'], + comlog=['com > x'], + conn1=['log mod:debug "d"', 'log mod:info "i"'], + conn2=['log com:comlog "> x"', 'log mod:info "i"']) + p.check(**checks) + p.conn2.send('logging com "off"') + p.mod.log.debug('d') + p.com.communicate('x') + p.mod.log.info('i') + checks['conn2'] = ['log mod:info "i"'] + p.check(**checks) + p.conn2.send('logging mod "off"') + p.mod.log.debug('d') + p.com.communicate('x') + p.mod.log.info('i') + checks['conn2'] = [] + p.check(**checks) diff --git a/test/test_modules.py b/test/test_modules.py index 7d24038..644b9fe 100644 --- a/test/test_modules.py +++ b/test/test_modules.py @@ -54,6 +54,7 @@ class LoggerStub: def debug(self, *args): print(*args) info = warning = exception = debug + handlers = [] logger = LoggerStub() @@ -65,7 +66,7 @@ class ServerStub: def test_Communicator(): - o = Communicator('communicator', LoggerStub(), {'.description':''}, ServerStub({})) + o = Communicator('communicator', LoggerStub(), {'.description': ''}, ServerStub({})) o.earlyInit() o.initModule() event = MultiEvent()