Merge pull request #278 from coreemu/log-updates

updates to try and clean up info logging, moved some statements to debug

daemon/core/api/grpc/server.py

@@ -175,7 +175,7 @@ class CoreGrpcServer(core_pb2_grpc.CoreApiServicer):
         context.abort(grpc.StatusCode.CANCELLED, "server stopping")
 
     def listen(self, address):
-        logging.info("starting grpc api: %s", address)
+        logging.info("CORE gRPC API listening on: %s", address)
         self.server = grpc.server(futures.ThreadPoolExecutor(max_workers=10))
         core_pb2_grpc.add_CoreApiServicer_to_server(self, self.server)
         self.server.add_insecure_port(address)

daemon/core/api/tlv/broker.py

@@ -164,7 +164,7 @@ class CoreBroker(object):
         """
         Reset to initial state.
         """
-        logging.info("clearing state")
+        logging.debug("broker reset")
         self.nodemap_lock.acquire()
         self.nodemap.clear()
         for server in self.nodecounts:

daemon/core/api/tlv/corehandlers.py

@@ -1611,7 +1611,9 @@ class CoreHandler(socketserver.BaseRequestHandler):
                     self.session.start_mobility(node_ids=(node.id,))
                     return ()
 
-                logging.warning("dropping unhandled Event message with node number")
+                logging.warning(
+                    "dropping unhandled event message for node: %s", node_id
+                )
                 return ()
             self.session.set_state(event_type)
 
@@ -1663,7 +1665,9 @@ class CoreHandler(socketserver.BaseRequestHandler):
                     handled = True
             if not handled:
                 logging.warning(
-                    "Unhandled event message: event type %s ", event_type.name
+                    "unhandled event message: event type %s, name %s ",
+                    event_type.name,
+                    name,
                 )
         elif event_type == EventTypes.FILE_OPEN:
             filename = event_data.name
@@ -1685,8 +1689,6 @@ class CoreHandler(socketserver.BaseRequestHandler):
                 self.session.add_event(float(etime), node=node, name=name, data=data)
             else:
                 raise NotImplementedError
-        else:
-            logging.warning("unhandled event message: event type %s", event_type)
 
         return ()
 
@@ -1797,7 +1799,6 @@ class CoreHandler(socketserver.BaseRequestHandler):
                     logging.warning("session %s not found", session_id)
                     continue
 
-                logging.info("request to modify to session: %s", session.id)
                 if names is not None:
                     session.name = names[index]
 

daemon/core/config.py

@@ -380,11 +380,8 @@ class ModelManager(ConfigurableManager):
         :param dict config: model configuration, None for default configuration
         :return: nothing
         """
-        logging.info(
-            "setting mobility model(%s) for node(%s): %s",
-            model_class.name,
-            node.id,
-            config,
+        logging.debug(
+            "setting model(%s) for node(%s): %s", model_class.name, node.id, config
         )
         self.set_model_config(node.id, model_class.name, config)
         config = self.get_model_config(node.id, model_class.name)

daemon/core/emane/emanemanager.py

@@ -220,7 +220,7 @@ class EmaneManager(ModelManager):
         Load EMANE models and make them available.
         """
         for emane_model in emane_models:
-            logging.info("loading emane model: %s", emane_model.__name__)
+            logging.debug("loading emane model: %s", emane_model.__name__)
             emane_prefix = self.session.options.get_config(
                 "emane_prefix", default=DEFAULT_EMANE_PREFIX
             )

daemon/core/emulator/session.py

