Merge commit '1acce39867' into debug-drawing-faster-failure-search

# Conflicts: # src/bonsai/bonsai/bim/module/drawing/operator.py
Speed up debug_active_drawing and improve drawing failure reporting
2026-08-21 04:32:23 +00:00 · 2026-07-01 06:13:40 -05:00 · 2026-06-30 21:46:55 -05:00 · 2026-05-13 08:17:45 -05:00 · 2026-05-13 07:56:09 -05:00 · 2026-03-18 22:17:49 +05:30
2 changed files with 240 additions and 74 deletions
@@ -16,12 +16,16 @@
 # You should have received a copy of the GNU General Public License
 # along with Bonsai.  If not, see <http://www.gnu.org/licenses/>.

+import contextlib
+import io
+import itertools
 import logging
 import os
 import platform
 import random
 import subprocess
 import sys
+import threading
 import time
 from collections import defaultdict
 from pathlib import Path
@@ -927,24 +931,90 @@ class PipInstall(bpy.types.Operator):
        return {"FINISHED"}


+class _ConsoleSpinner:
+    """Animate a spinner on the real stdout while a blocking call runs on the main thread.
+
+    Writes to ``sys.__stdout__`` so it isn't swallowed by ``contextlib.redirect_stdout()``,
+    which the drawing search uses to silence ``create_drawing``'s own output. The animation
+    runs on a daemon thread that only touches stdout (never bpy data), so it's safe while a
+    synchronous ``bpy.ops`` call blocks the main thread.
+    """
+
+    def __init__(self, message: str = "Working"):
+        self.message = message
+        self._stop = threading.Event()
+        self._thread: Union[threading.Thread, None] = None
+        self._start_time = 0.0
+
+    def __enter__(self) -> "_ConsoleSpinner":
+        self._start_time = time.time()
+        if sys.__stdout__ is not None:
+            self._thread = threading.Thread(target=self._spin, daemon=True)
+            self._thread.start()
+        return self
+
+    def _spin(self) -> None:
+        out = sys.__stdout__
+        assert out is not None
+        for frame in itertools.cycle("|/-\\"):
+            if self._stop.wait(0.1):
+                break
+            elapsed = time.time() - self._start_time
+            out.write(f"\r  {frame} {self.message} ({elapsed:0.0f}s) ")
+            out.flush()
+
+    def __exit__(self, *args: object) -> None:
+        self._stop.set()
+        if self._thread is not None:
+            self._thread.join()
+        out = sys.__stdout__
+        if out is not None:
+            # Clear the spinner line so it doesn't linger before the next print.
+            out.write("\r" + " " * (len(self.message) + 24) + "\r")
+            out.flush()
+
+
 class DebugActiveDrawing(bpy.types.Operator):
    bl_idname = "bim.debug_active_drawing"
    bl_label = "Search Active Drawing For Failing Elements"
    bl_description = (
        "Will iterate over all visible drawing's objects, trying to narrow down the list of possible failing objects"
    )
+    should_export_isolated_file: bpy.props.BoolProperty(
+        name="Export Failing Elements to IFC",
+        description="Save a minimal IFC file containing only the failing elements after the search completes",
+        default=False,
+    )
+
+    def invoke(self, context: bpy.types.Context, event: bpy.types.Event):
+        return context.window_manager.invoke_props_dialog(self)

    def execute(self, context: bpy.types.Context):
        ifc_file = tool.Ifc.get()
-        props = tool.Drawing.get_document_props()
-        drawing_item = props.drawings[props.active_drawing_index]
-        drawing = tool.Ifc.get().by_id(drawing_item.ifc_definition_id)
+        if not ifc_file:
+            self.report({"ERROR"}, "No IFC file loaded.")
+            return {"CANCELLED"}
+        if not context.scene.camera:
+            self.report({"ERROR"}, "No active drawing camera in the scene.")
+            return {"CANCELLED"}
+        drawing_id = tool.Blender.get_ifc_definition_id(context.scene.camera)
+        if not drawing_id:
+            self.report({"ERROR"}, "Active camera is not linked to an IFC drawing element.")
+            return {"CANCELLED"}
+        drawing = ifc_file.by_id(drawing_id)

        GREEN = "\033[92m"
