Resolve "Add DEBUG log writes to soar_bus to show messages in transit"

Closes #35 (closed)

api.py

 from endpoints.send import Send
 from endpoints.token import Token
 from models.token_model import TokenModel
+from logger import setup_logging
 
 
-LOG_LEVEL = logging.getLevelName(os.getenv('LOG_LEVEL', 'INFO'))
-logging.basicConfig(level=LOG_LEVEL)
-logging.getLogger("pika").setLevel(logging.ERROR)
+setup_logging()
 token = TokenModel()
 token.setSecret()
 

logger.py

+import logging 
+import os 
+
+
+def setup_logging():
+    # Add TRACE level for logging full message content
+    TRACE_LEVEL = 9 
+    logging.addLevelName(TRACE_LEVEL, "TRACE")
+    def logger_trace(self, message, *args, **kws):
+        self._log(TRACE_LEVEL, message, args, **kws)
+
+    def trace(message, *args, **kwargs): 
+        logger = logging.getLogger()
+        if (logger.isEnabledFor(TRACE_LEVEL)):
+            logger.trace(message, *args, **kwargs)         
+
+    logging.Logger.trace = logger_trace
+    logging.trace = trace
+
+    # Set log level from env var or default if not set 
+    LOG_LEVEL = logging.getLevelName(os.getenv('LOG_LEVEL', 'INFO'))
+    logging.basicConfig(level=LOG_LEVEL)
+
+    # Downgrade log level for pika/watchdog which are noisy in DEBUG mode
+    logging.getLogger("pika").setLevel(logging.ERROR)
+    logging.getLogger("watchdog").setLevel(logging.ERROR)

rmq.py

 
 def write_to_queue(queue_name, msg):
     logging.debug(f"Write to queue: {queue_name}")
+    logging.trace(msg)
     # write a single message to a queue
     connection, channel = pika_connect(host=host)
     setup_queue(channel=channel, queue_name=queue_name)
             break
     connection.close()
     logging.debug(f"Messages found: {len(messages)}")
+    logging.trace(json.dumps(messages))
     return messages
 
 
 
     def broadcast_callback(ch, method, properties, body):
         logging.debug(f"Broadcast from queue: {queue_name} to exchange {exchange_name}")    
+        logging.trace(body.decode())
         deliver_to_exchange(channel=ch, body=body, exchange_name=exchange_name)
         ch.basic_ack(delivery_tag=method.delivery_tag)
 
 
     def forward_callback(ch, method, properties, body):
         logging.debug(f"Forward from queue: {from_queue} to queue: {to_queue}")    
+        logging.trace(body.decode())
         channel.basic_publish(
             exchange="",
             routing_key=to_queue,
         message = json.loads(body.decode())
         topic = message["topic"]
         logging.debug(f"Publish from queue: {queue_name} to exchange {exchange_name} with topic {topic}")
+        logging.trace(body.decode())
         deliver_to_exchange(
             channel=ch, body=body, exchange_name=exchange_name, topic=topic
         )

soar_bus.py

 from rmq import broadcast, forward, publish, subscribe
 from models.client_model import ClientModel
 
-LOG_LEVEL = logging.getLevelName(os.getenv('LOG_LEVEL', 'INFO'))
-logging.basicConfig(level=LOG_LEVEL)
-logging.getLogger("pika").setLevel(logging.ERROR)
-logging.getLogger("watchdog").setLevel(logging.ERROR)
+from logger import setup_logging
+
+
+setup_logging()
 
 THREADS = {}
 RUNNING_CLIENTS = []
 def update_clients(updated_client_ids):
     global RUNNING_CLIENTS
     with concurrent.futures.ProcessPoolExecutor() as executor:
-        logging.info("Old: " + str(RUNNING_CLIENTS))
-        logging.info("New: " + str(updated_client_ids))
+        logging.debug("Old: " + str(RUNNING_CLIENTS))
+        logging.debug("New: " + str(updated_client_ids))
 
         for client_id in updated_client_ids:
             if client_id not in RUNNING_CLIENTS: