logging added to config parser.

aif/config/parser.py

@@ -20,6 +20,7 @@ class Config(object):
         self.xsd = None
         self.defaultsParser = None
         self.obj = None
+        _logger.debug('Instantiated {0}.'.format(type(self).__name__))
 
     def main(self, validate = True, populate_defaults = True):
         self.fetch()
@@ -41,51 +42,68 @@ class Config(object):
         raw_xsd = None
         base_url = None
         if xsdpath:
+            _logger.debug('XSD path specified.')
+            orig_xsdpath = xsdpath
             xsdpath = os.path.abspath(os.path.expanduser(xsdpath))
+            _logger.debug('Transformed XSD path: {0} => {1}'.format(orig_xsdpath, xsdpath))
             if not os.path.isfile(xsdpath):
-                raise ValueError(('An explicit XSD path was specified but '
+                _logger.error('The specified XSD path {0} does not exist on the local filesystem.'.format(xsdpath))
-                                  'does not exist on the local filesystem'))
+                raise ValueError('Specified XSD path does not exist')
             with open(xsdpath, 'rb') as fh:
                 raw_xsd = fh.read()
             base_url = os.path.split(xsdpath)[0]
         else:
+            _logger.debug('No XSD path specified; getting it from the configuration file.')
             xsi = self.xml.nsmap.get('xsi', 'http://www.w3.org/2001/XMLSchema-instance')
+            _logger.debug('xsi: {0}'.format(xsi))
             schemaLocation = '{{{0}}}schemaLocation'.format(xsi)
             schemaURL = self.xml.attrib.get(schemaLocation,
                                             'https://schema.xml.r00t2.io/projects/aif.xsd')
+            _logger.debug('Detected schema map: {0}'.format(schemaURL))
             split_url = schemaURL.split()
             if len(split_url) == 2:  # a properly defined schemaLocation
                 schemaURL = split_url[1]
             else:
                 schemaURL = split_url[0]  # a LAZY schemaLocation
+            _logger.info('Detected schema location: {0}'.format(schemaURL))
             if schemaURL.startswith('file://'):
                 schemaURL = re.sub(r'^file://', r'', schemaURL)
+                _logger.debug('Fetching local file {0}'.format(schemaURL))
                 with open(schemaURL, 'rb') as fh:
                     raw_xsd = fh.read()
                 base_url = os.path.dirname(schemaURL)
             else:
+                _logger.debug('Fetching remote file: {0}'.format(schemaURL))
                 req = requests.get(schemaURL)
                 if not req.ok:
-                    # TODO: logging!
+                    _logger.error('Unable to fetch XSD.')
                     raise RuntimeError('Could not download XSD')
                 raw_xsd = req.content
                 base_url = os.path.split(req.url)[0]  # This makes me feel dirty.
+        _logger.debug('Loaded XSD at {0} ({1} bytes).'.format(xsdpath, len(raw_xsd)))
+        _logger.debug('Parsed XML base URL: {0}'.format(base_url))
         self.xsd = etree.XMLSchema(etree.XML(raw_xsd, base_url = base_url))
+        _logger.info('Rendered XSD.')
         return(None)
 
     def parseRaw(self, parser = None):
-        # self.xml = etree.parse(self.raw, parser = parser)
         self.xml = etree.fromstring(self.raw, parser = parser)
-        # self.namespaced_xml = etree.parse(self.raw, parser = parser)
+        _logger.debug('Generated xml.')
         self.namespaced_xml = etree.fromstring(self.raw, parser = parser)
+        _logger.debug('Generated namespaced xml.')
         self.tree = self.xml.getroottree()
+        _logger.debug('Generated tree.')
         self.namespaced_tree = self.namespaced_xml.getroottree()
+        _logger.debug('Generated namespaced tree.')
         self.tree.xinclude()
+        _logger.debug('Parsed XInclude for tree.')
         self.namespaced_tree.xinclude()
+        _logger.debug('Parsed XInclude for namespaced tree.')
         self.stripNS()
         return(None)
 
     def populateDefaults(self):
+        _logger.info('Populating missing values with defaults from XSD.')
         if not self.xsd:
             self.getXSD()
         if not self.defaultsParser:
@@ -95,6 +113,7 @@ class Config(object):
 
     def pythonize(self, stripped = True, obj = 'tree'):
         # https://bugs.launchpad.net/lxml/+bug/1850221
+        _logger.debug('Pythonizing to native objects')
         strobj = self.toString(stripped = stripped, obj = obj)
         self.obj = objectify.fromstring(strobj)
         objectify.annotate(self.obj)
@@ -102,38 +121,49 @@ class Config(object):
         return(None)
 
     def removeDefaults(self):
+        _logger.info('Removing default values from missing values.')
         self.parseRaw()
         return(None)
 
     def stripNS(self, obj = None):
