Merge branch 'main' into iotaa-update

src/uwtools/config/formats/base.py

@@ -216,9 +216,9 @@ def dereference(self, context: Optional[dict] = None) -> None:
         """
 
         def logstate(state: str) -> None:
-            log.debug("Dereferencing, %s value:", state)
+            jinja2.deref_debug("Dereferencing, %s value:" % state)
             for line in yaml_to_str(self.data).split("\n"):
-                log.debug("%s%s", INDENT, line)
+                jinja2.deref_debug("%s%s" % (INDENT, line))
 
         while True:
             logstate("current")

src/uwtools/config/jinja2.py

@@ -13,7 +13,6 @@
 from jinja2.exceptions import UndefinedError
 
 from uwtools.config.support import UWYAMLConvert, UWYAMLRemove, format_to_config, uw_yaml_loader
-from uwtools.exceptions import UWConfigRealizeError
 from uwtools.logging import INDENT, MSGWIDTH, log
 from uwtools.utils.file import get_file_format, readable, writable
 
@@ -130,25 +129,35 @@ def dereference(
         rendered = {}
         for k, v in val.items():
             if isinstance(v, UWYAMLRemove):
-                _deref_debug("Removing value at", ".".join([*keys, k]))
+                deref_debug("Removing value at", ".".join([*keys, k]))
             else:
                 kd, vd = [dereference(x, context, val, [*keys, k]) for x in (k, v)]
                 rendered[kd] = vd
     elif isinstance(val, list):
         rendered = [dereference(v, context) for v in val]
     elif isinstance(val, str):
-        _deref_debug("Rendering", val)
+        deref_debug("Rendering", val)
         rendered = _deref_render(val, context, local)
     elif isinstance(val, UWYAMLConvert):
-        _deref_debug("Rendering", val.value)
+        deref_debug("Rendering", val.value)
         val.value = _deref_render(val.value, context, local)
         rendered = _deref_convert(val)
     else:
-        _deref_debug("Accepting", val)
+        deref_debug("Accepting", val)
         rendered = val
     return rendered
 
 
+def deref_debug(action: str, val: Optional[_ConfigVal] = "") -> None:
+    """
+    Log a debug-level message related to dereferencing.
+
+    :param action: The dereferencing activity being performed.
+    :param val: The value being dereferenced.
+    """
+    log.debug("[dereference] %s: %s", action, val)
+
+
 def render(
     values_src: Optional[Union[dict, Path]] = None,
     values_format: Optional[str] = None,
@@ -234,25 +243,15 @@ def _deref_convert(val: UWYAMLConvert) -> _ConfigVal:
     :return: The value translated to the specified type.
     """
     converted: _ConfigVal = val  # fall-back value
-    _deref_debug("Converting", val.value)
+    deref_debug("Converting", val.value)
     try:
         converted = val.convert()
-        _deref_debug("Converted", converted)
+        deref_debug("Converted", converted)
     except Exception as e:  # pylint: disable=broad-exception-caught
-        _deref_debug("Conversion failed", str(e))
+        deref_debug("Conversion failed", str(e))
     return converted
 
 