+        RED = "\033[91m"
        CYAN = "\033[96m"
+        BOLD = "\033[1m"
        END = "\033[0m"
        ATTEMPS = 10

+        def elem_label(e: ifcopenshell.entity_instance) -> str:
+            name = getattr(e, "Name", None) or "?"
+            guid = getattr(e, "GlobalId", None) or "?"
+            return f"#{e.id()} {e.is_a()} '{name}' ({guid})"
+
        # run create drawing with sync for once
        # to make sure everything is actually in sync
        try:
@@ -955,11 +1025,38 @@ class DebugActiveDrawing(bpy.types.Operator):
            self.report({"INFO"}, "No errors creating drawing, nothing to investigate.")
            return {"FINISHED"}

-        all_elements = [e for obj in context.visible_objects if (e := tool.Ifc.get_entity(obj))]
-        all_elements = set(all_elements)
+        all_elements = {e for obj in context.visible_objects if (e := tool.Ifc.get_entity(obj))}

        original_exclude = ifcopenshell.util.element.get_pset(drawing, "EPset_Drawing", "Exclude")
        pset = tool.Pset.get_element_pset(drawing, "EPset_Drawing")
+        failing_elements: list[ifcopenshell.entity_instance] = []
+
+        # Figure out which generation stage actually reproduces the failure so the
+        # bisection below can run ONLY that stage. The three stages (underlay, linework,
+        # annotation) produce independent SVGs, and re-running the expensive underlay/
+        # linework stages on every bisection step is what makes this operator slow --
+        # a single full create_drawing can take ~1 minute. Isolating the failing stage
+        # can cut each iteration (and thus the whole search) by more than half.
+        STAGES = ("underlay", "linework", "annotation")
+
+        def create_drawing_fails(**stage_toggles: bool) -> bool:
+            try:
+                with _ConsoleSpinner("Isolating failing stage"), contextlib.redirect_stdout(io.StringIO()):
+                    bpy.ops.bim.create_drawing(sync=False, **stage_toggles)
+                return False
+            except Exception:
+                return True
+
+        # Default: run everything (used if we can't isolate a single failing stage).
+        active_stages = {f"should_generate_{s}": True for s in STAGES}
+        for stage in ("annotation", "linework", "underlay"):
+            only_stage = {f"should_generate_{s}": (s == stage) for s in STAGES}
+            if create_drawing_fails(**only_stage):
+                active_stages = only_stage
+                print(f"{CYAN}Failure reproduces in the '{stage}' stage -- bisecting with only that stage.{END}")
+                break
+        else:
+            print(f"{CYAN}Could not isolate a single failing stage -- bisecting with all stages (slower).{END}")

        def drawing_fails_to_load(chunk_to_include: set[ifcopenshell.entity_instance]) -> bool:
            current_elements = all_elements - chunk_to_include
@@ -969,67 +1066,125 @@ class DebugActiveDrawing(bpy.types.Operator):
            ifcopenshell.api.pset.edit_pset(ifc_file, pset=pset, properties={"Exclude": new_exclude})

            try:
-                bpy.ops.bim.create_drawing(sync=False)
-                result = False
-            except Exception as e:
-                # print(e)
-                result = True
+                with _ConsoleSpinner(f"Testing {len(chunk_to_include)} element(s)"), contextlib.redirect_stdout(
+                    io.StringIO()
+                ):
+                    bpy.ops.bim.create_drawing(sync=False, **active_stages)
+                failed = False
+            except Exception:
+                failed = True

            ifcopenshell.api.pset.edit_pset(ifc_file, pset=pset, properties={"Exclude": original_exclude})
-            return result
+            return failed

        def test_elements(elements: list[ifcopenshell.entity_instance], attempts: int = ATTEMPS) -> None:
-            print(f"{CYAN}processing {len(elements)} elements{END}")
            if not elements:
