diff --git a/daemon/core/__init__.py b/daemon/core/__init__.py index 3a0d31a6..65b380c1 100644 --- a/daemon/core/__init__.py +++ b/daemon/core/__init__.py @@ -1,18 +1,24 @@ import json -import logging import logging.config import os import subprocess from core import constants -# setup logging -log_config_path = os.path.join(constants.CORE_CONF_DIR, "logging.conf") -with open(log_config_path, "r") as log_config_file: - log_config = json.load(log_config_file) - logging.config.dictConfig(log_config) +# setup default null handler +logging.getLogger(__name__).addHandler(logging.NullHandler()) -logger = logging.getLogger() + +def load_logging_config(): + """ + Load CORE logging configuration file. + + :return: nothing + """ + log_config_path = os.path.join(constants.CORE_CONF_DIR, "logging.conf") + with open(log_config_path, "r") as log_config_file: + log_config = json.load(log_config_file) + logging.config.dictConfig(log_config) class CoreCommandError(subprocess.CalledProcessError): diff --git a/daemon/core/broker.py b/daemon/core/broker.py index d3fef7e3..a1c45bd6 100644 --- a/daemon/core/broker.py +++ b/daemon/core/broker.py @@ -4,12 +4,12 @@ other emulation servers. The broker is consulted when handling messages to deter should be handled locally or forwarded on to another emulation server. """ +import logging import os import select import socket import threading -from core import logger from core.api import coreapi from core.coreobj import PyCoreNet from core.coreobj import PyCoreNode @@ -148,7 +148,7 @@ class CoreBroker(object): while len(self.servers) > 0: name, server = self.servers.popitem() if server.sock is not None: - logger.info("closing connection with %s: %s:%s", name, server.host, server.port) + logging.info("closing connection with %s: %s:%s", name, server.host, server.port) server.close() self.dorecvloop = False if self.recvthread is not None: @@ -158,7 +158,7 @@ class CoreBroker(object): """ Reset to initial state. """ - logger.info("clearing state") + logging.info("clearing state") self.nodemap_lock.acquire() self.nodemap.clear() for server, count in self.nodecounts.iteritems(): @@ -178,13 +178,13 @@ class CoreBroker(object): Spawn the receive loop for receiving messages. """ if self.recvthread is not None: - logger.info("server receive loop already started") + logging.info("server receive loop already started") if self.recvthread.isAlive(): return else: self.recvthread.join() # start reading data from connected sockets - logger.info("starting server receive loop") + logging.info("starting server receive loop") self.dorecvloop = True self.recvthread = threading.Thread(target=self.recvloop) self.recvthread.daemon = True @@ -207,14 +207,14 @@ class CoreBroker(object): r, _w, _x = select.select(rlist, [], [], 1.0) for sock in r: server = self.getserverbysock(sock) - logger.info("attempting to receive from server: peer:%s remote:%s", + logging.info("attempting to receive from server: peer:%s remote:%s", server.sock.getpeername(), server.sock.getsockname()) if server is None: # servers may have changed; loop again continue rcvlen = self.recv(server) if rcvlen == 0: - logger.info("connection with server(%s) closed: %s:%s", server.name, server.host, server.port) + logging.info("connection with server(%s) closed: %s:%s", server.name, server.host, server.port) def recv(self, server): """ @@ -230,23 +230,23 @@ class CoreBroker(object): msghdr = server.sock.recv(coreapi.CoreMessage.header_len) if len(msghdr) == 0: # server disconnected - logger.info("server disconnected, closing server") + logging.info("server disconnected, closing server") server.close() return 0 if len(msghdr) != coreapi.CoreMessage.header_len: - logger.warn("warning: broker received not enough data len=%s", len(msghdr)) + logging.warn("warning: broker received not enough data len=%s", len(msghdr)) return len(msghdr) msgtype, msgflags, msglen = coreapi.CoreMessage.unpack_header(msghdr) msgdata = server.sock.recv(msglen) data = msghdr + msgdata count = None - logger.debug("received message type: %s", MessageTypes(msgtype)) + logging.debug("received message type: %s", MessageTypes(msgtype)) # snoop exec response for remote interactive TTYs if msgtype == MessageTypes.EXECUTE.value and msgflags & MessageFlags.TTY.value: data = self.fixupremotetty(msghdr, msgdata, server.host) - logger.debug("created remote tty message: %s", data) + logging.debug("created remote tty message: %s", data) elif msgtype == MessageTypes.NODE.value: # snoop node delete response to decrement node counts if msgflags & MessageFlags.DELETE.value: @@ -266,13 +266,13 @@ class CoreBroker(object): if self.instantiation_complete(): self.session.check_runtime() else: - logger.error("unknown message type received: %s", msgtype) + logging.error("unknown message type received: %s", msgtype) try: for session_client in self.session_clients: session_client.sendall(data) except IOError: - logger.exception("error sending message") + logging.exception("error sending message") if count is not None and count < 1: return 0 @@ -296,17 +296,17 @@ class CoreBroker(object): # leave this socket connected return - logger.info("closing connection with %s @ %s:%s", name, server.host, server.port) + logging.info("closing connection with %s @ %s:%s", name, server.host, server.port) server.close() del self.servers[name] - logger.info("adding broker server(%s): %s:%s", name, host, port) + logging.info("adding broker server(%s): %s:%s", name, host, port) server = CoreDistributedServer(name, host, port) if host is not None and port is not None: try: server.connect() except IOError: - logger.exception("error connecting to server(%s): %s:%s", name, host, port) + logging.exception("error connecting to server(%s): %s:%s", name, host, port) if server.sock is not None: self.startrecvloop() self.servers[name] = server @@ -324,10 +324,10 @@ class CoreBroker(object): if s != server: raise ValueError("server removed was not the server provided") except KeyError: - logger.exception("error deleting server") + logging.exception("error deleting server") if server.sock is not None: - logger.info("closing connection with %s @ %s:%s", server.name, server.host, server.port) + logging.info("closing connection with %s @ %s:%s", server.name, server.host, server.port) server.close() def getserverbyname(self, name): @@ -411,10 +411,10 @@ class CoreBroker(object): remotenum = n2num if key in self.tunnels.keys(): - logger.warn("tunnel with key %s (%s-%s) already exists!", key, n1num, n2num) + logging.warn("tunnel with key %s (%s-%s) already exists!", key, n1num, n2num) else: objid = key & ((1 << 16) - 1) - logger.info("adding tunnel for %s-%s to %s with key %s", n1num, n2num, remoteip, key) + logging.info("adding tunnel for %s-%s to %s with key %s", n1num, n2num, remoteip, key) if localnum in self.physical_nodes: # no bridge is needed on physical nodes; use the GreTap directly gt = GreTap(node=None, name=None, session=self.session, @@ -431,7 +431,7 @@ class CoreBroker(object): Add GreTaps between network devices on different machines. The GreTapBridge is not used since that would add an extra bridge. """ - logger.debug("adding network tunnels for nodes: %s", self.network_nodes) + logging.debug("adding network tunnels for nodes: %s", self.network_nodes) for n in self.network_nodes: self.addnettunnel(n) @@ -445,30 +445,30 @@ class CoreBroker(object): """ try: net = self.session.get_object(node_id) - logger.info("adding net tunnel for: id(%s) %s", node_id, net) + logging.info("adding net tunnel for: id(%s) %s", node_id, net) except KeyError: raise KeyError("network node %s not found" % node_id) # add other nets here that do not require tunnels if nodeutils.is_node(net, NodeTypes.EMANE_NET): - logger.warn("emane network does not require a tunnel") + logging.warn("emane network does not require a tunnel") return None server_interface = getattr(net, "serverintf", None) if nodeutils.is_node(net, NodeTypes.CONTROL_NET) and server_interface is not None: - logger.warn("control networks with server interfaces do not need a tunnel") + logging.warn("control networks with server interfaces do not need a tunnel") return None servers = self.getserversbynode(node_id) if len(servers) < 2: - logger.warn("not enough servers to create a tunnel: %s", servers) + logging.warn("not enough servers to create a tunnel: %s", servers) return None hosts = [] for server in servers: if server.host is None: continue - logger.info("adding server host for net tunnel: %s", server.host) + logging.info("adding server host for net tunnel: %s", server.host) hosts.append(server.host) if len(hosts) == 0: @@ -476,7 +476,7 @@ class CoreBroker(object): # get IP address from API message sender (master) if session_client.client_address != "": address = session_client.client_address[0] - logger.info("adding session_client host: %s", address) + logging.info("adding session_client host: %s", address) hosts.append(address) r = [] @@ -489,11 +489,11 @@ class CoreBroker(object): myip = host key = self.tunnelkey(node_id, IpAddress.to_int(myip)) if key in self.tunnels.keys(): - logger.info("tunnel already exists, returning existing tunnel: %s", key) + logging.info("tunnel already exists, returning existing tunnel: %s", key) gt = self.tunnels[key] r.append(gt) continue - logger.info("adding tunnel for net %s to %s with key %s", node_id, host, key) + logging.info("adding tunnel for net %s to %s with key %s", node_id, host, key) gt = GreTap(node=None, name=None, session=self.session, remoteip=host, key=key) self.tunnels[key] = gt r.append(gt) @@ -513,7 +513,7 @@ class CoreBroker(object): """ key = self.tunnelkey(n1num, n2num) try: - logger.info("deleting tunnel between %s - %s with key: %s", n1num, n2num, key) + logging.info("deleting tunnel between %s - %s with key: %s", n1num, n2num, key) gt = self.tunnels.pop(key) except KeyError: gt = None @@ -530,7 +530,7 @@ class CoreBroker(object): :return: gre tap between nodes or none """ key = self.tunnelkey(n1num, n2num) - logger.debug("checking for tunnel(%s) in: %s", key, self.tunnels.keys()) + logging.debug("checking for tunnel(%s) in: %s", key, self.tunnels.keys()) if key in self.tunnels.keys(): return self.tunnels[key] else: @@ -600,9 +600,9 @@ class CoreBroker(object): :param int nodenum: node id to add :return: nothing """ - logger.info("adding net to broker: %s", nodenum) + logging.info("adding net to broker: %s", nodenum) self.network_nodes.add(nodenum) - logger.info("broker network nodes: %s", self.network_nodes) + logging.info("broker network nodes: %s", self.network_nodes) def addphys(self, nodenum): """ @@ -677,11 +677,11 @@ class CoreBroker(object): """ server = self.getserverbyname(servername) if server is None: - logger.warn("ignoring unknown server: %s", servername) + logging.warn("ignoring unknown server: %s", servername) return if server.sock is None or server.host is None or server.port is None: - logger.info("ignoring disconnected server: %s", servername) + logging.info("ignoring disconnected server: %s", servername) return # communicate this session"s current state to the server @@ -753,10 +753,10 @@ class CoreBroker(object): try: nodecls = nodeutils.get_node_class(NodeTypes(nodetype)) except KeyError: - logger.warn("broker invalid node type %s", nodetype) + logging.warn("broker invalid node type %s", nodetype) return handle_locally, servers if nodecls is None: - logger.warn("broker unimplemented node type %s", nodetype) + logging.warn("broker unimplemented node type %s", nodetype) return handle_locally, servers if issubclass(nodecls, PyCoreNet) and nodetype != NodeTypes.WIRELESS_LAN.value: # network node replicated on all servers; could be optimized @@ -808,7 +808,7 @@ class CoreBroker(object): # determine link message destination using non-network nodes nn = message.node_numbers() - logger.debug("checking link nodes (%s) with network nodes (%s)", nn, self.network_nodes) + logging.debug("checking link nodes (%s) with network nodes (%s)", nn, self.network_nodes) if nn[0] in self.network_nodes: if nn[1] in self.network_nodes: # two network nodes linked together - prevent loops caused by @@ -819,11 +819,11 @@ class CoreBroker(object): elif nn[1] in self.network_nodes: servers = self.getserversbynode(nn[0]) else: - logger.debug("link nodes are not network nodes") + logging.debug("link nodes are not network nodes") servers1 = self.getserversbynode(nn[0]) - logger.debug("servers for node(%s): %s", nn[0], servers1) + logging.debug("servers for node(%s): %s", nn[0], servers1) servers2 = self.getserversbynode(nn[1]) - logger.debug("servers for node(%s): %s", nn[1], servers2) + logging.debug("servers for node(%s): %s", nn[1], servers2) # nodes are on two different servers, build tunnels as needed if servers1 != servers2: localn = None @@ -852,7 +852,7 @@ class CoreBroker(object): if host is None: host = self.getlinkendpoint(message, localn == nn[0]) - logger.debug("handle locally(%s) and local node(%s)", handle_locally, localn) + logging.debug("handle locally(%s) and local node(%s)", handle_locally, localn) if localn is None: message = self.addlinkendpoints(message, servers1, servers2) elif message.flags & MessageFlags.ADD.value: @@ -955,10 +955,10 @@ class CoreBroker(object): # local emulation server, handle this locally handle_locally = True elif server.sock is None: - logger.info("server %s @ %s:%s is disconnected", server.name, server.host, server.port) + logging.info("server %s @ %s:%s is disconnected", server.name, server.host, server.port) else: - logger.info("forwarding message to server(%s): %s:%s", server.name, server.host, server.port) - logger.debug("message being forwarded:\n%s", message) + logging.info("forwarding message to server(%s): %s:%s", server.name, server.host, server.port) + logging.debug("message being forwarded:\n%s", message) server.sock.send(message.raw_message) return handle_locally @@ -986,7 +986,7 @@ class CoreBroker(object): lhost, lport = server.sock.getsockname() f.write("%s %s %s %s %s\n" % (server.name, server.host, server.port, lhost, lport)) except IOError: - logger.exception("error writing server list to the file: %s", filename) + logging.exception("error writing server list to the file: %s", filename) def writenodeserver(self, nodestr, server): """ @@ -1007,13 +1007,13 @@ class CoreBroker(object): os.makedirs(dirname) except OSError: # directory may already exist from previous distributed run - logger.exception("error creating directory: %s", dirname) + logging.exception("error creating directory: %s", dirname) try: with open(filename, "w") as f: f.write("%s\n%s\n" % (serverstr, nodestr)) except IOError: - logger.exception("error writing server file %s for node %s", filename, name) + logging.exception("error writing server file %s for node %s", filename, name) def local_instantiation_complete(self): """ @@ -1089,12 +1089,12 @@ class CoreBroker(object): control_nets = value.split() if len(control_nets) < 2: - logger.warn("multiple controlnet prefixes do not exist") + logging.warn("multiple controlnet prefixes do not exist") return servers = self.session.broker.getservernames() if len(servers) < 2: - logger.warn("not distributed") + logging.warn("not distributed") return servers.remove("localhost") diff --git a/daemon/core/conf.py b/daemon/core/conf.py index f42107ac..b2696b7a 100644 --- a/daemon/core/conf.py +++ b/daemon/core/conf.py @@ -2,9 +2,9 @@ Common support for configurable CORE objects. """ +import logging from collections import OrderedDict -from core import logger from core.data import ConfigData @@ -63,9 +63,9 @@ class ConfigShim(object): captions = None data_types = [] possible_values = [] - logger.debug("configurable: %s", configurable_options) - logger.debug("configuration options: %s", configurable_options.configurations) - logger.debug("configuration data: %s", config) + logging.debug("configurable: %s", configurable_options) + logging.debug("configuration options: %s", configurable_options.configurations) + logging.debug("configuration data: %s", config) for configuration in configurable_options.configurations(): if not captions: captions = configuration.label @@ -159,7 +159,7 @@ class ConfigurableManager(object): :param int node_id: node id to clear configurations for, default is None and clears all configurations :return: nothing """ - logger.debug("resetting all configurations: %s", self.__class__.__name__) + logging.debug("resetting all configurations: %s", self.__class__.__name__) if not node_id: self.node_configurations.clear() elif node_id in self.node_configurations: @@ -175,7 +175,7 @@ class ConfigurableManager(object): :param str config_type: configuration type to store configuration for :return: nothing """ - logger.debug("setting config for node(%s) type(%s): %s=%s", node_id, config_type, _id, value) + logging.debug("setting config for node(%s) type(%s): %s=%s", node_id, config_type, _id, value) node_configs = self.node_configurations.setdefault(node_id, OrderedDict()) node_type_configs = node_configs.setdefault(config_type, OrderedDict()) node_type_configs[_id] = value @@ -189,7 +189,7 @@ class ConfigurableManager(object): :param str config_type: configuration type to store configuration for :return: nothing """ - logger.debug("setting config for node(%s) type(%s): %s", node_id, config_type, config) + logging.debug("setting config for node(%s) type(%s): %s", node_id, config_type, config) node_configs = self.node_configurations.setdefault(node_id, OrderedDict()) node_configs[config_type] = config @@ -204,7 +204,7 @@ class ConfigurableManager(object): :return: configuration value :rtype str """ - logger.debug("getting config for node(%s) type(%s): %s", node_id, config_type, _id) + logging.debug("getting config for node(%s) type(%s): %s", node_id, config_type, _id) result = default node_type_configs = self.get_configs(node_id, config_type) if node_type_configs: @@ -220,7 +220,7 @@ class ConfigurableManager(object): :return: configurations :rtype: dict """ - logger.debug("getting configs for node(%s) type(%s)", node_id, config_type) + logging.debug("getting configs for node(%s) type(%s)", node_id, config_type) result = None node_configs = self.node_configurations.get(node_id) if node_configs: @@ -235,7 +235,7 @@ class ConfigurableManager(object): :return: all configuration types for a node :rtype: dict """ - logger.debug("getting all configs for node(%s)", node_id) + logging.debug("getting all configs for node(%s)", node_id) return self.node_configurations.get(node_id) @@ -369,7 +369,7 @@ class ModelManager(ConfigurableManager): :param dict config: model configuration, None for default configuration :return: nothing """ - logger.info("setting mobility model(%s) for node(%s): %s", model_class.name, node.objid, config) + logging.info("setting mobility model(%s) for node(%s): %s", model_class.name, node.objid, config) self.set_model_config(node.objid, model_class.name, config) config = self.get_model_config(node.objid, model_class.name) node.setmodel(model_class, config) @@ -394,5 +394,5 @@ class ModelManager(ConfigurableManager): model_class = self.models[model_name] models.append((model_class, config)) - logger.debug("models for node(%s): %s", node.objid, models) + logging.debug("models for node(%s): %s", node.objid, models) return models diff --git a/daemon/core/corehandlers.py b/daemon/core/corehandlers.py index 12e84f46..4a38bd3c 100644 --- a/daemon/core/corehandlers.py +++ b/daemon/core/corehandlers.py @@ -4,6 +4,7 @@ socket server request handlers leveraged by core servers. import Queue import SocketServer +import logging import os import shlex import shutil @@ -12,7 +13,6 @@ import threading import time from itertools import repeat -from core import logger from core.api import coreapi from core.api import dataconversion from core.conf import ConfigShim @@ -81,7 +81,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): if num_threads < 1: raise ValueError("invalid number of threads: %s" % num_threads) - logger.debug("launching core server handler threads: %s", num_threads) + logging.debug("launching core server handler threads: %s", num_threads) for _ in xrange(num_threads): thread = threading.Thread(target=self.handler_thread) self.handler_threads.append(thread) @@ -102,7 +102,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :return: nothing """ - logger.debug("new TCP connection: %s", self.client_address) + logging.debug("new TCP connection: %s", self.client_address) def finish(self): """ @@ -111,35 +111,35 @@ class CoreHandler(SocketServer.BaseRequestHandler): :return: nothing """ - logger.debug("finishing request handler") - logger.debug("remaining message queue size: %s", self.message_queue.qsize()) + logging.debug("finishing request handler") + logging.debug("remaining message queue size: %s", self.message_queue.qsize()) # give some time for message queue to deplete timeout = 10 wait = 0 while not self.message_queue.empty(): - logger.debug("waiting for message queue to empty: %s seconds", wait) + logging.debug("waiting for message queue to empty: %s seconds", wait) time.sleep(1) wait += 1 if wait == timeout: - logger.warn("queue failed to be empty, finishing request handler") + logging.warn("queue failed to be empty, finishing request handler") break - logger.info("client disconnected: notifying threads") + logging.info("client disconnected: notifying threads") self.done = True for thread in self.handler_threads: - logger.info("waiting for thread: %s", thread.getName()) + logging.info("waiting for thread: %s", thread.getName()) thread.join(timeout) if thread.isAlive(): - logger.warn("joining %s failed: still alive after %s sec", thread.getName(), timeout) + logging.warn("joining %s failed: still alive after %s sec", thread.getName(), timeout) - logger.info("connection closed: %s", self.client_address) + logging.info("connection closed: %s", self.client_address) if self.session: # remove client from session broker and shutdown if there are no clients self.remove_session_handlers() self.session.broker.session_clients.remove(self) if not self.session.broker.session_clients and not self.session.is_active(): - logger.info("no session clients left and not active, initiating shutdown") + logging.info("no session clients left and not active, initiating shutdown") self.coreemu.delete_session(self.session.session_id) return SocketServer.BaseRequestHandler.finish(self) @@ -217,7 +217,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param core.data.EventData event_data: event data to handle :return: nothing """ - logger.debug("handling broadcast event: %s", event_data) + logging.debug("handling broadcast event: %s", event_data) tlv_data = structutils.pack_values(coreapi.CoreEventTlv, [ (EventTlvs.NODE, event_data.node), @@ -232,7 +232,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): try: self.sendall(message) except IOError: - logger.exception("error sending event message") + logging.exception("error sending event message") def handle_broadcast_file(self, file_data): """ @@ -241,7 +241,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param core.data.FileData file_data: file data to handle :return: nothing """ - logger.debug("handling broadcast file: %s", file_data) + logging.debug("handling broadcast file: %s", file_data) tlv_data = structutils.pack_values(coreapi.CoreFileTlv, [ (FileTlvs.NODE, file_data.node), @@ -259,7 +259,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): try: self.sendall(message) except IOError: - logger.exception("error sending file message") + logging.exception("error sending file message") def handle_broadcast_config(self, config_data): """ @@ -268,12 +268,12 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param core.data.ConfigData config_data: config data to handle :return: nothing """ - logger.debug("handling broadcast config: %s", config_data) + logging.debug("handling broadcast config: %s", config_data) message = dataconversion.convert_config(config_data) try: self.sendall(message) except IOError: - logger.exception("error sending config message") + logging.exception("error sending config message") def handle_broadcast_exception(self, exception_data): """ @@ -282,7 +282,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param core.data.ExceptionData exception_data: exception data to handle :return: nothing """ - logger.debug("handling broadcast exception: %s", exception_data) + logging.debug("handling broadcast exception: %s", exception_data) tlv_data = structutils.pack_values(coreapi.CoreExceptionTlv, [ (ExceptionTlvs.NODE, exception_data.node), (ExceptionTlvs.SESSION, exception_data.session), @@ -296,7 +296,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): try: self.sendall(message) except IOError: - logger.exception("error sending exception message") + logging.exception("error sending exception message") def handle_broadcast_node(self, node_data): """ @@ -305,12 +305,12 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param core.data.NodeData node_data: node data to handle :return: nothing """ - logger.debug("handling broadcast node: %s", node_data) + logging.debug("handling broadcast node: %s", node_data) message = dataconversion.convert_node(node_data) try: self.sendall(message) except IOError: - logger.exception("error sending node message") + logging.exception("error sending node message") def handle_broadcast_link(self, link_data): """ @@ -319,7 +319,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param core.data.LinkData link_data: link data to handle :return: nothing """ - logger.debug("handling broadcast link: %s", link_data) + logging.debug("handling broadcast link: %s", link_data) tlv_data = structutils.pack_values(coreapi.CoreLinkTlv, [ (LinkTlvs.N1_NUMBER, link_data.node1_id), @@ -361,7 +361,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): try: self.sendall(message) except IOError: - logger.exception("error sending Event Message") + logging.exception("error sending Event Message") def register(self): """ @@ -369,7 +369,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :return: register message data """ - logger.info("GUI has connected to session %d at %s", self.session.session_id, time.ctime()) + logging.info("GUI has connected to session %d at %s", self.session.session_id, time.ctime()) tlv_data = "" tlv_data += coreapi.CoreRegisterTlv.pack(RegisterTlvs.EXECUTE_SERVER.value, "core-daemon") @@ -418,7 +418,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): message_type, message_flags, message_len = coreapi.CoreMessage.unpack_header(header) if message_len == 0: - logger.warn("received message with no data") + logging.warn("received message with no data") data = "" while len(data) < message_len: @@ -426,7 +426,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): if len(data) > message_len: error_message = "received message length does not match received data (%s != %s)" % ( len(data), message_len) - logger.error(error_message) + logging.error(error_message) raise IOError(error_message) try: @@ -435,7 +435,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): except KeyError: message = coreapi.CoreMessage(message_flags, header, data) message.message_type = message_type - logger.exception("unimplemented core message type: %s", message.type_str()) + logging.exception("unimplemented core message type: %s", message.type_str()) return message @@ -446,7 +446,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param message: message to queue :return: nothing """ - logger.debug("queueing msg (queuedtimes = %s): type %s", message.queuedtimes, MessageTypes( + logging.debug("queueing msg (queuedtimes = %s): type %s", message.queuedtimes, MessageTypes( message.message_type)) self.message_queue.put(message) @@ -474,13 +474,13 @@ class CoreHandler(SocketServer.BaseRequestHandler): :return: nothing """ if self.session and self.session.broker.handle_message(message): - logger.debug("message not being handled locally") + logging.debug("message not being handled locally") return - logger.debug("%s handling message:\n%s", threading.currentThread().getName(), message) + logging.debug("%s handling message:\n%s", threading.currentThread().getName(), message) if message.message_type not in self.message_handlers: - logger.error("no handler for message type: %s", message.type_str()) + logging.error("no handler for message type: %s", message.type_str()) return message_handler = self.message_handlers[message.message_type] @@ -490,7 +490,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): replies = message_handler(message) self.dispatch_replies(replies, message) except: - logger.exception("%s: exception while handling message: %s", threading.currentThread().getName(), message) + logging.exception("%s: exception while handling message: %s", threading.currentThread().getName(), message) def dispatch_replies(self, replies, message): """ @@ -500,7 +500,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param message: message for replies :return: nothing """ - logger.debug("dispatching replies") + logging.debug("dispatching replies") for reply in replies: message_type, message_flags, message_length = coreapi.CoreMessage.unpack_header(reply) try: @@ -514,12 +514,12 @@ class CoreHandler(SocketServer.BaseRequestHandler): reply_message = "CoreMessage (type %d flags %d length %d)" % ( message_type, message_flags, message_length) - logger.debug("dispatch reply:\n%s", reply_message) + logging.debug("dispatch reply:\n%s", reply_message) try: self.sendall(reply) except IOError: - logger.exception("error dispatching reply") + logging.exception("error dispatching reply") def handle(self): """ @@ -535,12 +535,12 @@ class CoreHandler(SocketServer.BaseRequestHandler): # TODO: add shutdown handler for session self.session = self.coreemu.create_session(port, master=False) # self.session.shutdown_handlers.append(self.session_shutdown) - logger.debug("created new session for client: %s", self.session.session_id) + logging.debug("created new session for client: %s", self.session.session_id) # TODO: hack to associate this handler with this sessions broker for broadcasting # TODO: broker needs to be pulled out of session to the server/handler level if self.master: - logger.debug("session set to master") + logging.debug("session set to master") self.session.master = True self.session.broker.session_clients.append(self) @@ -554,10 +554,10 @@ class CoreHandler(SocketServer.BaseRequestHandler): try: message = self.receive_message() except EOFError: - logger.info("client disconnected") + logging.info("client disconnected") break except IOError: - logger.exception("error receiving message") + logging.exception("error receiving message") break message.queuedtimes = 0 @@ -575,7 +575,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): if client == self: continue - logger.debug("BROADCAST TO OTHER CLIENT: %s", client) + logging.debug("BROADCAST TO OTHER CLIENT: %s", client) client.sendall(message.raw_message) def send_exception(self, level, source, text, node=None): @@ -599,7 +599,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.handle_broadcast_exception(exception_data) def add_session_handlers(self): - logger.debug("adding session broadcast handlers") + logging.debug("adding session broadcast handlers") self.session.event_handlers.append(self.handle_broadcast_event) self.session.exception_handlers.append(self.handle_broadcast_exception) self.session.node_handlers.append(self.handle_broadcast_node) @@ -608,7 +608,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.session.config_handlers.append(self.handle_broadcast_config) def remove_session_handlers(self): - logger.debug("removing session broadcast handlers") + logging.debug("removing session broadcast handlers") self.session.event_handlers.remove(self.handle_broadcast_event) self.session.exception_handlers.remove(self.handle_broadcast_exception) self.session.node_handlers.remove(self.handle_broadcast_node) @@ -625,7 +625,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): """ replies = [] if message.flags & MessageFlags.ADD.value and message.flags & MessageFlags.DELETE.value: - logger.warn("ignoring invalid message: add and delete flag both set") + logging.warn("ignoring invalid message: add and delete flag both set") return () node_type = None @@ -792,7 +792,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): reply = coreapi.CoreExecMessage.pack(MessageFlags.TTY.value, tlv_data) return reply, else: - logger.info("execute message with cmd=%s", command) + logging.info("execute message with cmd=%s", command) # execute command and send a response if message.flags & MessageFlags.STRING.value or message.flags & MessageFlags.TEXT.value: # shlex.split() handles quotes within the string @@ -800,7 +800,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): status, res = utils.cmd_output(command) else: status, res = node.cmd_output(command) - logger.info("done exec cmd=%s with status=%d res=(%d bytes)", command, status, len(res)) + logging.info("done exec cmd=%s with status=%d res=(%d bytes)", command, status, len(res)) if message.flags & MessageFlags.TEXT.value: tlv_data += coreapi.CoreExecuteTlv.pack(ExecuteTlvs.RESULT.value, res) if message.flags & MessageFlags.STRING.value: @@ -814,7 +814,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): else: node.cmd(command, wait=False) except KeyError: - logger.exception("error getting object: %s", node_num) + logging.exception("error getting object: %s", node_num) # XXX wait and queue this message to try again later # XXX maybe this should be done differently if not message.flags & MessageFlags.LOCAL.value: @@ -836,7 +836,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): execute_server = message.get_tlv(RegisterTlvs.EXECUTE_SERVER.value) if execute_server: try: - logger.info("executing: %s", execute_server) + logging.info("executing: %s", execute_server) if message.flags & MessageFlags.STRING.value: old_session_ids = set(self.coreemu.sessions.keys()) sys.argv = shlex.split(execute_server) @@ -864,22 +864,22 @@ class CoreHandler(SocketServer.BaseRequestHandler): new_sid = new_session_ids.difference(old_session_ids) try: sid = new_sid.pop() - logger.info("executed: %s as session %d", execute_server, sid) + logging.info("executed: %s as session %d", execute_server, sid) except KeyError: - logger.info("executed %s with unknown session ID", execute_server) + logging.info("executed %s with unknown session ID", execute_server) return replies - logger.debug("checking session %d for RUNTIME state", sid) + logging.debug("checking session %d for RUNTIME state", sid) session = self.coreemu.sessions.get(sid) retries = 10 # wait for session to enter RUNTIME state, to prevent GUI from # connecting while nodes are still being instantiated while session.state != EventTypes.RUNTIME_STATE.value: - logger.debug("waiting for session %d to enter RUNTIME state", sid) + logging.debug("waiting for session %d to enter RUNTIME state", sid) time.sleep(1) retries -= 1 if retries <= 0: - logger.debug("session %d did not enter RUNTIME state", sid) + logging.debug("session %d did not enter RUNTIME state", sid) return replies tlv_data = coreapi.CoreRegisterTlv.pack(RegisterTlvs.EXECUTE_SERVER.value, execute_server) @@ -887,7 +887,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): message = coreapi.CoreRegMessage.pack(0, tlv_data) replies.append(message) except Exception as e: - logger.exception("error executing: %s", execute_server) + logging.exception("error executing: %s", execute_server) tlv_data = coreapi.CoreExceptionTlv.pack(ExceptionTlvs.LEVEL.value, 2) tlv_data += coreapi.CoreExceptionTlv.pack(ExceptionTlvs.TEXT.value, str(e)) message = coreapi.CoreExceptionMessage.pack(0, tlv_data) @@ -897,7 +897,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): gui = message.get_tlv(RegisterTlvs.GUI.value) if gui is None: - logger.debug("ignoring Register message") + logging.debug("ignoring Register message") else: # register capabilities with the GUI self.master = True @@ -905,7 +905,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): # find the session containing this client and set the session to master for session in self.coreemu.sessions.itervalues(): if self in session.broker.session_clients: - logger.debug("setting session to master: %s", session.session_id) + logging.debug("setting session to master: %s", session.session_id) session.master = True break @@ -937,7 +937,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): network_id=message.get_tlv(ConfigTlvs.NETWORK_ID.value), opaque=message.get_tlv(ConfigTlvs.OPAQUE.value) ) - logger.debug("configuration message for %s node %s", config_data.object, config_data.node) + logging.debug("configuration message for %s node %s", config_data.object, config_data.node) message_type = ConfigFlags(config_data.type) replies = [] @@ -1003,7 +1003,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.session.location.reset() else: if not config_data.data_values: - logger.warn("location data missing") + logging.warn("location data missing") else: values = [float(x) for x in config_data.data_values.split("|")] @@ -1016,9 +1016,9 @@ class CoreHandler(SocketServer.BaseRequestHandler): # geographic reference point self.session.location.setrefgeo(lat, lon, alt) self.session.location.refscale = values[5] - logger.info("location configured: %s = %s scale=%s", self.session.location.refxyz, + logging.info("location configured: %s = %s scale=%s", self.session.location.refxyz, self.session.location.refgeo, self.session.location.refscale) - logger.info("location configured: UTM%s", self.session.location.refutm) + logging.info("location configured: UTM%s", self.session.location.refutm) def handle_config_metadata(self, message_type, config_data): replies = [] @@ -1045,7 +1045,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): if message_type not in [ConfigFlags.REQUEST, ConfigFlags.RESET]: session_id = config_data.session if not config_data.data_values: - logger.info("emulation server data missing") + logging.info("emulation server data missing") else: values = config_data.data_values.split("|") @@ -1086,7 +1086,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): session_id = config_data.session opaque = config_data.opaque - logger.debug("configuration request: node(%s) session(%s) opaque(%s)", node_id, session_id, opaque) + logging.debug("configuration request: node(%s) session(%s) opaque(%s)", node_id, session_id, opaque) # send back a list of available services if opaque is None: @@ -1108,10 +1108,10 @@ class CoreHandler(SocketServer.BaseRequestHandler): values = [] group_strings = [] start_index = 1 - logger.info("sorted groups: %s", groups) + logging.info("sorted groups: %s", groups) for group in groups: services = sorted(group_map[group], key=lambda x: x.name.lower()) - logger.info("sorted services for group(%s): %s", group, services) + logging.info("sorted services for group(%s): %s", group, services) end_index = start_index + len(services) - 1 group_strings.append("%s:%s-%s" % (group, start_index, end_index)) start_index += len(services) @@ -1135,7 +1135,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): node = self.session.get_object(node_id) if node is None: - logger.warn("request to configure service for unknown node %s", node_id) + logging.warn("request to configure service for unknown node %s", node_id) return replies services = ServiceShim.servicesfromopaque(opaque) @@ -1186,17 +1186,17 @@ class CoreHandler(SocketServer.BaseRequestHandler): error_message = "services config message that I don't know how to handle" if values is None: - logger.error(error_message) + logging.error(error_message) else: if opaque is None: values = values.split("|") # store default services for a node type in self.defaultservices[] if data_types is None or data_types[0] != ConfigDataTypes.STRING.value: - logger.info(error_message) + logging.info(error_message) return None key = values.pop(0) self.session.services.default_services[key] = values - logger.debug("default services for type %s set to %s", key, values) + logging.debug("default services for type %s set to %s", key, values) elif node_id: services = ServiceShim.servicesfromopaque(opaque) if services: @@ -1230,14 +1230,14 @@ class CoreHandler(SocketServer.BaseRequestHandler): if interface_id is not None: node_id = node_id * 1000 + interface_id - logger.debug("received configure message for %s nodenum: %s", object_name, node_id) + logging.debug("received configure message for %s nodenum: %s", object_name, node_id) if message_type == ConfigFlags.REQUEST: - logger.info("replying to configure request for model: %s", object_name) + logging.info("replying to configure request for model: %s", object_name) typeflags = ConfigFlags.NONE.value model_class = self.session.mobility.models.get(object_name) if not model_class: - logger.warn("model class does not exist: %s", object_name) + logging.warn("model class does not exist: %s", object_name) return [] config = self.session.mobility.get_model_config(node_id, object_name) @@ -1246,7 +1246,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): elif message_type != ConfigFlags.RESET: # store the configuration values for later use, when the node if not object_name: - logger.warn("no configuration object for node: %s", node_id) + logging.warn("no configuration object for node: %s", node_id) return [] parsed_config = {} @@ -1267,16 +1267,16 @@ class CoreHandler(SocketServer.BaseRequestHandler): if interface_id is not None: node_id = node_id * 1000 + interface_id - logger.debug("received configure message for %s nodenum: %s", object_name, node_id) + logging.debug("received configure message for %s nodenum: %s", object_name, node_id) if message_type == ConfigFlags.REQUEST: - logger.info("replying to configure request for %s model", object_name) + logging.info("replying to configure request for %s model", object_name) typeflags = ConfigFlags.NONE.value config = self.session.emane.get_configs() config_response = ConfigShim.config_data(0, node_id, typeflags, self.session.emane.emane_config, config) replies.append(config_response) elif message_type != ConfigFlags.RESET: if not object_name: - logger.info("no configuration object for node %s", node_id) + logging.info("no configuration object for node %s", node_id) return [] if values_str: @@ -1300,14 +1300,14 @@ class CoreHandler(SocketServer.BaseRequestHandler): if interface_id is not None: node_id = node_id * 1000 + interface_id - logger.debug("received configure message for %s nodenum: %s", object_name, node_id) + logging.debug("received configure message for %s nodenum: %s", object_name, node_id) if message_type == ConfigFlags.REQUEST: - logger.info("replying to configure request for model: %s", object_name) + logging.info("replying to configure request for model: %s", object_name) typeflags = ConfigFlags.NONE.value model_class = self.session.emane.models.get(object_name) if not model_class: - logger.warn("model class does not exist: %s", object_name) + logging.warn("model class does not exist: %s", object_name) return [] config = self.session.emane.get_model_config(node_id, object_name) @@ -1316,7 +1316,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): elif message_type != ConfigFlags.RESET: # store the configuration values for later use, when the node if not object_name: - logger.warn("no configuration object for node: %s", node_id) + logging.warn("no configuration object for node: %s", node_id) return [] parsed_config = {} @@ -1343,11 +1343,11 @@ class CoreHandler(SocketServer.BaseRequestHandler): compressed_data = message.get_tlv(FileTlvs.COMPRESSED_DATA.value) if compressed_data: - logger.warn("Compressed file data not implemented for File message.") + logging.warn("Compressed file data not implemented for File message.") return () if source_name and data: - logger.warn("ignoring invalid File message: source and data TLVs are both present") + logging.warn("ignoring invalid File message: source and data TLVs are both present") return () # some File Messages store custom files in services, @@ -1360,7 +1360,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): elif file_type.startswith("hook:"): _, state = file_type.split(':')[:2] if not state.isdigit(): - logger.error("error setting hook having state '%s'", state) + logging.error("error setting hook having state '%s'", state) return () state = int(state) self.session.add_hook(state, file_name, source_name, data) @@ -1388,7 +1388,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): :param message: interface message to handle :return: reply messages """ - logger.info("ignoring Interface message") + logging.info("ignoring Interface message") return () def handle_event_message(self, message): @@ -1412,7 +1412,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): event_type = EventTypes(event_data.event_type) node_id = event_data.node - logger.debug("handling event %s at %s", event_type.name, time.ctime()) + logging.debug("handling event %s at %s", event_type.name, time.ctime()) if event_type.value <= EventTypes.SHUTDOWN_STATE.value: if node_id is not None: try: @@ -1425,7 +1425,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.session.start_mobility(node_ids=(node.objid,)) return () - logger.warn("dropping unhandled Event message with node number") + logging.warn("dropping unhandled Event message with node number") return () self.session.set_state(event_type) @@ -1444,7 +1444,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.send_node_emulation_id(obj.objid) elif event_type == EventTypes.RUNTIME_STATE: if self.session.master: - logger.warn("Unexpected event message: RUNTIME state received at session master") + logging.warn("Unexpected event message: RUNTIME state received at session master") else: # master event queue is started in session.checkruntime() self.session.start_events() @@ -1452,7 +1452,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.session.data_collect() elif event_type == EventTypes.SHUTDOWN_STATE: if self.session.master: - logger.warn("Unexpected event message: SHUTDOWN state received at session master") + logging.warn("Unexpected event message: SHUTDOWN state received at session master") elif event_type in {EventTypes.START, EventTypes.STOP, EventTypes.RESTART, EventTypes.PAUSE, EventTypes.RECONFIGURE}: handled = False @@ -1467,7 +1467,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.session.mobility_event(event_data) handled = True if not handled: - logger.warn("Unhandled event message: event type %s ", event_type.name) + logging.warn("Unhandled event message: event type %s ", event_type.name) elif event_type == EventTypes.FILE_OPEN: filename = event_data.name self.session.open_xml(filename, start=False) @@ -1482,14 +1482,14 @@ class CoreHandler(SocketServer.BaseRequestHandler): name = event_data.name data = event_data.data if etime is None: - logger.warn("Event message scheduled event missing start time") + logging.warn("Event message scheduled event missing start time") return () if message.flags & MessageFlags.ADD.value: self.session.add_event(float(etime), node=node, name=name, data=data) else: raise NotImplementedError else: - logger.warn("unhandled event message: event type %s", event_type) + logging.warn("unhandled event message: event type %s", event_type) return () @@ -1508,7 +1508,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): try: node = self.session.get_object(node_id) except KeyError: - logger.warn("ignoring event for service '%s', unknown node '%s'", name, node_id) + logging.warn("ignoring event for service '%s', unknown node '%s'", name, node_id) return fail = "" @@ -1546,7 +1546,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): if num > 1: unknown_data += ", " num -= 1 - logger.warn("Event requested for unknown service(s): %s", unknown_data) + logging.warn("Event requested for unknown service(s): %s", unknown_data) unknown_data = "Unknown:" + unknown_data event_data = EventData( @@ -1574,7 +1574,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): files = coreapi.str_to_list(file_str) thumb = message.get_tlv(SessionTlvs.THUMB.value) user = message.get_tlv(SessionTlvs.USER.value) - logger.debug("SESSION message flags=0x%x sessions=%s" % (message.flags, session_id_str)) + logging.debug("SESSION message flags=0x%x sessions=%s" % (message.flags, session_id_str)) if message.flags == 0: for index, session_id in enumerate(session_ids): @@ -1585,10 +1585,10 @@ class CoreHandler(SocketServer.BaseRequestHandler): session = self.coreemu.sessions.get(session_id) if session is None: - logger.warn("session %s not found", session_id) + logging.warn("session %s not found", session_id) continue - logger.info("request to modify to session: %s", session.session_id) + logging.info("request to modify to session: %s", session.session_id) if names is not None: session.name = names[index] @@ -1610,12 +1610,12 @@ class CoreHandler(SocketServer.BaseRequestHandler): session = self.coreemu.sessions.get(session_id) if session is None: - logger.info("session %s not found (flags=0x%x)", session_id, message.flags) + logging.info("session %s not found (flags=0x%x)", session_id, message.flags) continue if message.flags & MessageFlags.ADD.value: # connect to the first session that exists - logger.info("request to connect to session %s", session_id) + logging.info("request to connect to session %s", session_id) # remove client from session broker and shutdown if needed self.remove_session_handlers() @@ -1632,7 +1632,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.session.broker.session_clients.append(self) # add broadcast handlers - logger.info("adding session broadcast handlers") + logging.info("adding session broadcast handlers") self.add_session_handlers() if user: @@ -1642,10 +1642,10 @@ class CoreHandler(SocketServer.BaseRequestHandler): self.send_objects() elif message.flags & MessageFlags.DELETE.value: # shut down the specified session(s) - logger.info("request to terminate session %s", session_id) + logging.info("request to terminate session %s", session_id) self.coreemu.delete_session(session_id) else: - logger.warn("unhandled session flags for session %s", session_id) + logging.warn("unhandled session flags for session %s", session_id) return () @@ -1665,7 +1665,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): try: self.sendall(reply) except IOError: - logger.exception("error sending node emulation id message: %s", node_id) + logging.exception("error sending node emulation id message: %s", node_id) del self.node_status_request[node_id] @@ -1698,7 +1698,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): for node_id in self.session.mobility.nodes(): for model_name, config in self.session.mobility.get_all_configs(node_id).iteritems(): model_class = self.session.mobility.models[model_name] - logger.debug("mobility config: node(%s) class(%s) values(%s)", node_id, model_class, config) + logging.debug("mobility config: node(%s) class(%s) values(%s)", node_id, model_class, config) config_data = ConfigShim.config_data(0, node_id, ConfigFlags.UPDATE.value, model_class, config) self.session.broadcast_config(config_data) @@ -1706,7 +1706,7 @@ class CoreHandler(SocketServer.BaseRequestHandler): for node_id in self.session.emane.nodes(): for model_name, config in self.session.emane.get_all_configs(node_id).iteritems(): model_class = self.session.emane.models[model_name] - logger.debug("emane config: node(%s) class(%s) values(%s)", node_id, model_class, config) + logging.debug("emane config: node(%s) class(%s) values(%s)", node_id, model_class, config) config_data = ConfigShim.config_data(0, node_id, ConfigFlags.UPDATE.value, model_class, config) self.session.broadcast_config(config_data) @@ -1769,4 +1769,4 @@ class CoreHandler(SocketServer.BaseRequestHandler): ) self.session.broadcast_config(config_data) - logger.info("informed GUI about %d nodes and %d links", len(nodes_data), len(links_data)) + logging.info("informed GUI about %d nodes and %d links", len(nodes_data), len(links_data)) diff --git a/daemon/core/emane/commeffect.py b/daemon/core/emane/commeffect.py index 4fc199ac..37fe0f67 100644 --- a/daemon/core/emane/commeffect.py +++ b/daemon/core/emane/commeffect.py @@ -2,11 +2,11 @@ commeffect.py: EMANE CommEffect model for CORE """ +import logging import os from lxml import etree -from core import logger from core.conf import ConfigGroup from core.emane import emanemanifest from core.emane import emanemodel @@ -18,7 +18,7 @@ except ImportError: try: from emanesh.events.commeffectevent import CommEffectEvent except ImportError: - logger.debug("compatible emane python bindings not installed") + logging.debug("compatible emane python bindings not installed") def convert_none(x): @@ -110,11 +110,11 @@ class EmaneCommEffectModel(emanemodel.EmaneModel): """ service = self.session.emane.service if service is None: - logger.warn("%s: EMANE event service unavailable", self.name) + logging.warn("%s: EMANE event service unavailable", self.name) return if netif is None or netif2 is None: - logger.warn("%s: missing NEM information", self.name) + logging.warn("%s: missing NEM information", self.name) return # TODO: batch these into multiple events per transmission @@ -124,7 +124,7 @@ class EmaneCommEffectModel(emanemodel.EmaneModel): nemid = emane_node.getnemid(netif) nemid2 = emane_node.getnemid(netif2) mbw = bw - logger.info("sending comm effect event") + logging.info("sending comm effect event") event.append( nemid, latency=convert_none(delay), diff --git a/daemon/core/emane/emanemanager.py b/daemon/core/emane/emanemanager.py index 5f0f566e..4255b7de 100644 --- a/daemon/core/emane/emanemanager.py +++ b/daemon/core/emane/emanemanager.py @@ -2,12 +2,12 @@ emane.py: definition of an Emane class for implementing configuration control of an EMANE emulation. """ +import logging import os import threading from core import CoreCommandError from core import constants -from core import logger from core.api import coreapi from core.api import dataconversion from core.conf import ConfigGroup @@ -42,7 +42,7 @@ except ImportError: from emanesh.events import LocationEvent from emanesh.events.eventserviceexception import EventServiceException except ImportError: - logger.debug("compatible emane python bindings not installed") + logging.debug("compatible emane python bindings not installed") EMANE_MODELS = [ EmaneRfPipeModel, @@ -147,7 +147,7 @@ class EmaneManager(ModelManager): try: # check for emane emane_version = utils.check_cmd(["emane", "--version"]) - logger.info("using EMANE: %s", emane_version) + logging.info("using EMANE: %s", emane_version) # load default emane models self.load_models(EMANE_MODELS) @@ -158,7 +158,7 @@ class EmaneManager(ModelManager): emane_models = utils.load_classes(custom_models_path, EmaneModel) self.load_models(emane_models) except CoreCommandError: - logger.info("emane is not installed") + logging.info("emane is not installed") def deleteeventservice(self): if self.service: @@ -186,7 +186,7 @@ class EmaneManager(ModelManager): self.event_device = self.get_config("eventservicedevice") eventnetidx = self.session.get_control_net_index(self.event_device) if eventnetidx < 0: - logger.error("invalid emane event service device provided: %s", self.event_device) + logging.error("invalid emane event service device provided: %s", self.event_device) return False # make sure the event control network is in place @@ -198,11 +198,11 @@ class EmaneManager(ModelManager): # disabled otachannel for event service # only needed for e.g. antennaprofile events xmit by models - logger.info("using %s for event service traffic", self.event_device) + logging.info("using %s for event service traffic", self.event_device) try: self.service = EventService(eventchannel=eventchannel, otachannel=None) except EventServiceException: - logger.exception("error instantiating emane EventService") + logging.exception("error instantiating emane EventService") return True @@ -211,7 +211,7 @@ class EmaneManager(ModelManager): Load EMANE models and make them available. """ for emane_model in emane_models: - logger.info("loading emane model: %s", emane_model.__name__) + logging.info("loading emane model: %s", emane_model.__name__) self.models[emane_model.name] = emane_model def add_node(self, emane_node): @@ -245,17 +245,17 @@ class EmaneManager(ModelManager): Emane.(SUCCESS, NOT_NEEDED, NOT_READY) in order to delay session instantiation. """ - logger.debug("emane setup") + logging.debug("emane setup") # TODO: drive this from the session object with self.session._objects_lock: for node in self.session.objects.itervalues(): if nodeutils.is_node(node, NodeTypes.EMANE): - logger.debug("adding emane node: id(%s) name(%s)", node.objid, node.name) + logging.debug("adding emane node: id(%s) name(%s)", node.objid, node.name) self.add_node(node) if not self._emane_nodes: - logger.debug("no emane nodes in session") + logging.debug("no emane nodes in session") return EmaneManager.NOT_NEEDED # control network bridge required for EMANE 0.9.2 @@ -264,20 +264,20 @@ class EmaneManager(ModelManager): if self.session.master: otadev = self.get_config("otamanagerdevice") netidx = self.session.get_control_net_index(otadev) - logger.debug("emane ota manager device: index(%s) otadev(%s)", netidx, otadev) + logging.debug("emane ota manager device: index(%s) otadev(%s)", netidx, otadev) if netidx < 0: - logger.error("EMANE cannot start, check core config. invalid OTA device provided: %s", otadev) + logging.error("EMANE cannot start, check core config. invalid OTA device provided: %s", otadev) return EmaneManager.NOT_READY ctrlnet = self.session.add_remove_control_net(net_index=netidx, remove=False, conf_required=False) self.distributedctrlnet(ctrlnet) eventdev = self.get_config("eventservicedevice") - logger.debug("emane event service device: eventdev(%s)", eventdev) + logging.debug("emane event service device: eventdev(%s)", eventdev) if eventdev != otadev: netidx = self.session.get_control_net_index(eventdev) - logger.debug("emane event service device index: %s", netidx) + logging.debug("emane event service device index: %s", netidx) if netidx < 0: - logger.error("EMANE cannot start, check core config. invalid event service device: %s", eventdev) + logging.error("EMANE cannot start, check core config. invalid event service device: %s", eventdev) return EmaneManager.NOT_READY ctrlnet = self.session.add_remove_control_net(net_index=netidx, remove=False, conf_required=False) @@ -328,7 +328,7 @@ class EmaneManager(ModelManager): for nodename, ifname, nemid in nems: f.write("%s %s %s\n" % (nodename, ifname, nemid)) except IOError: - logger.exception("Error writing EMANE NEMs file: %s") + logging.exception("Error writing EMANE NEMs file: %s") return EmaneManager.SUCCESS @@ -342,7 +342,7 @@ class EmaneManager(ModelManager): with self._emane_node_lock: for key in sorted(self._emane_nodes.keys()): emane_node = self._emane_nodes[key] - logger.debug("post startup for emane node: %s - %s", emane_node.objid, emane_node.name) + logging.debug("post startup for emane node: %s - %s", emane_node.objid, emane_node.name) emane_node.model.post_startup() for netif in emane_node.netifs(): x, y, z = netif.node.position.get() @@ -370,7 +370,7 @@ class EmaneManager(ModelManager): with self._emane_node_lock: if not self._emane_nodes: return - logger.info("stopping EMANE daemons.") + logging.info("stopping EMANE daemons.") self.deinstallnetifs() self.stopdaemons() self.stopeventmonitor() @@ -407,7 +407,7 @@ class EmaneManager(ModelManager): with self._emane_node_lock: if self._emane_nodes: master = self.session.master - logger.info("emane check distributed as master: %s.", master) + logging.info("emane check distributed as master: %s.", master) # we are not the master Emane object, wait for nem id and ports if not master: @@ -460,7 +460,7 @@ class EmaneManager(ModelManager): events and data. """ # assume self._objslock is already held here - logger.info("emane building xml...") + logging.info("emane building xml...") # on master, control network bridge added earlier in startup() ctrlnet = self.session.add_remove_control_net(net_index=0, remove=False, conf_required=False) self.buildplatformxml(ctrlnet) @@ -491,7 +491,7 @@ class EmaneManager(ModelManager): return # this generates a config message having controlnet prefix assignments - logger.info("Setting up default controlnet prefixes for distributed (%d configured)" % len(prefixes)) + logging.info("Setting up default controlnet prefixes for distributed (%d configured)" % len(prefixes)) prefixes = ctrlnet.DEFAULT_PREFIX_LIST[0] vals = 'controlnet="%s"' % prefixes tlvdata = "" @@ -510,21 +510,21 @@ class EmaneManager(ModelManager): """ for node_id in self._emane_nodes: emane_node = self._emane_nodes[node_id] - logger.debug("checking emane model for node: %s", node_id) + logging.debug("checking emane model for node: %s", node_id) # skip nodes that already have a model set if emane_node.model: - logger.debug("node(%s) already has model(%s)", emane_node.objid, emane_node.model.name) + logging.debug("node(%s) already has model(%s)", emane_node.objid, emane_node.model.name) continue # set model configured for node, due to legacy messaging configuration before nodes exist model_name = self.node_models.get(node_id) if not model_name: - logger.error("emane node(%s) has no node model", node_id) + logging.error("emane node(%s) has no node model", node_id) raise ValueError("emane node has no model set") config = self.get_model_config(node_id=node_id, model_name=model_name) - logger.debug("setting emane model(%s) config(%s)", model_name, config) + logging.debug("setting emane model(%s) config(%s)", model_name, config) model_class = self.models[model_name] emane_node.setmodel(model_class, config) @@ -603,7 +603,7 @@ class EmaneManager(ModelManager): try: group, port = self.get_config("eventservicegroup").split(":") except ValueError: - logger.exception("invalid eventservicegroup in EMANE config") + logging.exception("invalid eventservicegroup in EMANE config") return dev = self.get_config("eventservicedevice") @@ -615,12 +615,12 @@ class EmaneManager(ModelManager): Start one EMANE daemon per node having a radio. Add a control network even if the user has not configured one. """ - logger.info("starting emane daemons...") + logging.info("starting emane daemons...") loglevel = str(EmaneManager.DEFAULT_LOG_LEVEL) cfgloglevel = self.session.options.get_config_int("emane_log_level") realtime = self.session.options.get_config_bool("emane_realtime", default=True) if cfgloglevel: - logger.info("setting user-defined EMANE log level: %d", cfgloglevel) + logging.info("setting user-defined EMANE log level: %d", cfgloglevel) loglevel = str(cfgloglevel) emanecmd = ["emane", "-d", "-l", loglevel] @@ -647,11 +647,11 @@ class EmaneManager(ModelManager): self.session.add_remove_control_interface(node, 0, remove=False, conf_required=False) if otanetidx > 0: - logger.info("adding ota device ctrl%d", otanetidx) + logging.info("adding ota device ctrl%d", otanetidx) self.session.add_remove_control_interface(node, otanetidx, remove=False, conf_required=False) if eventservicenetidx >= 0: - logger.info("adding event service device ctrl%d", eventservicenetidx) + logging.info("adding event service device ctrl%d", eventservicenetidx) self.session.add_remove_control_interface(node, eventservicenetidx, remove=False, conf_required=False) # multicast route is needed for OTA data @@ -666,8 +666,8 @@ class EmaneManager(ModelManager): # start emane args = emanecmd + ["-f", os.path.join(path, "emane%d.log" % n), os.path.join(path, "platform%d.xml" % n)] output = node.check_cmd(args) - logger.info("node(%s) emane daemon running: %s", node.name, args) - logger.info("node(%s) emane daemon output: %s", node.name, output) + logging.info("node(%s) emane daemon running: %s", node.name, args) + logging.info("node(%s) emane daemon output: %s", node.name, output) if not run_emane_on_host: return @@ -676,7 +676,7 @@ class EmaneManager(ModelManager): emanecmd += ["-f", os.path.join(path, "emane.log")] args = emanecmd + [os.path.join(path, "platform.xml")] utils.check_cmd(args, cwd=path) - logger.info("host emane daemon running: %s", args) + logging.info("host emane daemon running: %s", args) def stopdaemons(self): """ @@ -699,7 +699,7 @@ class EmaneManager(ModelManager): utils.check_cmd(args) utils.check_cmd(["killall", "-q", "emanetransportd"]) except CoreCommandError: - logger.exception("error shutting down emane daemons") + logging.exception("error shutting down emane daemons") def installnetifs(self): """ @@ -708,7 +708,7 @@ class EmaneManager(ModelManager): """ for key in sorted(self._emane_nodes.keys()): emane_node = self._emane_nodes[key] - logger.info("emane install netifs for node: %d", key) + logging.info("emane install netifs for node: %d", key) emane_node.installnetifs() def deinstallnetifs(self): @@ -742,12 +742,12 @@ class EmaneManager(ModelManager): """ Start monitoring EMANE location events if configured to do so. """ - logger.info("emane start event monitor") + logging.info("emane start event monitor") if not self.doeventmonitor(): return if self.service is None: - logger.error("Warning: EMANE events will not be generated " + logging.error("Warning: EMANE events will not be generated " "because the emaneeventservice\n binding was " "unable to load " "(install the python-emaneeventservice bindings)") @@ -779,7 +779,7 @@ class EmaneManager(ModelManager): """ if self.service is None: return - logger.info("subscribing to EMANE location events. (%s)", threading.currentThread().getName()) + logging.info("subscribing to EMANE location events. (%s)", threading.currentThread().getName()) while self.doeventloop is True: _uuid, _seq, events = self.service.nextEvent() @@ -792,7 +792,7 @@ class EmaneManager(ModelManager): if eid == LocationEvent.IDENTIFIER: self.handlelocationevent(nem, eid, data) - logger.info("unsubscribing from EMANE location events. (%s)", threading.currentThread().getName()) + logging.info("unsubscribing from EMANE location events. (%s)", threading.currentThread().getName()) def handlelocationevent(self, rxnemid, eid, data): """ @@ -803,14 +803,14 @@ class EmaneManager(ModelManager): for event in events: txnemid, attrs = event if "latitude" not in attrs or "longitude" not in attrs or "altitude" not in attrs: - logger.warn("dropped invalid location event") + logging.warn("dropped invalid location event") continue # yaw,pitch,roll,azimuth,elevation,velocity are unhandled lat = attrs["latitude"] lon = attrs["longitude"] alt = attrs["altitude"] - logger.debug("emane location event: %s,%s,%s", lat, lon, alt) + logging.debug("emane location event: %s,%s,%s", lat, lon, alt) self.handlelocationeventtoxyz(txnemid, lat, lon, alt) def handlelocationeventtoxyz(self, nemid, lat, lon, alt): @@ -822,7 +822,7 @@ class EmaneManager(ModelManager): # convert nemid to node number _emanenode, netif = self.nemlookup(nemid) if netif is None: - logger.info("location event for unknown NEM %s", nemid) + logging.info("location event for unknown NEM %s", nemid) return False n = netif.node.objid @@ -831,12 +831,12 @@ class EmaneManager(ModelManager): x = int(x) y = int(y) z = int(z) - logger.info("location event NEM %s (%s, %s, %s) -> (%s, %s, %s)", nemid, lat, lon, alt, x, y, z) + logging.info("location event NEM %s (%s, %s, %s) -> (%s, %s, %s)", nemid, lat, lon, alt, x, y, z) xbit_check = x.bit_length() > 16 or x < 0 ybit_check = y.bit_length() > 16 or y < 0 zbit_check = z.bit_length() > 16 or z < 0 if any([xbit_check, ybit_check, zbit_check]): - logger.error("Unable to build node location message, received lat/long/alt exceeds coordinate " + logging.error("Unable to build node location message, received lat/long/alt exceeds coordinate " "space: NEM %s (%d, %d, %d)", nemid, x, y, z) return False @@ -844,7 +844,7 @@ class EmaneManager(ModelManager): try: node = self.session.get_object(n) except KeyError: - logger.exception("location event NEM %s has no corresponding node %s" % (nemid, n)) + logging.exception("location event NEM %s has no corresponding node %s" % (nemid, n)) return False # don"t use node.setposition(x,y,z) which generates an event diff --git a/daemon/core/emane/emanemanifest.py b/daemon/core/emane/emanemanifest.py index 40ac54cf..b07833c9 100644 --- a/daemon/core/emane/emanemanifest.py +++ b/daemon/core/emane/emanemanifest.py @@ -1,4 +1,5 @@ -from core import logger +import logging + from core.conf import Configuration from core.enumerations import ConfigDataTypes @@ -9,7 +10,7 @@ except ImportError: try: from emanesh import manifest except ImportError: - logger.debug("compatible emane python bindings not installed") + logging.debug("compatible emane python bindings not installed") def _type_value(config_type): diff --git a/daemon/core/emane/emanemodel.py b/daemon/core/emane/emanemodel.py index d1e5df22..284ef84a 100644 --- a/daemon/core/emane/emanemodel.py +++ b/daemon/core/emane/emanemodel.py @@ -1,9 +1,9 @@ """ Defines Emane Models used within CORE. """ +import logging import os -from core import logger from core.conf import ConfigGroup from core.conf import Configuration from core.emane import emanemanifest @@ -95,7 +95,7 @@ class EmaneModel(WirelessModel): :return: nothing """ - logger.info("emane model(%s) has no post setup tasks", self.name) + logging.info("emane model(%s) has no post setup tasks", self.name) def update(self, moved, moved_netifs): """ @@ -111,7 +111,7 @@ class EmaneModel(WirelessModel): wlan = self.session.get_object(self.object_id) wlan.setnempositions(moved_netifs) except KeyError: - logger.exception("error during update") + logging.exception("error during update") def linkconfig(self, netif, bw=None, delay=None, loss=None, duplicate=None, jitter=None, netif2=None): """ @@ -126,4 +126,4 @@ class EmaneModel(WirelessModel): :param core.netns.vif.Veth netif2: interface two :return: nothing """ - logger.warn("emane model(%s) does not support link configuration", self.name) + logging.warn("emane model(%s) does not support link configuration", self.name) diff --git a/daemon/core/emane/nodes.py b/daemon/core/emane/nodes.py index cde02611..b599d177 100644 --- a/daemon/core/emane/nodes.py +++ b/daemon/core/emane/nodes.py @@ -4,7 +4,8 @@ control of an EMANE emulation. An EmaneNode has several attached NEMs that share the same MAC+PHY model. """ -from core import logger +import logging + from core.coreobj import PyCoreNet from core.enumerations import LinkTypes from core.enumerations import NodeTypes @@ -16,7 +17,7 @@ except ImportError: try: from emanesh.events import LocationEvent except ImportError: - logger.debug("compatible emane python bindings not installed") + logging.debug("compatible emane python bindings not installed") class EmaneNet(PyCoreNet): @@ -68,14 +69,14 @@ class EmaneNode(EmaneNet): def updatemodel(self, config): if not self.model: raise ValueError("no model set to update for node(%s)", self.objid) - logger.info("node(%s) updating model(%s): %s", self.objid, self.model.name, config) + logging.info("node(%s) updating model(%s): %s", self.objid, self.model.name, config) self.model.set_configs(config, node_id=self.objid) def setmodel(self, model, config): """ set the EmaneModel associated with this node """ - logger.info("adding model: %s", model.name) + logging.info("adding model: %s", model.name) if model.config_type == RegisterTlvs.WIRELESS.value: # EmaneModel really uses values from ConfigurableManager # when buildnemxml() is called, not during init() @@ -126,7 +127,7 @@ class EmaneNode(EmaneNet): if self.session.emane.genlocationevents() and self.session.emane.service is None: warntxt = "unable to publish EMANE events because the eventservice " warntxt += "Python bindings failed to load" - logger.error(warntxt) + logging.error(warntxt) for netif in self.netifs(): external = self.session.emane.get_config("external", self.objid, self.model.name) @@ -159,15 +160,15 @@ class EmaneNode(EmaneNet): Publish a NEM location change event using the EMANE event service. """ if self.session.emane.service is None: - logger.info("position service not available") + logging.info("position service not available") return nemid = self.getnemid(netif) ifname = netif.localname if nemid is None: - logger.info("nemid for %s is unknown" % ifname) + logging.info("nemid for %s is unknown" % ifname) return lat, long, alt = self.session.location.getgeo(x, y, z) - logger.info("setnemposition %s (%s) x,y,z=(%d,%d,%s)(%.6f,%.6f,%.6f)", ifname, nemid, x, y, z, lat, long, alt) + logging.info("setnemposition %s (%s) x,y,z=(%d,%d,%s)(%.6f,%.6f,%.6f)", ifname, nemid, x, y, z, lat, long, alt) event = LocationEvent() # altitude must be an integer or warning is printed @@ -186,7 +187,7 @@ class EmaneNode(EmaneNet): return if self.session.emane.service is None: - logger.info("position service not available") + logging.info("position service not available") return event = LocationEvent() @@ -195,11 +196,11 @@ class EmaneNode(EmaneNet): nemid = self.getnemid(netif) ifname = netif.localname if nemid is None: - logger.info("nemid for %s is unknown" % ifname) + logging.info("nemid for %s is unknown" % ifname) continue x, y, z = netif.node.getposition() lat, long, alt = self.session.location.getgeo(x, y, z) - logger.info("setnempositions %d %s (%s) x,y,z=(%d,%d,%s)(%.6f,%.6f,%.6f)", + logging.info("setnempositions %d %s (%s) x,y,z=(%d,%d,%s)(%.6f,%.6f,%.6f)", i, ifname, nemid, x, y, z, lat, long, alt) # altitude must be an integer or warning is printed alt = int(round(alt)) diff --git a/daemon/core/emane/tdma.py b/daemon/core/emane/tdma.py index 1239182b..832f5d13 100644 --- a/daemon/core/emane/tdma.py +++ b/daemon/core/emane/tdma.py @@ -2,10 +2,10 @@ tdma.py: EMANE TDMA model bindings for CORE """ +import logging import os from core import constants -from core import logger from core.conf import Configuration from core.emane import emanemanifest from core.emane import emanemodel @@ -55,5 +55,5 @@ class EmaneTdmaModel(emanemodel.EmaneModel): event_device = self.session.emane.event_device # initiate tdma schedule - logger.info("setting up tdma schedule: schedule(%s) device(%s)", schedule, event_device) + logging.info("setting up tdma schedule: schedule(%s) device(%s)", schedule, event_device) utils.check_cmd(["emaneevent-tdmaschedule", "-i", event_device, schedule]) diff --git a/daemon/core/emulator/coreemu.py b/daemon/core/emulator/coreemu.py index a1a11787..d0b562cb 100644 --- a/daemon/core/emulator/coreemu.py +++ b/daemon/core/emulator/coreemu.py @@ -1,10 +1,10 @@ import atexit +import logging import os import signal import sys import core.services -from core import logger from core.coreobj import PyCoreNet from core.coreobj import PyCoreNode from core.data import NodeData @@ -28,7 +28,7 @@ def signal_handler(signal_number, _): :param _: ignored :return: nothing """ - logger.info("caught signal: %s", signal_number) + logging.info("caught signal: %s", signal_number) sys.exit(signal_number) @@ -142,7 +142,7 @@ class EmuSession(Session): :return: nodes, network nodes if present, and tunnel if present :rtype: tuple """ - logger.debug("link message between node1(%s) and node2(%s)", node_one_id, node_two_id) + logging.debug("link message between node1(%s) and node2(%s)", node_one_id, node_two_id) # values to fill net_one = None @@ -154,7 +154,7 @@ class EmuSession(Session): # both node ids are provided tunnel = self.broker.gettunnel(node_one_id, node_two_id) - logger.debug("tunnel between nodes: %s", tunnel) + logging.debug("tunnel between nodes: %s", tunnel) if nodeutils.is_node(tunnel, NodeTypes.TAP_BRIDGE): net_one = tunnel if tunnel.remotenum == node_one_id: @@ -182,7 +182,7 @@ class EmuSession(Session): net_two = node_two node_two = None - logger.debug("link node types n1(%s) n2(%s) net1(%s) net2(%s) tunnel(%s)", + logging.debug("link node types n1(%s) n2(%s) net1(%s) net2(%s) tunnel(%s)", node_one, node_two, net_one, net_two, tunnel) return node_one, node_two, net_one, net_two, tunnel @@ -198,17 +198,17 @@ class EmuSession(Session): objects = [x for x in objects if x] if len(objects) < 2: raise ValueError("wireless link failure: %s", objects) - logger.debug("handling wireless linking objects(%s) connect(%s)", objects, connect) + logging.debug("handling wireless linking objects(%s) connect(%s)", objects, connect) common_networks = objects[0].commonnets(objects[1]) if not common_networks: raise ValueError("no common network found for wireless link/unlink") for common_network, interface_one, interface_two in common_networks: if not nodeutils.is_node(common_network, [NodeTypes.WIRELESS_LAN, NodeTypes.EMANE]): - logger.info("skipping common network that is not wireless/emane: %s", common_network) + logging.info("skipping common network that is not wireless/emane: %s", common_network) continue - logger.info("wireless linking connect(%s): %s - %s", connect, interface_one, interface_two) + logging.info("wireless linking connect(%s): %s - %s", connect, interface_one, interface_two) if connect: common_network.link(interface_one, interface_two) else: @@ -242,27 +242,27 @@ class EmuSession(Session): else: # 2 nodes being linked, ptp network if all([node_one, node_two]) and not net_one: - logger.info("adding link for peer to peer nodes: %s - %s", node_one.name, node_two.name) + logging.info("adding link for peer to peer nodes: %s - %s", node_one.name, node_two.name) ptp_class = nodeutils.get_node_class(NodeTypes.PEER_TO_PEER) start = self.state > EventTypes.DEFINITION_STATE.value net_one = self.add_object(cls=ptp_class, start=start) # node to network if node_one and net_one: - logger.info("adding link from node to network: %s - %s", node_one.name, net_one.name) + logging.info("adding link from node to network: %s - %s", node_one.name, net_one.name) interface = create_interface(node_one, net_one, interface_one) link_config(net_one, interface, link_options) # network to node if node_two and net_one: - logger.info("adding link from network to node: %s - %s", node_two.name, net_one.name) + logging.info("adding link from network to node: %s - %s", node_two.name, net_one.name) interface = create_interface(node_two, net_one, interface_two) if not link_options.unidirectional: link_config(net_one, interface, link_options) # network to network if net_one and net_two: - logger.info("adding link from network to network: %s - %s", net_one.name, net_two.name) + logging.info("adding link from network to network: %s - %s", net_one.name, net_two.name) if nodeutils.is_node(net_two, NodeTypes.RJ45): interface = net_two.linknet(net_one) else: @@ -286,12 +286,12 @@ class EmuSession(Session): # tunnel node logic key = link_options.key if key and nodeutils.is_node(net_one, NodeTypes.TUNNEL): - logger.info("setting tunnel key for: %s", net_one.name) + logging.info("setting tunnel key for: %s", net_one.name) net_one.setkey(key) if addresses: net_one.addrconfig(addresses) if key and nodeutils.is_node(net_two, NodeTypes.TUNNEL): - logger.info("setting tunnel key for: %s", net_two.name) + logging.info("setting tunnel key for: %s", net_two.name) net_two.setkey(key) if addresses: net_two.addrconfig(addresses) @@ -299,12 +299,12 @@ class EmuSession(Session): # physical node connected with tunnel if not net_one and not net_two and (node_one or node_two): if node_one and nodeutils.is_node(node_one, NodeTypes.PHYSICAL): - logger.info("adding link for physical node: %s", node_one.name) + logging.info("adding link for physical node: %s", node_one.name) addresses = interface_one.get_addresses() node_one.adoptnetif(tunnel, interface_one.id, interface_one.mac, addresses) link_config(node_one, tunnel, link_options) elif node_two and nodeutils.is_node(node_two, NodeTypes.PHYSICAL): - logger.info("adding link for physical node: %s", node_two.name) + logging.info("adding link for physical node: %s", node_two.name) addresses = interface_two.get_addresses() node_two.adoptnetif(tunnel, interface_two.id, interface_two.mac, addresses) link_config(node_two, tunnel, link_options) @@ -360,7 +360,7 @@ class EmuSession(Session): if interface_one.net != interface_two.net and all([interface_one.up, interface_two.up]): raise ValueError("no common network found") - logger.info("deleting link node(%s):interface(%s) node(%s):interface(%s)", + logging.info("deleting link node(%s):interface(%s) node(%s):interface(%s)", node_one.name, interface_one.name, node_two.name, interface_two.name) net_one = interface_one.net interface_one.detachnet() @@ -470,7 +470,7 @@ class EmuSession(Session): try: node_class = nodeutils.get_node_class(_type) except KeyError: - logger.error("invalid node type to create: %s", _type) + logging.error("invalid node type to create: %s", _type) return None # set node start based on current session state, override and check when rj45 @@ -492,7 +492,7 @@ class EmuSession(Session): name = "%s%s" % (node_class.__name__, _id) # create node - logger.info("creating node(%s) id(%s) name(%s) start(%s)", node_class.__name__, _id, name, start) + logging.info("creating node(%s) id(%s) name(%s) start(%s)", node_class.__name__, _id, name, start) node = self.add_object(cls=node_class, objid=_id, name=name, start=start) # set node attributes @@ -506,7 +506,7 @@ class EmuSession(Session): # add services to default and physical nodes only if _type in [NodeTypes.DEFAULT, NodeTypes.PHYSICAL]: node.type = node_options.model - logger.debug("set node type: %s", node.type) + logging.debug("set node type: %s", node.type) self.services.add_services(node, node.type, node_options.services) # boot nodes if created after runtime, LcxNodes, Physical, and RJ45 are all PyCoreNodes @@ -542,7 +542,7 @@ class EmuSession(Session): # set node as updated successfully result = True except KeyError: - logger.error("failure to update node that does not exist: %s", node_id) + logging.error("failure to update node that does not exist: %s", node_id) return result @@ -620,7 +620,7 @@ class EmuSession(Session): :return: nothing """ - logger.info("session(%s) shutting down", self.session_id) + logging.info("session(%s) shutting down", self.session_id) self.set_state(EventTypes.DATACOLLECT_STATE, send_event=True) self.set_state(EventTypes.SHUTDOWN_STATE, send_event=True) super(EmuSession, self).shutdown() @@ -647,7 +647,7 @@ class EmuSession(Session): :return: True if active, False otherwise """ result = self.state in {EventTypes.RUNTIME_STATE.value, EventTypes.DATACOLLECT_STATE.value} - logger.info("session(%s) checking if active: %s", self.session_id, result) + logging.info("session(%s) checking if active: %s", self.session_id, result) return result def open_xml(self, file_name, start=False): @@ -813,7 +813,7 @@ class CoreEmu(object): # load custom services service_paths = self.config.get("custom_services_dir") - logger.debug("custom service paths: %s", service_paths) + logging.debug("custom service paths: %s", service_paths) if service_paths: for service_path in service_paths.split(','): service_path = service_path.strip() @@ -835,7 +835,7 @@ class CoreEmu(object): :return: nothing """ - logger.info("shutting down all sessions") + logging.info("shutting down all sessions") sessions = self.sessions.copy() self.sessions.clear() for session in sessions.itervalues(): @@ -860,7 +860,7 @@ class CoreEmu(object): break session = _cls(session_id, config=self.config) - logger.info("created session: %s", session_id) + logging.info("created session: %s", session_id) if master: session.master = True @@ -875,14 +875,14 @@ class CoreEmu(object): :return: True if deleted, False otherwise :rtype: bool """ - logger.info("deleting session: %s", _id) + logging.info("deleting session: %s", _id) session = self.sessions.pop(_id, None) result = False if session: - logger.info("shutting session down: %s", _id) + logging.info("shutting session down: %s", _id) session.shutdown() result = True else: - logger.error("session to delete did not exist: %s", _id) + logging.error("session to delete did not exist: %s", _id) return result diff --git a/daemon/core/location.py b/daemon/core/location.py index 6a64ad41..b95a8670 100644 --- a/daemon/core/location.py +++ b/daemon/core/location.py @@ -5,7 +5,8 @@ systems. Depends on utm contributed module, from https://pypi.python.org/pypi/utm (version 0.3.0). """ -from core import logger +import logging + from core.enumerations import RegisterTlvs from core.misc import utm @@ -117,7 +118,7 @@ class CoreLocation(object): try: lat, lon = utm.to_latlon(e, n, zone[0], zone[1]) except utm.OutOfRangeError: - logger.exception("UTM out of range error for n=%s zone=%s xyz=(%s,%s,%s)", n, zone, x, y, z) + logging.exception("UTM out of range error for n=%s zone=%s xyz=(%s,%s,%s)", n, zone, x, y, z) lat, lon = self.refgeo[:2] # self.info("getgeo(%s,%s,%s) e=%s n=%s zone=%s lat,lon,alt=" \ # "%.3f,%.3f,%.3f" % (x, y, z, e, n, zone, lat, lon, alt)) diff --git a/daemon/core/misc/ipaddress.py b/daemon/core/misc/ipaddress.py index fe1d894d..4da49642 100644 --- a/daemon/core/misc/ipaddress.py +++ b/daemon/core/misc/ipaddress.py @@ -2,14 +2,13 @@ Helper objects for dealing with IPv4/v6 addresses. """ +import logging import random import socket import struct from socket import AF_INET from socket import AF_INET6 -from core import logger - class MacAddress(object): """ @@ -151,7 +150,7 @@ class IpAddress(object): try: carry = int(other) except ValueError: - logger.exception("error during addition") + logging.exception("error during addition") return NotImplemented tmp = [ord(x) for x in self.addr] @@ -174,7 +173,7 @@ class IpAddress(object): try: tmp = -int(other) except ValueError: - logger.exception("error during subtraction") + logging.exception("error during subtraction") return NotImplemented return self.__add__(tmp) @@ -276,7 +275,7 @@ class IpPrefix(object): try: tmp = int(other) except ValueError: - logger.exception("error during addition") + logging.exception("error during addition") return NotImplemented a = IpAddress(self.af, self.prefix) + (tmp << (self.addrlen - self.prefixlen)) @@ -297,7 +296,7 @@ class IpPrefix(object): try: tmp = -int(other) except ValueError: - logger.exception("error during subtraction") + logging.exception("error during subtraction") return NotImplemented return self.__add__(tmp) diff --git a/daemon/core/misc/nodeutils.py b/daemon/core/misc/nodeutils.py index b6e8bb5e..645c0543 100644 --- a/daemon/core/misc/nodeutils.py +++ b/daemon/core/misc/nodeutils.py @@ -2,7 +2,7 @@ Serves as a global point for storing and retrieving node types needed during simulation. """ -from core import logger +import logging _NODE_MAP = None @@ -13,7 +13,7 @@ def _log_map(): name = None if value: name = value.__name__ - logger.debug("node type (%s) - class (%s)", key.name, name) + logging.debug("node type (%s) - class (%s)", key.name, name) def _convert_map(x, y): diff --git a/daemon/core/misc/structutils.py b/daemon/core/misc/structutils.py index fe0f8d9c..cfcc7a93 100644 --- a/daemon/core/misc/structutils.py +++ b/daemon/core/misc/structutils.py @@ -2,7 +2,7 @@ Utilities for working with python struct data. """ -from core import logger +import logging def pack_values(clazz, packers): @@ -40,7 +40,7 @@ def pack_values(clazz, packers): value = transformer(value) # pack and add to existing data - logger.debug("packing: %s - %s", tlv_type, value) + logging.debug("packing: %s - %s", tlv_type, value) data += clazz.pack(tlv_type.value, value) return data diff --git a/daemon/core/misc/utils.py b/daemon/core/misc/utils.py index 10e6192f..0aadd5fe 100644 --- a/daemon/core/misc/utils.py +++ b/daemon/core/misc/utils.py @@ -4,6 +4,7 @@ Miscellaneous utility functions, wrappers around some subprocess procedures. import importlib import inspect +import logging import os import shlex import subprocess @@ -12,7 +13,6 @@ import sys import fcntl from core import CoreCommandError -from core import logger DEVNULL = open(os.devnull, "wb") @@ -179,7 +179,7 @@ def cmd(args, wait=True): :rtype: int """ args = split_args(args) - logger.debug("command: %s", args) + logging.debug("command: %s", args) try: p = subprocess.Popen(args) if not wait: @@ -200,7 +200,7 @@ def cmd_output(args): :raises CoreCommandError: when the file to execute is not found """ args = split_args(args) - logger.debug("command: %s", args) + logging.debug("command: %s", args) try: p = subprocess.Popen(args, stdout=subprocess.PIPE, stderr=subprocess.STDOUT) stdout, _ = p.communicate() @@ -224,7 +224,7 @@ def check_cmd(args, **kwargs): kwargs["stdout"] = subprocess.PIPE kwargs["stderr"] = subprocess.STDOUT args = split_args(args) - logger.debug("command: %s", args) + logging.debug("command: %s", args) try: p = subprocess.Popen(args, **kwargs) stdout, _ = p.communicate() @@ -362,7 +362,7 @@ def load_config(filename, d): key, value = line.split("=", 1) d[key] = value.strip() except ValueError: - logger.exception("error reading file to dict: %s", filename) + logging.exception("error reading file to dict: %s", filename) def load_classes(path, clazz): @@ -374,13 +374,13 @@ def load_classes(path, clazz): :return: list of classes loaded """ # validate path exists - logger.debug("attempting to load modules from path: %s", path) + logging.debug("attempting to load modules from path: %s", path) if not os.path.isdir(path): - logger.warn("invalid custom module directory specified" ": %s" % path) + logging.warn("invalid custom module directory specified" ": %s" % path) # check if path is in sys.path parent_path = os.path.dirname(path) if parent_path not in sys.path: - logger.debug("adding parent path to allow imports: %s", parent_path) + logging.debug("adding parent path to allow imports: %s", parent_path) sys.path.append(parent_path) # retrieve potential service modules, and filter out invalid modules @@ -393,7 +393,7 @@ def load_classes(path, clazz): classes = [] for module_name in module_names: import_statement = "%s.%s" % (base_module, module_name) - logger.debug("importing custom module: %s", import_statement) + logging.debug("importing custom module: %s", import_statement) try: module = importlib.import_module(import_statement) members = inspect.getmembers(module, lambda x: _is_class(module, x, clazz)) @@ -401,6 +401,6 @@ def load_classes(path, clazz): valid_class = member[1] classes.append(valid_class) except: - logger.exception("unexpected error during import, skipping: %s", import_statement) + logging.exception("unexpected error during import, skipping: %s", import_statement) return classes diff --git a/daemon/core/mobility.py b/daemon/core/mobility.py index 0d935fd4..e8bb747d 100644 --- a/daemon/core/mobility.py +++ b/daemon/core/mobility.py @@ -3,12 +3,12 @@ mobility.py: mobility helpers for moving nodes and calculating wireless range. """ import heapq +import logging import math import os import threading import time -from core import logger from core.conf import ConfigGroup from core.conf import ConfigurableOptions from core.conf import Configuration @@ -63,13 +63,13 @@ class MobilityManager(ModelManager): node_ids = self.nodes() for node_id in node_ids: - logger.info("checking mobility startup for node: %s", node_id) - logger.info("node mobility configurations: %s", self.get_all_configs(node_id)) + logging.info("checking mobility startup for node: %s", node_id) + logging.info("node mobility configurations: %s", self.get_all_configs(node_id)) try: node = self.session.get_object(node_id) except KeyError: - logger.warn("skipping mobility configuration for unknown node: %s", node_id) + logging.warn("skipping mobility configuration for unknown node: %s", node_id) continue for model_name in self.models.iterkeys(): @@ -100,7 +100,7 @@ class MobilityManager(ModelManager): try: node = self.session.get_object(node_id) except KeyError: - logger.exception("Ignoring event for model '%s', unknown node '%s'", name, node_id) + logging.exception("Ignoring event for model '%s', unknown node '%s'", name, node_id) return # name is e.g. "mobility:ns2script" @@ -109,7 +109,7 @@ class MobilityManager(ModelManager): try: cls = self.models[model] except KeyError: - logger.warn("Ignoring event for unknown model '%s'", model) + logging.warn("Ignoring event for unknown model '%s'", model) continue if cls.config_type in [RegisterTlvs.WIRELESS.value, RegisterTlvs.MOBILITY.value]: @@ -118,11 +118,11 @@ class MobilityManager(ModelManager): continue if model is None: - logger.warn("Ignoring event, %s has no model", node.name) + logging.warn("Ignoring event, %s has no model", node.name) continue if cls.name != model.name: - logger.warn("Ignoring event for %s wrong model %s,%s", node.name, cls.name, model.name) + logging.warn("Ignoring event for %s wrong model %s,%s", node.name, cls.name, model.name) continue if event_type == EventTypes.STOP.value or event_type == EventTypes.RESTART.value: @@ -232,7 +232,7 @@ class MobilityManager(ModelManager): nodeypos = message.get_tlv(NodeTlvs.Y_POSITION.value) dummy.setposition(nodexpos, nodeypos, None) except KeyError: - logger.exception("error retrieving physical node: %s", nodenum) + logging.exception("error retrieving physical node: %s", nodenum) def installphysnodes(self, net): """ @@ -358,7 +358,7 @@ class BasicRangeModel(WirelessModel): :return: nothing """ self.range = float(config["range"]) - logger.info("basic range model configured for WLAN %d using range %d", self.wlan.objid, self.range) + logging.info("basic range model configured for WLAN %d using range %d", self.wlan.objid, self.range) self.bw = int(config["bandwidth"]) if self.bw == 0.0: self.bw = None @@ -467,20 +467,20 @@ class BasicRangeModel(WirelessModel): with self.wlan._linked_lock: linked = self.wlan.linked(a, b) - logger.debug("checking range netif1(%s) netif2(%s): linked(%s) actual(%s) > config(%s)", + logging.debug("checking range netif1(%s) netif2(%s): linked(%s) actual(%s) > config(%s)", a.name, b.name, linked, d, self.range) if d > self.range: if linked: - logger.debug("was linked, unlinking") + logging.debug("was linked, unlinking") self.wlan.unlink(a, b) self.sendlinkmsg(a, b, unlink=True) else: if not linked: - logger.debug("was not linked, linking") + logging.debug("was not linked, linking") self.wlan.link(a, b) self.sendlinkmsg(a, b) except KeyError: - logger.exception("error getting interfaces during calclinkS") + logging.exception("error getting interfaces during calclinkS") @staticmethod def calcdistance(p1, p2): @@ -689,7 +689,7 @@ class WayPointMobility(WirelessModel): :return: nothing """ - logger.info("running mobility scenario") + logging.info("running mobility scenario") self.timezero = time.time() self.lasttime = self.timezero - (0.001 * self.refresh_ms) self.movenodesinitial() @@ -947,7 +947,7 @@ class Ns2ScriptedMobility(WayPointMobility): def update_config(self, config): self.file = config["file"] - logger.info("ns-2 scripted mobility configured for WLAN %d using file: %s", self.object_id, self.file) + logging.info("ns-2 scripted mobility configured for WLAN %d using file: %s", self.object_id, self.file) self.refresh_ms = int(config["refresh_ms"]) self.loop = config["loop"].lower() == "on" self.autostart = config["autostart"] @@ -971,9 +971,9 @@ class Ns2ScriptedMobility(WayPointMobility): try: f = open(filename, "r") except IOError: - logger.exception("ns-2 scripted mobility failed to load file: %s", self.file) + logging.exception("ns-2 scripted mobility failed to load file: %s", self.file) return - logger.info("reading ns-2 script file: %s" % filename) + logging.info("reading ns-2 script file: %s" % filename) ln = 0 ix = iy = iz = None inodenum = None @@ -1017,7 +1017,7 @@ class Ns2ScriptedMobility(WayPointMobility): else: raise ValueError except ValueError: - logger.exception("skipping line %d of file %s '%s'", ln, self.file, line) + logging.exception("skipping line %d of file %s '%s'", ln, self.file, line) continue if ix is not None and iy is not None: self.addinitial(self.map(inodenum), ix, iy, iz) @@ -1067,7 +1067,7 @@ class Ns2ScriptedMobility(WayPointMobility): raise ValueError self.nodemap[int(parts[0])] = int(parts[1]) except ValueError: - logger.exception("ns-2 mobility node map error") + logging.exception("ns-2 mobility node map error") def map(self, nodenum): """ @@ -1090,15 +1090,15 @@ class Ns2ScriptedMobility(WayPointMobility): :return: nothing """ if self.autostart == '': - logger.info("not auto-starting ns-2 script for %s" % self.wlan.name) + logging.info("not auto-starting ns-2 script for %s" % self.wlan.name) return try: t = float(self.autostart) except ValueError: - logger.exception("Invalid auto-start seconds specified '%s' for %s", self.autostart, self.wlan.name) + logging.exception("Invalid auto-start seconds specified '%s' for %s", self.autostart, self.wlan.name) return self.movenodesinitial() - logger.info("scheduling ns-2 script for %s autostart at %s" % (self.wlan.name, t)) + logging.info("scheduling ns-2 script for %s autostart at %s" % (self.wlan.name, t)) self.state = self.STATE_RUNNING self.session.event_loop.add_event(t, self.run) @@ -1108,7 +1108,7 @@ class Ns2ScriptedMobility(WayPointMobility): :return: nothing """ - logger.info("starting script") + logging.info("starting script") laststate = self.state super(Ns2ScriptedMobility, self).start() if laststate == self.STATE_PAUSED: diff --git a/daemon/core/netns/nodes.py b/daemon/core/netns/nodes.py index dd0994f1..4f9b4a51 100644 --- a/daemon/core/netns/nodes.py +++ b/daemon/core/netns/nodes.py @@ -3,6 +3,7 @@ Definition of LxcNode, CoreNode, and other node classes that inherit from the Co implementing specific node types. """ +import logging import socket import threading from socket import AF_INET @@ -10,7 +11,6 @@ from socket import AF_INET6 from core import CoreCommandError from core import constants -from core import logger from core.coreobj import PyCoreNetIf from core.coreobj import PyCoreNode from core.coreobj import PyCoreObj @@ -80,15 +80,15 @@ class CtrlNet(LxBrNet): else: addr = self.prefix.max_addr() - logger.info("added control network bridge: %s %s", self.brname, self.prefix) + logging.info("added control network bridge: %s %s", self.brname, self.prefix) if self.assign_address: addrlist = ["%s/%s" % (addr, self.prefix.prefixlen)] self.addrconfig(addrlist=addrlist) - logger.info("address %s", addr) + logging.info("address %s", addr) if self.updown_script: - logger.info("interface %s updown script (%s startup) called", self.brname, self.updown_script) + logging.info("interface %s updown script (%s startup) called", self.brname, self.updown_script) utils.check_cmd([self.updown_script, self.brname, "startup"]) if self.serverintf: @@ -108,7 +108,7 @@ class CtrlNet(LxBrNet): """ status, output = utils.cmd_output([constants.BRCTL_BIN, "show"]) if status != 0: - logger.error("Unable to retrieve list of installed bridges") + logging.error("Unable to retrieve list of installed bridges") else: lines = output.split("\n") for line in lines[1:]: @@ -117,7 +117,7 @@ class CtrlNet(LxBrNet): flds = cols[0].split(".") if len(flds) == 3: if flds[0] == "b" and flds[1] == self.objid: - logger.error( + logging.error( "error: An active control net bridge (%s) found. " "An older session might still be running. " "Stop all sessions and, if needed, delete %s to continue.", oldbr, oldbr @@ -135,14 +135,14 @@ class CtrlNet(LxBrNet): try: utils.check_cmd([constants.BRCTL_BIN, "delif", self.brname, self.serverintf]) except CoreCommandError: - logger.exception("error deleting server interface %s from bridge %s", self.serverintf, self.brname) + logging.exception("error deleting server interface %s from bridge %s", self.serverintf, self.brname) if self.updown_script is not None: try: - logger.info("interface %s updown script (%s shutdown) called", self.brname, self.updown_script) + logging.info("interface %s updown script (%s shutdown) called", self.brname, self.updown_script) utils.check_cmd([self.updown_script, self.brname, "shutdown"]) except CoreCommandError: - logger.exception("error issuing shutdown script shutdown") + logging.exception("error issuing shutdown script shutdown") LxBrNet.shutdown(self) @@ -383,7 +383,7 @@ class WlanNode(LxBrNet): :param dict config: configuration for model being set :return: nothing """ - logger.info("adding model: %s", model.name) + logging.info("adding model: %s", model.name) if model.config_type == RegisterTlvs.WIRELESS.value: self.model = model(session=self.session, object_id=self.objid) self.model.update_config(config) @@ -406,7 +406,7 @@ class WlanNode(LxBrNet): def updatemodel(self, config): if not self.model: raise ValueError("no model set to update for node(%s)", self.objid) - logger.info("node(%s) updating model(%s): %s", self.objid, self.model.name, config) + logging.info("node(%s) updating model(%s): %s", self.objid, self.model.name, config) self.model.set_configs(config, node_id=self.objid) if self.model.position_callback: for netif in self.netifs(): @@ -492,7 +492,7 @@ class RJ45Node(PyCoreNode, PyCoreNetIf): utils.check_cmd([constants.IP_BIN, "addr", "flush", "dev", self.localname]) utils.check_cmd([constants.TC_BIN, "qdisc", "del", "dev", self.localname, "root"]) except CoreCommandError: - logger.exception("error shutting down") + logging.exception("error shutting down") self.up = False self.restorestate() diff --git a/daemon/core/netns/openvswitch.py b/daemon/core/netns/openvswitch.py index 91f5ed16..c0b86d0a 100644 --- a/daemon/core/netns/openvswitch.py +++ b/daemon/core/netns/openvswitch.py @@ -2,6 +2,7 @@ TODO: probably goes away, or implement the usage of "unshare", or docker formal. """ +import logging import socket import threading from socket import AF_INET @@ -9,7 +10,6 @@ from socket import AF_INET6 from core import CoreCommandError from core import constants -from core import logger from core.coreobj import PyCoreNet from core.data import LinkData from core.enumerations import LinkTypes @@ -100,7 +100,7 @@ class OvsNet(PyCoreNet): def shutdown(self): if not self.up: - logger.info("exiting shutdown, object is not up") + logging.info("exiting shutdown, object is not up") return ebtables_queue.stopupdateloop(self) @@ -113,7 +113,7 @@ class OvsNet(PyCoreNet): [constants.EBTABLES_BIN, "-X", self.bridge_name] ]) except CoreCommandError: - logger.exception("error bringing bridge down and removing it") + logging.exception("error bringing bridge down and removing it") # removes veth pairs used for bridge-to-bridge connections for interface in self.netifs(): @@ -206,7 +206,7 @@ class OvsNet(PyCoreNet): burst = max(2 * netif.mtu, bw / 1000) limit = 0xffff # max IP payload tbf = ["tbf", "rate", str(bw), "burst", str(burst), "limit", str(limit)] - logger.info("linkconfig: %s" % [tc + parent + ["handle", "1:"] + tbf]) + logging.info("linkconfig: %s" % [tc + parent + ["handle", "1:"] + tbf]) utils.check_cmd(tc + parent + ["handle", "1:"] + tbf) netif.setparam("has_tbf", True) elif netif.getparam("has_tbf") and bw <= 0: @@ -262,12 +262,12 @@ class OvsNet(PyCoreNet): tc[2] = "delete" if self.up: - logger.info("linkconfig: %s" % ([tc + parent + ["handle", "10:"]],)) + logging.info("linkconfig: %s" % ([tc + parent + ["handle", "10:"]],)) utils.check_cmd(tc + parent + ["handle", "10:"]) netif.setparam("has_netem", False) elif len(netem) > 1: if self.up: - logger.info("linkconfig: %s" % ([tc + parent + ["handle", "10:"] + netem],)) + logging.info("linkconfig: %s" % ([tc + parent + ["handle", "10:"] + netem],)) utils.check_cmd(tc + parent + ["handle", "10:"] + netem) netif.setparam("has_netem", True) @@ -373,10 +373,10 @@ class OvsCtrlNet(OvsNet): if self.assign_address: self.addrconfig(addresses=addresses) message += " address %s" % addr - logger.info(message) + logging.info(message) if self.updown_script: - logger.info("interface %s updown script %s startup called" % (self.bridge_name, self.updown_script)) + logging.info("interface %s updown script %s startup called" % (self.bridge_name, self.updown_script)) utils.check_cmd([self.updown_script, self.bridge_name, "startup"]) if self.serverintf: @@ -395,7 +395,7 @@ class OvsCtrlNet(OvsNet): for line in output.split("\n"): bride_name = line.split(".") if bride_name[0] == "b" and bride_name[1] == self.objid: - logger.error("older session may still be running with conflicting id for bridge: %s", line) + logging.error("older session may still be running with conflicting id for bridge: %s", line) return True return False @@ -405,15 +405,15 @@ class OvsCtrlNet(OvsNet): try: utils.check_cmd([constants.OVS_BIN, "del-port", self.bridge_name, self.serverintf]) except CoreCommandError: - logger.exception("error deleting server interface %s to controlnet bridge %s", + logging.exception("error deleting server interface %s to controlnet bridge %s", self.serverintf, self.bridge_name) if self.updown_script: try: - logger.info("interface %s updown script (%s shutdown) called", self.bridge_name, self.updown_script) + logging.info("interface %s updown script (%s shutdown) called", self.bridge_name, self.updown_script) utils.check_cmd([self.updown_script, self.bridge_name, "shutdown"]) except CoreCommandError: - logger.exception("error during updown script shutdown") + logging.exception("error during updown script shutdown") OvsNet.shutdown(self) @@ -595,7 +595,7 @@ class OvsWlanNode(OvsNet): """ Mobility and wireless model. """ - logger.info("adding model %s", model.name) + logging.info("adding model %s", model.name) if model.type == RegisterTlvs.WIRELESS.value: self.model = model(session=self.session, object_id=self.objid, config=config) @@ -612,7 +612,7 @@ class OvsWlanNode(OvsNet): def updatemodel(self, config): if not self.model: raise ValueError("no model set to update for node(%s)", self.objid) - logger.info("node(%s) updating model(%s): %s", self.objid, self.model.name, config) + logging.info("node(%s) updating model(%s): %s", self.objid, self.model.name, config) self.model.set_configs(config, node_id=self.objid) if self.model.position_callback: for netif in self.netifs(): diff --git a/daemon/core/netns/vif.py b/daemon/core/netns/vif.py index 5a6653e4..8b224c1e 100644 --- a/daemon/core/netns/vif.py +++ b/daemon/core/netns/vif.py @@ -2,11 +2,11 @@ virtual ethernet classes that implement the interfaces available under Linux. """ +import logging import time from core import CoreCommandError from core import constants -from core import logger from core.coreobj import PyCoreNetIf from core.enumerations import NodeTypes from core.misc import nodeutils @@ -65,13 +65,13 @@ class VEth(PyCoreNetIf): try: self.node.check_cmd([constants.IP_BIN, "-6", "addr", "flush", "dev", self.name]) except CoreCommandError: - logger.exception("error shutting down interface") + logging.exception("error shutting down interface") if self.localname: try: utils.check_cmd([constants.IP_BIN, "link", "delete", self.localname]) except CoreCommandError: - logger.exception("error deleting link") + logging.exception("error deleting link") self.up = False @@ -126,7 +126,7 @@ class TunTap(PyCoreNetIf): try: self.node.check_cmd([constants.IP_BIN, "-6", "addr", "flush", "dev", self.name]) except CoreCommandError: - logger.exception("error shutting down tunnel tap") + logging.exception("error shutting down tunnel tap") self.up = False @@ -150,14 +150,14 @@ class TunTap(PyCoreNetIf): msg = "attempt %s failed with nonzero exit status %s" % (i, r) if i < attempts + 1: msg += ", retrying..." - logger.info(msg) + logging.info(msg) time.sleep(delay) delay += delay if delay > maxretrydelay: delay = maxretrydelay else: msg += ", giving up" - logger.info(msg) + logging.info(msg) return result @@ -169,7 +169,7 @@ class TunTap(PyCoreNetIf): :return: wait for device local response :rtype: int """ - logger.debug("waiting for device local: %s", self.localname) + logging.debug("waiting for device local: %s", self.localname) def localdevexists(): args = [constants.IP_BIN, "link", "show", self.localname] @@ -183,7 +183,7 @@ class TunTap(PyCoreNetIf): :return: nothing """ - logger.debug("waiting for device node: %s", self.name) + logging.debug("waiting for device node: %s", self.name) def nodedevexists(): args = [constants.IP_BIN, "link", "show", self.name] @@ -300,7 +300,7 @@ class GreTap(PyCoreNetIf): args = [constants.IP_BIN, "link", "del", self.localname] utils.check_cmd(args) except CoreCommandError: - logger.exception("error during shutdown") + logging.exception("error during shutdown") self.localname = None diff --git a/daemon/core/netns/vnet.py b/daemon/core/netns/vnet.py index 070c0b70..55dc855d 100644 --- a/daemon/core/netns/vnet.py +++ b/daemon/core/netns/vnet.py @@ -3,13 +3,13 @@ PyCoreNet and LxBrNet classes that implement virtual networks using Linux Ethernet bridging and ebtables rules. """ +import logging import os import threading import time from core import CoreCommandError from core import constants -from core import logger from core.coreobj import PyCoreNet from core.misc import utils from core.netns.vif import GreTap @@ -80,7 +80,7 @@ class EbtablesQueue(object): try: del self.last_update_time[wlan] except KeyError: - logger.exception("error deleting last update time for wlan, ignored before: %s", wlan) + logging.exception("error deleting last update time for wlan, ignored before: %s", wlan) if len(self.last_update_time) > 0: return @@ -181,7 +181,7 @@ class EbtablesQueue(object): try: os.unlink(self.atomic_file) except OSError: - logger.exception("error removing atomic file: %s", self.atomic_file) + logging.exception("error removing atomic file: %s", self.atomic_file) def ebchange(self, wlan): """ @@ -310,7 +310,7 @@ class LxBrNet(PyCoreNet): [constants.EBTABLES_BIN, "-X", self.brname] ]) except CoreCommandError: - logger.exception("error during shutdown") + logging.exception("error during shutdown") # removes veth pairs used for bridge-to-bridge connections for netif in self.netifs(): @@ -438,7 +438,7 @@ class LxBrNet(PyCoreNet): "burst", str(burst), "limit", str(limit)] if bw > 0: if self.up: - logger.debug("linkconfig: %s" % ([tc + parent + ["handle", "1:"] + tbf],)) + logging.debug("linkconfig: %s" % ([tc + parent + ["handle", "1:"] + tbf],)) utils.check_cmd(tc + parent + ["handle", "1:"] + tbf) netif.setparam("has_tbf", True) changed = True @@ -483,12 +483,12 @@ class LxBrNet(PyCoreNet): return tc[2] = "delete" if self.up: - logger.debug("linkconfig: %s" % ([tc + parent + ["handle", "10:"]],)) + logging.debug("linkconfig: %s" % ([tc + parent + ["handle", "10:"]],)) utils.check_cmd(tc + parent + ["handle", "10:"]) netif.setparam("has_netem", False) elif len(netem) > 1: if self.up: - logger.debug("linkconfig: %s" % ([tc + parent + ["handle", "10:"] + netem],)) + logging.debug("linkconfig: %s" % ([tc + parent + ["handle", "10:"] + netem],)) utils.check_cmd(tc + parent + ["handle", "10:"] + netem) netif.setparam("has_netem", True) diff --git a/daemon/core/netns/vnode.py b/daemon/core/netns/vnode.py index d2850275..3c41e33a 100644 --- a/daemon/core/netns/vnode.py +++ b/daemon/core/netns/vnode.py @@ -3,6 +3,7 @@ PyCoreNode and LxcNode classes that implement the network namespac virtual node. """ import errno +import logging import os import random import shutil @@ -12,7 +13,6 @@ import threading from core import CoreCommandError from core import constants -from core import logger from core.coreobj import PyCoreNetIf from core.coreobj import PyCoreNode from core.enumerations import NodeTypes @@ -107,11 +107,11 @@ class SimpleLxcNode(PyCoreNode): self.client = vnodeclient.VnodeClient(self.name, self.ctrlchnlname) # bring up the loopback interface - logger.debug("bringing up loopback interface") + logging.debug("bringing up loopback interface") self.check_cmd([constants.IP_BIN, "link", "set", "lo", "up"]) # set hostname for node - logger.debug("setting hostname: %s", self.name) + logging.debug("setting hostname: %s", self.name) self.check_cmd(["hostname", self.name]) # mark node as up @@ -141,7 +141,7 @@ class SimpleLxcNode(PyCoreNode): os.waitpid(self.pid, 0) except OSError as e: if e.errno != 10: - logger.exception("error killing process") + logging.exception("error killing process") # remove node directory if present try: @@ -149,7 +149,7 @@ class SimpleLxcNode(PyCoreNode): except OSError as e: # no such file or directory if e.errno != errno.ENOENT: - logger.exception("error removing node directory") + logging.exception("error removing node directory") # clear interface data, close client, and mark self and not up self._netif.clear() @@ -207,7 +207,7 @@ class SimpleLxcNode(PyCoreNode): :raises CoreCommandError: when a non-zero exit status occurs """ source = os.path.abspath(source) - logger.info("node(%s) mounting: %s at %s", self.name, source, target) + logging.info("node(%s) mounting: %s at %s", self.name, source, target) cmd = 'mkdir -p "%s" && %s -n --bind "%s" "%s"' % (target, constants.MOUNT_BIN, source, target) status, output = self.client.shcmd_result(cmd) if status: @@ -267,12 +267,12 @@ class SimpleLxcNode(PyCoreNode): # TODO: potentially find better way to query interface ID # retrieve interface information output = self.check_cmd(["ip", "link", "show", veth.name]) - logger.debug("interface command output: %s", output) + logging.debug("interface command output: %s", output) output = output.split("\n") veth.flow_id = int(output[0].strip().split(":")[0]) + 1 - logger.debug("interface flow index: %s - %s", veth.name, veth.flow_id) + logging.debug("interface flow index: %s - %s", veth.name, veth.flow_id) veth.hwaddr = MacAddress.from_string(output[1].strip().split()[1]) - logger.debug("interface mac: %s - %s", veth.name, veth.hwaddr) + logging.debug("interface mac: %s - %s", veth.name, veth.hwaddr) try: self.addnetif(veth, ifindex) @@ -359,7 +359,7 @@ class SimpleLxcNode(PyCoreNode): try: self._netif[ifindex].deladdr(addr) except ValueError: - logger.exception("trying to delete unknown address: %s" % addr) + logging.exception("trying to delete unknown address: %s" % addr) if self.up: self.check_cmd([constants.IP_BIN, "addr", "del", str(addr), "dev", self.ifname(ifindex)]) @@ -475,7 +475,7 @@ class SimpleLxcNode(PyCoreNode): :return: nothing :raises CoreCommandError: when a non-zero exit status occurs """ - logger.info("adding file from %s to %s", srcname, filename) + logging.info("adding file from %s to %s", srcname, filename) directory = os.path.dirname(filename) cmd = 'mkdir -p "%s" && mv "%s" "%s" && sync' % (directory, srcname, filename) @@ -530,7 +530,7 @@ class LxcNode(SimpleLxcNode): try: super(LxcNode, self).shutdown() except OSError: - logger.exception("error during shutdown") + logging.exception("error during shutdown") finally: self.rmnodedir() @@ -590,7 +590,7 @@ class LxcNode(SimpleLxcNode): with self.opennodefile(filename, "w") as open_file: open_file.write(contents) os.chmod(open_file.name, mode) - logger.info("node(%s) added file: %s; mode: 0%o", self.name, open_file.name, mode) + logging.info("node(%s) added file: %s; mode: 0%o", self.name, open_file.name, mode) def nodefilecopy(self, filename, srcfilename, mode=None): """ @@ -606,4 +606,4 @@ class LxcNode(SimpleLxcNode): shutil.copy2(srcfilename, hostfilename) if mode is not None: os.chmod(hostfilename, mode) - logger.info("node(%s) copied file: %s; mode: %s", self.name, hostfilename, mode) + logging.info("node(%s) copied file: %s; mode: %s", self.name, hostfilename, mode) diff --git a/daemon/core/netns/vnodeclient.py b/daemon/core/netns/vnodeclient.py index 5d05d955..11669a59 100644 --- a/daemon/core/netns/vnodeclient.py +++ b/daemon/core/netns/vnodeclient.py @@ -5,13 +5,13 @@ The control channel can be accessed via calls to the vcmd Python module or by invoking the vcmd shell command. """ +import logging import os import vcmd from core import CoreCommandError from core import constants -from core import logger from core.misc import utils @@ -158,7 +158,7 @@ class VnodeClient(object): # wait for and return exit status status = p.wait() if status: - logger.warn("cmd exited with status %s: %s", status, args) + logging.warn("cmd exited with status %s: %s", status, args) return status def term(self, sh="/bin/sh"): @@ -236,16 +236,16 @@ class VnodeClient(object): elif line[3] == "link": interface["inet6link"].append(line[1]) else: - logger.warn("unknown scope: %s" % line[3]) + logging.warn("unknown scope: %s" % line[3]) err = stderr.read() stdout.close() stderr.close() status = p.wait() if status: - logger.warn("nonzero exist status (%s) for cmd: %s", status, args) + logging.warn("nonzero exist status (%s) for cmd: %s", status, args) if err: - logger.warn("error output: %s", err) + logging.warn("error output: %s", err) self._addr[ifname] = interface return interface @@ -285,9 +285,9 @@ class VnodeClient(object): stderr.close() status = p.wait() if status: - logger.warn("nonzero exist status (%s) for cmd: %s", status, args) + logging.warn("nonzero exist status (%s) for cmd: %s", status, args) if err: - logger.warn("error output: %s", err) + logging.warn("error output: %s", err) if ifname is not None: return stats[ifname] else: diff --git a/daemon/core/phys/pnodes.py b/daemon/core/phys/pnodes.py index 2ee77233..08b892e7 100644 --- a/daemon/core/phys/pnodes.py +++ b/daemon/core/phys/pnodes.py @@ -2,13 +2,13 @@ PhysicalNode class for including real systems in the emulated network. """ +import logging import os import subprocess import threading from core import CoreCommandError from core import constants -from core import logger from core.coreobj import PyCoreNode from core.misc import utils from core.netns.vnet import GreTap @@ -121,7 +121,7 @@ class PhysicalNode(PyCoreNode): try: self._netif[ifindex].deladdr(addr) except ValueError: - logger.exception("trying to delete unknown address: %s", addr) + logging.exception("trying to delete unknown address: %s", addr) if self.up: self.check_cmd([constants.IP_BIN, "addr", "del", str(addr), "dev", self.ifname(ifindex)]) @@ -172,7 +172,7 @@ class PhysicalNode(PyCoreNode): return ifindex def newnetif(self, net=None, addrlist=None, hwaddr=None, ifindex=None, ifname=None): - logger.info("creating interface") + logging.info("creating interface") if not addrlist: addrlist = [] @@ -210,17 +210,17 @@ class PhysicalNode(PyCoreNode): def mount(self, source, target): source = os.path.abspath(source) - logger.info("mounting %s at %s", source, target) + logging.info("mounting %s at %s", source, target) os.makedirs(target) self.check_cmd([constants.MOUNT_BIN, "--bind", source, target]) self._mounts.append((source, target)) def umount(self, target): - logger.info("unmounting '%s'" % target) + logging.info("unmounting '%s'" % target) try: self.check_cmd([constants.UMOUNT_BIN, "-l", target]) except CoreCommandError: - logger.exception("unmounting failed for %s", target) + logging.exception("unmounting failed for %s", target) def opennodefile(self, filename, mode="w"): dirname, basename = os.path.split(filename) @@ -242,4 +242,4 @@ class PhysicalNode(PyCoreNode): with self.opennodefile(filename, "w") as node_file: node_file.write(contents) os.chmod(node_file.name, mode) - logger.info("created nodefile: '%s'; mode: 0%o", node_file.name, mode) + logging.info("created nodefile: '%s'; mode: 0%o", node_file.name, mode) diff --git a/daemon/core/sdt.py b/daemon/core/sdt.py index 73bbc997..21843d98 100644 --- a/daemon/core/sdt.py +++ b/daemon/core/sdt.py @@ -2,11 +2,11 @@ sdt.py: Scripted Display Tool (SDT3D) helper """ +import logging import socket from urlparse import urlparse from core import constants -from core import logger from core.coreobj import PyCoreNet from core.coreobj import PyCoreObj from core.enumerations import EventTypes @@ -149,7 +149,7 @@ class Sdt(object): return False self.seturl() - logger.info("connecting to SDT at %s://%s" % (self.protocol, self.address)) + logging.info("connecting to SDT at %s://%s" % (self.protocol, self.address)) if self.sock is None: try: if self.protocol.lower() == "udp": @@ -159,7 +159,7 @@ class Sdt(object): # Default to tcp self.sock = socket.create_connection(self.address, 5) except IOError: - logger.exception("SDT socket connect error") + logging.exception("SDT socket connect error") return False if not self.initialize(): @@ -199,7 +199,7 @@ class Sdt(object): try: self.sock.close() except IOError: - logger.error("error closing socket") + logging.error("error closing socket") finally: self.sock = None @@ -211,7 +211,7 @@ class Sdt(object): :return: nothing """ - logger.info("SDT shutdown!") + logging.info("SDT shutdown!") self.cmd("clear all") self.disconnect() self.showerror = True @@ -229,11 +229,11 @@ class Sdt(object): if self.sock is None: return False try: - logger.info("sdt: %s" % cmdstr) + logging.info("sdt: %s" % cmdstr) self.sock.sendall("%s\n" % cmdstr) return True except IOError: - logger.exception("SDT connection error") + logging.exception("SDT connection error") self.sock = None self.connected = False return False diff --git a/daemon/core/service.py b/daemon/core/service.py index 41612c52..ba8a98ed 100644 --- a/daemon/core/service.py +++ b/daemon/core/service.py @@ -7,6 +7,7 @@ a list of available services to the GUI and for configuring individual services. """ +import logging import time from multiprocessing.pool import ThreadPool @@ -14,7 +15,6 @@ import enum from core.constants import which from core import CoreCommandError -from core import logger from core.data import FileData from core.enumerations import MessageFlags from core.enumerations import RegisterTlvs @@ -63,7 +63,7 @@ class ServiceDependencies(object): paths = [] for service in self.node_services.itervalues(): if service.name in self.booted: - logger.debug("skipping service that will already be booted: %s", service.name) + logging.debug("skipping service that will already be booted: %s", service.name) continue path = self._start(service) @@ -81,12 +81,12 @@ class ServiceDependencies(object): self.visiting.clear() def _start(self, service): - logger.debug("starting service dependency check: %s", service.name) + logging.debug("starting service dependency check: %s", service.name) self._reset() return self._visit(service) def _visit(self, current_service): - logger.debug("visiting service(%s): %s", current_service.name, self.path) + logging.debug("visiting service(%s): %s", current_service.name, self.path) self.visited.add(current_service.name) self.visiting.add(current_service.name) @@ -103,7 +103,7 @@ class ServiceDependencies(object): self._visit(service) # add service when bottom is found - logger.debug("adding service to boot path: %s", current_service.name) + logging.debug("adding service to boot path: %s", current_service.name) self.booted.add(current_service.name) self.path.append(current_service) self.visiting.remove(current_service.name) @@ -157,7 +157,7 @@ class ServiceShim(object): cls.setvalue(service, key, values[cls.keys.index(key)]) except IndexError: # old config does not need to have new keys - logger.exception("error indexing into key") + logging.exception("error indexing into key") @classmethod def setvalue(cls, service, key, value): @@ -223,7 +223,7 @@ class ServiceManager(object): :return: nothing """ name = service.name - logger.debug("loading service: class(%s) name(%s)", service.__name__, name) + logging.debug("loading service: class(%s) name(%s)", service.__name__, name) # avoid duplicate services if name in cls.services: @@ -232,7 +232,7 @@ class ServiceManager(object): # validate dependent executables are present for executable in service.executables: if not which(executable): - logger.debug("service(%s) missing executable: %s", service.name, executable) + logging.debug("service(%s) missing executable: %s", service.name, executable) raise ValueError("service(%s) missing executable: %s" % (service.name, executable)) # make service available @@ -269,7 +269,7 @@ class ServiceManager(object): cls.add(service) except ValueError as e: service_errors.append(service.name) - logger.debug("not loading service: %s", e) + logging.debug("not loading service: %s", e) return service_errors @@ -311,14 +311,14 @@ class CoreServices(object): :return: default services :rtype: list[CoreService] """ - logger.debug("getting default services for type: %s", node_type) + logging.debug("getting default services for type: %s", node_type) results = [] defaults = self.default_services.get(node_type, []) for name in defaults: - logger.debug("checking for service with service manager: %s", name) + logging.debug("checking for service with service manager: %s", name) service = ServiceManager.get(name) if not service: - logger.warn("default service %s is unknown", name) + logging.warn("default service %s is unknown", name) else: results.append(service) return results @@ -349,7 +349,7 @@ class CoreServices(object): :param str service_name: name of service to set :return: nothing """ - logger.debug("setting custom service(%s) for node: %s", service_name, node_id) + logging.debug("setting custom service(%s) for node: %s", service_name, node_id) service = self.get_service(node_id, service_name) if not service: service_class = ServiceManager.get(service_name) @@ -369,16 +369,16 @@ class CoreServices(object): :return: nothing """ if not services: - logger.info("using default services for node(%s) type(%s)", node.name, node_type) + logging.info("using default services for node(%s) type(%s)", node.name, node_type) services = self.default_services.get(node_type, []) - logger.info("setting services for node(%s): %s", node.name, services) + logging.info("setting services for node(%s): %s", node.name, services) for service_name in services: service = self.get_service(node.objid, service_name, default_service=True) if not service: - logger.warn("unknown service(%s) for node(%s)", service_name, node.name) + logging.warn("unknown service(%s) for node(%s)", service_name, node.name) continue - logger.info("adding service to node(%s): %s", node.name, service_name) + logging.info("adding service to node(%s): %s", node.name, service_name) node.addservice(service) def all_configs(self): @@ -444,12 +444,12 @@ class CoreServices(object): :param list[CoreService] boot_path: service to start in dependent order :return: nothing """ - logger.info("booting node services: %s", " -> ".join([x.name for x in boot_path])) + logging.info("booting node services: %s", " -> ".join([x.name for x in boot_path])) for service in boot_path: try: self.boot_service(node, service) except: - logger.exception("exception booting service: %s", service.name) + logging.exception("exception booting service: %s", service.name) raise def boot_service(self, node, service): @@ -461,7 +461,7 @@ class CoreServices(object): :param CoreService service: service to start :return: nothing """ - logger.info("starting node(%s) service(%s) validation(%s)", node.name, service.name, + logging.info("starting node(%s) service(%s) validation(%s)", node.name, service.name, service.validation_mode.name) # create service directories @@ -469,7 +469,7 @@ class CoreServices(object): try: node.privatedir(directory) except (CoreCommandError, ValueError) as e: - logger.warn("error mounting private dir '%s' for service '%s': %s", + logging.warn("error mounting private dir '%s' for service '%s': %s", directory, service.name, e) # create service files @@ -534,19 +534,19 @@ class CoreServices(object): :return: service validation status :rtype: int """ - logger.info("validating node(%s) service(%s)", node.name, service.name) + logging.info("validating node(%s) service(%s)", node.name, service.name) cmds = service.validate if not service.custom: cmds = service.get_validate(node) status = 0 for cmd in cmds: - logger.debug("validating service(%s) using: %s", service.name, cmd) + logging.debug("validating service(%s) using: %s", service.name, cmd) try: node.check_cmd(cmd) except CoreCommandError as e: - logger.error("node(%s) service(%s) validate failed", node.name, service.name) - logger.error("cmd(%s): %s", e.cmd, e.output) + logging.error("node(%s) service(%s) validate failed", node.name, service.name) + logging.error("cmd(%s): %s", e.cmd, e.output) status = -1 break @@ -576,7 +576,7 @@ class CoreServices(object): try: node.check_cmd(args) except CoreCommandError: - logger.exception("error running stop command %s", args) + logging.exception("error running stop command %s", args) status = -1 return status @@ -638,13 +638,13 @@ class CoreServices(object): # retrieve custom service service = self.get_service(node_id, service_name) if service is None: - logger.warn("received file name for unknown service: %s", service_name) + logging.warn("received file name for unknown service: %s", service_name) return # validate file being set is valid config_files = service.configs if file_name not in config_files: - logger.warn("received unknown file(%s) for service(%s)", file_name, service_name) + logging.warn("received unknown file(%s) for service(%s)", file_name, service_name) return # set custom service file data @@ -673,7 +673,7 @@ class CoreServices(object): else: node.cmd(cmd, wait=False) except CoreCommandError: - logger.exception("error starting command") + logging.exception("error starting command") status = -1 return status @@ -685,14 +685,14 @@ class CoreServices(object): :param CoreService service: service to reconfigure :return: nothing """ - logger.info("node(%s) service(%s) creating config files", node.name, service.name) + logging.info("node(%s) service(%s) creating config files", node.name, service.name) # get values depending on if custom or not config_files = service.configs if not service.custom: config_files = service.get_configs(node) for file_name in config_files: - logger.debug("generating service config: %s", file_name) + logging.debug("generating service config: %s", file_name) if service.custom: cfg = service.config_data.get(file_name) if cfg is None: @@ -703,7 +703,7 @@ class CoreServices(object): if self.copy_service_file(node, file_name, cfg): continue except IOError: - logger.exception("error copying service file: %s", file_name) + logging.exception("error copying service file: %s", file_name) continue else: cfg = service.generate_config(node, file_name) diff --git a/daemon/core/services/dockersvc.py b/daemon/core/services/dockersvc.py index d4061206..75a31c54 100644 --- a/daemon/core/services/dockersvc.py +++ b/daemon/core/services/dockersvc.py @@ -97,14 +97,15 @@ Limitations: depending on how many nodes you have. """ -from core import logger +import logging + from core.service import CoreService from core.service import ServiceManager try: from docker import Client except ImportError: - logger.debug("missing python docker bindings") + logging.debug("missing python docker bindings") class DockerService(CoreService): @@ -154,7 +155,7 @@ done @classmethod def on_load(cls): - logger.debug("loading custom docker services") + logging.debug("loading custom docker services") if "Client" in globals(): client = Client(version="1.10") diff --git a/daemon/core/services/security.py b/daemon/core/services/security.py index 38d9d16e..9ed3fc39 100644 --- a/daemon/core/services/security.py +++ b/daemon/core/services/security.py @@ -3,8 +3,9 @@ security.py: defines security services (vpnclient, vpnserver, ipsec and firewall) """ +import logging + from core import constants -from core import logger from core.service import CoreService @@ -29,7 +30,7 @@ class VPNClient(CoreService): try: cfg += open(fname, "rb").read() except IOError: - logger.exception("Error opening VPN client configuration template (%s)", fname) + logging.exception("Error opening VPN client configuration template (%s)", fname) return cfg @@ -56,7 +57,7 @@ class VPNServer(CoreService): try: cfg += open(fname, "rb").read() except IOError: - logger.exception("Error opening VPN server configuration template (%s)", fname) + logging.exception("Error opening VPN server configuration template (%s)", fname) return cfg @@ -83,7 +84,7 @@ class IPsec(CoreService): try: cfg += open(fname, "rb").read() except IOError: - logger.exception("Error opening IPsec configuration template (%s)", fname) + logging.exception("Error opening IPsec configuration template (%s)", fname) return cfg @@ -107,7 +108,7 @@ class Firewall(CoreService): try: cfg += open(fname, "rb").read() except IOError: - logger.exception("Error opening Firewall configuration template (%s)", fname) + logging.exception("Error opening Firewall configuration template (%s)", fname) return cfg diff --git a/daemon/core/services/xorp.py b/daemon/core/services/xorp.py index 9020fc93..49425ab7 100644 --- a/daemon/core/services/xorp.py +++ b/daemon/core/services/xorp.py @@ -2,7 +2,8 @@ xorp.py: defines routing services provided by the XORP routing suite. """ -from core import logger +import logging + from core.service import CoreService @@ -42,7 +43,7 @@ class XorpRtrmgr(CoreService): s.dependencies.index(cls.name) cfg += s.generatexorpconfig(node) except ValueError: - logger.exception("error getting value from service: %s", cls.name) + logging.exception("error getting value from service: %s", cls.name) return cfg diff --git a/daemon/core/session.py b/daemon/core/session.py index 3f52997c..5d955c2a 100644 --- a/daemon/core/session.py +++ b/daemon/core/session.py @@ -3,6 +3,7 @@ session.py: defines the Session class used by the core-daemon daemon program that manages a CORE session. """ +import logging import os import random import shutil @@ -15,7 +16,6 @@ from multiprocessing.pool import ThreadPool import pwd from core import constants -from core import logger from core.api import coreapi from core.broker import CoreBroker from core.conf import ConfigurableManager @@ -207,12 +207,12 @@ class Session(object): state_name = state.name if self.state == state_value: - logger.info("session(%s) is already in state: %s, skipping change", self.session_id, state_name) + logging.info("session(%s) is already in state: %s, skipping change", self.session_id, state_name) return self.state = state_value self._state_time = time.time() - logger.info("changing session(%s) to state %s", self.session_id, state_name) + logging.info("changing session(%s) to state %s", self.session_id, state_name) self.write_state(state_value) self.run_hooks(state_value) @@ -234,7 +234,7 @@ class Session(object): state_file.write("%d %s\n" % (state, coreapi.state_name(state))) state_file.close() except IOError: - logger.exception("error writing state file: %s", state) + logging.exception("error writing state file: %s", state) def run_hooks(self, state): """ @@ -256,7 +256,7 @@ class Session(object): for hook in hooks: self.run_hook(hook) else: - logger.info("no state hooks for %s", state) + logging.info("no state hooks for %s", state) def set_hook(self, hook_type, file_name, source_name, data): """ @@ -268,11 +268,11 @@ class Session(object): :param data: hook data :return: nothing """ - logger.info("setting state hook: %s - %s from %s", hook_type, file_name, source_name) + logging.info("setting state hook: %s - %s from %s", hook_type, file_name, source_name) _hook_id, state = hook_type.split(':')[:2] if not state.isdigit(): - logger.error("error setting hook having state '%s'", state) + logging.error("error setting hook having state '%s'", state) return state = int(state) @@ -285,7 +285,7 @@ class Session(object): # immediately run a hook if it is in the current state # (this allows hooks in the definition and configuration states) if self.state == state: - logger.info("immediately running new state hook") + logging.info("immediately running new state hook") self.run_hook(hook) def del_hooks(self): @@ -302,7 +302,7 @@ class Session(object): :return: nothing """ file_name, data = hook - logger.info("running hook %s", file_name) + logging.info("running hook %s", file_name) # write data to hook file try: @@ -310,14 +310,14 @@ class Session(object): hook_file.write(data) hook_file.close() except IOError: - logger.exception("error writing hook '%s'", file_name) + logging.exception("error writing hook '%s'", file_name) # setup hook stdout and stderr try: stdout = open(os.path.join(self.session_dir, file_name + ".log"), "w") stderr = subprocess.STDOUT except IOError: - logger.exception("error setting up hook stderr and stdout") + logging.exception("error setting up hook stderr and stdout") stdout = None stderr = None @@ -327,7 +327,7 @@ class Session(object): subprocess.check_call(args, stdout=stdout, stderr=stderr, close_fds=True, cwd=self.session_dir, env=self.get_environment()) except (OSError, subprocess.CalledProcessError): - logger.exception("error running hook: %s", file_name) + logging.exception("error running hook: %s", file_name) def run_state_hooks(self, state): """ @@ -341,7 +341,7 @@ class Session(object): hook(state) except: message = "exception occured when running %s state hook: %s" % (coreapi.state_name(state), hook) - logger.exception(message) + logging.exception(message) self.exception(ExceptionLevels.ERROR, "Session.run_state_hooks", None, message) def add_state_hook(self, state, hook): @@ -414,7 +414,7 @@ class Session(object): if os.path.isfile(environment_config_file): utils.load_config(environment_config_file, env) except IOError: - logger.warn("environment configuration file does not exist: %s", environment_config_file) + logging.warn("environment configuration file does not exist: %s", environment_config_file) # attempt to read and add user environment file if self.user: @@ -422,7 +422,7 @@ class Session(object): try: utils.load_config(environment_user_file, env) except IOError: - logger.debug("user core environment settings file not present: %s", environment_user_file) + logging.debug("user core environment settings file not present: %s", environment_user_file) return env @@ -434,7 +434,7 @@ class Session(object): :return: nothing """ if not os.path.exists(thumb_file): - logger.error("thumbnail file to set does not exist: %s", thumb_file) + logging.error("thumbnail file to set does not exist: %s", thumb_file) self.thumbnail = None return @@ -456,7 +456,7 @@ class Session(object): gid = os.stat(self.session_dir).st_gid os.chown(self.session_dir, uid, gid) except IOError: - logger.exception("failed to set permission on %s", self.session_dir) + logging.exception("failed to set permission on %s", self.session_dir) self.user = user @@ -532,7 +532,7 @@ class Session(object): obj = self.objects.pop(object_id) obj.shutdown() except KeyError: - logger.error("failed to remove object, object with id was not found: %s", object_id) + logging.error("failed to remove object, object with id was not found: %s", object_id) def delete_objects(self): """ @@ -556,14 +556,14 @@ class Session(object): nodes_file.write("%s %s %s %s\n" % (object_id, obj.name, obj.apitype, type(obj))) nodes_file.close() except IOError: - logger.exception("error writing nodes file") + logging.exception("error writing nodes file") def dump_session(self): """ Log information about the session in its current state. """ - logger.info("session id=%s name=%s state=%s", self.session_id, self.name, self.state) - logger.info("file=%s thumbnail=%s node_count=%s/%s", + logging.info("session id=%s name=%s state=%s", self.session_id, self.name, self.state) + logging.info("file=%s thumbnail=%s node_count=%s/%s", self.file_name, self.thumbnail, self.get_node_count(), len(self.objects)) def exception(self, level, source, object_id, text): @@ -647,10 +647,10 @@ class Session(object): # this is called from instantiate() after receiving an event message # for the instantiation state, and from the broker when distributed # nodes have been started - logger.info("session(%s) checking if not in runtime state, current state: %s", self.session_id, + logging.info("session(%s) checking if not in runtime state, current state: %s", self.session_id, coreapi.state_name(self.state)) if self.state == EventTypes.RUNTIME_STATE.value: - logger.info("valid runtime state found, returning") + logging.info("valid runtime state found, returning") return # check to verify that all nodes and networks are running @@ -694,7 +694,7 @@ class Session(object): and links remain. """ node_count = self.get_node_count() - logger.info("session(%s) checking shutdown: %s nodes remaining", self.session_id, node_count) + logging.info("session(%s) checking shutdown: %s nodes remaining", self.session_id, node_count) shutdown = False if node_count == 0: @@ -726,7 +726,7 @@ class Session(object): # TODO: PyCoreNode is not the type to check if isinstance(obj, nodes.PyCoreNode) and not nodeutils.is_node(obj, NodeTypes.RJ45): # add a control interface if configured - logger.info("booting node: %s", obj.name) + logging.info("booting node: %s", obj.name) self.add_remove_control_interface(node=obj, remove=False) result = pool.apply_async(self.services.boot_services, (obj,)) results.append(result) @@ -735,7 +735,7 @@ class Session(object): pool.join() for result in results: result.get() - logger.debug("boot run time: %s", time.time() - start) + logging.debug("boot run time: %s", time.time() - start) self.update_control_interface_hosts() @@ -766,7 +766,7 @@ class Session(object): """ d0 = self.options.get_config("controlnetif0") if d0: - logger.error("controlnet0 cannot be assigned with a host interface") + logging.error("controlnet0 cannot be assigned with a host interface") d1 = self.options.get_config("controlnetif1") d2 = self.options.get_config("controlnetif2") d3 = self.options.get_config("controlnetif3") @@ -806,7 +806,7 @@ class Session(object): :return: control net object :rtype: core.netns.nodes.CtrlNet """ - logger.debug("add/remove control net: index(%s) remove(%s) conf_required(%s)", net_index, remove, conf_required) + logging.debug("add/remove control net: index(%s) remove(%s) conf_required(%s)", net_index, remove, conf_required) prefix_spec_list = self.get_control_net_prefixes() prefix_spec = prefix_spec_list[net_index] if not prefix_spec: @@ -816,7 +816,7 @@ class Session(object): else: control_net_class = nodeutils.get_node_class(NodeTypes.CONTROL_NET) prefix_spec = control_net_class.DEFAULT_PREFIX_LIST[net_index] - logger.debug("prefix spec: %s", prefix_spec) + logging.debug("prefix spec: %s", prefix_spec) server_interface = self.get_control_net_server_interfaces()[net_index] @@ -842,7 +842,7 @@ class Session(object): if net_index == 0: updown_script = self.options.get_config("controlnet_updown_script") if not updown_script: - logger.warning("controlnet updown script not configured") + logging.warning("controlnet updown script not configured") prefixes = prefix_spec.split() if len(prefixes) > 1: @@ -875,7 +875,7 @@ class Session(object): break if not prefix: - logger.error("Control network prefix not found for server '%s'" % servers[0]) + logging.error("Control network prefix not found for server '%s'" % servers[0]) assign_address = False try: prefix = prefixes[0].split(':', 1)[1] @@ -935,7 +935,7 @@ class Session(object): msg = "Control interface not added to node %s. " % node.objid msg += "Invalid control network prefix (%s). " % control_net.prefix msg += "A longer prefix length may be required for this many nodes." - logger.exception(msg) + logging.exception(msg) return interface1 = node.newnetif(net=control_net, @@ -958,12 +958,12 @@ class Session(object): try: control_net = self.get_control_net_object(net_index) except KeyError: - logger.exception("error retrieving control net object") + logging.exception("error retrieving control net object") return header = "CORE session %s host entries" % self.session_id if remove: - logger.info("Removing /etc/hosts file entries.") + logging.info("Removing /etc/hosts file entries.") utils.file_demunge("/etc/hosts", header) return @@ -973,7 +973,7 @@ class Session(object): for address in interface.addrlist: entries.append("%s %s" % (address.split("/")[0], name)) - logger.info("Adding %d /etc/hosts file entries." % len(entries)) + logging.info("Adding %d /etc/hosts file entries." % len(entries)) utils.file_munge("/etc/hosts", header, "\n".join(entries) + "\n") @@ -1003,7 +1003,7 @@ class Session(object): if current_time > 0.0: if time <= current_time: - logger.warn("could not schedule past event for time %s (run time is now %s)", time, current_time) + logging.warn("could not schedule past event for time %s (run time is now %s)", time, current_time) return event_time = event_time - current_time @@ -1011,7 +1011,7 @@ class Session(object): if not name: name = "" - logger.info("scheduled event %s at time %s data=%s", name, event_time + current_time, data) + logging.info("scheduled event %s at time %s data=%s", name, event_time + current_time, data) # TODO: if data is None, this blows up, but this ties into how event functions are ran, need to clean that up def run_event(self, node_id=None, name=None, data=None): @@ -1027,7 +1027,7 @@ class Session(object): if not name: name = "" - logger.info("running event %s at time %s cmd=%s" % (name, now, data)) + logging.info("running event %s at time %s cmd=%s" % (name, now, data)) if not node_id: utils.mute_detach(data) else: diff --git a/daemon/core/xml/corexml.py b/daemon/core/xml/corexml.py index 83fa42f2..36ced216 100644 --- a/daemon/core/xml/corexml.py +++ b/daemon/core/xml/corexml.py @@ -1,7 +1,8 @@ +import logging + from lxml import etree from core import coreobj -from core import logger from core.emulator.emudata import InterfaceData from core.emulator.emudata import LinkOptions from core.emulator.emudata import NodeOptions @@ -321,7 +322,7 @@ class CoreXmlWriter(object): continue for model_name, config in all_configs.iteritems(): - logger.info("writing emane config node(%s) model(%s)", node_id, model_name) + logging.info("writing emane config node(%s) model(%s)", node_id, model_name) if model_name == -1: emane_configuration = create_emane_config(node_id, self.session.emane.emane_config, config) else: @@ -340,7 +341,7 @@ class CoreXmlWriter(object): continue for model_name, config in all_configs.iteritems(): - logger.info("writing mobility config node(%s) model(%s)", node_id, model_name) + logging.info("writing mobility config node(%s) model(%s)", node_id, model_name) mobility_configuration = etree.SubElement(mobility_configurations, "mobility_configuration") add_attribute(mobility_configuration, "node", node_id) add_attribute(mobility_configuration, "model", model_name) @@ -399,7 +400,7 @@ class CoreXmlWriter(object): for netif in node.netifs(sort=True): othernet = getattr(netif, "othernet", None) if othernet and othernet.objid != node.objid: - logger.info("writer ignoring node(%s) othernet(%s)", node.name, othernet.name) + logging.info("writer ignoring node(%s) othernet(%s)", node.name, othernet.name) return network = NetworkElement(self.session, node) @@ -525,7 +526,7 @@ class CoreXmlReader(object): services = [] for service in node.iterchildren(): services.append(service.get("name")) - logger.info("reading default services for nodes(%s): %s", node_type, services) + logging.info("reading default services for nodes(%s): %s", node_type, services) self.session.services.default_services[node_type] = services def read_session_metadata(self): @@ -538,7 +539,7 @@ class CoreXmlReader(object): name = data.get("name") value = data.get("value") configs[name] = value - logger.info("reading session metadata: %s", configs) + logging.info("reading session metadata: %s", configs) self.session.metadata.set_configs(configs) def read_session_options(self): @@ -551,7 +552,7 @@ class CoreXmlReader(object): name = config.get("name") value = config.get("value") configs[name] = value - logger.info("reading session options: %s", configs) + logging.info("reading session options: %s", configs) self.session.options.set_configs(configs) def read_session_hooks(self): @@ -564,7 +565,7 @@ class CoreXmlReader(object): state = hook.get("state") data = hook.text hook_type = "hook:%s" % state - logger.info("reading hook: state(%s) name(%s)", state, name) + logging.info("reading hook: state(%s) name(%s)", state, name) self.session.set_hook(hook_type, file_name=name, source_name=None, data=data) def read_session_origin(self): @@ -576,19 +577,19 @@ class CoreXmlReader(object): lon = get_float(session_origin, "lon") alt = get_float(session_origin, "alt") if all([lat, lon, alt]): - logger.info("reading session reference geo: %s, %s, %s", lat, lon, alt) + logging.info("reading session reference geo: %s, %s, %s", lat, lon, alt) self.session.location.setrefgeo(lat, lon, alt) scale = get_float(session_origin, "scale") if scale: - logger.info("reading session reference scale: %s", scale) + logging.info("reading session reference scale: %s", scale) self.session.location.refscale = scale x = get_float(session_origin, "x") y = get_float(session_origin, "y") z = get_float(session_origin, "z") if all([x, y]): - logger.info("reading session reference xyz: %s, %s, %s", x, y, z) + logging.info("reading session reference xyz: %s, %s, %s", x, y, z) self.session.location.refxyz = (x, y, z) def read_service_configs(self): @@ -599,7 +600,7 @@ class CoreXmlReader(object): for service_configuration in service_configurations.iterchildren(): node_id = get_int(service_configuration, "node") service_name = service_configuration.get("name") - logger.info("reading custom service(%s) for node(%s)", service_name, node_id) + logging.info("reading custom service(%s) for node(%s)", service_name, node_id) self.session.services.set_service(node_id, service_name) service = self.session.services.get_service(node_id, service_name) @@ -654,7 +655,7 @@ class CoreXmlReader(object): value = config.get("value") configs[name] = value - logger.info("reading emane configuration node(%s) model(%s)", node_id, model_name) + logging.info("reading emane configuration node(%s) model(%s)", node_id, model_name) self.session.emane.set_model_config(node_id, model_name, configs) def read_mobility_configs(self): @@ -672,7 +673,7 @@ class CoreXmlReader(object): value = config.get("value") configs[name] = value - logger.info("reading mobility configuration node(%s) model(%s)", node_id, model_name) + logging.info("reading mobility configuration node(%s) model(%s)", node_id, model_name) self.session.mobility.set_model_config(node_id, model_name, configs) def read_nodes(self): @@ -709,7 +710,7 @@ class CoreXmlReader(object): if all([lat, lon, alt]): node_options.set_location(lat, lon, alt) - logger.info("reading node id(%s) model(%s) name(%s)", node_id, model, name) + logging.info("reading node id(%s) model(%s) name(%s)", node_id, model, name) self.session.add_node(_id=node_id, node_options=node_options) def read_network(self, network_element): @@ -731,7 +732,7 @@ class CoreXmlReader(object): if all([lat, lon, alt]): node_options.set_location(lat, lon, alt) - logger.info("reading node id(%s) node_type(%s) name(%s)", node_id, node_type, name) + logging.info("reading node id(%s) node_type(%s) name(%s)", node_id, node_type, name) self.session.add_node(_type=node_type, _id=node_id, node_options=node_options) def read_links(self): @@ -772,5 +773,5 @@ class CoreXmlReader(object): link_options.opaque = options_element.get("opaque") link_options.gui_attributes = options_element.get("gui_attributes") - logger.info("reading link node_one(%s) node_two(%s)", node_one, node_two) + logging.info("reading link node_one(%s) node_two(%s)", node_one, node_two) self.session.add_link(node_one, node_two, interface_one, interface_two, link_options) diff --git a/daemon/core/xml/corexmldeployment.py b/daemon/core/xml/corexmldeployment.py index cea69e0e..ea1dfc72 100644 --- a/daemon/core/xml/corexmldeployment.py +++ b/daemon/core/xml/corexmldeployment.py @@ -4,7 +4,6 @@ import socket from lxml import etree from core import constants -from core import logger from core.coreobj import PyCoreNode from core.enumerations import NodeTypes from core.misc import utils, nodeutils, ipaddress diff --git a/daemon/core/xml/emanexml.py b/daemon/core/xml/emanexml.py index f21b9fac..c1c9fbb6 100644 --- a/daemon/core/xml/emanexml.py +++ b/daemon/core/xml/emanexml.py @@ -1,8 +1,8 @@ +import logging import os from lxml import etree -from core import logger from core.misc import utils from core.misc.ipaddress import MacAddress from core.xml import corexml @@ -40,7 +40,7 @@ def _value_to_params(value): return values except SyntaxError: - logger.exception("error in value string to param list") + logging.exception("error in value string to param list") return None @@ -108,11 +108,11 @@ def build_node_platform_xml(emane_manager, control_net, node, nem_id, platform_x :return: the next nem id that can be used for creating platform xml files :rtype: int """ - logger.debug("building emane platform xml for node(%s): %s", node, node.name) + logging.debug("building emane platform xml for node(%s): %s", node, node.name) nem_entries = {} if node.model is None: - logger.warn("warning: EmaneNode %s has no associated model", node.name) + logging.warn("warning: EmaneNode %s has no associated model", node.name) return nem_entries for netif in node.netifs(): @@ -133,7 +133,7 @@ def build_node_platform_xml(emane_manager, control_net, node, nem_id, platform_x # build transport xml transport_type = netif.transport_type if not transport_type: - logger.info("warning: %s interface type unsupported!", netif.name) + logging.info("warning: %s interface type unsupported!", netif.name) transport_type = "raw" transport_file = transport_file_name(node.objid, transport_type) transport_element = etree.SubElement(nem_element, "transport", definition=transport_file) @@ -209,7 +209,7 @@ def build_xml_files(emane_manager, node): :param core.emane.nodes.EmaneNode node: node to write platform xml for :return: nothing """ - logger.debug("building all emane xml for node(%s): %s", node, node.name) + logging.debug("building all emane xml for node(%s): %s", node, node.name) if node.model is None: return diff --git a/daemon/examples/api/emane80211.py b/daemon/examples/api/emane80211.py index e6f08d9e..0e2d2377 100644 --- a/daemon/examples/api/emane80211.py +++ b/daemon/examples/api/emane80211.py @@ -5,11 +5,14 @@ import datetime import parser +from core import load_logging_config from core.emane.ieee80211abg import EmaneIeee80211abgModel from core.emulator.coreemu import CoreEmu from core.emulator.emudata import IpPrefixes from core.enumerations import EventTypes +load_logging_config() + def example(options): # ip generator for example diff --git a/daemon/examples/api/switch.py b/daemon/examples/api/switch.py index 5f63bb8e..87f031cd 100644 --- a/daemon/examples/api/switch.py +++ b/daemon/examples/api/switch.py @@ -8,10 +8,13 @@ import datetime import parser +from core import load_logging_config from core.emulator.coreemu import CoreEmu from core.emulator.emudata import IpPrefixes from core.enumerations import NodeTypes, EventTypes +load_logging_config() + def example(options): # ip generator for example diff --git a/daemon/examples/api/switch_inject.py b/daemon/examples/api/switch_inject.py index 374f1a18..f727f0ca 100644 --- a/daemon/examples/api/switch_inject.py +++ b/daemon/examples/api/switch_inject.py @@ -4,10 +4,12 @@ # n nodes are connected to a virtual wlan; run test for testsec # and repeat for minnodes <= n <= maxnodes with a step size of # nodestep - +from core import load_logging_config from core.emulator.emudata import IpPrefixes from core.enumerations import NodeTypes, EventTypes +load_logging_config() + def example(nodes): # ip generator for example diff --git a/daemon/examples/api/wlan.py b/daemon/examples/api/wlan.py index 65523cf4..f152de37 100644 --- a/daemon/examples/api/wlan.py +++ b/daemon/examples/api/wlan.py @@ -8,11 +8,14 @@ import datetime import parser +from core import load_logging_config from core.emulator.coreemu import CoreEmu from core.emulator.emudata import IpPrefixes, NodeOptions from core.enumerations import NodeTypes, EventTypes from core.mobility import BasicRangeModel +load_logging_config() + def example(options): # ip generator for example diff --git a/daemon/examples/eventloop.py b/daemon/examples/eventloop.py index 8cf670b0..7c1b0f8f 100644 --- a/daemon/examples/eventloop.py +++ b/daemon/examples/eventloop.py @@ -1,6 +1,6 @@ +import logging import time -from core import logger from core.misc.event import EventLoop @@ -9,7 +9,7 @@ def main(): def msg(arg): delta = time.time() - loop.start - logger.debug("%s arg: %s", delta, arg) + logging.debug("%s arg: %s", delta, arg) def repeat(interval, count): count -= 1 diff --git a/daemon/scripts/core-daemon b/daemon/scripts/core-daemon index 1943fa10..34c516d3 100644 --- a/daemon/scripts/core-daemon +++ b/daemon/scripts/core-daemon @@ -6,17 +6,20 @@ message handlers are defined and some support for sending messages. """ import ConfigParser +import logging import optparse import sys import time +from core import load_logging_config from core import constants from core import enumerations -from core import logger from core.corehandlers import CoreHandler from core.coreserver import CoreServer from core.misc.utils import close_onexec +load_logging_config() + def banner(): """ @@ -24,7 +27,7 @@ def banner(): :return: nothing """ - logger.info("CORE daemon v.%s started %s", constants.COREDPY_VERSION, time.ctime()) + logging.info("CORE daemon v.%s started %s", constants.COREDPY_VERSION, time.ctime()) def cored(cfg, use_ovs): @@ -46,11 +49,11 @@ def cored(cfg, use_ovs): from core.netns.openvswitch import OVS_NODES server.coreemu.update_nodes(OVS_NODES) except: - logger.exception("error starting main server on: %s:%s", host, port) + logging.exception("error starting main server on: %s:%s", host, port) sys.exit(1) close_onexec(server.fileno()) - logger.info("server started, listening on: %s:%s", host, port) + logging.info("server started, listening on: %s:%s", host, port) server.serve_forever() @@ -113,7 +116,7 @@ def main(): # get a configuration merged from config file and command-line arguments cfg, args = get_merged_config("%s/core.conf" % constants.CORE_CONF_DIR) for a in args: - logger.error("ignoring command line argument: %s", a) + logging.error("ignoring command line argument: %s", a) banner() @@ -123,7 +126,7 @@ def main(): try: cored(cfg, use_ovs) except KeyboardInterrupt: - logger.info("keyboard interrupt, stopping core daemon") + logging.info("keyboard interrupt, stopping core daemon") sys.exit(0) diff --git a/ns3/corens3/obj.py b/ns3/corens3/obj.py index 119384f8..acb56e1c 100644 --- a/ns3/corens3/obj.py +++ b/ns3/corens3/obj.py @@ -2,6 +2,7 @@ ns3.py: defines classes for running emulations with ns-3 simulated networks. """ +import logging import subprocess import threading import time @@ -16,7 +17,6 @@ import ns.wifi import ns.wimax from core import constants -from core import logger from core.coreobj import PyCoreNet from core.enumerations import EventTypes from core.enumerations import LinkTypes @@ -174,7 +174,7 @@ class CoreNs3Net(PyCoreNet): netif.poshook = self.setns3position def setns3position(self, netif, x, y, z): - logger.info("setns3position: %s (%s, %s, %s)", netif.node.name, x, y, z) + logging.info("setns3position: %s (%s, %s, %s)", netif.node.name, x, y, z) netif.node.setns3position(x, y, z) @@ -246,7 +246,7 @@ class Ns3LteNet(CoreNs3Net): # ns.core.IntegerValue(ns.tap_bridge.TapBridge.USE_LOCAL)) tap = self.tapbridge.Install(netif.node, ns3dev) # tap.SetMode(ns.tap_bridge.TapBridge.USE_LOCAL) - logger.info("using TAP device %s for %s/%s", netif.localname, netif.node.name, netif.name) + logging.info("using TAP device %s for %s/%s", netif.localname, netif.node.name, netif.name) subprocess.check_call(['tunctl', '-t', netif.localname, '-n']) # check_call([IP_BIN, 'link', 'set', 'dev', netif.localname, \ # 'address', '%s' % netif.hwaddr]) @@ -373,12 +373,12 @@ class Ns3Session(Session): def runthread(): ns.core.Simulator.Stop(ns.core.Seconds(self.duration)) - logger.info("running ns-3 simulation for %d seconds", self.duration) + logging.info("running ns-3 simulation for %d seconds", self.duration) if vis: try: import visualizer except ImportError: - logger.exception("visualizer is not available") + logging.exception("visualizer is not available") ns.core.Simulator.Run() else: visualizer.start() @@ -509,7 +509,7 @@ class Ns3Session(Session): net.mobility.setnodeposition(node, x, y, z) nodemap[node.GetId()] = node - logger.info("mobilitytrace opening '%s'", filename) + logging.info("mobilitytrace opening '%s'", filename) f = None try: @@ -529,7 +529,7 @@ class Ns3Session(Session): continue sleep = 0.001 items = dict(x.split("=") for x in line.split()) - logger.info("trace: %s %s %s", items['node'], items['pos'], items['vel']) + logging.info("trace: %s %s %s", items['node'], items['pos'], items['vel']) x, y, z = map(float, items['pos'].split(':')) vel = map(float, items['vel'].split(':')) node = nodemap[int(items['node'])] @@ -544,7 +544,7 @@ class Ns3Session(Session): net.mobility.state = net.mobility.STATE_RUNNING self.event_loop.add_event(0, net.mobility.runround) except IOError: - logger.exception("mobilitytrace error opening: %s", filename) + logging.exception("mobilitytrace error opening: %s", filename) finally: if f: f.close() diff --git a/ns3/examples/ns3lte.py b/ns3/examples/ns3lte.py index d9dada18..ef3a6fc2 100644 --- a/ns3/examples/ns3lte.py +++ b/ns3/examples/ns3lte.py @@ -4,13 +4,13 @@ ns3lte.py - This script demonstrates using CORE with the ns-3 LTE model. - issues connecting TapBridge with LteNetDevice """ +import logging import optparse import sys import ns.core import ns.mobility -from core import logger from core.misc import ipaddress from core.misc import nodemaps from core.misc import nodeutils @@ -84,13 +84,13 @@ def main(): usage("invalid numnodes: %s" % opt.numnodes) for a in args: - logger.warn("ignoring command line argument: '%s'", a) + logging.warn("ignoring command line argument: '%s'", a) return ltesession(opt) def cleanup(): - logger.info("shutting down session") + logging.info("shutting down session") session.shutdown() diff --git a/ns3/examples/ns3wifi.py b/ns3/examples/ns3wifi.py index b5691677..759c5675 100644 --- a/ns3/examples/ns3wifi.py +++ b/ns3/examples/ns3wifi.py @@ -22,12 +22,12 @@ To run with the CORE GUI: """ +import logging import optparse import sys import ns.core -from core import logger from core.misc import ipaddress from core.misc import nodeutils from core.misc import nodemaps @@ -105,11 +105,11 @@ def main(): usage("invalid numnodes: %s" % opt.numnodes) for a in args: - logger.warn("ignoring command line argument: '%s'", a) + logging.warn("ignoring command line argument: '%s'", a) return wifisession(opt) if __name__ == "__main__" or __name__ == "__builtin__": session = main() - logger.info("\nsession =%s", session) + logging.info("\nsession =%s", session) diff --git a/ns3/examples/ns3wifirandomwalk.py b/ns3/examples/ns3wifirandomwalk.py index bab30a6b..2946f359 100644 --- a/ns3/examples/ns3wifirandomwalk.py +++ b/ns3/examples/ns3wifirandomwalk.py @@ -11,6 +11,7 @@ How to run this: python -i ns3wifirandomwalk.py """ +import logging import optparse import sys @@ -19,7 +20,6 @@ import ns.network from corens3.obj import Ns3Session from corens3.obj import Ns3WifiNet -from core import logger from core.misc import ipaddress from core.misc import nodemaps from core.misc import nodeutils @@ -109,11 +109,11 @@ def main(): usage("invalid numnodes: %s" % opt.numnodes) for a in args: - logger.warn("ignoring command line argument: '%s'", a) + logging.warn("ignoring command line argument: '%s'", a) return wifisession(opt) if __name__ == "__main__" or __name__ == "__builtin__": session = main() - logger.info("\nsession =%s", session) + logging.info("\nsession =%s", session) diff --git a/ns3/examples/ns3wimax.py b/ns3/examples/ns3wimax.py index d3d165a9..e939e934 100644 --- a/ns3/examples/ns3wimax.py +++ b/ns3/examples/ns3wimax.py @@ -9,10 +9,10 @@ Current issues: - no packets are sent between nodes - no connection? """ +import logging import optparse import sys -from core import logger from core.misc import ipaddress from core.misc import nodemaps from core.misc import nodeutils @@ -76,7 +76,7 @@ def main(): usage("invalid numnodes: %s" % opt.numnodes) for a in args: - logger.warn("ignoring command line argument: '%s'", a) + logging.warn("ignoring command line argument: '%s'", a) return wimaxsession(opt)