From ed2863108d972e9e355e0726983338a8fccc7ad3 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Pavel=20K=C3=A1cha?= <ph@cesnet.cz>
Date: Sat, 17 Jan 2015 18:33:00 +0100
Subject: [PATCH] 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 | 50 ++++++++++++++++++--------
1 file changed, 36 insertions(+), 14 deletions(-)
diff --git a/warden3/warden_server/warden_server.py b/warden3/warden_server/warden_server.py
index e876648..64e6224 100755
--- a/warden3/warden_server/warden_server.py
+++ b/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"]
--
GitLab