Improved logging for Shapiro by adding custom logger (rather than reu…

…sing uvicorn's logger).

Added logging to model and renderer.

requirements.txt

@@ -10,4 +10,5 @@ asyncio
 whoosh
 python-liquid
 httpx
-markdown
+markdown
+colorlog

shapiro_model.py

@@ -2,8 +2,11 @@
 from rdflib.plugins.sparql import prepareQuery
 from rdflib.plugin import PluginException
 from typing import Tuple, List
-from shapiro_util import NotFoundException, prune_iri
+from shapiro_util import NotFoundException, prune_iri, get_logger
 from urllib.parse import urlparse
+import logging
+
+log = get_logger("SHAPIRO_RENDER")
 
 class Subscriptable:
 
@@ -46,6 +49,7 @@ class SemanticModelElement(Subscriptable):
                 """)
 
     def __init__(self, iri:str, graph: Graph = None):
+        log.info("Initializing model for {}".format(iri))
         self.iri = iri
         self.graph = graph
         self.label, self.title, self.comment, self.description, self.definition = ( "", "", "", "", "" )
@@ -58,18 +62,22 @@ def __init__(self, iri:str, graph: Graph = None):
                     else:
                         try: 
                             self.graph = Graph().parse(iri)
-                        except PluginException:
+                        except PluginException as p:
+                            log.warn("Creating empty graph in response to {}".format(p))
                             self.graph = Graph() # some schema servers like FOAF don't act nice for term references
                 except Exception as x:
                     # happens when the overall ontology is exists, but any term contained does not resolve (e.g. if the IRIs are wrong)
                     msg = msg = "Cannot resolve the requested term in the existing ontology '{}' ({})".format(iri,x)
+                    log.error(msg)
                     if '#' in iri:
                         msg += " It looks like your IRI contains a URL fragment ('#') not supported by Shapiro."
                     raise NotFoundException(msg)
             self.label, self.title, self.comment, self.description, self.definition = self.get_label_and_descriptions()
             if self.label == "" and self.title == "":
+                log.warn("Empty title, label, description and comment from graph query. Setting label/title to default for {}".format(self.iri))
                 self.label = self.title = prune_iri(self.iri, True)
         else:
+            log.warn("Cannot create graph - setting to 'unnamed' 'n/a' for {}".format(self.iri))
             self.label = self.title = "unnamed"
             self.comment = self.description = self.definition = "n/a"
 
@@ -92,7 +100,6 @@ def get_label_and_descriptions(self) -> Tuple[str, str, str, str, str]:
                     description = str(r.description)
                 if r.definition is not None:
                     definition = str(r.definition)
-        #return (label, title, comment, description, definition)
         return (label, title, comment, description, definition)
 
     def get_types(self) -> str:

shapiro_render.py

@@ -8,9 +8,11 @@
 from urllib.parse import urlparse
 from urllib.error import HTTPError
 from shapiro_model import RdfClass, RdfProperty, SemanticModel, SemanticModelElement, ShaclConstraint, ShaclProperty
-from shapiro_util import NotFoundException, prune_iri
+from shapiro_util import NotFoundException, prune_iri, get_logger
 import markdown as md
 
+log = get_logger("SHAPIRO_RENDER")
+
 def url(value:str) -> str:
     url = urlparse(value)
     if url.scheme != '' and url.scheme is not None:
@@ -34,6 +36,7 @@ def render_page(self, base_url:str, content:str) -> str:
         return self.env.get_template("render_page.html").render(url = base_url, content = content)
 
     def render_model(self, base_url:str, model_iri: str) -> str:
+        log.info("HTML rendering model at {}".format(model_iri), stack_info=True)
         s = SemanticModel(model_iri)
         class_list = s.get_classes()
         shape_list = s.get_node_shapes()
@@ -61,6 +64,7 @@ def render_model(self, base_url:str, model_iri: str) -> str:
         return self.render_page( base_url, content )
 
     def render_model_element( self, base_url:str, iri: str) -> str:
+        log.info("HTML rendering model element at {}".format(iri))
         s = SemanticModel(iri)
         content = ""
         for t in s.get_types_of_instance(iri):
@@ -73,10 +77,14 @@ def render_model_element( self, base_url:str, iri: str) -> str:
             elif t == s.SHACL_PROPERTY:
                 content += self.render_shacl_property(base_url, s)
         if content == "" or content is None:
-            raise NotFoundException("Cannot render HTML for {} (element not found, or type of element could not be determined)".format(iri))
+            msg = "Cannot render HTML for {} (element not found, or type of element could not be determined)".format(iri)
+            log.error(msg)
+            raise NotFoundException(msg)
+        log.info("HTML rendering full page for model element at {}".format(iri))
         return self.render_page( base_url, content )
 
     def render_class(self, base_url:str, model:SemanticModel) -> str:
+        log.info("HTML rendering class at {}".format(model.iri))
         for c in model.get_classes():
             if c.iri == model.iri:
                 prop_types = {}
@@ -98,6 +106,7 @@ def render_class(self, base_url:str, model:SemanticModel) -> str:
                 )
 
     def render_property(self, base_url:str, model:SemanticModel) -> str:
+        log.info("HTML rendering property at {}".format(model.iri))
         for p in model.get_properties():
             if p.iri == model.iri:
                 shacl_props = p.get_shacl_properties()
@@ -122,6 +131,7 @@ def render_property(self, base_url:str, model:SemanticModel) -> str:
                 )
 
     def render_nodeshape(self, base_url:str, model:SemanticModel) -> str:
+        log.info("HTML rendering nodeshape at {}".format(model.iri))
         for n in model.get_node_shapes():
             if n.iri == model.iri:
                 shacl_props = n.get_shacl_properties()
@@ -144,6 +154,7 @@ def render_nodeshape(self, base_url:str, model:SemanticModel) -> str:
                 )
 
     def render_shacl_property(self, base_url:str, model:SemanticModel) -> str:
+        log.info("HTML rendering SHACL property at {}".format(model.iri))
         shacl_props = model.get_shacl_properties()
         for sp in shacl_props:
             if sp.iri == model.iri:

shapiro_server.py

@@ -1,4 +1,5 @@
 from abc import abstractmethod
+import colorlog
 import uvicorn
 import asyncio
 import argparse
@@ -25,7 +26,7 @@
 from liquid import StrictUndefined
 from liquid import FileSystemLoader
 from shapiro_render import HtmlRenderer
-from shapiro_util import BadSchemaException, NotFoundException
+from shapiro_util import BadSchemaException, NotFoundException, get_logger
 
 MIME_HTML = "text/html"
 MIME_JSONLD = "application/ld+json"
@@ -53,7 +54,7 @@
 
 HTML_RENDERER = HtmlRenderer()
 
-log = logging.getLogger("uvicorn")
+log = get_logger("SHAPIRO_SERVER")
 
 app = FastAPI()
 
@@ -698,6 +699,7 @@ def get_ranked_mime_types(accept_header: str):
     weights = []
     q_buckets = {}
     for mime_type in mime_types:
+        mime_type = mime_type.strip()
         if mime_type.split(";")[0] == mime_type:
             # no quality factor
             if 1.0 not in weights:

shapiro_util.py

@@ -1,4 +1,18 @@
 from urllib.parse import urlparse
+import colorlog
+import logging
+
+handler = colorlog.StreamHandler()
+handler.setFormatter(colorlog.ColoredFormatter(
+    '%(asctime)s  %(log_color)s%(levelname)-8s  %(name)-14s  %(reset)s%(message)s',
+    datefmt = "%Y-%m-%d %H:%M:%S"
+))
+
+def get_logger(name:str):
+    logger = colorlog.getLogger(name)
+    logger.addHandler(handler)
+    logger.setLevel(logging.INFO)
+    return logger
 
 class BadSchemaException(Exception):