From 4251d0dec70f7c9425acc2dc7b1dbcb97907f0a7 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Pavel=20K=C3=A1cha?= <ph@cesnet.cz>
Date: Wed, 7 Sep 2016 17:28:32 +0200
Subject: [PATCH] Reworked logging to not spill to root logger (and to
 webserver logs)

---
 warden3/warden_server/warden_server.py | 47 +++++++++++++-------------
 1 file changed, 23 insertions(+), 24 deletions(-)

diff --git a/warden3/warden_server/warden_server.py b/warden3/warden_server/warden_server.py
index be4a435..625eebb 100755
--- a/warden3/warden_server/warden_server.py
+++ b/warden3/warden_server/warden_server.py
@@ -143,6 +143,7 @@ def get_clean_root_logger(level=logging.INFO):
         logger.removeHandler(logger.handlers[0])
     while logger.filters:
         logger.removeFilter(logger.filters[0])
+    logger.propagate = False
     return logger
 
 
@@ -291,17 +292,17 @@ class PlainAuthenticator(ObjectReq):
         client = self.db.get_client_by_name(hostnames, name, secret)
 
         if not client:
-            logging.info("authenticate: client not found by name: \"%s\", secret: %s, hostnames: %s" % (
+            logging.getLogger(__name__).info("authenticate: client not found by name: \"%s\", secret: %s, hostnames: %s" % (
                 name, secret, str(hostnames)))
             return None
 
         # Clients with 'secret' set must get authenticated by it.
         # No secret turns secret auth off for this particular client.
         if client.secret is not None and secret is None:
-            logging.info("authenticate: missing secret argument")
+            logging.getLogger(__name__).info("authenticate: missing secret argument")
             return None
 
-        logging.info("authenticate: %s" % str(client))
+        logging.getLogger(__name__).info("authenticate: %s" % str(client))
 
         return client
 
@@ -309,25 +310,24 @@ class PlainAuthenticator(ObjectReq):
     def authorize(self, env, client, path, method):
         if method.debug:
             if not client.debug:
-                logging.info("authorize: failed, client does not have debug enabled")
+                logging.getLogger(__name__).info("authorize: failed, client does not have debug enabled")
                 return None
             return client
 
         if method.read:
             if not client.read:
-                logging.info("authorize: failed, client does not have read enabled")
+                logging.getLogger(__name__).info("authorize: failed, client does not have read enabled")
                 return None
             return client
 
         if method.write:
             if not (client.write or client.test):
-                logging.info("authorize: failed, client is not allowed to write or test")
+                logging.getLogger(__name__).info("authorize: failed, client is not allowed to write or test")
                 return None
 
         return client
 
 
-
 class X509Authenticator(PlainAuthenticator):
 
     def get_cert_dns_names(self, pem):
@@ -501,7 +501,7 @@ class MySQL(ObjectReq):
             try:
                 if crs is None:
                     crs = self.con.cursor()
-                logging.debug("execute: %s %s" % (args, kwargs))
+                logging.getLogger(__name__).debug("execute: %s %s" % (args, kwargs))
                 crs.execute(*args, **kwargs)
                 if commit:
                     self.con.commit()
@@ -509,7 +509,7 @@ class MySQL(ObjectReq):
             except my.OperationalError:
                 if not countdown:
                     raise
-                logging.info("execute: Database down, trying to reconnect (%d attempts left)..." % countdown)
+                logging.getLogger(__name__).info("execute: Database down, trying to reconnect (%d attempts left)..." % countdown)
                 if countdown<self.retry_count:
                     sleep(self.retry_pause)    # no need to melt down server on longer outage
                 self.close()
@@ -541,8 +541,7 @@ class MySQL(ObjectReq):
         rows = self.query("".join(query), params, commit=True).fetchall()
 
         if len(rows)>1:
-            logging.warn("get_client_by_name: query returned more than one result: %s" % ", ".join(
-                [str(Client(**row)) for row in rows]))
+            logging.getLogger(__name__).warn("get_client_by_name: query returned more than one result (cert_names = %s, name = %s, secret = %s): %s" % (cert_names, name, secret, ", ".join([str(Client(**row)) for row in rows])))
             return None
 
         return Client(**rows[0]) if rows else None
@@ -712,7 +711,7 @@ class MySQL(ObjectReq):
 
 
     def insertLastReceivedId(self, client, id):
-        logging.debug("insertLastReceivedId: id %i for client %i(%s)" % (id, client.id, client.hostname))
+        logging.getLogger(__name__).debug("insertLastReceivedId: id %i for client %i(%s)" % (id, client.id, client.hostname))
         try:
             self.query("INSERT INTO last_events(client_id, event_id, timestamp) VALUES(%s, %s, NOW())", (client.id, id))
             self.con.commit()
@@ -733,10 +732,10 @@ class MySQL(ObjectReq):
             row = res[0]
         except IndexError:
             id = None
-            logging.debug("getLastReceivedId: probably first access, unable to get id for client %i(%s)" % (client.id, client.hostname))
+            logging.getLogger(__name__).debug("getLastReceivedId: probably first access, unable to get id for client %i(%s)" % (client.id, client.hostname))
         else:
             id = row["id"]
-            logging.debug("getLastReceivedId: id %i for client %i(%s)" % (id, client.id, client.hostname))
+            logging.getLogger(__name__).debug("getLastReceivedId: id %i for client %i(%s)" % (id, client.id, client.hostname))
 
         return id
 
@@ -823,7 +822,7 @@ class Server(ObjectReq):
         for a in intargs:
             del args[a]
         if intargs:
-            logging.info("sanitize_args: Called with internal args: %s" % ", ".join(intargs))
+            logging.getLogger(__name__).info("sanitize_args: Called with internal args: %s" % ", ".join(intargs))
 
         # silently remove surplus arguments - potential forward
         # compatibility (unknown args will get ignored)
@@ -831,7 +830,7 @@ class Server(ObjectReq):
         for a in badargs:
             del args[a]
         if badargs:
-            logging.info("sanitize_args: Called with superfluous args: %s" % ", ".join(badargs))
+            logging.getLogger(__name__).info("sanitize_args: Called with superfluous args: %s" % ", ".join(badargs))
 
         return args
 
@@ -1006,7 +1005,7 @@ class WardenHandler(ObjectReq):
             try:
                 id = self.db.getLastReceivedId(self.req.client)
             except Exception, e:
-                logging.info("cannot getLastReceivedId - " + type(e).__name__ + ": " + str(e))
+                logging.getLogger(__name__).info("cannot getLastReceivedId - " + type(e).__name__ + ": " + str(e))
                 
         if id is None:
             # First access, remember the guy and get him last id
@@ -1034,7 +1033,7 @@ class WardenHandler(ObjectReq):
 
         self.db.insertLastReceivedId(self.req.client, res['lastid'])
 
-        logging.info("sending %d events, lastid is %i" % (len(res["events"]), res["lastid"]))
+        logging.getLogger(__name__).info("sending %d events, lastid is %i" % (len(res["events"]), res["lastid"]))
 
         return res
 
@@ -1114,7 +1113,7 @@ class WardenHandler(ObjectReq):
         else:
             saved = len(events_tosend)
 
-        logging.info("Saved %i events" % saved)
+        logging.getLogger(__name__).info("Saved %i events" % saved)
         if errs:
             raise self.req.error(errors=errs)
 
@@ -1164,7 +1163,7 @@ def fallback_wsgi(environ, start_response, exc_info=None):
     output = '{"errors": [{"error": %d, "message": "%s"}]}' % (
         error, message)
 
-    logging.critical(logline)
+    logging.getLogger(__name__).critical(logline)
     start_response(status, headers)
     return [output]
 
@@ -1309,7 +1308,7 @@ def build_server(conf):
 
         if isinstance(obj, Object):
             # Log only objects here, functions must take care of themselves
-            logging.info("Initialized %s" % str(obj))
+            logging.getLogger(__name__).info("Initialized %s" % str(obj))
 
         objects[sect_name] = obj
         return obj
@@ -1327,11 +1326,11 @@ def build_server(conf):
         for o in ("log", "db", "auth", "validator", "handler", "server"):
             init_obj(o)
     except Exception as e:
-        logging.critical(str(e))
-        logging.debug("", exc_info=sys.exc_info())
+        logging.getLogger(__name__).critical(str(e))
+        logging.getLogger(__name__).debug("", exc_info=sys.exc_info())
         return fallback_wsgi
 
-    logging.info("Server ready")
+    logging.getLogger(__name__).info("Server ready")
 
     return objects["server"]
 
-- 
GitLab