-                print(f"Empty list of elements, will stop...")
                return

-            n_elements = len(elements)
-            middle = int(n_elements / 2)
+            if len(elements) == 1:
+                element = elements[0]
+                if drawing_fails_to_load({element}):
+                    print(f"  {RED}FAIL{END}  {elem_label(element)}")
+                    failing_elements.append(element)
+                else:
+                    print(f"  {GREEN}ok{END}    {elem_label(element)}")
+                return
+
+            print(f"{CYAN}Narrowing {len(elements)} elements...{END}")
+            middle = len(elements) // 2
            chunk1, chunk2 = elements[:middle], elements[middle:]
            test_chunk_1 = drawing_fails_to_load(set(chunk1))
            test_chunk_2 = drawing_fails_to_load(set(chunk2))

-            if (
-                # both chunks do not fail anymore
-                (not test_chunk_1 and not test_chunk_2)
-                # or we have 1 element chunk that is still failing
-                or (test_chunk_1 and not chunk2)
-                or (test_chunk_2 and not chunk1)
-            ):
-                if attempts == 0 or n_elements in (1, 2):
-                    print(f"{GREEN}Couldn't narrow it down any further.{END}")
-                    print(f"It's some of the {n_elements} elements:")
-                    print(elements)
-
-                    print("Let's test excluding them...")
-                    for element in elements:
-                        test = drawing_fails_to_load(all_elements - {element})
-                        if test:
-                            print(f"{CYAN}Excluding element didn't fixed the drawing: {END}")
-                            print(element)
-                        else:
-                            print(f"{GREEN}Excluding element fixed the drawing: {END}")
-                            print(element)
-                else:
-                    print(f"{CYAN}Will try to reshuffle elements and try again, attempt {ATTEMPS-attempts+1}/{ATTEMPS}")
-                    attempts -= 1
+            if not test_chunk_1 and not test_chunk_2:
+                # Neither half alone fails — elements may interact; reshuffle and retry
+                if attempts > 0:
+                    print(f"{CYAN}  Neither half fails alone, reshuffling (attempt {ATTEMPS - attempts + 1}/{ATTEMPS})...{END}")
                    random.shuffle(elements)
-                    test_elements(elements, attempts)
+                    test_elements(elements, attempts - 1)
+                else:
+                    print(f"{CYAN}  Could not isolate further. Possible interacting candidates:{END}")
+                    for e in elements:
+                        print(f"    ? {elem_label(e)}")
                return

-            # if chunk fails we need to investigate it further
            if test_chunk_1:
                test_elements(chunk1)
-
            if test_chunk_2:
                test_elements(chunk2)

+        print(f"\n{BOLD}{'='*60}{END}")
+        print(f"{BOLD}Searching {len(all_elements)} elements for drawing failures...{END}")
+        print(f"{BOLD}{'='*60}{END}\n")
+
        test_elements(list(all_elements))

-        self.report({"INFO"}, "See system console for the results")
+        if failing_elements:
+            for obj in context.scene.objects:
+                obj.select_set(False)
+            for element in failing_elements:
+                if obj := tool.Ifc.get_object(element):
+                    obj.select_set(True)
+
+        print(f"\n{BOLD}{'='*60}{END}")
+        if failing_elements:
+            print(f"{BOLD}{RED}Found {len(failing_elements)} failing element(s):{END}")
+            for e in failing_elements:
+                print(f"  {RED}✗{END} {elem_label(e)}")
+            if self.should_export_isolated_file:
+                output_path = os.path.splitext(tool.Ifc.get_path())[0] + "_failing_elements.ifc"
+                print(f"\n{CYAN}Exporting isolated IFC file...{END}", flush=True)
+                self._export_elements(ifc_file, failing_elements, output_path)
+                print(f"{GREEN}Done.{END} Saved to: {output_path}")
+                print(
+                    f"\n{CYAN}Please attach {os.path.basename(output_path)} when reporting this issue at"
+                    f" https://github.com/IfcOpenShell/IfcOpenShell/issues/new/choose"
+                    f" — this helps the team reproduce and fix the underlying geometry bug.{END}"
+                )
+                self.report({"INFO"}, f"Found {len(failing_elements)} failing element(s) — exported to {output_path}")
+            else:
+                print(
+                    f"\n{CYAN}If possible, re-run with 'Export Failing Elements to IFC' enabled, then attach"
+                    f" the exported file when reporting at https://github.com/IfcOpenShell/IfcOpenShell/issues/new/choose"
+                    f" — this could help fix deeper geometry bugs.{END}"
+                )
+                self.report({"INFO"}, f"Found {len(failing_elements)} failing element(s) — see system console.")
+        else:
+            print(f"{BOLD}{GREEN}No individually failing elements found.{END}")
+            print("  (Failure may require a specific combination of elements.)")
+            self.report({"INFO"}, "No individually failing elements found — see system console.")
+        print(f"{BOLD}{'='*60}{END}\n")
+
        return {"FINISHED"}

