Request now retains randomly generated id, distinct for each query.

Logging now automatically adds this request id + called method into all log messages.

warden3/warden_server/warden_server.py

@@ -20,6 +20,7 @@ from math import trunc
 from io import BytesIO
 from urlparse import parse_qs
 from os import path
+from random import randint
 
 # for local version of up to date jsonschema
 sys.path.append(path.join(path.dirname(__file__), "..", "lib"))
@@ -116,12 +117,29 @@ def StreamLogger(stream=sys.stderr, level=logging.INFO):
 
 
 
+class LogRequestFilter(logging.Filter):
+
+    def __init__(self, req):
+        logging.Filter.__init__(self)
+        self.req = req
+
+
+    def filter(self, record):
+        record.req_preamble = ""
+        if self.req.env:
+            record.req_preamble = "%8x/%s: " % (self.req.req_id or 0, self.req.path)
+        return True
+
+
+
 def FileLogger(req, filename, level=logging.INFO):
 
     fhand = logging.FileHandler(filename)
-    fform = logging.Formatter('%(asctime)s %(filename)s[%(process)d]: (%(levelname)s) %(message)s')
+    fform = logging.Formatter('%(asctime)s %(filename)s[%(process)d]: (%(levelname)s) %(req_preamble)s%(message)s')
     fhand.setFormatter(fform)
+    ffilt = LogRequestFilter(req)
     logger = get_clean_root_logger(level)
+    logger.addFilter(ffilt)
     logger.addHandler(fhand)
     logging.info("Initialized FileLogger(req=%s, filename=\"%s\", \"%s\")" % (type(req).__name__, filename, level))
 
@@ -132,7 +150,9 @@ def SysLogger(req, socket="/dev/log", facility=logging.handlers.SysLogHandler.LO
     fhand = logging.handlers.SysLogHandler(address=socket, facility=facility)
     fform = logging.Formatter('%(filename)s[%(process)d]: (%(levelname)s) %(message)s')
     fhand.setFormatter(fform)
+    ffilt = LogRequestFilter(req)
     logger = get_clean_root_logger(level)
+    logger.addFilter(ffilt)
     logger.addHandler(fhand)
     logging.info("Initialized SysLogger(req=%s, socket=\"%s\", facility=\"%s\", level=\"%s\")" % (type(req).__name__, socket, facility, level))
 
@@ -171,10 +191,14 @@ class Request(Object):
         return "%s()" % (type(self).__name__, str(self.env), str(self.client))
 
 
-    def reset(self, env=None, client=None, path=None):
+    def reset(self, env=None, client=None, path=None, req_id=None):
         self.env = {} if env is None else env
         self.client = {} if client is None else client
         self.path = "" if path is None else path
+        if req_id is not None:
+            self.req_id = req_id
+        else:
+            self.req_id = 0 if env is None else randint(0x00000000, 0xFFFFFFFF)
 
 
 
@@ -258,7 +282,7 @@ class X509Authenticator(NoAuthenticator):
             service = client["services"][identity]
         except KeyError:
             # We are unable to pair service in message to service in db
-            logging.info("Auth failed: '%s' from event not found in services for client %i" % (identity, client["id"]))
+            logging.info("authorize: failed, '%s' from event not found in services for client %i" % (identity, client["id"]))
             return None
 
         client["service"] = service
@@ -266,12 +290,12 @@ class X509Authenticator(NoAuthenticator):
         # Authorize for sending events
         if (path == "sendEvents"):
             if not (service["write"] or service["test"]):
-                logging.info("Auth failed: service %i (%s) is not allowed to write or test" % (service["service_id"], identity))
+                logging.info("authorize: failed, service %i (%s) is not allowed to write or test" % (service["service_id"], identity))
                 return None
 
             test = 'Test' in event.get('Category', [])
             if not test:
-                logging.info("Auth failed: service %i (%s) does not send Test category in event" % (service["service_id"], identity))
+                logging.info("authorize: failed, service %i (%s) does not send Test category in event" % (service["service_id"], identity))
                 return None
         
         return client
@@ -554,7 +578,7 @@ class Server(ObjectReq):
         for a in intargs:
             del args[a]
         if intargs:
-            logging.info("%s called with internal args: %s" % (path, ", ".join(intargs)))
+            logging.info("sanitize_args: Called with internal args: %s" % ", ".join(intargs))
 
         # silently remove surplus arguments - potential forward
         # compatibility (unknown args will get ignored)
@@ -562,7 +586,7 @@ class Server(ObjectReq):
         for a in badargs:
             del args[a]
         if badargs:
-            logging.info("%s called with superfluous args: %s" % (path, ", ".join(badargs)))
+            logging.info("sanitize_args: Called with superfluous args: %s" % ", ".join(badargs))
 
         return args
 
@@ -598,7 +622,7 @@ class Server(ObjectReq):
                     exc=sys.exc_info(), detail={"args": injson})
 
             args = parse_qs(environ.get('QUERY_STRING', ""))
-            logging.debug("%s called with %s" % (path, str(args)))
+            logging.debug("calling handler with %s" % str(args))
             if events:
                 args["events"] = events
 
@@ -729,7 +753,7 @@ class WardenHandler(ObjectReq):
             try:
                 id = self.db.getLastReceivedId(self.req.client)
             except Exception, e:
-                logging.info("getEvents: cannot getLastReceivedId - " + type(e).__name__ + ": " + e)
+                logging.info("cannot getLastReceivedId - " + type(e).__name__ + ": " + e)
                 
         if id is None:
             # First access, remember the guy and get him last event
@@ -749,7 +773,7 @@ class WardenHandler(ObjectReq):
             count = min(count, self.get_events_limit)
 
         res = self.db.fetch_events(self.req.client, id, count, cat, nocat, tag, notag, group, nogroup)
-        logging.info("getEvents(%d, %d, %s, %s, %s, %s, %s, %s): sending %d events" % (
+        logging.info("fetch_events(%d, %d, %s, %s, %s, %s, %s, %s) returned %d events" % (
             id, count, cat, nocat, tag, notag, group, nogroup, len(res["events"])))
 
         self.db.insertLastReceivedId(self.req.client, res['lastid'])
@@ -788,9 +812,9 @@ class WardenHandler(ObjectReq):
 
             saved += 1
 
-        logging.info("sendEvents: Saved %i events" % saved)
+        logging.info("Saved %i events" % saved)
         if errs:
-            logging.info("sendEvents errors: \n%s\n" % str(errs))
+            logging.info("Errors: \n%s\n" % str(errs))
 
         return errs
 
@@ -939,8 +963,6 @@ def build_server(conf):
         sect_name = sect_name.lower()
         sect_def = section_def[sect_name]
 
-        #logging.debug("Testing %s" % sect_name)
-
         try:    # Object type defined?
             objtype = config["type"]
             del config["type"]