diff --git a/qcodes/__init__.py b/qcodes/__init__.py index f7a65d3adeab..3715e077798f 100644 --- a/qcodes/__init__.py +++ b/qcodes/__init__.py @@ -9,7 +9,14 @@ from qcodes.version import __version__ from qcodes.process.helpers import set_mp_method from qcodes.utils.helpers import in_notebook +from qcodes import config +if config.addzmqlogging: + from qcodes.utils.loggingGUI import installZMQlogger + qlogger=installZMQlogger() + + +#if qcodes.config # code that should only be imported into the main (notebook) thread # in particular, importing matplotlib in the side processes takes a long # time and spins up other processes in order to try and get a front end diff --git a/qcodes/config.py b/qcodes/config.py new file mode 100644 index 000000000000..b3dc453264cd --- /dev/null +++ b/qcodes/config.py @@ -0,0 +1,7 @@ + +import os +import tempfile + +addzmqlogging = os.environ.get('ZMQLOGGING', 1) + +heartbeatfile = os.path.join(tempfile.gettempdir(), r'qcodes-heartbeat.bin' ) diff --git a/qcodes/process/heartbeat.py b/qcodes/process/heartbeat.py new file mode 100644 index 000000000000..5bd2b668bdfd --- /dev/null +++ b/qcodes/process/heartbeat.py @@ -0,0 +1,49 @@ +import os +import mmap + +from qcodes import config + + +def makeHeartBeatFile(bfile, reinit=False): + if (not os.path.exists(bfile)) or reinit: + f = open(bfile, 'wb') + f.write(bytes([99, 1])) # heartbeat on + f.close() + + +def initHeartBeat(bfile, reinit=False): + ''' Initialize connection to heartbeat for writing, use with setHeartBeat ''' + if (not os.path.exists(bfile)) or reinit: + f = open(bfile, 'wb') + f.write(bytes([99, 1])) # heartbeat on + f.close() + + f = open(bfile, 'a+b') + f.seek(0) + m = mmap.mmap(f.fileno(), 0, access=mmap.ACCESS_WRITE) + m.flush() + # print(m[0]) + # print(m[1]) + # print('size %d' % m.size() ) + + return m + + +def openHeartBeat(bfile): + f = open(bfile, 'r') + m = mmap.mmap(f.fileno(), 0, access=mmap.ACCESS_READ) + return m + + +def setHeartBeat(m, value): + ''' Set heartbeat value ''' + m[1] = value + + +def readHeartBeat(m): + ''' Return heartbeat value ''' + return m[1] + + +_bfile = config.heartbeatfile +makeHeartBeatFile(_bfile) diff --git a/qcodes/process/server.py b/qcodes/process/server.py index 7acc408bd720..991d7bedacf1 100644 --- a/qcodes/process/server.py +++ b/qcodes/process/server.py @@ -5,12 +5,15 @@ from uuid import uuid4 import builtins import logging +import time QUERY_WRITE = 'WRITE' QUERY_ASK = 'ASK' RESPONSE_OK = 'OK' RESPONSE_ERROR = 'ERROR' +from qcodes import config +from qcodes.utils import loggingGUI from qcodes.utils.nested_attrs import NestedAttrAccess from .qcodes_process import QcodesProcess from .helpers import kill_queue @@ -205,6 +208,11 @@ def close(self): del self.query_lock +import qcodes.process.heartbeat +from multiprocessing import current_process + + + class BaseServer(NestedAttrAccess): """ @@ -271,6 +279,9 @@ def __init__(self, query_queue, response_queue, shared_attrs=None): self._response_queue = response_queue self._shared_attrs = shared_attrs + self.hb = qcodes.process.heartbeat.openHeartBeat( + qcodes.config.heartbeatfile) + def run_event_loop(self): """ The default event loop. When this method returns, the server stops. @@ -282,9 +293,27 @@ def run_event_loop(self): it's not by setting `self.running = False`) """ self.running = True + + if qcodes.config.addzmqlogging: + self.timeout = 5 # temporary to make heartbeat work + _ = loggingGUI.installZMQlogger() + logging.info('run_event_loop') + + ptime=time.time() while self.running: - query = self._query_queue.get(timeout=self.timeout) - self.process_query(query) + try: + query = self._query_queue.get(timeout=self.timeout) + except mp.queues.Empty: + query = None + if query is not None: + self.process_query(query) + if not qcodes.process.heartbeat.readHeartBeat(self.hb): + logging.info('no heartbeat, stopping process') + self.running = False + else: + if (time.time()-ptime)>.1: + logging.info('heartbeat of %s: alive... %s' % (current_process().name, time.ctime()) ) + ptime=time.time() def process_query(self, query): """ diff --git a/qcodes/tests/instrument_mocks.py b/qcodes/tests/instrument_mocks.py index 685b5ed380bc..f4eb33ba1800 100644 --- a/qcodes/tests/instrument_mocks.py +++ b/qcodes/tests/instrument_mocks.py @@ -196,6 +196,7 @@ def __init__(self, name='dummy', gates=['dac1', 'dac2', 'dac3'], **kwargs): """ super().__init__(name, **kwargs) + logging.info('create DummyInstrument') # make gates for _, g in enumerate(gates): self.add_parameter(g, diff --git a/qcodes/utils/loggingGUI.py b/qcodes/utils/loggingGUI.py new file mode 100644 index 000000000000..fba1958b454e --- /dev/null +++ b/qcodes/utils/loggingGUI.py @@ -0,0 +1,261 @@ +""" +A GUI for multi-processing logging using ZMQ + +Code is adapted from https://github.com/zeromq/pyzmq/blob/master/examples/logger/zmqlogger.py + +Pieter Eendebak + +""" + +#%% Import packages +import logging +import os +import signal +import time +import argparse +import re + +from qtpy import QtGui +from qtpy import QtWidgets + + +import zmq +from zmq.log.handlers import PUBHandler + +parser = argparse.ArgumentParser() +parser.add_argument('-v', '--verbose', default=1, help="verbosity level") +parser.add_argument( + '-l', '--level', default=logging.DEBUG, help="logging level") +parser.add_argument('-p', '--port', type=int, default=5800, help="zmq port") +parser.add_argument('-g', '--gui', type=int, default=1, help="show gui") +args = parser.parse_args() + + +#%% Util functions + + +def static_var(varname, value): + """ Helper function to create a static variable """ + def decorate(func): + setattr(func, varname, value) + return func + return decorate + + +@static_var("time", 0) +def tprint(string, dt=1, output=False): + """ Print progress of a loop every dt seconds """ + if (time.time() - tprint.time) > dt: + print(string) + tprint.time = time.time() + if output: + return True + else: + return + else: + if output: + return False + else: + return + +#%% Functions for installing the logger + + +import zmq.log.handlers + + +def removeZMQlogger(name=None): + logger = logging.getLogger(name) + + for h in logger.handlers: + if isinstance(h, zmq.log.handlers.PUBHandler): + print('removing handler %s' % h) + logger.removeHandler(h) + + +def installZMQlogger(port=5800, name=None, clear=True, level=logging.INFO): + if clear: + removeZMQlogger(name) + + ctx = zmq.Context() + pub = ctx.socket(zmq.PUB) + pub.setsockopt(zmq.RCVHWM, 10) + + pub.connect('tcp://127.0.0.1:%i' % port) + + if name is None: + rootlogger = logging.getLogger() + else: + rootlogger = logging.getLogger(name) + if level is not None: + rootlogger.setLevel(level) + handler = PUBHandler(pub) + pid = os.getpid() + pstr = 'pid %d: ' % pid + handler.formatters = { + logging.DEBUG: logging.Formatter(pstr + + "%(levelname)s %(filename)s:%(lineno)d - %(message)s\n"), + logging.INFO: logging.Formatter(pstr + "%(message)s\n"), + logging.WARN: logging.Formatter(pstr + + "%(levelname)s %(filename)s:%(lineno)d - %(message)s\n"), + logging.ERROR: logging.Formatter(pstr + + "%(levelname)s %(filename)s:%(lineno)d - %(message)s - %(exc_info)s\n"), + logging.CRITICAL: logging.Formatter(pstr + + "%(levelname)s %(filename)s:%(lineno)d - %(message)s\n")} + + rootlogger.addHandler(handler) + logging.debug('installZMQlogger: handler installed') + # first message always is discarded + return rootlogger + +#%% + + +class zmqLoggingGUI(QtWidgets.QDialog): + + LOG_LEVELS = dict({logging.DEBUG: 'debug', logging.INFO: 'info', + logging.WARN: 'warning', logging.ERROR: 'error', logging.CRITICAL: 'critical'}) + + def __init__(self, parent=None): + super(zmqLoggingGUI, self).__init__(parent) + + self.setWindowTitle('ZMQ logger') + + self.imap = dict((v, k) for k, v in self.LOG_LEVELS.items()) + + self._console = QtWidgets.QPlainTextEdit(self) + self._console.setMaximumBlockCount(2000) + + self._button = QtWidgets.QPushButton(self) + self._button.setText('Clear') + self._killbutton = QtWidgets.QPushButton(self) + self._killbutton.setText('Kill heartbeat') + + self._levelBox = QtWidgets.QComboBox(self) + for k in sorted(self.LOG_LEVELS.keys()): + print('item %s' % k) + val = self.LOG_LEVELS[k] + self._levelBox.insertItem(k, val) + + blayout = QtWidgets.QHBoxLayout() + blayout.addWidget(self._button) + blayout.addWidget(self._killbutton) + blayout.addWidget(self._levelBox) + self._button.clicked.connect(self.clearMessages) + self._killbutton.clicked.connect(self.killPID) + self._levelBox.currentIndexChanged.connect(self.setLevel) + + layout = QtWidgets.QVBoxLayout() + layout.addWidget(self._console) + layout.addLayout(blayout) + self.setLayout(layout) + + self.addMessage('logging started...' + '\n') + + self._levelBox.setCurrentIndex(1) + self.loglevel = logging.INFO + self.nkill = 0 + + def setLevel(self, boxidx): + name = self._levelBox.itemText(boxidx) + lvl = self.imap.get(name, None) + print('set level to %s: %d' % (name, lvl)) + if lvl is not None: + self.loglevel = lvl + + def addMessage(self, msg, level=None): + if level is not None: + if level < self.loglevel: + return + self._console.moveCursor(QtGui.QTextCursor.End) + self._console.insertPlainText(msg) + self._console.moveCursor(QtGui.QTextCursor.End) + + def clearMessages(self): + ''' Clear the messages in the logging window ''' + self._console.clear() + self.addMessage('cleared messages...\n') + + def killPID(self): + ''' Clear the messages in the logging window ''' + self.nkill = 10 + + +def qt_logger(port, dlg, level=logging.INFO, verbose=1): + ctx = zmq.Context() + sub = ctx.socket(zmq.SUB) + sub.bind('tcp://127.0.0.1:%i' % port) + sub.setsockopt(zmq.SUBSCRIBE, b"") + sub.setsockopt(zmq.RCVHWM, 10) + + logging.basicConfig(level=level) + app = QtWidgets.QApplication.instance() + app.processEvents() + + print('connected to port %s' % port) + while True: + tprint('ZMQ logger: logging...', dt=5) + try: + level, message = sub.recv_multipart(zmq.NOBLOCK) + # level, message = sub.recv_multipart() + message = message.decode('ascii') + if message.endswith('\n'): + # trim trailing newline, which will get appended again + message = message[:-1] + level = level.lower().decode('ascii') + log = getattr(logging, level) + lvlvalue = dlg.imap.get(level, None) + + if verbose >= 2: + log(message) + dlg.addMessage(message + '\n', lvlvalue) + + if dlg.nkill > 0: + print('check pid') + m = re.match('pid (\d*): heartbeat', message) + dlg.nkill = dlg.nkill - 1 + if m is not None: + pid = int(m.group(1)) + print('killing pid %d' % pid) + mysignal = getattr(signal, 'SIGKILL', signal.SIGTERM) + os.kill(pid, mysignal) # or signal.SIGKILL + dlg.addMessage( + 'send kill signal to pid %d\n' % pid, logging.CRITICAL) + app.processEvents() + + if verbose >= 2: + print('message: %s (level %s)' % (message, level)) + except zmq.error.Again: + # no messages in system.... + app.processEvents() + time.sleep(.06) + message = '' + level = None + +#%% +if __name__ == '__main__': + + port = args.port + verbose = args.verbose + + app = None + if (not QtWidgets.QApplication.instance()): + app = QtWidgets.QApplication([]) + dlg = zmqLoggingGUI() + dlg.resize(800, 400) + dlg.show() + + # start the log watcher + try: + qt_logger(port, level=args.level, verbose=verbose, dlg=dlg) + except KeyboardInterrupt: + pass + + # if (app): + # app.exec_() + +#%% Send message to logger +if 0: + port = 5800 + installZMQlogger(port=port, level=None) + logging.warning('test')