Capture lower level errors in validate.py reported in C++

src/ifcopenshell-python/ifcopenshell/validate.py

@@ -54,7 +54,9 @@ class json_logger:
         self.instance = instance
 
     def log(self, level, message, *args, **kwargs):
-        self.statements.append(log_entry_type(level, message % args, kwargs.get("instance"))._asdict())
+        self.statements.append(
+            log_entry_type(level, message % args, kwargs.get("instance"))._asdict()
+        )
 
     def __getattr__(self, level):
         return functools.partial(self.log, level, instance=self.instance)
@@ -74,34 +76,41 @@ simple_type_python_mapping = {
 
 def annotate_inst_attr_pos(inst, pos):
     def get_pos():
-        depth=0
+        depth = 0
-        idx=-1
+        idx = -1
         for c in str(inst):
-            if c == '(':
+            if c == "(":
                 depth += 1
                 if depth == 1:
                     idx = 0
                     yield -1
                 else:
                     yield idx
-            elif c == ')':
+            elif c == ")":
                 depth -= 1
                 if depth == 0:
                     idx = -1
                     yield -1
                 else:
                     yield idx
-            elif depth == 1 and c == ',':
+            elif depth == 1 and c == ",":
                 idx += 1
                 yield -1
             else:
                 yield idx
+
     return "".join(" ^"[i == pos] for i in get_pos())
 
 
 def format(val):
-    if isinstance(val, tuple) and val and isinstance(val[0], ifcopenshell.entity_instance):
+    if (
-        return "[\n%s\n    ]" % "\n".join("      {}. {}".format(*x) for x in enumerate(val, start=1))
+        isinstance(val, tuple)
+        and val
+        and isinstance(val[0], ifcopenshell.entity_instance)
+    ):
+        return "[\n%s\n    ]" % "\n".join(
+            "      {}. {}".format(*x) for x in enumerate(val, start=1)
+        )
     else:
         return repr(val)
 
@@ -117,9 +126,13 @@ def assert_valid_inverse(attr, val, schema):
         b1 = attr.bound1()
         b2 = attr.bound2()
 
-        attr_formatted = f"{attr.name()} : {aggr} [{b1}:{b2}] OF {ent_ref} FOR {attr_ref}"
+        attr_formatted = (
+            f"{attr.name()} : {aggr} [{b1}:{b2}] OF {ent_ref} FOR {attr_ref}"
+        )
 
-        raise ValidationError(f"With inverse:\n    {attr_formatted}\nValue:\n    {format(val)}\nNot valid\n")
+        raise ValidationError(
+            f"With inverse:\n    {attr_formatted}\nValue:\n    {format(val)}\nNot valid\n"
+        )
     return True
 
 
@@ -148,7 +161,9 @@ def assert_valid(attr, val, schema):
         else:
             invalid = type(val) != simple_type_python
     elif isinstance(attr_type, (entity_type, type_declaration)):
-        invalid = not isinstance(val, ifcopenshell.entity_instance) or not val.is_a(attr_type.name())
+        invalid = not isinstance(val, ifcopenshell.entity_instance) or not val.is_a(
+            attr_type.name()
+        )
     elif isinstance(attr_type, select_type):
         val_to_use = val
         if isinstance(schema.declaration_by_name(val.is_a()), enumeration_type):
@@ -157,18 +172,26 @@ def assert_valid(attr, val, schema):
             else:
                 invalid = True
         if not invalid:
-            invalid = not any(try_valid(x, val_to_use, schema) for x in attr_type.select_list())
+            invalid = not any(
+                try_valid(x, val_to_use, schema) for x in attr_type.select_list()
+            )
     elif isinstance(attr_type, enumeration_type):
         invalid = val not in attr_type.enumeration_items()
     elif isinstance(attr_type, aggregation_type):
         b1, b2 = attr_type.bound1(), attr_type.bound2()
         ty = attr_type.type_of_element()
-        invalid = len(val) < b1 or (b2 != -1 and len(val) > b2) or not all(assert_valid(ty, v, schema) for v in val)
+        invalid = (
+            len(val) < b1
+            or (b2 != -1 and len(val) > b2)
+            or not all(assert_valid(ty, v, schema) for v in val)
+        )
     else:
         raise NotImplementedError("Not impl %s %s" % (type(attr_type), attr_type))
 
     if invalid:
-        raise ValidationError(f"With attribute:\n    {attr}\nValue:\n    {val}\nNot valid\n")
+        raise ValidationError(
+            f"With attribute:\n    {attr}\nValue:\n    {val}\nNot valid\n"
+        )
 
     return True
 
@@ -180,9 +203,42 @@ def try_valid(attr, val, schema):
         return False
 
 
+def log_internal_cpp_errors(filename, logger):
+    import re
+    import bisect
+
+    chr_offset_re = re.compile("at offset (\d+)\s*")
+
+    log = ifcopenshell.get_log()
+    msgs = list(map(json.loads, filter(None, log.split("\n"))))
+    chr_offsets = [chr_offset_re.findall(m["message"]) for m in msgs]
+    if chr_offsets:
+
+        # The file is opened in binary mode, in order
+        # to correspond with the offsets reported by
+        # IfcOpenShell C++
+        lines = list(open(filename, "rb"))
+        lengths = list(map(len, lines))
+        cumsum = 0
+        cs = [cumsum := cumsum + x for x in lengths]
+
+        for offsets, msg in zip(chr_offsets, msgs):
+            if offsets:
+                line = lines[bisect.bisect_left(cs, int(offsets[0]))].decode(
+                    "ascii", errors="ignore"
+                )
+                m = chr_offset_re.sub("", msg["message"])
+
+                if hasattr(logger, "set_instance"):
+                    logger.set_instance(line)
+                    logger.error(m)
+                else:
+                    logger.error("For instance:\n    %s\n%s", line, m)
+
+
 def validate(f, logger):
     """
-    For an IFC population model `f` validate whether the entity attribute values are correctly supplied. As this
+    For an IFC population model `f` (or filepath to such a file) validate whether the entity attribute values are correctly supplied. As this
     is a function that is applied after a file has been parsed, certain types of errors in syntax, duplicate
     numeric identifiers or invalidate entity names are not caught by this function. Some of these might have been
     logged and can be retrieved by calling `ifcopenshell.get_log()`. A verification of the type, entity and global
@@ -195,7 +251,23 @@ def validate(f, logger):
     to one of the leaves. For enumerations it is checked that the value is indeed on of the items. For aggregations it
     is checked that the elements and the cardinality conforms. Type declarations (IfcInteger which is an integer) are
     unpacked until one of the above cases is reached.
+
+    It is recommended to supply the path to the file, so that internal C++ errors reported during the parse stage
+    are also captured.
     """
+    filename = None
+    if not isinstance(f, ifcopenshell.file):
+
+        # get_log() clears log existing output
+        ifcopenshell.get_log()
+        # @todo restore log format
+        ifcopenshell.ifcopenshell_wrapper.set_log_format_json()
+
+        filename = f
+        f = ifcopenshell.open(f)
+
+        log_internal_cpp_errors(filename, logger)
+
     schema = ifcopenshell.ifcopenshell_wrapper.schema_by_name(f.schema)
     for inst in f:
         if hasattr(logger, "set_instance"):
@@ -230,7 +302,9 @@ def validate(f, logger):
                 has_invalid_value = True
 
         if not has_invalid_value:
-            for i, (attr, val, is_derived) in enumerate(zip(attrs, inst, entity.derived())):
+            for i, (attr, val, is_derived) in enumerate(
+                zip(attrs, inst, entity.derived())
+            ):
 
                 if val is None and not (is_derived or attr.optional()):
                     if hasattr(logger, "set_instance"):
@@ -240,7 +314,7 @@ def validate(f, logger):
                             "For instance:\n    %s\n    %s\nWith attribute:\n    %s\nNot optional\n",
                             inst,
                             annotate_inst_attr_pos(inst, i),
-                            attr
+                            attr,
                         )
 
                 if val is not None:
