set default logging to INFO, cleaned up logging to help isolate debug type messages to DEBUG level, fixed issue with shutdown
This commit is contained in:
Blake J. Harnden
parent
ba3669712a
commit
44781d0aec
18 changed files with 114 additions and 114 deletions
|
|
@ -10,7 +10,6 @@ import struct
|
|||
|
||||
from enum import Enum
|
||||
|
||||
from core import logger
|
||||
from core.enumerations import ConfigTlvs
|
||||
from core.enumerations import EventTlvs
|
||||
from core.enumerations import EventTypes
|
||||
|
|
@ -275,7 +274,6 @@ class CoreTlvDataIpv4Addr(CoreTlvDataObj):
|
|||
:return: Ipv4 address
|
||||
:rtype: core.misc.ipaddress.IpAddress
|
||||
"""
|
||||
logger.info("getting new ipv4 address for: %s", value)
|
||||
return IpAddress(af=socket.AF_INET, address=value)
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -158,7 +158,7 @@ class CoreBroker(ConfigurableManager):
|
|||
"""
|
||||
Reset to initial state.
|
||||
"""
|
||||
logger.info("broker reset")
|
||||
logger.info("clearing state")
|
||||
self.nodemap_lock.acquire()
|
||||
self.nodemap.clear()
|
||||
for server, count in self.nodecounts.iteritems():
|
||||
|
|
@ -302,7 +302,7 @@ class CoreBroker(ConfigurableManager):
|
|||
server.close()
|
||||
del self.servers[name]
|
||||
|
||||
logger.info("adding server: %s @ %s:%s" % (name, host, port))
|
||||
logger.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:
|
||||
|
|
@ -432,7 +432,7 @@ class CoreBroker(ConfigurableManager):
|
|||
Add GreTaps between network devices on different machines.
|
||||
The GreTapBridge is not used since that would add an extra bridge.
|
||||
"""
|
||||
logger.info("adding network tunnels for nodes: %s", self.network_nodes)
|
||||
logger.debug("adding network tunnels for nodes: %s", self.network_nodes)
|
||||
for n in self.network_nodes:
|
||||
self.addnettunnel(n)
|
||||
|
||||
|
|
@ -531,7 +531,7 @@ class CoreBroker(ConfigurableManager):
|
|||
:return: gre tap between nodes or none
|
||||
"""
|
||||
key = self.tunnelkey(n1num, n2num)
|
||||
logger.info("checking for tunnel(%s) in: %s", key, self.tunnels.keys())
|
||||
logger.debug("checking for tunnel(%s) in: %s", key, self.tunnels.keys())
|
||||
if key in self.tunnels.keys():
|
||||
return self.tunnels[key]
|
||||
else:
|
||||
|
|
@ -709,8 +709,6 @@ class CoreBroker(ConfigurableManager):
|
|||
if message.message_type == MessageTypes.LINK.value:
|
||||
# prepare a server list from two node numbers in link message
|
||||
handle_locally, servers, message = self.handlelinkmsg(message)
|
||||
logger.info("broker handle link message: %s - %s", handle_locally,
|
||||
map(lambda x: "%s:%s" % (x.host, x.port), servers))
|
||||
elif len(servers) == 0:
|
||||
# check for servers based on node numbers in all messages but link
|
||||
nn = message.node_numbers()
|
||||
|
|
@ -868,7 +866,7 @@ class CoreBroker(ConfigurableManager):
|
|||
|
||||
# determine link message destination using non-network nodes
|
||||
nn = message.node_numbers()
|
||||
logger.info("checking link nodes (%s) with network nodes (%s)", nn, self.network_nodes)
|
||||
logger.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
|
||||
|
|
@ -879,11 +877,11 @@ class CoreBroker(ConfigurableManager):
|
|||
elif nn[1] in self.network_nodes:
|
||||
servers = self.getserversbynode(nn[0])
|
||||
else:
|
||||
logger.info("link nodes are not network nodes")
|
||||
logger.debug("link nodes are not network nodes")
|
||||
servers1 = self.getserversbynode(nn[0])
|
||||
logger.info("servers for node(%s): %s", nn[0], servers1)
|
||||
logger.debug("servers for node(%s): %s", nn[0], servers1)
|
||||
servers2 = self.getserversbynode(nn[1])
|
||||
logger.info("servers for node(%s): %s", nn[1], servers2)
|
||||
logger.debug("servers for node(%s): %s", nn[1], servers2)
|
||||
# nodes are on two different servers, build tunnels as needed
|
||||
if servers1 != servers2:
|
||||
localn = None
|
||||
|
|
@ -912,7 +910,7 @@ class CoreBroker(ConfigurableManager):
|
|||
if host is None:
|
||||
host = self.getlinkendpoint(message, localn == nn[0])
|
||||
|
||||
logger.info("handle locally(%s) and local node(%s)", handle_locally, localn)
|
||||
logger.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:
|
||||
|
|
|
|||
|
|
@ -212,7 +212,7 @@ class ConfigurableManager(object):
|
|||
:return: nothing
|
||||
"""
|
||||
if conftype not in self._modelclsmap:
|
||||
logger.warn("Unknown model type '%s'" % conftype)
|
||||
logger.warn("unknown model type '%s'", conftype)
|
||||
return
|
||||
model = self._modelclsmap[conftype]
|
||||
keys = model.getnames()
|
||||
|
|
@ -220,8 +220,7 @@ class ConfigurableManager(object):
|
|||
values = list(model.getdefaultvalues())
|
||||
for key, value in keyvalues:
|
||||
if key not in keys:
|
||||
logger.warn("Skipping unknown configuration key for %s: '%s'" % \
|
||||
(conftype, key))
|
||||
logger.warn("Skipping unknown configuration key for %s: '%s'", conftype, key)
|
||||
continue
|
||||
i = keys.index(key)
|
||||
values[i] = value
|
||||
|
|
@ -327,7 +326,7 @@ class Configurable(object):
|
|||
if interface_id is not None:
|
||||
node_id = node_id * 1000 + interface_id
|
||||
|
||||
logger.info("received configure message for %s nodenum:%s", cls.name, str(node_id))
|
||||
logger.debug("received configure message for %s nodenum:%s", cls.name, str(node_id))
|
||||
if config_type == ConfigFlags.REQUEST.value:
|
||||
logger.info("replying to configure request for %s model", cls.name)
|
||||
# when object name is "all", the reply to this request may be None
|
||||
|
|
|
|||
|
|
@ -168,8 +168,7 @@ class EmaneManager(ConfigurableManager):
|
|||
load EMANE models and make them available.
|
||||
"""
|
||||
for emane_model in emane_models:
|
||||
logger.info("loading emane model: (%s) %s - %s",
|
||||
emane_model, emane_model.name, RegisterTlvs(emane_model.config_type))
|
||||
logger.info("loading emane model: %s", emane_model.__name__)
|
||||
self._modelclsmap[emane_model.name] = emane_model
|
||||
self.session.add_config_object(emane_model.name, emane_model.config_type, emane_model.configure_emane)
|
||||
|
||||
|
|
|
|||
|
|
@ -142,7 +142,7 @@ class FutureSession(Session):
|
|||
:return: nodes, network nodes if present, and tunnel if present
|
||||
:rtype: tuple
|
||||
"""
|
||||
logger.info("link message between node1(%s) and node2(%s)", node_one_id, node_two_id)
|
||||
logger.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 FutureSession(Session):
|
|||
|
||||
# both node ids are provided
|
||||
tunnel = self.broker.gettunnel(node_one_id, node_two_id)
|
||||
logger.info("tunnel between nodes: %s", tunnel)
|
||||
logger.debug("tunnel between nodes: %s", tunnel)
|
||||
if nodeutils.is_node(tunnel, NodeTypes.TAP_BRIDGE):
|
||||
net_one = tunnel
|
||||
if tunnel.remotenum == node_one_id:
|
||||
|
|
@ -182,8 +182,8 @@ class FutureSession(Session):
|
|||
net_two = node_two
|
||||
node_two = None
|
||||
|
||||
logger.info("link node types n1(%s) n2(%s) net1(%s) net2(%s) tunnel(%s)",
|
||||
node_one, node_two, net_one, net_two, tunnel)
|
||||
logger.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
|
||||
|
||||
# TODO: this doesn't appear to ever be used, EMANE or basic wireless range
|
||||
|
|
@ -198,7 +198,7 @@ class FutureSession(Session):
|
|||
objects = [x for x in objects if x]
|
||||
if len(objects) < 2:
|
||||
raise ValueError("wireless link failure: %s", objects)
|
||||
logger.info("handling wireless linking objects(%) connect(%s)", objects, connect)
|
||||
logger.debug("handling wireless linking objects(%) 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")
|
||||
|
|
@ -242,23 +242,27 @@ class FutureSession(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)
|
||||
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)
|
||||
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)
|
||||
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", net_one.name, net_two.name)
|
||||
if nodeutils.is_node(net_two, NodeTypes.RJ45):
|
||||
interface = net_two.linknet(net_one)
|
||||
else:
|
||||
|
|
@ -282,10 +286,12 @@ class FutureSession(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)
|
||||
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)
|
||||
net_two.setkey(key)
|
||||
if addresses:
|
||||
net_two.addrconfig(addresses)
|
||||
|
|
@ -293,10 +299,12 @@ class FutureSession(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)
|
||||
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)
|
||||
addresses = interface_two.get_addresses()
|
||||
node_two.adoptnetif(tunnel, interface_two.id, interface_two.mac, addresses)
|
||||
link_config(node_two, tunnel, link_options)
|
||||
|
|
@ -351,11 +359,12 @@ class FutureSession(Session):
|
|||
interface_two = common_interface_two
|
||||
break
|
||||
|
||||
logger.info("deleting link for interfaces interface_one(%s) interface_two(%s)",
|
||||
interface_one, interface_two)
|
||||
if all([interface_one, interface_two]) and any([interface_one.net, interface_two.net]):
|
||||
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)",
|
||||
node_one.name, interface_one.name, node_two.name, interface_two.name)
|
||||
net_one = interface_one.net
|
||||
interface_one.detachnet()
|
||||
interface_two.detachnet()
|
||||
|
|
@ -488,7 +497,7 @@ class FutureSession(Session):
|
|||
name = "%s%s" % (node_class.__name__, _id)
|
||||
|
||||
# create node
|
||||
logger.info("creating node(%s) id(%s) name(%s) start(%s)", node_class, _id, name, start)
|
||||
logger.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
|
||||
|
|
@ -503,7 +512,6 @@ class FutureSession(Session):
|
|||
if _type in [NodeTypes.DEFAULT, NodeTypes.PHYSICAL]:
|
||||
node.type = node_options.model
|
||||
logger.debug("set node type: %s", node.type)
|
||||
logger.info("setting model (%s) with services (%s)", node.type, node_options.services)
|
||||
services = "|".join(node_options.services) or None
|
||||
self.services.addservicestonode(node, node.type, services)
|
||||
|
||||
|
|
@ -874,9 +882,10 @@ class CoreEmu(object):
|
|||
:return: nothing
|
||||
"""
|
||||
logger.info("shutting down all session")
|
||||
for session in self.sessions.values():
|
||||
session.shutdown()
|
||||
sessions = self.sessions.copy()
|
||||
self.sessions.clear()
|
||||
for session in sessions.itervalues():
|
||||
session.shutdown()
|
||||
|
||||
def create_session(self, _id=None, master=True):
|
||||
"""
|
||||
|
|
|
|||
|
|
@ -73,7 +73,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
if num_threads < 1:
|
||||
raise ValueError("invalid number of threads: %s" % num_threads)
|
||||
|
||||
logger.info("launching core server handler threads: %s", num_threads)
|
||||
logger.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)
|
||||
|
|
@ -94,7 +94,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("new TCP connection: %s", self.client_address)
|
||||
logger.debug("new TCP connection: %s", self.client_address)
|
||||
|
||||
def finish(self):
|
||||
"""
|
||||
|
|
@ -103,14 +103,14 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("finishing request handler")
|
||||
logger.info("remaining message queue size: %s", self.message_queue.qsize())
|
||||
logger.debug("finishing request handler")
|
||||
logger.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.info("waiting for message queue to empty: %s seconds", wait)
|
||||
logger.debug("waiting for message queue to empty: %s seconds", wait)
|
||||
time.sleep(1)
|
||||
wait += 1
|
||||
if wait == timeout:
|
||||
|
|
@ -151,8 +151,6 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
thumb_list = []
|
||||
num_sessions = 0
|
||||
|
||||
logger.info("creating session message: %s", self.coreemu.sessions.keys())
|
||||
|
||||
with self._sessions_lock:
|
||||
for session_id, session in self.coreemu.sessions.iteritems():
|
||||
num_sessions += 1
|
||||
|
|
@ -211,7 +209,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param core.data.EventData event_data: event data to handle
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("handling broadcast event: %s", event_data)
|
||||
logger.debug("handling broadcast event: %s", event_data)
|
||||
|
||||
tlv_data = structutils.pack_values(coreapi.CoreEventTlv, [
|
||||
(EventTlvs.NODE, event_data.node),
|
||||
|
|
@ -235,7 +233,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param core.data.FileData file_data: file data to handle
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("handling broadcast file: %s", file_data)
|
||||
logger.debug("handling broadcast file: %s", file_data)
|
||||
|
||||
tlv_data = structutils.pack_values(coreapi.CoreFileTlv, [
|
||||
(FileTlvs.NODE, file_data.node),
|
||||
|
|
@ -262,7 +260,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param core.data.ConfigData config_data: config data to handle
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("handling broadcast config: %s", config_data)
|
||||
logger.debug("handling broadcast config: %s", config_data)
|
||||
|
||||
tlv_data = structutils.pack_values(coreapi.CoreConfigTlv, [
|
||||
(ConfigTlvs.NODE, config_data.node),
|
||||
|
|
@ -293,7 +291,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param core.data.ExceptionData exception_data: exception data to handle
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("handling broadcast exception: %s", exception_data)
|
||||
logger.debug("handling broadcast exception: %s", exception_data)
|
||||
tlv_data = structutils.pack_values(coreapi.CoreExceptionTlv, [
|
||||
(ExceptionTlvs.NODE, exception_data.node),
|
||||
(ExceptionTlvs.SESSION, exception_data.session),
|
||||
|
|
@ -316,7 +314,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param core.data.NodeData node_data: node data to handle
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("handling broadcast node: %s", node_data)
|
||||
logger.debug("handling broadcast node: %s", node_data)
|
||||
|
||||
tlv_data = structutils.pack_values(coreapi.CoreNodeTlv, [
|
||||
(NodeTlvs.NUMBER, node_data.id),
|
||||
|
|
@ -354,7 +352,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param core.data.LinkData link_data: link data to handle
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("handling broadcast link: %s", link_data)
|
||||
logger.debug("handling broadcast link: %s", link_data)
|
||||
|
||||
tlv_data = structutils.pack_values(coreapi.CoreLinkTlv, [
|
||||
(LinkTlvs.N1_NUMBER, link_data.node1_id),
|
||||
|
|
@ -476,8 +474,8 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param message: message to queue
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("queueing msg (queuedtimes = %s): type %s",
|
||||
message.queuedtimes, MessageTypes(message.message_type))
|
||||
logger.debug("queueing msg (queuedtimes = %s): type %s", message.queuedtimes, MessageTypes(
|
||||
message.message_type))
|
||||
self.message_queue.put(message)
|
||||
|
||||
def handler_thread(self):
|
||||
|
|
@ -504,13 +502,13 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:return: nothing
|
||||
"""
|
||||
if self.session and self.session.broker.handle_message(message):
|
||||
logger.info("message not being handled locally")
|
||||
logger.debug("message not being handled locally")
|
||||
return
|
||||
|
||||
logger.info("%s handling message:\n%s", threading.currentThread().getName(), message)
|
||||
logger.debug("%s handling message:\n%s", threading.currentThread().getName(), message)
|
||||
|
||||
if message.message_type not in self.message_handlers:
|
||||
logger.warn("no handler for message type: %s", message.type_str())
|
||||
logger.error("no handler for message type: %s", message.type_str())
|
||||
return
|
||||
|
||||
message_handler = self.message_handlers[message.message_type]
|
||||
|
|
@ -520,8 +518,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)
|
||||
logger.exception("%s: exception while handling message: %s", threading.currentThread().getName(), message)
|
||||
|
||||
def dispatch_replies(self, replies, message):
|
||||
"""
|
||||
|
|
@ -531,7 +528,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
:param message: message for replies
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("dispatching replies")
|
||||
logger.debug("dispatching replies")
|
||||
for reply in replies:
|
||||
message_type, message_flags, message_length = coreapi.CoreMessage.unpack_header(reply)
|
||||
try:
|
||||
|
|
@ -545,7 +542,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
reply_message = "CoreMessage (type %d flags %d length %d)" % (
|
||||
message_type, message_flags, message_length)
|
||||
|
||||
logger.info("dispatch reply:\n%s", reply_message)
|
||||
logger.debug("dispatch reply:\n%s", reply_message)
|
||||
|
||||
try:
|
||||
self.sendall(reply)
|
||||
|
|
@ -566,17 +563,16 @@ 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.info("created new session for client: %s", self.session.session_id)
|
||||
logger.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.info("session set to master")
|
||||
logger.debug("session set to master")
|
||||
self.session.master = True
|
||||
self.session.broker.session_clients.append(self)
|
||||
|
||||
# add handlers for various data
|
||||
logger.info("adding session broadcast handlers")
|
||||
self.add_session_handlers()
|
||||
|
||||
# set initial session state
|
||||
|
|
@ -607,11 +603,11 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
if client == self:
|
||||
continue
|
||||
|
||||
logger.info("BROADCAST TO OTHER CLIENT: %s", client)
|
||||
logger.debug("BROADCAST TO OTHER CLIENT: %s", client)
|
||||
client.sendall(message.raw_message)
|
||||
|
||||
def add_session_handlers(self):
|
||||
logger.info("adding session broadcast handlers")
|
||||
logger.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)
|
||||
|
|
@ -620,7 +616,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
self.session.config_handlers.append(self.handle_broadcast_config)
|
||||
|
||||
def remove_session_handlers(self):
|
||||
logger.info("removing session broadcast handlers")
|
||||
logger.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)
|
||||
|
|
@ -876,17 +872,17 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
logger.info("executed %s with unknown session ID", execute_server)
|
||||
return replies
|
||||
|
||||
logger.info("checking session %d for RUNTIME state", sid)
|
||||
logger.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.info("waiting for session %d to enter RUNTIME state", sid)
|
||||
logger.debug("waiting for session %d to enter RUNTIME state", sid)
|
||||
time.sleep(1)
|
||||
retries -= 1
|
||||
if retries <= 0:
|
||||
logger.info("session %d did not enter RUNTIME state", sid)
|
||||
logger.debug("session %d did not enter RUNTIME state", sid)
|
||||
return replies
|
||||
|
||||
tlv_data = coreapi.CoreRegisterTlv.pack(RegisterTlvs.EXECUTE_SERVER.value, execute_server)
|
||||
|
|
@ -904,7 +900,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
|
||||
gui = message.get_tlv(RegisterTlvs.GUI.value)
|
||||
if gui is None:
|
||||
logger.info("ignoring Register message")
|
||||
logger.debug("ignoring Register message")
|
||||
else:
|
||||
# register capabilities with the GUI
|
||||
self.master = True
|
||||
|
|
@ -912,7 +908,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.info("setting session to master: %s", session.session_id)
|
||||
logger.debug("setting session to master: %s", session.session_id)
|
||||
session.master = True
|
||||
break
|
||||
|
||||
|
|
@ -944,7 +940,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
network_id=message.get_tlv(ConfigTlvs.NETWORK_ID.value),
|
||||
opaque=message.get_tlv(ConfigTlvs.OPAQUE.value)
|
||||
)
|
||||
logger.info("Configuration message for %s node %s", config_data.object, config_data.node)
|
||||
logger.debug("configuration message for %s node %s", config_data.object, config_data.node)
|
||||
|
||||
# dispatch to any registered callback for this object type
|
||||
replies = self.session.config_object(config_data)
|
||||
|
|
@ -1039,7 +1035,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
event_type = EventTypes(event_data.event_type)
|
||||
node_id = event_data.node
|
||||
|
||||
logger.info("EVENT %s at %s", event_type.name, time.ctime())
|
||||
logger.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:
|
||||
|
|
@ -1116,7 +1112,7 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
else:
|
||||
raise NotImplementedError
|
||||
else:
|
||||
logger.warn("Unhandled event message: event type %s", event_type)
|
||||
logger.warn("unhandled event message: event type %s", event_type)
|
||||
|
||||
return ()
|
||||
|
||||
|
|
@ -1135,7 +1131,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.info("SESSION message flags=0x%x sessions=%s" % (message.flags, session_id_str))
|
||||
logger.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):
|
||||
|
|
@ -1146,10 +1142,10 @@ class CoreHandler(SocketServer.BaseRequestHandler):
|
|||
session = self.coreemu.sessions.get(session_id)
|
||||
|
||||
if session is None:
|
||||
logger.info("session %s not found", session_id)
|
||||
logger.warn("session %s not found", session_id)
|
||||
continue
|
||||
|
||||
logger.info("request to modify to session %s", session.session_id)
|
||||
logger.info("request to modify to session: %s", session.session_id)
|
||||
if names is not None:
|
||||
session.name = names[index]
|
||||
|
||||
|
|
|
|||
|
|
@ -63,7 +63,7 @@ class CoreLocation(ConfigurableManager):
|
|||
values = config_data.data_values
|
||||
|
||||
if values is None:
|
||||
logger.info("location data missing")
|
||||
logger.warn("location data missing")
|
||||
return None
|
||||
values = values.split('|')
|
||||
|
||||
|
|
|
|||
|
|
@ -2,8 +2,6 @@
|
|||
Serves as a global point for storing and retrieving node types needed during simulation.
|
||||
"""
|
||||
|
||||
import pprint
|
||||
|
||||
from core import logger
|
||||
|
||||
_NODE_MAP = None
|
||||
|
|
@ -11,8 +9,11 @@ _NODE_MAP = None
|
|||
|
||||
def _log_map():
|
||||
global _NODE_MAP
|
||||
print_map = reduce(lambda x, y: _convert_map(x, y), _NODE_MAP.items(), {})
|
||||
logger.info("node class map: \n%s", pprint.pformat(print_map, indent=4))
|
||||
for key, value in _NODE_MAP.iteritems():
|
||||
name = None
|
||||
if value:
|
||||
name = value.__name__
|
||||
logger.info("node type (%s) - class (%s)", key.name, name)
|
||||
|
||||
|
||||
def _convert_map(x, y):
|
||||
|
|
|
|||
|
|
@ -40,7 +40,7 @@ def pack_values(clazz, packers):
|
|||
value = transformer(value)
|
||||
|
||||
# pack and add to existing data
|
||||
logger.info("packing: %s - %s", tlv_type, value)
|
||||
logger.debug("packing: %s - %s", tlv_type, value)
|
||||
data += clazz.pack(tlv_type.value, value)
|
||||
|
||||
return data
|
||||
|
|
|
|||
|
|
@ -370,13 +370,13 @@ def load_classes(path, clazz):
|
|||
:return: list of classes loaded
|
||||
"""
|
||||
# validate path exists
|
||||
logger.info("attempting to load modules from path: %s", path)
|
||||
logger.debug("attempting to load modules from path: %s", path)
|
||||
if not os.path.isdir(path):
|
||||
logger.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.info("adding parent path to allow imports: %s", parent_path)
|
||||
logger.debug("adding parent path to allow imports: %s", parent_path)
|
||||
sys.path.append(parent_path)
|
||||
|
||||
# retrieve potential service modules, and filter out invalid modules
|
||||
|
|
@ -389,7 +389,7 @@ def load_classes(path, clazz):
|
|||
classes = []
|
||||
for module_name in module_names:
|
||||
import_statement = "%s.%s" % (base_module, module_name)
|
||||
logger.info("importing custom module: %s", import_statement)
|
||||
logger.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))
|
||||
|
|
|
|||
|
|
@ -525,8 +525,8 @@ class BasicRangeModel(WirelessModel):
|
|||
with self.wlan._linked_lock:
|
||||
linked = self.wlan.linked(a, b)
|
||||
|
||||
logger.info("checking range netif1(%s) netif2(%s): linked(%s) actual(%s) > config(%s)",
|
||||
a.name, b.name, linked, d, self.range)
|
||||
logger.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.info("was linked, unlinking")
|
||||
|
|
|
|||
|
|
@ -107,11 +107,11 @@ class SimpleLxcNode(PyCoreNode):
|
|||
self.client = vnodeclient.VnodeClient(self.name, self.ctrlchnlname)
|
||||
|
||||
# bring up the loopback interface
|
||||
logger.info("bringing up loopback interface")
|
||||
logger.debug("bringing up loopback interface")
|
||||
self.check_cmd([constants.IP_BIN, "link", "set", "lo", "up"])
|
||||
|
||||
# set hostname for node
|
||||
logger.info("setting hostname: %s", self.name)
|
||||
logger.debug("setting hostname: %s", self.name)
|
||||
self.check_cmd(["hostname", self.name])
|
||||
|
||||
# mark node as up
|
||||
|
|
@ -216,7 +216,7 @@ class SimpleLxcNode(PyCoreNode):
|
|||
:raises CoreCommandError: when a non-zero exit status occurs
|
||||
"""
|
||||
source = os.path.abspath(source)
|
||||
logger.info("mounting %s at %s", source, target)
|
||||
logger.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:
|
||||
|
|
@ -230,7 +230,7 @@ class SimpleLxcNode(PyCoreNode):
|
|||
:param str target: target directory to unmount
|
||||
:return: nothing
|
||||
"""
|
||||
logger.info("unmounting: %s", target)
|
||||
logger.info("node(%s) unmounting: %s", self.name, target)
|
||||
try:
|
||||
self.check_cmd([constants.UMOUNT_BIN, "-n", "-l", target])
|
||||
except CoreCommandError:
|
||||
|
|
@ -289,12 +289,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.info("interface command output: %s", output)
|
||||
logger.debug("interface command output: %s", output)
|
||||
output = output.split("\n")
|
||||
veth.flow_id = int(output[0].strip().split(":")[0]) + 1
|
||||
logger.info("interface flow index: %s - %s", veth.name, veth.flow_id)
|
||||
logger.debug("interface flow index: %s - %s", veth.name, veth.flow_id)
|
||||
veth.hwaddr = MacAddress.from_string(output[1].strip().split()[1])
|
||||
logger.info("interface mac: %s - %s", veth.name, veth.hwaddr)
|
||||
logger.debug("interface mac: %s - %s", veth.name, veth.hwaddr)
|
||||
|
||||
try:
|
||||
self.addnetif(veth, ifindex)
|
||||
|
|
@ -625,7 +625,7 @@ class LxcNode(SimpleLxcNode):
|
|||
with self.opennodefile(filename, "w") as open_file:
|
||||
open_file.write(contents)
|
||||
os.chmod(open_file.name, mode)
|
||||
logger.info("created nodefile: %s; mode: 0%o", open_file.name, mode)
|
||||
logger.info("node(%s) added file: %s; mode: 0%o", self.name, open_file.name, mode)
|
||||
|
||||
def nodefilecopy(self, filename, srcfilename, mode=None):
|
||||
"""
|
||||
|
|
@ -641,4 +641,4 @@ class LxcNode(SimpleLxcNode):
|
|||
shutil.copy2(srcfilename, hostfilename)
|
||||
if mode is not None:
|
||||
os.chmod(hostfilename, mode)
|
||||
logger.info("copied nodefile: %s; mode: %s", hostfilename, mode)
|
||||
logger.info("node(%s) copied file: %s; mode: %s", self.name, hostfilename, mode)
|
||||
|
|
|
|||
|
|
@ -44,7 +44,7 @@ class ServiceManager(object):
|
|||
insert = index + 1
|
||||
break
|
||||
|
||||
logger.info("loading service: %s - %s: %s", insert, service, service._name)
|
||||
logger.info("loading service: %s", service.__name__)
|
||||
cls.services.insert(insert, service)
|
||||
|
||||
@classmethod
|
||||
|
|
@ -89,7 +89,7 @@ class CoreServices(ConfigurableManager):
|
|||
name = "services"
|
||||
config_type = RegisterTlvs.UTILITY.value
|
||||
|
||||
_invalid_custom_names = ('core', 'api', 'emane', 'misc', 'netns', 'phys', 'services')
|
||||
_invalid_custom_names = ("core", "api", "emane", "misc", "netns", "phys", "services")
|
||||
|
||||
def __init__(self, session):
|
||||
"""
|
||||
|
|
@ -200,21 +200,21 @@ class CoreServices(ConfigurableManager):
|
|||
:return: nothing
|
||||
"""
|
||||
if services_str is not None:
|
||||
logger.info("setting node specific services: %s", services_str)
|
||||
logger.info("setting custom services for node(%s)", node.name)
|
||||
services = services_str.split("|")
|
||||
for name in services:
|
||||
s = ServiceManager.get(name)
|
||||
if s is None:
|
||||
logger.warn("configured service %s for node %s is unknown", name, node.name)
|
||||
continue
|
||||
logger.info("adding configured service %s to node %s", s._name, node.name)
|
||||
logger.info("adding service to node(%s): %s", node.name, s._name)
|
||||
s = self.getcustomservice(node.objid, s)
|
||||
node.addservice(s)
|
||||
else:
|
||||
logger.info("setting default services for node (%s) type (%s)", node.objid, nodetype)
|
||||
logger.info("setting default services for node(%s) type (%s)", node.name, nodetype)
|
||||
services = self.getdefaultservices(nodetype)
|
||||
for s in services:
|
||||
logger.info("adding default service %s to node %s", s._name, node.name)
|
||||
logger.info("adding service to node(%s): %s", node.name, s._name)
|
||||
s = self.getcustomservice(node.objid, s)
|
||||
node.addservice(s)
|
||||
|
||||
|
|
@ -290,7 +290,7 @@ class CoreServices(ConfigurableManager):
|
|||
self.bootnodecustomservice(node, service, services, use_startup_service)
|
||||
return
|
||||
|
||||
logger.info("starting service %s (%s)", service._name, service._startindex)
|
||||
logger.info("starting node(%s) service: %s (%s)", node.name, service._name, service._startindex)
|
||||
for directory in service._dirs:
|
||||
node.privatedir(directory)
|
||||
|
||||
|
|
@ -386,8 +386,7 @@ class CoreServices(ConfigurableManager):
|
|||
:return: service validation status
|
||||
:rtype: int
|
||||
"""
|
||||
logger.info("validating service for node (%s - %s): %s (%s)",
|
||||
node.objid, node.name, service._name, service._startindex)
|
||||
logger.info("validating service for node (%s): %s (%s)", node.name, service._name, service._startindex)
|
||||
if service._custom:
|
||||
validate_cmds = service._validate
|
||||
else:
|
||||
|
|
@ -452,7 +451,7 @@ class CoreServices(ConfigurableManager):
|
|||
session_id = config_data.session
|
||||
opaque = config_data.opaque
|
||||
|
||||
logger.info("configuration request: node(%s) session(%s) opaque(%s)", node_id, session_id, opaque)
|
||||
logger.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:
|
||||
|
|
@ -545,7 +544,7 @@ class CoreServices(ConfigurableManager):
|
|||
return None
|
||||
key = values.pop(0)
|
||||
self.defaultservices[key] = values
|
||||
logger.info("default services for type %s set to %s" % (key, values))
|
||||
logger.debug("default services for type %s set to %s", key, values)
|
||||
else:
|
||||
# store service customized config in self.customservices[]
|
||||
if node_id is None:
|
||||
|
|
|
|||
|
|
@ -245,13 +245,12 @@ class Session(object):
|
|||
state_name = state.name
|
||||
|
||||
if self.state == state_value:
|
||||
logger.info("session is already in state: %s, skipping change", state_name)
|
||||
logger.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(%s) at %s",
|
||||
self.session_id, state_value, state_name, self._state_time)
|
||||
logger.info("changing session(%s) to state %s", self.session_id, state_name)
|
||||
|
||||
self.write_state(state_value)
|
||||
self.run_hooks(state_value)
|
||||
|
|
@ -462,7 +461,7 @@ class Session(object):
|
|||
try:
|
||||
utils.load_config(environment_user_file, env)
|
||||
except IOError:
|
||||
logger.info("error reading user core environment settings file: %s", environment_user_file)
|
||||
logger.debug("user core environment settings file not present: %s", environment_user_file)
|
||||
|
||||
return env
|
||||
|
||||
|
|
@ -610,7 +609,7 @@ class Session(object):
|
|||
:return: nothing
|
||||
"""
|
||||
register_tlv = RegisterTlvs(object_type)
|
||||
logger.info("adding config object callback: %s - %s", name, register_tlv)
|
||||
logger.debug("adding config object callback: %s - %s", name, register_tlv)
|
||||
with self._config_objects_lock:
|
||||
self.config_objects[name] = (object_type, callback)
|
||||
|
||||
|
|
@ -624,8 +623,9 @@ class Session(object):
|
|||
:rtype: list
|
||||
"""
|
||||
name = config_data.object
|
||||
logger.info("session(%s): handling config message(%s): \n%s",
|
||||
self.session_id, name, config_data)
|
||||
logger.info("session(%s) setting config(%s)", self.session_id, name)
|
||||
for key, value in config_data.__dict__.iteritems():
|
||||
logger.debug("%s = %s", key, value)
|
||||
|
||||
replies = []
|
||||
|
||||
|
|
@ -795,7 +795,8 @@ 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("checking runtime: %s", self.state)
|
||||
logger.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")
|
||||
return
|
||||
|
|
@ -841,7 +842,7 @@ class Session(object):
|
|||
and links remain.
|
||||
"""
|
||||
node_count = self.get_node_count()
|
||||
logger.info("checking shutdown for session %d: %d nodes remaining", self.session_id, node_count)
|
||||
logger.info("session(%s) checking shutdown: %s nodes remaining", self.session_id, node_count)
|
||||
|
||||
shutdown = False
|
||||
if node_count == 0:
|
||||
|
|
@ -869,7 +870,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 - %s", obj.objid, obj.name)
|
||||
logger.info("booting node: %s", obj.name)
|
||||
self.add_remove_control_interface(node=obj, remove=False)
|
||||
obj.boot()
|
||||
|
||||
|
|
|
|||
|
|
@ -77,7 +77,7 @@ class CoreDocumentWriter1(Document):
|
|||
objects from the given session.
|
||||
"""
|
||||
Document.__init__(self)
|
||||
logger.info('Exporting to NMF XML version 1.0')
|
||||
logger.debug('Exporting to NMF XML version 1.0')
|
||||
with session._objects_lock:
|
||||
self.scenarioPlan = ScenarioPlan(self, session)
|
||||
if session.state == EventTypes.RUNTIME_STATE.value:
|
||||
|
|
|
|||
|
|
@ -14,7 +14,7 @@
|
|||
}
|
||||
},
|
||||
"root": {
|
||||
"level": "DEBUG",
|
||||
"level": "INFO",
|
||||
"handlers": ["console"]
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -51,7 +51,7 @@ def cored(cfg, use_ovs):
|
|||
sys.exit(1)
|
||||
|
||||
close_onexec(server.fileno())
|
||||
logger.info("main server started, listening on: %s:%s", host, port)
|
||||
logger.debug("main server started, listening on: %s:%s", host, port)
|
||||
server.serve_forever()
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -90,7 +90,7 @@ def run_cmd(node, exec_cmd):
|
|||
message_data = server.sock.recv(message_length)
|
||||
|
||||
# If we get the right response return the results
|
||||
print "received response message: %s" % MessageTypes(message_type)
|
||||
print "received response message: %s" % message_type
|
||||
if message_type == MessageTypes.EXECUTE.value:
|
||||
message = coreapi.CoreExecMessage(message_flags, message_header, message_data)
|
||||
result = message.get_tlv(ExecuteTlvs.RESULT.value)
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue