diff --git a/labrad/logging.py b/labrad/logging.py new file mode 100644 index 0000000..1826098 --- /dev/null +++ b/labrad/logging.py @@ -0,0 +1,143 @@ +""" +labrad.logging + +Contains functions to set up logging. +""" + +import os +import sys +import logging + +__all__ = ["labradLogFormatter", "_LoggerWriter", "setupLogging"] + + +labradLogFormatter = logging.Formatter( + "%(asctime)s [%(name)-15.15s] [%(sender_host)-15.15s] [%(sender_name)-25.25s] [%(levelname)-10.10s] %(message)s" +) + + +class _LoggerWriter: + """ + Redirects stdout to logger. + """ + encoding = 'utf-8' + + def __init__(self, level): + self.level = level + + def write(self, message): + if message != '\n': + self.level(message) + + def flush(self): + self.level(sys.stderr) + + +def setupLogging( + logger_name, sender=None, extraDict=None, + logHandlers=[], log_level=logging.DEBUG, + logfile=None, + syslog=True, syslog_rfc='5424', + syslog_socket=(os.environ['LABRADHOST'], os.environ['EGGS_LABRAD_SYSLOG_PORT']) + ): + """ + Sets up the logger. + Arguments: + logger_name : the name of the logger to set up. + sender : the sender. + extraDict : the logging dict to send with each log. + logHandlers : extra handlers to send the logger. + log_level : the default logging level. + logfile : the directory to create a logfile in. + syslog : whether to create syslog handlers. + syslog_rfc : the RFC standard for syslog. + syslog_socket : the syslog socket to log to if syslog is True. + """ + from socket import SOCK_STREAM, gethostname + + # ensure we can create a custom loghandler with labels specific to each sender + if (sender is None) and (extraDict is None): + raise Exception("Either sender or extraDict must be specified.") + elif extraDict is None: + extraDict = { + 'sender_host': gethostname(), + 'sender_name': sender.__class__.__name__, + } + + # create and configure logger + logging.basicConfig(level=log_level, handlers=None) + logger = logging.getLogger(logger_name) + logger.propagate = False + + # remove any existing loggers, keeping only those related to labrad + handlers = [] + for name, logger_obj in logging.Logger.manager.loggerDict.items(): + # check log handlers have already been specified + if isinstance(logger_obj, logging.Logger) and (name == logger_name): + for log_handler in logger_obj.handlers: + handlers.append(log_handler) + # otherwise, turn off any loggers that aren't labrad related + elif isinstance(logger_obj, logging.Logger) and ('labrad' not in name): + logger_obj.disabled = True + + # add extra log handlers + for log_handler in logHandlers: + try: + logger.addHandler(log_handler) + except Exception as e: + print(e) + print("Error: unable to add log_handler {}.".format(log_handler)) + + # only add core handlers if they don't already exist + # this prevents the duplication of log messages + if len(handlers) == 0: + + # create console handler + console_handler = logging.StreamHandler(sys.stdout) + console_handler.setFormatter(labradLogFormatter) + logger.addHandler(console_handler) + + # create logfile + if logfile is not None: + from logging.handlers import FileHandler + logfile_handler = FileHandler(logfile) + logfile_handler.setFormatter(labradLogFormatter) + logger.addHandler(logfile_handler) + + if syslog: + # create syslog handler for RFC3164 + if syslog_rfc == '3164': + # todo: add extradict to this syslog handler + from logging.handlers import SysLogHandler + syslog_handler = SysLogHandler(address=syslog_socket) + syslog_handler.setFormatter(labradLogFormatter) + logger.addHandler(syslog_handler) + + # create syslog handler for RFC5424 + elif syslog_rfc == '5424': + try: + from rfc5424logging import Rfc5424SysLogHandler + syslog5424_handler = Rfc5424SysLogHandler( + address=syslog_socket, + socktype=SOCK_STREAM, + enterprise_id=88888 + ) + logger.addHandler(syslog5424_handler) + except ImportError: + print("Error: RFC5424 syslog handler module is not installed.") + except Exception as e: + print(e) + print("Error: unable to create RFC5424 syslog handler.") + + # adapt logger and return + if syslog and (syslog_rfc == '5424'): + try: + from rfc5424logging.adapter import Rfc5424SysLogAdapter + logger_adapter = Rfc5424SysLogAdapter(logger, extraDict) + return logger_adapter + except ImportError: + print("Error: RFC5424 syslog handler module is not installed.") + except Exception as e: + print("Error: unable to create RFC5424 syslog handler.") + else: + return logger diff --git a/labrad/node/__init__.py b/labrad/node/__init__.py index 26663f6..66566b1 100644 --- a/labrad/node/__init__.py +++ b/labrad/node/__init__.py @@ -65,43 +65,54 @@ :syslogtag,contains,"labrad" /var/log/labrad.log;RSYSLOG_TraditionalFileFormat """ -import logging -import logging.handlers import os +import sys import shlex import socket -import sys import zipfile +import argparse + +import logging +import logging.handlers + from datetime import datetime -from twisted.application.internet import TCPClient -from twisted.application.service import MultiService from twisted.internet import defer, reactor +from twisted.internet.protocol import ProcessProtocol from twisted.internet.defer import inlineCallbacks, returnValue from twisted.internet.error import ProcessDone, ProcessTerminated -from twisted.internet.protocol import ProcessProtocol -from twisted.python import usage + from twisted.python.runtime import platformType import labrad import labrad.support -from labrad import auth, protocol, util, types as T, constants as C +import labrad.types as T +import labrad.constants as C + +from labrad import util +from labrad import auth +from labrad import protocol from labrad.node import server_config +from labrad.logging import setupLogging from labrad.server import LabradServer, setting -from labrad.util import DeferredSignal, interpEnvironmentVars, mux - +from labrad.util import mux # Maximum number of lines of stdout to keep per server. LOG_LENGTH = 1000 - # Named message fired by the manager when new servers connect. SERVER_CONNECTED = 'Server Connect' - # Labrad type of the node status info. STATUS_TYPE = '*(s{name} s{desc} s{ver} s{instname} *s{vars} *s{running})' +# create a logger for all of the node module +_extraDict = { + 'sender_host': socket.gethostname(), + 'sender_name': "node", +} +node_log_global = setupLogging('labrad.node', extraDict=_extraDict) + class ServerProcess(ProcessProtocol): """A class to represent a running server instance.""" @@ -138,18 +149,17 @@ def __init__(self, config, env, client, on_message): if config.path: self.full_env['DIR'] = config.path self.client = client - self.name = interpEnvironmentVars(config.instance_name, self.full_env) + self.name = util.interpEnvironmentVars(config.instance_name, self.full_env) self.args = shlex.split(config.cmdline) - self.args = [interpEnvironmentVars(a, self.full_env) for a in self.args] + self.args = [util.interpEnvironmentVars(a, self.full_env) for a in self.args] self.status = None self.output = [] self.on_message = on_message self._lock = defer.DeferredLock() - logname = 'labrad.' + labrad.support.mangle(self.name) - self.logger = logging.getLogger(logname) + self.logger = node_log_global # Signal that will fire when the server process is shutdown. - self.on_shutdown = DeferredSignal() + self.on_shutdown = util.DeferredSignal() @property def server_name(self): @@ -234,10 +244,10 @@ def on_server_connect(message_ctx, msg): # wait for the server to connect to labrad, shutdown, or timeout, # whichever comes first. - selected = yield mux.select({ + selected = yield util.mux.select({ 'connected': connected, 'shutdown': self.on_shutdown(), - 'timeout': mux.after(self.timeout) + 'timeout': util.mux.after(self.timeout) }) # stop listening for server connect messages @@ -292,9 +302,9 @@ def _stop(self): self.logger.info('Error while shutting down with setting', exc_info=True) - selected = yield mux.select({ + selected = yield util.mux.select({ 'shutdown': self.on_shutdown(), - 'timeout': mux.after(self.config.shutdown_timeout) + 'timeout': util.mux.after(self.config.shutdown_timeout) }) if selected.key == 'shutdown': @@ -367,7 +377,7 @@ def __init__(self, nodename, host, port, username, password, @inlineCallbacks def run(self): """Run the node in a loop, reconnecting after connection loss.""" - log = logging.getLogger('labrad.node') + log = node_log_global while True: print('Connecting to {}:{}...'.format(self.host, self.port)) try: @@ -494,7 +504,7 @@ def _handleMessage(self, c, msg): config = yield self._load() self._update(config) except Exception: - logging.error('Error in _handleMessage', exc_info=True) + self.logger.error('Error in _handleMessage', exc_info=True) @inlineCallbacks def update_autostart(self, autostart): @@ -527,7 +537,7 @@ def __init__(self, nodename, host, port, credential): environment variable. host (str): The host where the labrad manager is running. port (int): The port where the labrad manager is running. - credential (labrad.auth.Password): Credentials for connecting to the + credential (auth.Password): Credentials for connecting to the labrad manager. """ LabradServer.__init__(self) @@ -644,8 +654,7 @@ def refreshServers(self): versions.setdefault(config.version, []).append(config) except Exception: fname = os.path.join(path, f) - logging.error('Error while loading config file "%s":' % fname, - exc_info=True) + self.logger.error('Error while loading config file "%s":' % fname, exc_info=True) server_configs = {} for versions in configs.values(): @@ -653,7 +662,7 @@ def refreshServers(self): if len(servers) > 1: conflicting_files = [s.filename for s in servers] s = servers[0] - logging.warning( + self.logger.warning( 'Found redundant server configs with same name and ' 'version; will use {}. name={}, version={}, ' 'conflicting_files={}' @@ -814,7 +823,7 @@ def autostart(self, c): try: yield deferred except Exception: - logging.error('Failed to autostart "%s"', name, exc_info=True) + self.logger.error('Failed to autostart "%s"', name, exc_info=True) @setting(201, returns='*s') def autostart_list(self, c): @@ -856,7 +865,7 @@ def outdated_restart(self, c): try: yield restart except Exception: - logging.error('Failed to restart "%s"', info['instance'], + self.logger.error('Failed to restart "%s"', info['instance'], exc_info=True) info['status'] = 'failed to restart' else: @@ -897,83 +906,68 @@ def node_version(self, c): return list(info.items()) -class NodeOptions(usage.Options): - optParameters = [ - ['name', 'n', util.getNodeName(), 'Node name.'], - ['host', 'h', C.MANAGER_HOST, 'Manager location.'], - ['port', 'p', C.MANAGER_PORT, 'Manager port.'], - ['username', 'u', None, 'Login username.'], - ['password', 'w', None, 'Login password.'], - ['tls', '', C.MANAGER_TLS, - 'TLS mode for connecting to manager (on/starttls/off)'], - ['logfile', 'l', None, 'Enable logging to a file'], - ['syslog_socket', 'x', None, - 'Override default syslog socket. Absolute path or host[:port]']] - optFlags = [['syslog', 's', 'Enable syslog'], - ['verbose', 'v', 'Enable debug output']] - - -def makeService(options): - """Construct a TCPServer from a LabRAD node.""" - name = options['name'] - host = options['host'] - port = int(options['port']) - username = options['username'] - password = options['password'] - tls_mode = C.check_tls_mode(options['tls']) - return Node(name, host, port, username, password, tls_mode) - - -def setup_logging(options): - logging.basicConfig() - node_log = logging.getLogger('labrad') - if options['syslog']: - # We need to find the path to the system log socket, which varies by - # platform. Linux and OS/X defaults are listed below. On windows the - # only option is UDP logging, but since UDP is connectionless there is - # no way to tell if there is actually a syslog daemon listening. - # https://docs.python.org/2/library/logging.handlers.html#sysloghandler - if options['syslog_socket']: - if '/' in options['syslog_socket']: - address = options['syslog_socket'] - else: - host, _, port = options['syslog_socket'].partition(':') - if port == '': - address = (host, 514) - else: - address = (host, int(port)) - elif sys.platform.startswith('linux'): - address = '/dev/log' - elif sys.platform.startswith('darwin'): - address = '/var/run/syslog' - else: - node_log.critical( - 'Syslog specified, but default socket not known for ' - 'platform {}. Use -s option'.format(sys.platform)) - sys.exit(1) - syslog_handler = logging.handlers.SysLogHandler(address=address) - syslog_handler.setFormatter(logging.Formatter('%(name)s: %(message)s')) - node_log.addHandler(syslog_handler) - if options['logfile']: - file_handler = logging.handlers.RotatingFileHandler( - options['logfile'], maxBytes=800000, backupCount=5) - formatter = logging.Formatter('%(asctime)s - %(name)s: %(message)s', - datefmt='%Y-%m-%d %H:%M:%S') - file_handler.setFormatter(formatter) - node_log.addHandler(file_handler) - if options['verbose']: - node_log.setLevel(logging.DEBUG) - else: - node_log.setLevel(logging.INFO) +def get_argparser(): + parser = argparse.ArgumentParser(description="LabRAD Node") + + parser.add_argument("-n", "--name", default=util.getNodeName(), + help="node name (default: '%(default)s')") + + # manager arguments + manager_group = parser.add_argument_group("manager") + manager_group.add_argument("--host", default=C.MANAGER_HOST, + help="manager host ip address (default: '%(default)s')") + manager_group.add_argument("-p", "--port", default=C.MANAGER_PORT, + help="manager host ip port (default: '%(default)s')") + manager_group.add_argument("--tls", default=C.MANAGER_TLS, choices=('ON', 'STARTTLS', 'OFF'), + help="TLS mode for connecting to manager (default: '%(default)s')") + + # login arguments + manager_group.add_argument("-u", "--username", default=None, help="login username") + manager_group.add_argument("-w", "--password", default=None, help="login password") + + # logging arguments + logging_group = parser.add_argument_group("logging") + logging_group.add_argument("-v", "--verbose", default=logging.INFO, + help="set the logging level for the node (default: '%(default)s')") + logging_group.add_argument("-l", "--logfile", default=None, + help="log to a logfile in the specified directory (default: '%(default)s')") + logging_group.add_argument("-s", "--syslog", default=True, + help="enable syslog (default: %(default)s)") + logging_group.add_argument("-x", "--syslog_socket", default='{}:{}'.format(C.MANAGER_HOST, os.environ["EGGS_LABRAD_SYSLOG_PORT"]), + help="the socket to log to (default: '%(default)s')") + logging_group.add_argument("-z", "--syslog_rfc", default='5424', choices=('5424', '3164'), + help="set the protocol to use for syslog (default: '%(default)s')") + + return parser + def main(): - config = NodeOptions() - config.parseOptions() - setup_logging(config) - logging.getLogger('labrad.node').info('Starting') - service = makeService(config) + # get node config + node_parser = get_argparser() + args = node_parser.parse_args() + + # extract logging args + logging_args = {} + for group in node_parser._action_groups: + if group.title == 'logging': + logging_args = {arg.dest: getattr(args, arg.dest, None) for arg in group._group_actions} + + # massage argparse options into arguments of setupLogging + logging_args['log_level'] = logging_args.pop('verbose') + if logging_args['syslog']: + logging_args['syslog_socket'] = tuple(args.syslog_socket.split(':')) + + # create logger! + node_log = setupLogging('labrad.node', extraDict=_extraDict, **logging_args) + + # construct a TCPServer from a LabRAD node + service = Node(args.name, args.host, args.port, + args.username, args.password, + C.check_tls_mode(args.tls)) + node_log.info('Starting...') service.run() reactor.run() + if __name__ == '__main__': main() diff --git a/labrad/protocol.py b/labrad/protocol.py index 7004cbf..d4122cf 100644 --- a/labrad/protocol.py +++ b/labrad/protocol.py @@ -26,11 +26,11 @@ from twisted.internet import reactor, protocol, defer from twisted.internet.defer import inlineCallbacks, returnValue -from twisted.python import failure, log import labrad.types as T -from labrad import auth, constants as C, crypto, errors, oauth, support, util +from labrad.logging import setupLogging from labrad.stream import packetStream, flattenPacket +from labrad import auth, constants as C, crypto, errors, oauth, support, util class LabradProtocol(protocol.Protocol): @@ -47,6 +47,8 @@ def __init__(self): self.clearCache() self.endianness = '>' self.request_handler = None + # set up logging + self.log = setupLogging('labrad.protocol', sender=self) # create a generator to assemble the packets self.packetStream = packetStream(self.packetReceived, self.endianness) next(self.packetStream) # start the packet stream diff --git a/labrad/server.py b/labrad/server.py index 41900d1..af6b359 100644 --- a/labrad/server.py +++ b/labrad/server.py @@ -20,22 +20,24 @@ servers with labrad. """ -from datetime import datetime -from operator import attrgetter +import sys import threading import traceback - +from datetime import datetime from concurrent import futures +from operator import attrgetter + from twisted.internet import defer, reactor, threads from twisted.internet.defer import inlineCallbacks, returnValue from twisted.internet.error import ConnectionDone, ConnectionLost -from twisted.python import failure, log, threadable +from twisted.python import failure, threadable -from labrad import constants as C, types as T, util import labrad.backend import labrad.client import labrad.concurrent +from labrad import types as T, util from labrad.decorators import setting +from labrad.logging import setupLogging, _LoggerWriter from labrad.wrappers import ClientAsync @@ -192,6 +194,10 @@ class LabradServer(object): def __init__(self): self.description, self.notes = util.parseSettingDoc(self.__doc__) + # set logger as instance variable + self.logger = setupLogging('labrad.server', sender=self) + sys.stdout = _LoggerWriter(self.logger.info) + self.started = False self.stopping = False @@ -360,7 +366,7 @@ def startup(self, protocol): self.started = True self.onStartup.callback(self) except Exception as e: - log.err("connection failed, disconnecting") + self.logger.error("Connection failed, disconnecting.") traceback.print_exc() self.disconnect(e) raise @@ -394,7 +400,7 @@ def _initServer(self): Here we register the settings and signals found on this server and set up message handlers for messages coming from the manager. """ - log.msg('%s starting...' % self.name) + self.logger.info('%s starting...' % self.name) # register handlers for settings and signals mgr = self.client.manager p = mgr.packet() @@ -425,7 +431,7 @@ def _initServer(self): # let the rest of the world know we're ready yield mgr.s__start_serving() - log.msg('%s now serving' % self.name) + self.logger.info('%s now serving.' % self.name) @inlineCallbacks def _stopServer(self, *ignored): @@ -578,10 +584,14 @@ def debug(self, c, data): return repr(c) - # Signals + # SIGNALS onLog = Signal(13131313, 'signal: log', 't*s') def log(self, *messages): + # log messages to self.logger as well + for msg in messages: + self.logger.info(msg) + # send messages to listeners self.onLog((datetime.now(), messages)) diff --git a/labrad/util/__init__.py b/labrad/util/__init__.py index 94ffba0..359b6d9 100644 --- a/labrad/util/__init__.py +++ b/labrad/util/__init__.py @@ -13,21 +13,23 @@ # You should have received a copy of the GNU General Public License # along with this program. If not, see . -import contextlib import os import re import sys import textwrap +import contextlib from twisted.internet import defer, reactor from twisted.internet.defer import inlineCallbacks, returnValue from twisted.internet.threads import blockingCallFromThread -from twisted.python import log, reflect, util -from labrad import constants as C, crypto, support, thread +from labrad import thread +from labrad import constants as C +from labrad.logging import setupLogging from labrad.support import getNodeName from labrad.util.unwrap import unwrap + def fancyHelp(ID, name, accepts, returns, units, about): """Create informative help text for a server setting. """ @@ -255,6 +257,7 @@ def maybeTimeout(deferred, timeout, timeoutResult): consumeErrors=True) returnValue(result) + class DeferredSignal(object): """An object that can create multiple deferreds on demand. @@ -386,9 +389,8 @@ def runServer(srv, run_reactor=True, stop_reactor=True): config = parseServerOptions(name=srv.name) updateServerOptions(srv, config) - log.startLogging(sys.stdout) - #observer = MyLogObserver(sys.stdout) - #log.startLoggingWithObserver(observer.emit) + # set up logging + logger = setupLogging('labrad.server', srv) @inlineCallbacks def run(srv): @@ -400,9 +402,9 @@ def run(srv): config['password']) yield srv.startup(p) yield srv.onShutdown() - log.msg('Disconnected cleanly.') + logger.info('Disconnected cleanly.') except Exception as e: - log.msg('There was an error: {}'.format(e)) + logger.info('There was an error: {}'.format(e)) if stop_reactor: try: reactor.stop() @@ -448,30 +450,3 @@ def stop_server(): blockingCallFromThread(reactor, stop_server) except Exception: pass # don't care about exceptions here - - - -class MyLogObserver(log.FileLogObserver): - timeFormat = '%Y/%m/%d %H:%M -' - - def emit(self, eventDict): - edm = eventDict['message'] - if not edm: - if eventDict['isError'] and 'failure' in eventDict: - text = ((eventDict.get('why') or 'Unhandled Error') - + '\n' + eventDict['failure'].getTraceback()) - elif 'format' in eventDict: - text = self._safeFormat(eventDict['format'], eventDict) - else: - # we don't know how to log this - return - else: - text = ' '.join(map(reflect.safe_str, edm)) - - timeStr = self.formatTime(eventDict['time']) - fmtDict = {'text': text.replace("\n", "\n\t")} - msgStr = self._safeFormat("%(text)s\n", fmtDict) - - util.untilConcludes(self.write, timeStr + " " + msgStr) - util.untilConcludes(self.flush) # Hoorj! - diff --git a/requirements.txt b/requirements.txt index 2fd083c..a63ec73 100644 --- a/requirements.txt +++ b/requirements.txt @@ -6,3 +6,4 @@ pyparsing >= 2.1.* requests service_identity twisted >= 18.4.* +rfc5424-logging-handler >= 1.4.3