Error is now raised via req.error helper, which automatically adds already...

Error is now raised via req.error helper, which automatically adds already known info (method, request id), thus calls are terser.
Client's Error communicates request id, if received from server.
exc_info made explicit everywhere. Automatic exc_info gathering sometimes returned bogus info about unrelated exception from far before.

warden3/warden_client/warden_client.py

@@ -58,13 +58,14 @@ class Error(Exception):
     """
 
     def __init__(self, message, logger=None, error=None, prio="error", method=None,
-            detail=None, exc=None):
+            req_id=None, detail=None, exc=None):
 
+        self.message = message
         self.error = error
         self.method = method
-        self.message = message
+        self.req_id = req_id
         self.detail = detail
-        (self.exctype, self.excval, self.exctb) = exc or exc_info()
+        (self.exctype, self.excval, self.exctb) = exc or (None, None, None)
         self.cause = self.excval # compatibility with other exceptions
         if logger:
             getattr(logger, prio, "error")(str(self))
@@ -96,7 +97,9 @@ class Error(Exception):
         out = []
         out.append("(%s)" % (self.error or "local"))
         if self.method is not None:
-            out.append(" in \"%s\"" % self.method)
+            out.append(" in %s" % self.method)
+        if self.req_id is not None:
+            out.append("(%8x)" % self.req_id)
         if self.message is not None:
             out.append(": %s" % self.message)
         if self.excval is not None:
@@ -194,7 +197,7 @@ class Client(object):
                 fl.setFormatter(format_time)
                 self.logger.addHandler(fl)
             except Exception as e:
-                Error("Unable to setup file logging", self.logger)
+                Error("Unable to setup file logging", self.logger, exc=exc_info())
 
         if syslog is not None:
             try:
@@ -205,7 +208,7 @@ class Client(object):
                 sl.setFormatter(format_notime)
                 self.logger.addHandler(sl)
             except Exception as e:
-                Error("Unable to setup syslog logging", self.logger)
+                Error("Unable to setup syslog logging", self.logger, exc=exc_info())
 
         if not (errlog or filelog or syslog):
             # User wants explicitly no logging, so let him shoot its socks off.
@@ -234,7 +237,7 @@ class Client(object):
                 return Error("Don't know how to connect to \"%s\"" % self.url.scheme, self.logger,
                         detail={"url": self.url.geturl()})
         except Exception:
-            return Error("HTTPS connection failed", self.logger,
+            return Error("HTTPS connection failed", self.logger, exc=exc_info(),
                 detail={
                     "url": self.url.geturl(),
                     "timeout": self.timeout,
@@ -264,7 +267,7 @@ class Client(object):
                 data = json.dumps(payload)
         except:
             return Error("Serialization to JSON failed", self.logger,
-                method=func, detail=payload)
+                exc=exc_info(), method=func, detail=payload)
 
         self.headers = {
             "Content-Type": "application/json",
@@ -286,7 +289,7 @@ class Client(object):
             self.conn.request("POST", loc, data, self.headers)
         except:
             return Error("Sending of request to server failed", self.logger,
-                method=func, detail={
+                exc=exc_info(), method=func, detail={
                     "loc": loc,
                     "headers": self.headers,
                     "data": data})
@@ -294,19 +297,19 @@ class Client(object):
         try:
             res = self.conn.getresponse()
         except:
-            return Error("HTTP reply failed", self.logger, method=func)
+            return Error("HTTP reply failed", self.logger, method=func, exc=exc_info())
 
         try:
             response_data = res.read()
         except:
-            return Error("Fetching HTTP data from server failed", self.logger, method=func)
+            return Error("Fetching HTTP data from server failed", self.logger, method=func, exc=exc_info())
 
         if res.status==httplib.OK:
             try:
                 data = json.loads(response_data)
             except:
                 data = Error("JSON message parsing failed", self.logger,
-                    method=func, detail={"response": response_data})
+                    exc=exc_info(), method=func, detail={"response": response_data})
         else:
             try:
                 data = json.loads(response_data)
@@ -315,11 +318,13 @@ class Client(object):
                 data = Error("Generic server HTTP error", self.logger,
                     method=func,
                     error=res.status,
+                    exc=exc_info(),
                     detail={"response": response_data})
             else:
                 data = Error(data.get("message", None), self.logger,
                     method=data.get("method", None),
                     error=res.status,
+                    req_id=data.get("req_id", None),
                     detail=data.get("detail", None))
 
         return data
@@ -334,7 +339,8 @@ class Client(object):
                 f.write(str(id))
         except (ValueError, IOError) as e:
             # Use Error instance just for proper logging
-            Error("Writing id file \"%s\" failed" % idf, self.logger, prio="info", detail={"idstore": idf})
+            Error("Writing id file \"%s\" failed" % idf, self.logger,
+                prio="info", exc=exc_info(), detail={"idstore": idf})
         return id
 
 
@@ -346,7 +352,8 @@ class Client(object):
             with open(idf, "r") as f:
                 id = int(f.read())
         except (ValueError, IOError) as e:
-            Error("Reading id file \"%s\" failed, relying on server" % idf, self.logger, prio="info", detail={"idstore": idf})
+            Error("Reading id file \"%s\" failed, relying on server" % idf,
+                self.logger, prio="info", exc=exc_info(), detail={"idstore": idf})
             id = None
         return id
 
@@ -383,7 +390,8 @@ class Client(object):
             events = res["events"]
             newid = res["lastid"]
         except KeyError:
-            return Error("Server returned bogus reply", self.logger, method="getEvents", detail={"response": res})
+            return Error("Server returned bogus reply", self.logger,
+                method="getEvents", exc=exc_info(), detail={"response": res})
 
         self._saveID(newid)
 

warden3/warden_client/warden_curl_test.sh

@@ -43,6 +43,26 @@ curl \
     $url/getEvents
 echo
 
+echo "Test  Called with unknown category"
+curl \
+    --key $keyfile \
+    --cert $certfile \
+    --cacert $cafile \
+    --connect-timeout 3 \
+    --request POST \
+    $url/getEvents?cat=bflm
+echo
+
+echo "Test  Called with both cat and nocat"
+curl \
+    --key $keyfile \
+    --cert $certfile \
+    --cacert $cafile \
+    --connect-timeout 3 \
+    --request POST \
+    "$url/getEvents?cat=Other&nocat=Test"
+echo
+
 echo "Test  Invalid data for getEvents - silently discarded"
 curl \
     --key $keyfile \

warden3/warden_server/warden_server.py

@@ -33,14 +33,15 @@ VERSION = "3.0-not-even-alpha"
 
 class Error(Exception):
 
-    def __init__(self, message, error=500, method=None,
-            detail=None, exc=(None, None, None)):
+    def __init__(self, message, error=500, exc=None,
+            method=None, req_id=None, detail=None):
+        self.message = message
         self.error = int(error)
+        (self.exctype, self.excval, self.exctb) = exc or (None, None, None)
+        self.cause = self.excval # compatibility with other exceptions
         self.method = method
-        self.message = message
+        self.req_id = req_id
         self.detail = detail
-        (self.exctype, self.excval, self.exctb) = exc or sys.exc_info()
-        self.cause = self.excval # compatibility with other exceptions
 
 
     def __str__(self):
@@ -78,6 +79,8 @@ class Error(Exception):
             d["message"] = self.message
         if self.detail is not None:
             d["detail"] = self.detail
+        if self.req_id is not None:
+            d["req_id"] = self.req_id
         return d
 
 
@@ -118,6 +121,10 @@ def StreamLogger(stream=sys.stderr, level=logging.INFO):
 
 
 class LogRequestFilter(logging.Filter):
+    """ Filter class, instance of which is added to logger class to add
+        info about request automatically into every logline, no matter
+        how it came into existence.
+    """
 
     def __init__(self, req):
         logging.Filter.__init__(self)
@@ -125,9 +132,10 @@ class LogRequestFilter(logging.Filter):
 
 
     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)
+        else:
+            record.req_preamble = ""
         return True
 
 
@@ -201,6 +209,11 @@ class Request(Object):
             self.req_id = 0 if env is None else randint(0x00000000, 0xFFFFFFFF)
 
 
+    def error(self, message, error=500, exc=None, detail=None):
+        return Error(message, error, exc, self.path, self.req_id, detail=detail)
+
+
+
 
 class ObjectReq(Object):
 
@@ -421,8 +434,8 @@ class MySQL(ObjectReq):
             try:
                 mapped_id = section[v]
             except KeyError:
-                raise Error("Wrong tag or category used in query.", 422, method='getEvents', 
-                    exc=sys.exc_info(), detail={"key": v})
+                raise self.req.error("Wrong tag or category used in query.", 422,
+                    sys.exc_info(), detail={"key": v})
 
             if mapped_id % 100:
                 variables_id.append(mapped_id)
@@ -443,14 +456,14 @@ class MySQL(ObjectReq):
         logging.debug("fetch_events: id=%i, count=%i, cat=%s, nocat=%s, tag=%s, notag=%s, group=%s, nogroup=%s" % (id, count, str(cat), str(nocat), str(tag), str(notag), str(group), str(nogroup)))
 
         if cat and nocat:
-            raise Error("Unrealizable conditions. Choose cat or nocat option.", 422, method='getEvents', 
-                        exc=sys.exc_info(), detail={'cat': cat, 'nocat' : nocat})
+            raise self.req.error("Unrealizable conditions. Choose cat or nocat option.", 422,
+                        detail={'cat': cat, 'nocat' : nocat})
         if tag and notag:
-            raise Error("Unrealizable conditions. Choose tag or notag option.", 422, method='getEvents', 
-                        exc=sys.exc_info(), detail={'tag': cat, 'notag' : nocat})
+            raise self.req.error("Unrealizable conditions. Choose tag or notag option.", 422,
+                        detail={'tag': cat, 'notag' : nocat})
         if group and nogroup:
-            raise Error("Unrealizable conditions. Choose group or nogroup option.", 422, method='getEvents', 
-                        exc=sys.exc_info(), detail={'tag': cat, 'notag' : nocat})
+            raise self.req.error("Unrealizable conditions. Choose group or nogroup option.", 422,
+                        detail={'tag': cat, 'notag' : nocat})
 
         sqlwhere = []
         sqlparams = []
@@ -603,23 +616,23 @@ class Server(ObjectReq):
             try:
                 injson = environ['wsgi.input'].read()
             except:
-                raise Error("Data read error.", 408, method=path, exc=sys.exc_info())
+                raise self.req.error("Data read error.", 408, sys.exc_info())
 
             try:
                 method = getattr(self.handler, path)
                 method.exposed    # dummy access to trigger AttributeError
             except Exception:
-                raise Error("You've fallen of the cliff.", 404, method=path)
+                raise self.req.error("You've fallen of the cliff.", 404)
 
             self.req.client = client = self.auth.authenticate(environ)
             if not client:
-                raise Error("I'm watching. Authenticate.", 403, method=path)
+                raise self.req.error("I'm watching. Authenticate.", 403)
 
             try:
                 events = json.loads(injson) if injson else None
-            except Exception:
-                raise Error("Deserialization error", 400, method=path,
-                    exc=sys.exc_info(), detail={"args": injson})
+            except Exception as e:
+                raise self.req.error("Deserialization error", 400,
+                    sys.exc_info(), detail={"args": injson, "parser": str(e)})
 
             args = parse_qs(environ.get('QUERY_STRING', ""))
             logging.debug("calling handler with %s" % str(args))
@@ -634,13 +647,13 @@ class Server(ObjectReq):
                 # which could (although shouldn't) appear in handler code
                 output = json.dumps(result, default=lambda v: str(v))
             except Exception as e:
-                raise Error("Serialization error", 500, method=path,
-                    exc=sys.exc_info(), detail={"args": str(result)})
+                raise self.req.error("Serialization error", 500,
+                    sys.exc_info(), detail={"args": str(result)})
 
         except Error as e:
             exception = e
         except Exception as e:
-            exception = Error("Server exception", 500, method=path, exc=sys.exc_info())
+            exception = self.req.error("Server exception", 500, sys.exc_info())
 
         if exception:
             status = "%d %s" % (exception.error, exception.message)
@@ -695,7 +708,7 @@ class WardenHandler(ObjectReq):
     def getDebug(self):
         auth = self.auth.authorize(self.req.env, self.req.client, self.req.path, None)
         if not auth:
-            raise Error("I'm watching. Authorize.", 403, method='getDebug', detail={"client": self.req.client})
+            raise self.req.error("I'm watching. Authorize.", 403, detail={"client": self.req.client["hostname"]})
 
         return {
             "environment": self.req.env,
@@ -722,7 +735,7 @@ class WardenHandler(ObjectReq):
     def getInfo(self):
         auth = self.auth.authorize(self.req.env, self.req.client, self.req.path, None)
         if not auth:
-            raise Error("I'm watching. Authorize.", 403, method='getDebug', detail={"client": self.req.client})
+            raise self.req.error("I'm watching. Authorize.", 403, detail={"client": self.req.client["hostname"]})
 
         info = {
             "version": VERSION,
@@ -742,7 +755,7 @@ class WardenHandler(ObjectReq):
 
         auth = self.auth.authorize(self.req.env, self.req.client, self.req.path, None)
         if not auth:
-            raise Error("I'm watching. Authorize.", 403, method='getDebug', detail={"client": self.req.client})
+            raise self.req.error("I'm watching. Authorize.", 403, detail={"client": self.req.client["hostname"]})
 
         try:
             id = int(id[0])
@@ -784,10 +797,10 @@ class WardenHandler(ObjectReq):
     @expose
     def sendEvents(self, events=[]):
         if not isinstance(events, list):
-            raise Error("List of events expected.", 400, method="sendEvents")
+            raise self.req.error("List of events expected.", 400)
 
         if len(events)>self.send_events_limit:
-            raise Error("Too much events in one batch.", 413, method="sendEvents",
+            raise self.req.error("Too much events in one batch.", 413,
                 detail={"limit": self.send_events_limit})
 
         saved = 0