+    def _export_elements(
+        self,
+        ifc_file: ifcopenshell.file,
+        elements: list[ifcopenshell.entity_instance],
+        output_path: str,
+    ) -> None:
+        from ifcpatch.recipes.ExtractElements import Patcher
+
+        patcher = Patcher.__new__(Patcher)
+        patcher.file = ifc_file
+        patcher.logger = None
+        patcher.contained_ins = {}
+        patcher.aggregates = {}
+        patcher.new = ifcopenshell.file(schema_version=ifc_file.schema_version)
+        patcher.owner_history = None
+        patcher.reuse_identities = {}
+        patcher.assume_asset_uniqueness_by_name = True
+        for owner_history in ifc_file.by_type("IfcOwnerHistory"):
+            patcher.owner_history = patcher.new.add(owner_history)
+            break
+        projects = ifc_file.by_type("IfcProject")
+        if projects:
+            patcher.add_element(projects[0])
+        for element in elements:
+            patcher.add_element(element)
+        patcher.create_spatial_tree()
+        patcher.new.write(output_path)
+

 class ToggleDetailedIOSLogs(bpy.types.Operator):
    bl_idname = "bim.toggle_detailed_ios_logs"
@@ -24,9 +24,9 @@ import os
 import shutil
 import subprocess
 import time
+import traceback
 from math import radians
 from pathlib import Path
-from timeit import default_timer as timer
 from typing import (
    TYPE_CHECKING,
    Any,
@@ -48,6 +48,7 @@ import ifcopenshell.api.style
 import ifcopenshell.geom
 import ifcopenshell.ifcopenshell_wrapper
 import ifcopenshell.util.element
+import ifcopenshell.util.profiler
 import ifcopenshell.util.representation
 import ifcopenshell.util.selector
 import ifcopenshell.util.shape_builder
@@ -86,21 +87,6 @@ if TYPE_CHECKING:
 cwd = os.path.dirname(os.path.realpath(__file__))


-class profile:
-    """
-    A python context manager timing utility
-    """
-
-    def __init__(self, task):
-        self.task = task
-
-    def __enter__(self):
-        self.start = timer()
-
-    def __exit__(self, *args):
-        print(self.task, timer() - self.start)
-
-
 class LineworkContexts(NamedTuple):
    body: list[list[int]]
    annotation: list[list[int]]
@@ -261,11 +247,19 @@ class CreateDrawing(bpy.types.Operator):
        description="Could save some time if you're sure IFC and current Blender session are already in sync",
        default=True,
    )
+    # Stage toggles, mainly for bim.debug_active_drawing so it can reproduce a failure
+    # by running only the culprit stage instead of the full (slow) generation each time.
+    should_generate_underlay: bpy.props.BoolProperty(name="Generate Underlay", default=True, options={"SKIP_SAVE"})
+    should_generate_linework: bpy.props.BoolProperty(name="Generate Linework", default=True, options={"SKIP_SAVE"})
+    should_generate_annotation: bpy.props.BoolProperty(name="Generate Annotation", default=True, options={"SKIP_SAVE"})

    if TYPE_CHECKING:
        print_all: bool
        open_viewer: bool
        sync: bool