@@ -1462,7 +1462,7 @@ 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
-        logging.info(
+        logging.debug(
             "session(%s) checking if not in runtime state, current state: %s",
             self.id,
             coreapi.state_name(self.state),
@@ -1513,7 +1513,7 @@ class Session(object):
         and links remain.
         """
         node_count = self.get_node_count()
-        logging.info(
+        logging.debug(
             "session(%s) checking shutdown: %s nodes remaining", self.id, node_count
         )
 
@@ -1550,7 +1550,11 @@ class Session(object):
                     node, NodeTypes.RJ45
                 ):
                     # add a control interface if configured
-                    logging.info("booting node(%s): %s", node.name, node.services)
+                    logging.info(
+                        "booting node(%s): %s",
+                        node.name,
+                        [x.name for x in node.services],
+                    )
                     self.add_remove_control_interface(node=node, remove=False)
                     result = pool.apply_async(self.services.boot_services, (node,))
                     results.append(result)

daemon/core/location/mobility.py

@@ -72,8 +72,8 @@ class MobilityManager(ModelManager):
             node_ids = self.nodes()
 
         for node_id in node_ids:
-            logging.info("checking mobility startup for node: %s", node_id)
-            logging.info(
+            logging.debug("checking mobility startup for node: %s", node_id)
+            logging.debug(
                 "node mobility configurations: %s", self.get_all_configs(node_id)
             )
 
@@ -415,7 +415,7 @@ class BasicRangeModel(WirelessModel):
         :return: nothing
         """
         self.range = int(float(config["range"]))
-        logging.info(
+        logging.debug(
             "basic range model configured for WLAN %d using range %d",
             self.wlan.id,
             self.range,

daemon/core/nodes/base.py

@@ -624,7 +624,7 @@ class CoreNode(CoreNodeBase):
         :raises CoreCommandError: when a non-zero exit status occurs
         """
         source = os.path.abspath(source)
-        logging.info("node(%s) mounting: %s at %s", self.name, source, target)
+        logging.debug("node(%s) mounting: %s at %s", self.name, source, target)
         cmd = 'mkdir -p "%s" && %s -n --bind "%s" "%s"' % (
             target,
             constants.MOUNT_BIN,
@@ -1020,7 +1020,7 @@ class CoreNode(CoreNodeBase):
         with self.opennodefile(filename, "w") as open_file:
             open_file.write(contents)
             os.chmod(open_file.name, mode)
-            logging.info(
+            logging.debug(
                 "node(%s) added file: %s; mode: 0%o", self.name, open_file.name, mode
             )
 

daemon/core/nodes/docker.py

@@ -250,7 +250,7 @@ class DockerNode(CoreNode):
         :param str path: path to create
         :return: nothing
         """
-        logging.info("creating node dir: %s", path)
+        logging.debug("creating node dir: %s", path)
         args = "mkdir -p {path}".format(path=path)
         self.check_cmd(args)
 
@@ -263,7 +263,7 @@ class DockerNode(CoreNode):
         :return: nothing
         :raises CoreCommandError: when a non-zero exit status occurs
         """
-        logging.info("mounting source(%s) target(%s)", source, target)
+        logging.debug("mounting source(%s) target(%s)", source, target)
         raise Exception("not supported")
 
     def nodefile(self, filename, contents, mode=0o644):
@@ -275,8 +275,8 @@ class DockerNode(CoreNode):
         :param int mode: mode for file
         :return: nothing
         """
-        logging.info("node dir(%s) ctrlchannel(%s)", self.nodedir, self.ctrlchnlname)
-        logging.info("nodefile filename(%s) mode(%s)", filename, mode)
+        logging.debug("node dir(%s) ctrlchannel(%s)", self.nodedir, self.ctrlchnlname)
+        logging.debug("nodefile filename(%s) mode(%s)", filename, mode)
         file_path = os.path.join(self.nodedir, filename)
         with open(file_path, "w") as f:
             os.chmod(f.name, mode)

daemon/core/nodes/lxd.py

@@ -262,7 +262,7 @@ class LxcNode(CoreNode):
         :return: nothing
         :raises CoreCommandError: when a non-zero exit status occurs
         """
-        logging.info("mounting source(%s) target(%s)", source, target)
+        logging.debug("mounting source(%s) target(%s)", source, target)
         raise Exception("not supported")
 
     def nodefile(self, filename, contents, mode=0o644):
@@ -274,8 +274,8 @@ class LxcNode(CoreNode):
         :param int mode: mode for file
         :return: nothing
         """
-        logging.info("node dir(%s) ctrlchannel(%s)", self.nodedir, self.ctrlchnlname)
-        logging.info("nodefile filename(%s) mode(%s)", filename, mode)
+        logging.debug("node dir(%s) ctrlchannel(%s)", self.nodedir, self.ctrlchnlname)
+        logging.debug("nodefile filename(%s) mode(%s)", filename, mode)
         file_path = os.path.join(self.nodedir, filename)
         with open(file_path, "w") as f:
             os.chmod(f.name, mode)

daemon/core/nodes/network.py

@@ -1153,7 +1153,7 @@ class WlanNode(CoreNetwork):
         :param dict config: configuration for model being set
         :return: nothing
         """
-        logging.info("adding model: %s", model.name)
+        logging.debug("node(%s) setting model: %s", self.name, model.name)
         if model.config_type == RegisterTlvs.WIRELESS.value:
             self.model = model(session=self.session, _id=self.id)
             self.updatemodel(config)
@@ -1169,7 +1169,7 @@ class WlanNode(CoreNetwork):
     def updatemodel(self, config):
         if not self.model:
             raise ValueError("no model set to update for node(%s)", self.id)
-        logging.info(
+        logging.debug(
             "node(%s) updating model(%s): %s", self.id, self.model.name, config
         )
         self.model.update_config(config)

daemon/core/services/coreservices.py

@@ -414,7 +414,6 @@ class CoreServices(object):
                     "unknown service(%s) for node(%s)", service_name, node.name
                 )
                 continue
-            logging.info("adding service to node(%s): %s", node.name, service_name)
             node.services.append(service)
 
     def all_configs(self):
@@ -483,7 +482,9 @@ class CoreServices(object):
         :return: nothing
         """
         logging.info(
-            "booting node services: %s", " -> ".join([x.name for x in boot_path])
+            "booting node(%s) services: %s",
+            node.name,
+            " -> ".join([x.name for x in boot_path]),
         )
         for service in boot_path:
             try:
@@ -743,9 +744,6 @@ class CoreServices(object):
         :param CoreService service: service to reconfigure
         :return: nothing
         """
-        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:

daemon/core/xml/corexml.py

@@ -360,7 +360,7 @@ class CoreXmlWriter(object):
 
             for model_name in all_configs:
                 config = all_configs[model_name]
-                logging.info(
+                logging.debug(
                     "writing mobility config node(%s) model(%s)", node_id, model_name
                 )
                 mobility_configuration = etree.SubElement(

daemon/scripts/core-daemon

@@ -81,7 +81,7 @@ def cored(cfg, use_ovs):
     # close handlers
     close_onexec(server.fileno())
 
-    logging.info("tcp/udp servers started, listening on: %s:%s", host, port)
+    logging.info("CORE TLV API TCP/UDP listening on: %s:%s", host, port)
     server.serve_forever()