-def _deref_debug(action: str, val: _ConfigVal) -> None:
-    """
-    Log a debug-level message related to dereferencing.
-
-    :param action: The dereferencing activity being performed.
-    :param val: The value being dereferenced.
-    """
-    log.debug("[dereference] %s: %s", action, val)
-
-
 def _deref_render(val: str, context: dict, local: Optional[dict] = None) -> str:
     """
     Render a Jinja2 variable/expression as part of dereferencing.
@@ -269,13 +268,22 @@ def _deref_render(val: str, context: dict, local: Optional[dict] = None) -> str:
     context = {**(local or {}), **context}
     try:
         rendered = _register_filters(env).from_string(val).render(context)
-        if isinstance(yaml.load(rendered, Loader=uw_yaml_loader()), UWYAMLConvert):
-            _deref_debug("Held", rendered)
-            raise UWConfigRealizeError()
-        _deref_debug("Rendered", rendered)
+        deref_debug("Rendered", rendered)
+    except Exception as e:  # pylint: disable=broad-exception-caught
+        rendered = val
+        deref_debug("Rendering failed", val)
+        for line in str(e).split("\n"):
+            deref_debug(line)
+    try:
+        loaded = yaml.load(rendered, Loader=uw_yaml_loader())
     except Exception as e:  # pylint: disable=broad-exception-caught
+        loaded = None
+        deref_debug("Loading rendered value as YAML", rendered)
+        for line in str(e).split("\n"):
+            deref_debug(line)
+    if isinstance(loaded, UWYAMLConvert):
         rendered = val
-        _deref_debug("Rendering failed", str(e))
+        deref_debug("Held", rendered)
     return rendered
 
 

src/uwtools/tests/config/test_jinja2.py

@@ -167,6 +167,12 @@ def test_dereference_str_variable_rendered_str():
     assert jinja2.dereference(val=val, context={"greeting": "hello"}) == "hello"
 
 
+def test_deref_debug(caplog):
+    log.setLevel(logging.DEBUG)
+    jinja2.deref_debug(action="Frobnicated", val="foo")
+    assert logged(caplog, "[dereference] Frobnicated: foo")
+
+
 def test_register_filters_env():
     s = "hello {{ 'RECIPIENT' | env }}"
     template = jinja2._register_filters(Environment(undefined=DebugUndefined)).from_string(s)
@@ -309,40 +315,47 @@ def test__deref_convert_ok(caplog, converted, tag, value):
     assert not regex_logged(caplog, "Conversion failed")
 
 
-def test__deref_debug(caplog):
-    log.setLevel(logging.DEBUG)
-    jinja2._deref_debug(action="Frobnicated", val="foo")
-    assert logged(caplog, "[dereference] Frobnicated: foo")
-
-
 def test__deref_render_held(caplog):
+    log.setLevel(logging.DEBUG)
     val, context = "!int '{{ a }}'", yaml.load("a: !int '{{ 42 }}'", Loader=uw_yaml_loader())
     assert jinja2._deref_render(val=val, context=context) == val
-    assert not regex_logged(caplog, "Rendered")
+    assert regex_logged(caplog, "Rendered")
     assert regex_logged(caplog, "Held")
 
 
 def test__deref_render_no(caplog, deref_render_assets):
+    log.setLevel(logging.DEBUG)
     val, context, _ = deref_render_assets
     assert jinja2._deref_render(val=val, context=context) == val
     assert not regex_logged(caplog, "Rendered")
     assert regex_logged(caplog, "Rendering failed")
 
 
 def test__deref_render_ok(caplog, deref_render_assets):
+    log.setLevel(logging.DEBUG)
     val, context, local = deref_render_assets
     assert jinja2._deref_render(val=val, context=context, local=local) == "hello world"
     assert regex_logged(caplog, "Rendered")
     assert not regex_logged(caplog, "Rendering failed")
 
 
+def test__deref_render_unloadable_val(caplog):
+    log.setLevel(logging.DEBUG)
+    val = "&XMLENTITY;"
+    assert jinja2._deref_render(val='{{ "%s" if True }}' % val, context={}) == val
+    assert regex_logged(caplog, "Rendered")
+    assert not regex_logged(caplog, "Rendering failed")
+
+
 def test__dry_run_template(caplog):
+    log.setLevel(logging.DEBUG)
     jinja2._dry_run_template("roses are red\nviolets are blue")
     assert logged(caplog, "roses are red")
     assert logged(caplog, "violets are blue")
 
 
 def test__log_missing_values(caplog):
+    log.setLevel(logging.DEBUG)
     missing = ["roses_color", "violets_color"]
     jinja2._log_missing_values(missing)
     assert logged(caplog, "Value(s) required to render template not provided:")