@@ -251,10 +325,12 @@ def validate(f, logger):
                         if hasattr(logger, "set_instance"):
                             logger.error(str(e))
                         else:
-                            logger.error("For instance:\n    %s\n    %s\n%s",
+                            logger.error(
+                                "For instance:\n    %s\n    %s\n%s",
                                 inst,
                                 annotate_inst_attr_pos(inst, i),
-                                e)
+                                e,
+                            )
 
         for attr in entity.all_inverse_attributes():
             val = getattr(inst, attr.name())
@@ -266,6 +342,14 @@ def validate(f, logger):
                 else:
                     logger.error("For instance:\n    %s\n%s", inst, e)
 
+    if filename:
+        # IfcOpenShell uses lazy-loading, so entity instance
+        # attributes aren't parsed yet, and counts aren't verified yet.
+        # Re capturing the log when validate() is finished
+        # iterating over every instance so that all attribute counts
+        # are verified.
+        log_internal_cpp_errors(filename, logger)
+
 
 if __name__ == "__main__":
     import sys
@@ -281,10 +365,9 @@ if __name__ == "__main__":
             logger = logging.getLogger("validate")
             logger.setLevel(logging.DEBUG)
 
-        f = ifcopenshell.open(fn)
-
         print("Validating", fn, file=sys.stderr)
-        validate(f, logger)
+
+        validate(fn, logger)
 
         if "--json" in flags:
             print("\n".join(json.dumps(x, default=str) for x in logger.statements))