feat: add tracing logger statements

src/django_components/component.py

@@ -20,7 +20,7 @@ from django.views import View
 # way the two modules depend on one another.
 from django_components.component_registry import registry  # NOQA
 from django_components.component_registry import AlreadyRegistered, ComponentRegistry, NotRegistered, register  # NOQA
-from django_components.logger import logger
+from django_components.logger import logger, trace_msg
 from django_components.middleware import is_dependency_middleware_active
 from django_components.slots import (
     FillContent,
@@ -258,9 +258,11 @@ class Component(View, metaclass=SimplifiedInterfaceMediaDefiningClass):
         context = context_data if isinstance(context_data, Context) else Context(context_data)
         template = self.get_template(context)
 
-        # Associate the slots with this component
+        # Associate the slots with this component for this context
+        # This allows us to look up component-specific slot fills.
         def on_node(node: Node) -> None:
             if isinstance(node, SlotNode):
+                trace_msg("ASSOC", "SLOT", node.name, node.node_id, component_id=self.component_id)
                 node.component_id = self.component_id
 
         walk_nodelist(template.nodelist, on_node)
@@ -328,6 +330,8 @@ class ComponentNode(Node):
         )
 
     def render(self, context: Context) -> str:
+        trace_msg("RENDR", "COMP", self.name_fexp, self.component_id)
+
         resolved_component_name = self.name_fexp.resolve(context)
         component_cls: Type[Component] = registry.get(resolved_component_name)
 
@@ -377,9 +381,12 @@ class ComponentNode(Node):
             rendered_component = component.render(context)
 
         if is_dependency_middleware_active():
-            return RENDERED_COMMENT_TEMPLATE.format(name=resolved_component_name) + rendered_component
+            output = RENDERED_COMMENT_TEMPLATE.format(name=resolved_component_name) + rendered_component
         else:
-            return rendered_component
+            output = rendered_component
+
+        trace_msg("RENDR", "COMP", self.name_fexp, self.component_id, "...Done!")
+        return output
 
 
 def safe_resolve(context_item: FilterExpression, context: Context) -> Any:

src/django_components/logger.py

@@ -1,3 +1,35 @@
 import logging
+from typing import Literal, Optional
 
 logger = logging.getLogger("django_components")
+
+
+def trace_msg(
+    action: Literal["PARSE", "ASSOC", "RENDR", "GET", "SET"],
+    node_type: Literal["COMP", "FILL", "SLOT", "IFSB", "N/A"],
+    node_name: str,
+    node_id: str,
+    msg: str = "",
+    component_id: Optional[str] = None,
+) -> None:
+    """
+    Log a tracing statement to `logger.debug` like so:
+
+    `"ASSOC SLOT test_slot ID 0088 TO COMP 0087"`
+    """
+    msg_prefix = ""
+    if action == "ASSOC":
+        if not component_id:
+            raise ValueError("component_id must be set for the ASSOC action")
+        msg_prefix = f"TO COMP {component_id}"
+    elif action == "RENDR" and node_type != "COMP":
+        if not component_id:
+            raise ValueError("component_id must be set for the RENDER action")
+        msg_prefix = f"FOR COMP {component_id}"
+
+    msg_parts = [f"{action} {node_type} {node_name} ID {node_id}", *([msg_prefix] if msg_prefix else []), msg]
+    full_msg = " ".join(msg_parts)
+
+    # NOTE: When debugging tests during development, it may be easier to change
+    # this to `print()`
+    logger.debug(full_msg)

src/django_components/slots.py

@@ -116,6 +116,7 @@ class SlotNode(Node):
 
     def render(self, context: Context) -> SafeString:
         slot_fill_content = get_slot_fill(context, self.component_id, self.name, callee_node_name=f"SlotNode '{self.name}'")
+        trace_msg("RENDR", "SLOT", self.name, self.node_id, component_id=component_id)
 
         extra_context = {}
         if slot_fill_content is None:
@@ -133,7 +134,10 @@ class SlotNode(Node):
 
         used_ctx = self.resolve_slot_context(context)
         with used_ctx.update(extra_context):