+        _logger.debug('Stripping namespace.')
         # https://stackoverflow.com/questions/30232031/how-can-i-strip-namespaces-out-of-an-lxml-tree/30233635#30233635
         xpathq = "descendant-or-self::*[namespace-uri()!='']"
         if not obj:
+            _logger.debug('No XML object selected; using instance\'s xml and tree.')
             for x in (self.tree, self.xml):
                 for e in x.xpath(xpathq):
                     e.tag = etree.QName(e).localname
         elif isinstance(obj, (etree._Element, etree._ElementTree)):
+            _logger.debug('XML object provided: {0}'.format(etree.tostring(obj)))
             obj = copy.deepcopy(obj)
             for e in obj.xpath(xpathq):
                 e.tag = etree.QName(e).localname
             return(obj)
         else:
+            _logger.error('A non-XML object was provided.')
             raise ValueError('Did not know how to parse obj parameter')
         return(None)
 
     def toString(self, stripped = False, obj = None):
         if isinstance(obj, (etree._Element, etree._ElementTree)):
+            _logger.debug('Converting an XML object to a string')
             if stripped:
+                _logger.debug('Stripping before stringifying.')
                 obj = self.stripNS(obj)
         elif obj in ('tree', None):
             if not stripped:
+                _logger.debug('Converting the instance\'s namespaced tree to a string.')
                 obj = self.namespaced_tree
             else:
+                _logger.debug('Converting the instance\'s stripped tree to a string.')
                 obj = self.tree
         elif obj == 'xml':
             if not stripped:
+                _logger.debug('Converting instance\'s namespaced XML to a string')
                 obj = self.namespaced_xml
             else:
+                _logger.debug('Converting instance\'s stripped XML to a string')
                 obj = self.xml
         else:
             raise ValueError(('obj parameter must be "tree", "xml", or of type '
@@ -145,11 +175,13 @@ class Config(object):
                                 pretty_print = True,
                                 with_tail = True,
                                 inclusive_ns_prefixes = True)
+        _logger.debug('Rendered string output successfully.')
         return(strxml)
 
     def validate(self):
         if not self.xsd:
             self.getXSD()
+        _logger.debug('Checking validation against namespaced tree.')
         self.xsd.assertValid(self.namespaced_tree)
         return(None)
 
@@ -161,11 +193,15 @@ class LocalFile(Config):
         self.source = path
 
     def fetch(self):
-        self.source = os.path.realpath(self.source)
+        orig_src = self.source
+        self.source = os.path.abspath(os.path.expanduser(self.source))
+        _logger.debug('Canonized path: {0} => {1}'.format(orig_src, self.source))
         if not os.path.isfile(self.source):
-            raise ValueError('{0} does not exist'.format(self.source))
+            _logger.error('Config at {0} not found.'.format(self.source))
+            raise ValueError('Config file does not exist'.format(self.source))
         with open(self.source, 'rb') as fh:
             self.raw = fh.read()
+        _logger.debug('Fetched configuration ({0} bytes).'.format(len(self.raw)))
         return(None)
 
 
@@ -178,8 +214,10 @@ class RemoteFile(Config):
     def fetch(self):
         r = requests.get(self.source)
         if not r.ok():
+            _logger.error('Could not fetch {0}'.format(self.source))
             raise RuntimeError('Could not download XML')
         self.raw = r.content
+        _logger.debug('Fetched configuration ({0} bytes).'.format(len(self.raw)))
         return(None)
 
 
@@ -191,6 +229,7 @@ class ConfigStr(Config):
 
     def fetch(self):
         self.raw = self.source.encode('utf-8')
+        _logger.debug('Raw configuration (str) passed in ({0} bytes); converted to bytes.'.format(len(self.raw)))
         return(None)
 
 
@@ -202,6 +241,7 @@ class ConfigBin(Config):
 
     def fetch(self):
         self.raw = self.source
+        _logger.debug('Raw configuration (binary) passed in ({0} bytes); converted to bytes.'.format(len(self.raw)))
         return(None)
 
 
@@ -217,14 +257,18 @@ def getConfig(cfg_ref, validate = True, populate_defaults = True, xsd_path = Non
         try:
             if pattern.search(cfg_ref):
                 cfgobj = configClass(cfg_ref, xsd_path = xsd_path)
+                _logger.info('Config detected as {0}.'.format(configtype))
                 break
         except TypeError:
             ptrn = re.compile(detector['raw'][0].pattern.encode('utf-8'))
             if not ptrn.search(cfg_ref):
-                raise ValueError('Received junk data for cfg_ref')
+                _logger.error('Could not detect which configuration type was passed.')
+                raise ValueError('Unespected/unparseable cfg_ref.')
             else:
+                _logger.info('Config detected as ConfigBin.')
                 cfgobj = ConfigBin(cfg_ref, xsd_path = xsd_path)
                 break
     if cfgobj:
+        _logger.info('Parsing configuration.')
         cfgobj.main(validate = validate, populate_defaults = populate_defaults)
     return(cfgobj)