+        should_generate_underlay: bool
+        should_generate_linework: bool
+        should_generate_annotation: bool

    drawing_name: str
    is_manifold_cache: dict[str, bool]
@@ -298,6 +292,23 @@ class CreateDrawing(bpy.types.Operator):
        return self.execute(context)

    def execute(self, context):
+        try:
+            return self._execute(context)
+        except Exception:
+            # Print the full traceback so developers (and `bim.debug_active_drawing`,
+            # which bisects the drawing to find the offending element) still get it.
+            traceback.print_exc()
+            drawing_name = getattr(self, "drawing_name", None) or "?"
+            self.report(
+                {"ERROR"},
+                f"Failed to create drawing '{drawing_name}'. This is usually caused by a corrupt or "
+                "out-of-bounds element in the drawing (e.g. an annotation with a runaway coordinate). "
+                "Run Debug > 'Search Active Drawing For Failing Elements' (bpy.ops.bim.debug_active_drawing) "
+                "to locate the offending element.",
+            )
+            return {"CANCELLED"}
+
+    def _execute(self, context):
        self.props = tool.Drawing.get_document_props()
        assert context.scene and context.scene.camera

@@ -328,8 +339,8 @@ class CreateDrawing(bpy.types.Operator):
            self.camera_document = tool.Drawing.get_drawing_document(self.camera_element)
            self.file = tool.Ifc.get()

-            with profile("Drawing generation process"):
-                with profile("Initialize drawing generation process"):
+            with ifcopenshell.util.profiler.Profiler("Drawing generation process"):
+                with ifcopenshell.util.profiler.Profiler("Initialize drawing generation process"):
                    self.cprops = tool.Drawing.get_camera_props(self.camera)
                    self.drawing = self.file.by_id(drawing_id)
                    self.drawing_name = self.drawing.Name
@@ -355,8 +366,10 @@ class CreateDrawing(bpy.types.Operator):
                linework_svg = None
                annotation_svg = None