-            return nodelist.render(used_ctx)
+            output = nodelist.render(used_ctx)
+
+        trace_msg("RENDR", "SLOT", self.name, self.node_id, component_id=component_id, msg="...Done!")
+        return output
 
     def resolve_slot_context(self, context: Context) -> Context:
         """
@@ -417,8 +421,7 @@ def _prepare_component_template_filled_slot_context(
     slot_name2fill_content = _collect_slot_fills_from_component_template(template, fill_content, registered_name)
 
     # Give slot nodes knowledge of their parent component.
-    for node in template.nodelist.get_nodes_by_type((SlotNode, IfSlotFilledConditionBranchNode)):
-        if isinstance(node, (SlotNode, IfSlotFilledConditionBranchNode)):
+            trace_msg("ASSOC", "IFSB", node.slot_name, node.node_id, component_id=component_id)
             node.component_id = component_id
 
     # Return updated FILLED_SLOTS_CONTEXT map

src/django_components/templatetags/component_tags.py

@@ -10,6 +10,7 @@ from django_components.app_settings import app_settings
 from django_components.component import RENDERED_COMMENT_TEMPLATE, ComponentNode
 from django_components.component_registry import ComponentRegistry
 from django_components.component_registry import registry as component_registry
+from django_components.logger import trace_msg
 from django_components.middleware import (
     CSS_DEPENDENCY_PLACEHOLDER,
     JS_DEPENDENCY_PLACEHOLDER,
@@ -149,6 +150,7 @@ def do_slot(parser: Parser, token: Token) -> SlotNode:
     # Use a unique ID to be able to tie the fill nodes with components and slots
     # NOTE: MUST be called BEFORE `parser.parse()` to ensure predictable numbering
     slot_id = gen_id()
+    trace_msg("PARSE", "SLOT", slot_name, slot_id)
 
     nodelist = parser.parse(parse_until=["endslot"])
     parser.delete_first_token()
@@ -160,6 +162,7 @@ def do_slot(parser: Parser, token: Token) -> SlotNode:
         node_id=slot_id,
     )
 
+    trace_msg("PARSE", "SLOT", slot_name, slot_id, "...Done!")
     return slot_node
 
 
@@ -191,6 +194,7 @@ def do_fill(parser: Parser, token: Token) -> FillNode:
     # Use a unique ID to be able to tie the fill nodes with components and slots
     # NOTE: MUST be called BEFORE `parser.parse()` to ensure predictable numbering
     fill_id = gen_id()
+    trace_msg("PARSE", "FILL", tgt_slot_name, fill_id)
 
     nodelist = parser.parse(parse_until=["endfill"])
     parser.delete_first_token()
@@ -202,6 +206,7 @@ def do_fill(parser: Parser, token: Token) -> FillNode:
         node_id=fill_id,
     )
 
+    trace_msg("PARSE", "FILL", tgt_slot_name, fill_id, "...Done!")
     return fill_node
 
 
@@ -227,6 +232,7 @@ def do_component(parser: Parser, token: Token) -> ComponentNode:
     # Use a unique ID to be able to tie the fill nodes with components and slots
     # NOTE: MUST be called BEFORE `parser.parse()` to ensure predictable numbering
     component_id = gen_id()
+    trace_msg("PARSE", "COMP", component_name, component_id)
 
     body: NodeList = parser.parse(parse_until=["endcomponent"])
     parser.delete_first_token()
@@ -234,6 +240,7 @@ def do_component(parser: Parser, token: Token) -> ComponentNode:
 
     # Tag all fill nodes as children of this particular component instance
     for node in fill_nodes:
+        trace_msg("ASSOC", "FILL", node.name_fexp, node.node_id, component_id=component_id)
         node.component_id = component_id
 
     component_node = ComponentNode(
@@ -245,6 +252,7 @@ def do_component(parser: Parser, token: Token) -> ComponentNode:
         component_id=component_id,
     )
 
+    trace_msg("PARSE", "COMP", component_name, component_id, "...Done!")
     return component_node