Fix: Allow dbt project ref, source, and config macros to override the builtin version and use the logger for dbt logging macros (#1606)

Author: crericha

sqlmesh/dbt/builtin.py

@@ -37,7 +37,7 @@ def raise_compiler_error(self, msg: str) -> None:
             raise CompilationException(msg)
 
     def warn(self, msg: str) -> str:
-        print(msg)
+        logger.warning(msg)
         return ""
 
 
@@ -146,11 +146,7 @@ def env_var(name: str, default: t.Optional[str] = None) -> t.Optional[str]:
 
 
 def log(msg: str, info: bool = False) -> str:
-    print(msg)
-    return ""
-
-
-def no_log(msg: str, info: bool = False) -> str:
+    logger.debug(msg)
     return ""
 
 
@@ -260,9 +256,9 @@ def _try_literal_eval(value: str) -> t.Any:
     "flags": Flags(),
     "fromjson": from_json,
     "fromyaml": from_yaml,
-    "log": no_log,
+    "log": log,
     "modules": Modules(),
-    "print": no_log,
+    "print": log,
     "return": return_val,
     "set": to_set,
     "set_strict": set,
@@ -337,14 +333,12 @@ def create_builtin_globals(
             table_mapping=jinja_globals.get("table_mapping", {}),
             is_dev=jinja_globals.get("is_dev", False),
         )
-        builtin_globals.update({"log": log, "print": log})
     else:
         adapter = ParsetimeAdapter(
             jinja_macros,
             jinja_globals={**builtin_globals, **jinja_globals},
             dialect=dialect,
         )
-        builtin_globals.update({"log": no_log, "print": no_log})
 
     sql_execution = SQLExecution(adapter)
     builtin_globals.update(

sqlmesh/utils/jinja.py

@@ -271,9 +271,9 @@ def build_environment(self, **kwargs: t.Any) -> Environment:
 
         env = environment()
 
+        context.update(self._create_builtin_globals(kwargs))
         context.update(root_macros)
         context.update(package_macros)
-        context.update(self._create_builtin_globals(kwargs))
 
         env.globals.update(context)
         env.filters.update(self._environment.filters)

tests/dbt/test_transformation.py

@@ -1,6 +1,8 @@
 import json
+import logging
 import typing as t
 from pathlib import Path
+from unittest.mock import patch
 
 import agate
 import pytest
@@ -214,22 +216,26 @@ def test_seed_columns():
 
 
 @pytest.mark.parametrize("model", ["sushi.waiters", "sushi.waiter_names"])
-def test_hooks(capsys, sushi_test_dbt_context: Context, model: str):
+def test_hooks(sushi_test_dbt_context: Context, model: str):
     engine_adapter = sushi_test_dbt_context.engine_adapter
     waiters = sushi_test_dbt_context.models[model]
-    capsys.readouterr()
 
-    engine_adapter.execute(
-        waiters.render_pre_statements(engine_adapter=engine_adapter, execution_time="2023-01-01")
-    )
-    assert "pre-hook" in capsys.readouterr().out
+    logger = logging.getLogger("sqlmesh.dbt.builtin")
+    with patch.object(logger, "debug") as mock_logger:
+        engine_adapter.execute(
+            waiters.render_pre_statements(
+                engine_adapter=engine_adapter, execution_time="2023-01-01"
+            )
+        )
+    assert "pre-hook" in mock_logger.call_args[0][0]
 
-    engine_adapter.execute(
-        waiters.render_post_statements(
-            engine_adapter=sushi_test_dbt_context.engine_adapter, execution_time="2023-01-01"
+    with patch.object(logger, "debug") as mock_logger:
+        engine_adapter.execute(
+            waiters.render_post_statements(
+                engine_adapter=sushi_test_dbt_context.engine_adapter, execution_time="2023-01-01"
+            )
         )
-    )
-    assert "post-hook" in capsys.readouterr().out
+    assert "post-hook" in mock_logger.call_args[0][0]
 
 
 def test_target_jinja(sushi_test_project: Project):
@@ -311,24 +317,29 @@ def test_run_query(sushi_test_project: Project, runtime_renderer: t.Callable):
     )
 
 
-def test_logging(capsys, sushi_test_project: Project, runtime_renderer: t.Callable):
+def test_logging(sushi_test_project: Project, runtime_renderer: t.Callable):
     context = sushi_test_project.context
     assert context.target
     engine_adapter = context.target.to_sqlmesh().create_engine_adapter()
     renderer = runtime_renderer(context, engine_adapter=engine_adapter)
 
-    assert renderer('{{ log("foo") }}') == ""
-    assert "foo" in capsys.readouterr().out
+    logger = logging.getLogger("sqlmesh.dbt.builtin")
+    with patch.object(logger, "debug") as mock_logger:
+        assert renderer('{{ log("foo") }}') == ""
+    assert "foo" in mock_logger.call_args[0][0]
 
-    assert renderer('{{ print("bar") }}') == ""
-    assert "bar" in capsys.readouterr().out
+    with patch.object(logger, "debug") as mock_logger:
+        assert renderer('{{ print("bar") }}') == ""
+    assert "bar" in mock_logger.call_args[0][0]
 
 
-def test_exceptions(capsys, sushi_test_project: Project):
+def test_exceptions(sushi_test_project: Project):
     context = sushi_test_project.context
 
-    assert context.render('{{ exceptions.warn("Warning") }}') == ""
-    assert "Warning" in capsys.readouterr().out
+    logger = logging.getLogger("sqlmesh.dbt.builtin")
+    with patch.object(logger, "warning") as mock_logger:
+        assert context.render('{{ exceptions.warn("Warning") }}') == ""
+    assert "Warning" in mock_logger.call_args[0][0]
 
     with pytest.raises(CompilationError, match="Error"):
         context.render('{{ exceptions.raise_compiler_error("Error") }}')