Repository: databricks/dbt-databricks
Pull request #946 (2025-02-26 18:26:36)

Cleanup logging
### Description

Removing low information/redundant lines from debug log.  This makes debug logs easier to read, since there is less noise between the core actions.  Removing based on which events have not been useful for investigation in the last year.  Also starting to clean up the formatting of macros, though limited how much of that is in this PR, since there are many places that need attention and it would make this PR too big.  Will clean up macro renderings as I touch them going forward.

FYI, generally macros are gross because the way we want to write them as code is not aligned with how we need to write them so that they get rendered out reasonably.

### Checklist

- [x] I have run this code in development and it appears to resolve the stated issue
- [x] This PR includes tests, or tests are not required/relevant for this PR
- [x] I have updated the `CHANGELOG.md` and added information about my change to the "dbt-databricks next" section.



Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 3d0bb491..ca1114ac 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -10,6 +10,7 @@
 
 - Update pinned python SDK version from 0.17.0 to 0.41.0. ([827](https://github.com/databricks/dbt-databricks/pull/827))
 - Implement new constraint logic for use_materialization_v2 flag ([846](https://github.com/databricks/dbt-databricks/pull/846/files)), ([876](https://github.com/databricks/dbt-databricks/pull/876))
+- Streamlining debug logging to make it more usable ([946](https://github.com/databricks/dbt-databricks/pull/946))
 
 ## dbt-databricks 1.9.7 (Feb 25, 2025)
 
diff --git a/dbt/adapters/databricks/connections.py b/dbt/adapters/databricks/connections.py
index 4fcde9ab..27690e22 100644
--- a/dbt/adapters/databricks/connections.py
+++ b/dbt/adapters/databricks/connections.py
@@ -30,14 +30,10 @@ from dbt.adapters.databricks.credentials import (
     DatabricksCredentials,
 )
 from dbt.adapters.databricks.events.connection_events import (
-    ConnectionAcquire,
     ConnectionCreate,
     ConnectionCreateError,
-    ConnectionIdleCheck,
     ConnectionIdleClose,
-    ConnectionRelease,
     ConnectionReset,
-    ConnectionRetrieve,
     ConnectionReuse,
 )
 from dbt.adapters.databricks.events.other_events import QueryError
@@ -155,12 +151,6 @@ class DatabricksDBTConnection(Connection):
             self.last_used_time = time.time()
         self.language = query_header_context.language
 
-        logger.debug(
-            ConnectionAcquire(
-                str(self), query_header_context, self.compute_name, self.thread_identifier
-            )
-        )
-
     def _release(self) -> None:
         """Indicate that this connection is not in use."""
         # Need to check for > 0 because in some situations the dbt code will make an extra
@@ -173,8 +163,6 @@ class DatabricksDBTConnection(Connection):
         if self.acquire_release_count == 0 and self.language != "python":
             self.last_used_time = time.time()
 
-        logger.debug(ConnectionRelease(str(self)))
-
     def _get_idle_time(self) -> float:
         return 0 if self.last_used_time is None else time.time() - self.last_used_time
 
@@ -183,10 +171,9 @@ class DatabricksDBTConnection(Connection):
 
     def __str__(self) -> str:
         return (
-            f"DatabricksDBTConnection(id={id(self)}, session-id={self.session_id}, "
-            f"name={self.name}, idle-time={self._get_idle_time()}s, acquire-count="
-            f"{self.acquire_release_count}, language={self.language}, thread-identifier="
-            f"{self.thread_identifier}, compute-name={self.compute_name})"
+            f"DatabricksDBTConnection(session-id={self.session_id}, "
+            f"name={self.name}, idle-time={self._get_idle_time()}s, language={self.language}, "
+            f"compute-name={self.compute_name})"
         )
 
     def _reset_handle(self, open: Callable[[Connection], Connection]) -> None:
@@ -515,8 +502,6 @@ class DatabricksConnectionManager(SparkConnectionManager):
     def get_thread_connection(self) -> Connection:
         conn = super().get_thread_connection()
         self._cleanup_idle_connections()
-        dbr_conn = cast(DatabricksDBTConnection, conn)
-        logger.debug(ConnectionRetrieve(str(dbr_conn)))
 
         return conn
 
@@ -537,8 +522,6 @@ class DatabricksConnectionManager(SparkConnectionManager):
             # if different models use different compute resources
             thread_conns = self._get_compute_connections()
             for conn in thread_conns.values():
-                logger.debug(ConnectionIdleCheck(str(conn)))
-
                 # Generally speaking we only want to close/refresh the connection if the
                 # acquire_release_count is zero.  i.e. the connection is not currently in use.
                 # However python models acquire a connection then run the pyton model, which
diff --git a/dbt/adapters/databricks/events/connection_events.py b/dbt/adapters/databricks/events/connection_events.py
index 3f533c1d..347e36b9 100644
--- a/dbt/adapters/databricks/events/connection_events.py
+++ b/dbt/adapters/databricks/events/connection_events.py
@@ -1,5 +1,5 @@
 from abc import ABC
-from typing import Any, Optional
+from typing import Optional
 
 from databricks.sql.client import Connection
 
@@ -33,34 +33,6 @@ class ConnectionWrapperEvent(ABC):
         return f"{self.description} - {self.message}"
 
 
-class ConnectionAcquire(ConnectionWrapperEvent):
-    def __init__(
-        self,
-        description: str,
-        model: Optional[Any],
-        compute_name: Optional[str],
-        thread_identifier: tuple[int, int],
-    ):
-        message = f"Acquired connection on thread {thread_identifier}, using "
-        if not compute_name:
-            message += "default compute resource"
-        else:
-            message += f"compute resource '{compute_name}'"
-
-        if model:
-            # ResultNode *should* have relation_name attr, but we work around a core
-            # issue by checking.
-            relation_name = getattr(model, "relation_name", "[Unknown]")
-            message += f" for model '{relation_name}'"
-
-        super().__init__(description, message)
-
-
-class ConnectionRelease(ConnectionWrapperEvent):
-    def __init__(self, description: str):
-        super().__init__(description, "Released connection")
-
-
 class ConnectionReset(ConnectionWrapperEvent):
     def __init__(self, description: str):
         super().__init__(description, "Reset connection handle")
@@ -76,19 +48,9 @@ class ConnectionCreate(ConnectionWrapperEvent):
         super().__init__(description, "Creating connection")
 
 
-class ConnectionIdleCheck(ConnectionWrapperEvent):
-    def __init__(self, description: str):
-        super().__init__(description, "Checking idleness")
-
-
 class ConnectionIdleClose(ConnectionWrapperEvent):
     def __init__(self, description: str):
-        super().__init__(description, "Closing for idleness")
-
-
-class ConnectionRetrieve(ConnectionWrapperEvent):
-    def __init__(self, description: str):
-        super().__init__(description, "Retrieving connection")
+        super().__init__(description, "Recreating due to idleness")
 
 
 class ConnectionCreated(ConnectionWrapperEvent):
diff --git a/dbt/include/databricks/macros/adapters/columns.sql b/dbt/include/databricks/macros/adapters/columns.sql
index d9b041cc..fcddcdcb 100644
--- a/dbt/include/databricks/macros/adapters/columns.sql
+++ b/dbt/include/databricks/macros/adapters/columns.sql
@@ -41,4 +41,23 @@
       ALTER TABLE {{ relation.render() }} ADD COLUMNS ({{ api.Column.format_add_column_list(add_columns) }})
     {%- endcall -%}
   {% endif %}
+{% endmacro %}
+
+{% macro databricks__get_empty_subquery_sql(select_sql, select_sql_header=none) %}
+  {%- if select_sql_header is not none -%}
+  {{ select_sql_header }}
+  {%- endif %}
+  select * from (
+    {{ select_sql }}
+  ) as __dbt_sbq
+  where false
+  limit 0
+{% endmacro %}
+
+{% macro databricks__get_columns_in_query(select_sql) %}
+  {{ log("Getting column information via empty query")}}
+  {% call statement('get_columns_in_query', fetch_result=True, auto_begin=False) -%}
+     {{ get_empty_subquery_sql(select_sql) }}
+  {% endcall %}
+  {{ return(load_result('get_columns_in_query').table.columns | map(attribute='name') | list) }}
 {% endmacro %}
\ No newline at end of file
diff --git a/dbt/include/databricks/macros/adapters/metadata.sql b/dbt/include/databricks/macros/adapters/metadata.sql
index a63cbb75..01abc648 100644
--- a/dbt/include/databricks/macros/adapters/metadata.sql
+++ b/dbt/include/databricks/macros/adapters/metadata.sql
@@ -85,19 +85,21 @@
 {% endmacro %}
 
 {% macro get_uc_tables(relation) %}
-  {% call statement('get_uc_tables', fetch_result=True) -%}
-    select
-      table_name,
-      if(table_type in ('EXTERNAL', 'MANAGED', 'MANAGED_SHALLOW_CLONE', 'EXTERNAL_SHALLOW_CLONE'), 'table', lower(table_type)) as table_type,
-      lower(data_source_format) as file_format,
-      table_owner
-    from `system`.`information_schema`.`tables`
-    where table_catalog = '{{ relation.database|lower }}'
-      and table_schema = '{{ relation.schema|lower }}'
-    {% if relation.identifier %}
-      and table_name = '{{ relation.identifier|lower }}'
+  {{ log("Fetching tables for: " ~ relation.render()) }}
+  {%- call statement('get_uc_tables', fetch_result=True) %}
+
+  select
+    table_name,
+    if(table_type in ('EXTERNAL', 'MANAGED', 'MANAGED_SHALLOW_CLONE', 'EXTERNAL_SHALLOW_CLONE'), 'table', lower(table_type)) as table_type,
+    lower(data_source_format) as file_format,
+    table_owner
+  from `system`.`information_schema`.`tables`
+  where table_catalog = '{{ relation.database|lower }}' 
+    and table_schema = '{{ relation.schema|lower }}'
+    {%- if relation.identifier %}
+    and table_name = '{{ relation.identifier|lower }}'
     {% endif %}
-  {% endcall %}
+  {% endcall -%}
 
   {% do return(load_result('get_uc_tables').table) %}
 {% endmacro %}
\ No newline at end of file
diff --git a/dbt/include/databricks/macros/materializations/view.sql b/dbt/include/databricks/macros/materializations/view.sql
index 8c062edf..08cac9c6 100644
--- a/dbt/include/databricks/macros/materializations/view.sql
+++ b/dbt/include/databricks/macros/materializations/view.sql
@@ -1,4 +1,5 @@
 {% materialization view, adapter='databricks' -%}
+  {{ log("MATERIALIZING VIEW") }}
   {%- set identifier = model['alias'] -%}
 
   {%- set old_relation = adapter.get_relation(database=database, schema=schema, identifier=identifier) -%}
diff --git a/dbt/include/databricks/macros/relations/comment.sql b/dbt/include/databricks/macros/relations/comment.sql
new file mode 100644
index 00000000..897624c3
--- /dev/null
+++ b/dbt/include/databricks/macros/relations/comment.sql
@@ -0,0 +1,11 @@
+{% macro databricks__comment_clause() %}
+  {%- set raw_persist_docs = config.get('persist_docs', {}) -%}
+  {%- if raw_persist_docs is mapping -%}
+    {%- set raw_relation = raw_persist_docs.get('relation', false) -%}
+      {%- if raw_relation -%}
+      comment '{{ model.description | replace("'", "\\'") }}'
+      {%- endif -%}
+  {%- elif raw_persist_docs -%}
+    {{ exceptions.raise_compiler_error("Invalid value provided for 'persist_docs'. Expected dict but got value: " ~ raw_persist_docs) }}
+  {% endif %}
+{%- endmacro -%}
\ No newline at end of file
diff --git a/dbt/include/databricks/macros/relations/table/create.sql b/dbt/include/databricks/macros/relations/table/create.sql
index b13e5dc6..f7b3c141 100644
--- a/dbt/include/databricks/macros/relations/table/create.sql
+++ b/dbt/include/databricks/macros/relations/table/create.sql
@@ -1,11 +1,11 @@
 {% macro create_table_at(relation, intermediate_relation, compiled_code) %}
   {% set tags = config.get('databricks_tags') %}
-  {%- set model_columns = model.get('columns', []) -%}
-  {%- set existing_columns = adapter.get_columns_in_relation(intermediate_relation) -%}
+  {% set model_columns = model.get('columns', []) %}
+  {% set existing_columns = adapter.get_columns_in_relation(intermediate_relation) %}
   {% set model_constraints = model.get('constraints', []) %}
   {% set columns_and_constraints = adapter.parse_columns_and_constraints(existing_columns, model_columns, model_constraints) %}
-
-  {%- set target_relation = relation.enrich(columns_and_constraints[1]) -%}
+  {% set target_relation = relation.enrich(columns_and_constraints[1]) %}
+  
   {% call statement('main') %}
     {{ get_create_table_sql(target_relation, columns_and_constraints[0], compiled_code) }}
   {% endcall %}
@@ -24,12 +24,12 @@
   {%- set contract_enforced = contract and contract.enforced -%}
   {%- if contract_enforced -%}
     {{ get_assert_columns_equivalent(compiled_code) }}
-  {% endif %}
+  {%- endif -%}
 
-  {% if file_format == 'delta' %}
-    create or replace table {{ target_relation }}
+  {%- if file_format == 'delta' %}
+  create or replace table {{ target_relation }}
   {% else %}
-    create table {{ target_relation }}
+  create table {{ target_relation }}
   {% endif -%}
   {{ get_column_and_constraints_sql(target_relation, columns) }}
   {{ file_format_clause() }}
diff --git a/dbt/include/databricks/macros/relations/view/create.sql b/dbt/include/databricks/macros/relations/view/create.sql
index 5399b4ef..9ef56be4 100644
--- a/dbt/include/databricks/macros/relations/view/create.sql
+++ b/dbt/include/databricks/macros/relations/view/create.sql
@@ -1,20 +1,39 @@
-{% macro databricks__create_view_as(relation, sql) -%}
+{% macro databricks__create_view_as(relation, sql) %}
+  {{ log("Creating view " ~ relation) }}
   create or replace view {{ relation.render() }}
-  {% if config.persist_column_docs() -%}
-    {% set model_columns = model.columns %}
-    {% set query_columns = get_columns_in_query(sql) %}
-    {% if query_columns %}
-      (
-        {{ get_persist_docs_column_list(model_columns, query_columns) }}
-      )
-    {% endif %}
-  {% endif %}
+  {%- if config.persist_column_docs() -%}
+    {%- set model_columns = model.columns -%}
+    {%- set query_columns = get_columns_in_query(sql) -%}
+    {%- if query_columns %}
+  (
+    {{ get_persist_docs_column_list(model_columns, query_columns) }}
+  )
+    {%- endif -%}
+  {%- endif %}
   {{ comment_clause() }}
   {%- set contract_config = config.get('contract') -%}
-  {% if contract_config and contract_config.enforced %}
-    {{ get_assert_columns_equivalent(sql) }}
-  {%- endif %}
+  {%- if contract_config and contract_config.enforced %}
+  {{ get_assert_columns_equivalent(sql) }}
+  {%- endif -%}
   {{ tblproperties_clause() }}
-  as
+  as (
     {{ sql }}
+  )
 {% endmacro %}
+
+
+{% macro get_column_comment_sql(column_name, column_dict) -%}
+  {%- if column_name in column_dict and column_dict[column_name]["description"] -%}
+    {%- set escaped_description = column_dict[column_name]["description"] | replace("'", "\\'") -%}
+    {%- set column_comment_clause = "comment '" ~ escaped_description ~ "'" -%}
+    {{ adapter.quote(column_name) }} {{ column_comment_clause }}
+  {%- else -%}
+    {{ adapter.quote(column_name) }}
+  {%- endif -%}
+{%- endmacro %}
+
+{% macro get_persist_docs_column_list(model_columns, query_columns) -%}
+  {%- for column_name in query_columns -%}
+    {{ get_column_comment_sql(column_name, model_columns) }}{{",\n\t" if not loop.last else "" }}
+  {%- endfor -%}
+{% endmacro %}
\ No newline at end of file


Test patch:
diff --git a/tests/functional/adapter/aliases/fixtures.py b/tests/functional/adapter/aliases/fixtures.py
index 2f7803a6..4123435b 100644
--- a/tests/functional/adapter/aliases/fixtures.py
+++ b/tests/functional/adapter/aliases/fixtures.py
@@ -4,7 +4,7 @@ MACROS__CAST_SQL = """
   {{ adapter.dispatch('string_literal', macro_namespace='test')(s) }}
 {%- endmacro %}
 
-{% macro databricks__string_literal(s) %}
+{% macro databricks__string_literal(s) -%}
     cast('{{ s }}' as STRING)
-{% endmacro %}
+{%- endmacro %}
 """
diff --git a/tests/functional/adapter/ephemeral/test_ephemeral.py b/tests/functional/adapter/ephemeral/test_ephemeral.py
index 52efdc0f..86f33c52 100644
--- a/tests/functional/adapter/ephemeral/test_ephemeral.py
+++ b/tests/functional/adapter/ephemeral/test_ephemeral.py
@@ -39,11 +39,11 @@ class TestEphemeralNested(BaseEphemeral):
         sql_file = re.sub(r"\d+", "", sql_file)
         expected_sql = (
             f"create or replace view `{project.database}`.`test_test_ephemeral`.`root_view` as "
-            "with __dbt__cte__ephemeral_level_two as ("
+            "( with __dbt__cte__ephemeral_level_two as ("
             f"select * from `{project.database}`.`test_test_ephemeral`.`source_table`"
             "),  __dbt__cte__ephemeral as ("
             "select * from __dbt__cte__ephemeral_level_two"
-            ")select * from __dbt__cte__ephemeral"
+            ") select * from __dbt__cte__ephemeral )"
         )
 
         sql_file = "".join(sql_file.split())
diff --git a/tests/functional/adapter/warehouse_per_model/test_warehouse_per_model.py b/tests/functional/adapter/warehouse_per_model/test_warehouse_per_model.py
index cf309fa3..426e74bf 100644
--- a/tests/functional/adapter/warehouse_per_model/test_warehouse_per_model.py
+++ b/tests/functional/adapter/warehouse_per_model/test_warehouse_per_model.py
@@ -91,74 +91,3 @@ class TestSpecifyingForProjectModelsInFolder(BaseSpecifyingCompute):
     @pytest.fixture(scope="class")
     def test_config(self):
         return {"model_names": ["target4"]}
-
-
-class TestWarehousePerModel(BaseWarehousePerModel):
-    @pytest.fixture(scope="class")
-    def seeds(self):
-        return {
-            "source.csv": fixtures.source,
-            "properties.yml": fixtures.seed_properties,
-        }
-
-    @pytest.fixture(scope="class")
-    def snapshots(self):
-        return {
-            "target_snap.sql": fixtures.target_snap,
-        }
-
-    def test_wpm(self, project, profile_dir):
-        _, log = util.run_dbt_and_capture(
-            [
-                "--debug",
-                "seed",
-                "--profiles-dir",
-                profile_dir,
-                "--target",
-                "alternate_warehouse",
-            ]
-        )
-
-        assert (
-            "using compute resource 'alternate_warehouse2' for model "
-            f"'`{project.database}`.`{project.test_schema}`.`source`'" in log
-        )
-
-        _, log = util.run_dbt_and_capture(
-            [
-                "--debug",
-                "run",
-                "--select",
-                "target",
-                "target3",
-                "--profiles-dir",
-                profile_dir,
-                "--target",
-                "alternate_warehouse",
-            ]
-        )
-        assert (
-            "using compute resource 'alternate_warehouse' for model "
-            f"'`{project.database}`.`{project.test_schema}`.`target`'" in log
-        )
-        assert (
-            f"using default compute resource for model '`{project.database}`."
-            f"`{project.test_schema}`.`target3`'" in log
-        )
-
-        _, log = util.run_dbt_and_capture(
-            [
-                "--debug",
-                "snapshot",
-                "--profiles-dir",
-                profile_dir,
-                "--target",
-                "alternate_warehouse",
-            ]
-        )
-        assert (
-            "using compute resource 'alternate_warehouse3' for model "
-            f"'`{project.database}`.`snapshots`.`target_snap`'" in log
-        )
-
-        util.check_relations_equal(project.adapter, ["target", "source"])
diff --git a/tests/unit/events/test_connection_events.py b/tests/unit/events/test_connection_events.py
index 6c005fb6..6f5208a6 100644
--- a/tests/unit/events/test_connection_events.py
+++ b/tests/unit/events/test_connection_events.py
@@ -1,7 +1,6 @@
 from unittest.mock import Mock
 
 from dbt.adapters.databricks.events.connection_events import (
-    ConnectionAcquire,
     ConnectionEvent,
 )
 
@@ -27,37 +26,3 @@ class TestConnectionEvents:
         mock.get_session_id_hex.return_value = "1234"
         event = ConnectionTestEvent(mock)
         assert str(event) == "Connection(session-id=1234) - This is a test"
-
-
-class TestConnectionAcquire:
-    def test_connection_acquire__missing_data(self):
-        event = ConnectionAcquire(None, None, None, (0, 0))
-        assert (
-            str(event)
-            == "None - Acquired connection on thread (0, 0), using default compute resource"
-        )
-
-    def test_connection_acquire__with_compute_name(self):
-        event = ConnectionAcquire(None, None, "Eniac", (0, 0))
-        assert (
-            str(event)
-            == "None - Acquired connection on thread (0, 0), using compute resource 'Eniac'"
-        )
-
-    def test_connection_acquire__with_nonmodel_node(self):
-        event = ConnectionAcquire(None, Mock([]), None, (0, 0))
-        assert (
-            str(event)
-            == "None - Acquired connection on thread (0, 0), using default compute resource"
-            " for model '[Unknown]'"
-        )
-
-    def test_connection_acquire__with_everything(self):
-        model = Mock()
-        model.relation_name = "MyModel"
-        event = ConnectionAcquire("Connection", model, "Eniac", (0, 0))
-        assert (
-            str(event)
-            == "Connection - Acquired connection on thread (0, 0), using compute resource 'Eniac'"
-            " for model 'MyModel'"
-        )
diff --git a/tests/unit/macros/base.py b/tests/unit/macros/base.py
index cb9c7f28..3d129b6a 100644
--- a/tests/unit/macros/base.py
+++ b/tests/unit/macros/base.py
@@ -47,6 +47,7 @@ class MacroTestBase:
             "statement": lambda r, caller: r,
             "adapter": Mock(),
             "var": Mock(),
+            "log": Mock(return_value=""),
             "return": lambda r: r,
             "is_incremental": Mock(return_value=False),
         }
diff --git a/tests/unit/macros/relations/test_view_macros.py b/tests/unit/macros/relations/test_view_macros.py
index 700e966a..9914d34d 100644
--- a/tests/unit/macros/relations/test_view_macros.py
+++ b/tests/unit/macros/relations/test_view_macros.py
@@ -29,7 +29,7 @@ class TestCreateViewAs(MacroTestBase):
         sql = self.render_create_view_as(template_bundle)
         expected = (
             f"create or replace view {template_bundle.relation} "
-            "tblproperties ('tblproperties_to_view' = 'true' ) as select 1"
+            "tblproperties ('tblproperties_to_view' = 'true' ) as ( select 1 )"
         )
 
         assert sql == expected