From bf10ab9e83bab2aa09f8fa8ec011336e93b08b2a Mon Sep 17 00:00:00 2001 From: Themis Valtinos <73662635+themisvaltinos@users.noreply.github.com> Date: Tue, 12 Aug 2025 18:48:05 +0300 Subject: [PATCH 1/2] Fix(dbt): Use the info to control logging for dbt log builtin --- sqlmesh/dbt/builtin.py | 8 +++++++- tests/dbt/test_transformation.py | 23 ++++++++++++++++++++--- 2 files changed, 27 insertions(+), 4 deletions(-) diff --git a/sqlmesh/dbt/builtin.py b/sqlmesh/dbt/builtin.py index 4646011d57..f0ff2361c1 100644 --- a/sqlmesh/dbt/builtin.py +++ b/sqlmesh/dbt/builtin.py @@ -170,7 +170,13 @@ def env_var(name: str, default: t.Optional[str] = None) -> t.Optional[str]: def log(msg: str, info: bool = False) -> str: - logger.debug(msg) + if info: + # Write to both log file and stdout + logger.info(msg) + print(msg) + else: + logger.debug(msg) + return "" diff --git a/tests/dbt/test_transformation.py b/tests/dbt/test_transformation.py index c67621b206..0ea41acecf 100644 --- a/tests/dbt/test_transformation.py +++ b/tests/dbt/test_transformation.py @@ -847,16 +847,33 @@ def test_run_query(sushi_test_project: Project, runtime_renderer: t.Callable): @pytest.mark.xdist_group("dbt_manifest") -def test_logging(sushi_test_project: Project, runtime_renderer: t.Callable): +def test_logging(sushi_test_project: Project, runtime_renderer: t.Callable, capsys): 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) logger = logging.getLogger("sqlmesh.dbt.builtin") - with patch.object(logger, "debug") as mock_logger: + + # Test log with info=False (default) which should only log with debug + with patch.object(logger, "debug") as mock_debug, patch.object(logger, "info") as mock_info: assert renderer('{{ log("foo") }}') == "" - assert "foo" in mock_logger.call_args[0][0] + mock_debug.assert_called_once() + assert "foo" in mock_debug.call_args[0][0] + mock_info.assert_not_called() + + captured = capsys.readouterr() + assert "foo" not in captured.out + + # Test log with info=True, now should log with info and also print to stdout + with patch.object(logger, "debug") as mock_debug, patch.object(logger, "info") as mock_info: + assert renderer('{{ log("output to be logged with info", info=true) }}') == "" + mock_info.assert_called_once() + assert "output to be logged with info" in mock_info.call_args[0][0] + mock_debug.assert_not_called() + + captured = capsys.readouterr() + assert "output to be logged with info" in captured.out with patch.object(logger, "debug") as mock_logger: assert renderer('{{ print("bar") }}') == "" From 8c3645d02b062163d67bae409d5159d8554b9ba7 Mon Sep 17 00:00:00 2001 From: Themis Valtinos <73662635+themisvaltinos@users.noreply.github.com> Date: Tue, 12 Aug 2025 20:13:14 +0300 Subject: [PATCH 2/2] use console instead of print; adapt tests --- sqlmesh/dbt/builtin.py | 3 ++- tests/dbt/test_transformation.py | 40 ++++++++++++++++++++------------ 2 files changed, 27 insertions(+), 16 deletions(-) diff --git a/sqlmesh/dbt/builtin.py b/sqlmesh/dbt/builtin.py index f0ff2361c1..49f07f597c 100644 --- a/sqlmesh/dbt/builtin.py +++ b/sqlmesh/dbt/builtin.py @@ -14,6 +14,7 @@ from ruamel.yaml import YAMLError from sqlglot import Dialect +from sqlmesh.core.console import get_console from sqlmesh.core.engine_adapter import EngineAdapter from sqlmesh.core.snapshot.definition import DeployabilityIndex from sqlmesh.dbt.adapter import BaseAdapter, ParsetimeAdapter, RuntimeAdapter @@ -173,7 +174,7 @@ def log(msg: str, info: bool = False) -> str: if info: # Write to both log file and stdout logger.info(msg) - print(msg) + get_console().log_status_update(msg) else: logger.debug(msg) diff --git a/tests/dbt/test_transformation.py b/tests/dbt/test_transformation.py index 0ea41acecf..e8b355e9f5 100644 --- a/tests/dbt/test_transformation.py +++ b/tests/dbt/test_transformation.py @@ -847,7 +847,7 @@ def test_run_query(sushi_test_project: Project, runtime_renderer: t.Callable): @pytest.mark.xdist_group("dbt_manifest") -def test_logging(sushi_test_project: Project, runtime_renderer: t.Callable, capsys): +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() @@ -855,29 +855,39 @@ def test_logging(sushi_test_project: Project, runtime_renderer: t.Callable, caps logger = logging.getLogger("sqlmesh.dbt.builtin") - # Test log with info=False (default) which should only log with debug - with patch.object(logger, "debug") as mock_debug, patch.object(logger, "info") as mock_info: + # Test log with info=False (default), should only log to file with debug and not to console + with ( + patch.object(logger, "debug") as mock_debug, + patch.object(logger, "info") as mock_info, + patch.object(get_console(), "log_status_update") as mock_console, + ): assert renderer('{{ log("foo") }}') == "" mock_debug.assert_called_once() assert "foo" in mock_debug.call_args[0][0] mock_info.assert_not_called() - - captured = capsys.readouterr() - assert "foo" not in captured.out - - # Test log with info=True, now should log with info and also print to stdout - with patch.object(logger, "debug") as mock_debug, patch.object(logger, "info") as mock_info: + mock_console.assert_not_called() + + # Test log with info=True, should log to info and also call log_status_update + with ( + patch.object(logger, "debug") as mock_debug, + patch.object(logger, "info") as mock_info, + patch.object(get_console(), "log_status_update") as mock_console, + ): assert renderer('{{ log("output to be logged with info", info=true) }}') == "" mock_info.assert_called_once() assert "output to be logged with info" in mock_info.call_args[0][0] mock_debug.assert_not_called() - - captured = capsys.readouterr() - assert "output to be logged with info" in captured.out - - with patch.object(logger, "debug") as mock_logger: + mock_console.assert_called_once() + assert "output to be logged with info" in mock_console.call_args[0][0] + + # Test print function as well, should use debug + with ( + patch.object(logger, "debug") as mock_logger, + patch.object(get_console(), "log_status_update") as mock_console, + ): assert renderer('{{ print("bar") }}') == "" - assert "bar" in mock_logger.call_args[0][0] + assert "bar" in mock_logger.call_args[0][0] + mock_console.assert_not_called() @pytest.mark.xdist_group("dbt_manifest")