-                with profile("Generate underlay"):
-                    if ifcopenshell.util.element.get_pset(self.drawing, "EPset_Drawing", "HasUnderlay"):
+                with ifcopenshell.util.profiler.Profiler("Generate underlay"):
+                    if self.should_generate_underlay and ifcopenshell.util.element.get_pset(
+                        self.drawing, "EPset_Drawing", "HasUnderlay"
+                    ):
                        drawing_style = self.cprops.get_active_drawing_style()
                        if not drawing_style:
                            self.report(
@@ -383,20 +396,18 @@ class CreateDrawing(bpy.types.Operator):

                        underlay_svg = self.generate_underlay(context)

-                with profile("Generate linework"):
-                    if tool.Drawing.is_camera_orthographic():
+                with ifcopenshell.util.profiler.Profiler("Generate linework"):
+                    if self.should_generate_linework and tool.Drawing.is_camera_orthographic():
                        if self.cprops.linework_mode == "OPENCASCADE":
                            linework_svg = self.generate_linework(context)
                        elif self.cprops.linework_mode == "FREESTYLE":
                            linework_svg = self.generate_freestyle_linework(context)
-                    elif self.cprops.linework_mode == "FREESTYLE":
-                        linework_svg = self.generate_freestyle_linework(context)

-                with profile("Generate annotation"):
-                    if tool.Drawing.is_camera_orthographic():
+                with ifcopenshell.util.profiler.Profiler("Generate annotation"):
+                    if self.should_generate_annotation and tool.Drawing.is_camera_orthographic():
                        annotation_svg = self.generate_annotation(context)

-                with profile("Combine SVG layers"):
+                with ifcopenshell.util.profiler.Profiler("Combine SVG layers"):
                    svg_path = self.combine_svgs(context, underlay_svg, linework_svg, annotation_svg)

            if self.open_viewer:
@@ -606,7 +617,7 @@ class CreateDrawing(bpy.types.Operator):
        drawing_elements = drawing_elements.copy()
        contexts_: list[list[int]] = getattr(contexts, context_type)
        for context in contexts_:
-            with profile(f"Processing {context_type} context"):
+            with ifcopenshell.util.profiler.Profiler(f"Processing {context_type} context"):
                if not context or not drawing_elements:
                    continue
                geom_settings = ifcopenshell.geom.settings()
@@ -897,7 +908,7 @@ class CreateDrawing(bpy.types.Operator):

        # in case of printing multiple drawings we need to sync just once
        if self.sync and self.drawing_index == 0:
-            with profile("sync"):
+            with ifcopenshell.util.profiler.Profiler("sync"):
                # All very hackish whilst prototyping
                exporter = bonsai.bim.export_ifc.IfcExporter(None)
                exporter.file = tool.Ifc.get()
@@ -953,7 +964,7 @@ class CreateDrawing(bpy.types.Operator):
            self.serialize_contexts_elements(ifc, tree, contexts, "annotation", drawing_elements, target_view)

            if tool.Ifc.get() == ifc and self.camera_element not in drawing_elements:
-                with profile("Camera element"):
+                with ifcopenshell.util.profiler.Profiler("Camera element"):
                    # The camera must always be included, regardless of any include/exclude filters.
                    geom_settings = ifcopenshell.geom.settings()
                    geom_settings.set("iterator-output", ifcopenshell.ifcopenshell_wrapper.NATIVE)
@@ -961,7 +972,7 @@ class CreateDrawing(bpy.types.Operator):
                    for elem in it:
                        self.serialiser.write(elem)

-        with profile("Finalizing"):
+        with ifcopenshell.util.profiler.Profiler("Finalizing"):
            self.serialiser.finalize()
        results = self.svg_buffer.get_value()
Author	SHA1	Message	Date
Ryan Schultz	9283d86661	Merge commit '1acce39867' into debug-drawing-faster-failure-search # Conflicts: # src/bonsai/bonsai/bim/module/drawing/operator.py	2026-07-01 06:13:40 -05:00
Ryan Schultz	c7c4cfa946	Speed up debug_active_drawing and improve drawing failure reporting When a drawing fails to generate (e.g. an annotation with a runaway coordinate that makes project_point_onto_camera return None), surface an actionable error instead of a raw traceback, and make the search for the offending element much faster. drawing/operator.py: - Wrap CreateDrawing.execute so any failure prints the full traceback (still consumed by debug_active_drawing) and reports a clear message pointing users at "Search Active Drawing For Failing Elements". - Add should_generate_underlay/linework/annotation toggles so the generation stages can be run independently. debug/operator.py: - Detect which stage (underlay/linework/annotation) reproduces the failure and bisect with only that stage, skipping the expensive underlay render and OpenCASCADE linework on every iteration. - Add a console spinner (background thread, writes to the real stdout) so long silent waits no longer look frozen. - Include the GlobalId in element labels. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>	2026-06-30 21:46:55 -05:00
Ryan Schultz	647a1f44ee	select all the offending objects at the end.	2026-05-13 08:17:45 -05:00
Ryan Schultz	790978df3c	Add export option to DebugActiveDrawing Fix failure detection by switching from `except Exception` to checking the return value, then back to `except Exception` once it was confirmed that `bpy.ops` re-raises inside another operator. Identify the drawing via the active scene camera (consistent with CreateDrawing) to avoid the `ifc_definition_id=0` crash on non-drawing list entries. Improve the binary search to test each candidate in isolation, enabling multiple independent failures to be found in one pass. Suppress drawing-generation log noise during tests and print a clean summary with element id, type, and name. Add a `should_export_isolated_file` operator property that extracts the failing elements into a minimal standalone IFC file using ExtractElements, making it easy to attach a reproduction case when filing a bug report. Generated with the assistance of an AI coding tool.	2026-05-13 07:56:09 -05:00
Parag Debnath	1acce39867	Replaced the old profiler function with the ifcopenshell.util profiler	2026-03-18 22:17:49 +05:30