log() и приёмы отладки Jinja

Когда Jinja-шаблон не делает того, что вы ожидаете, нужны инструменты для отладки. SQL вы запускаете и смотрите ошибку warehouse-а — но что если ошибка в самом шаблоне, который не дошёл до warehouse? В этом уроке — про log(), target/compiled, target/run и приёмы, которые экономят часы дебага.

log(): печать в консоль

Главный инструмент Jinja-разработчика. log() пишет сообщение в stdout или stderr во время компиляции/выполнения шаблона:

{% set x = 42 %}
{{ log("Значение x = " ~ x, info=True) }}

select 1

Запустим:

$ dbt compile --select my_model
14:35:12  Running with dbt=1.10.2
14:35:13  Значение x = 42
14:35:13  Done. Compiled 1 model

Что важно:

• log("message", info=True) — основная форма. info=True означает «уровень INFO, видно в обычном режиме».
• Без info=True сообщение пишется в logs/dbt.log файл, но не выводится в консоль — может казаться, что log не сработал.
• В dbt run, dbt build, dbt test — то же самое.
• Сообщение конкатенируется через ~ (Jinja string concatenation).

log как expression vs statement

В курсе вы увидите две формы:

{# Форма 1: expression #}
{{ log("hello", info=True) }}

{# Форма 2: statement через do #}
{% do log("hello", info=True) %}

Обе работают. Различие: {{ }} ВОЗВРАЩАЕТ значение в output, но log() возвращает пустую строку — в output ничего лишнего. {% do %} явно выполняет без возврата. Современный стиль — {% do log(...) %}, потому что чище семантически: log — побочный эффект, не вычисление значения.

Чтобы не дёргаться — оба варианта валидны и стандартный код dbt использует оба.

Типичные сценарии log

1. Печатать переменную из var/env_var

{% set start_date = var('start_date', '2026-01-01') %}
{% do log("start_date for " ~ this ~ " = " ~ start_date, info=True) %}

select * from {{ ref('orders') }}
where order_date >= '{{ start_date }}'

this — magic-переменная, ссылающаяся на текущую модель (полный qualifier). Полезно, когда логируете из общего macro и хочется знать, кому он сейчас компилируется.

2. Печатать структуру результата run_query

{% set results = run_query("select count(*) from orders") %}

{% if execute %}
    {% do log("Columns: " ~ results.column_names, info=True) %}
    {% do log("Rows: " ~ results.rows, info=True) %}
    {% do log("Count: " ~ results.columns[0].values()[0], info=True) %}
{% endif %}

Вывод:

14:42:01  Columns: ['count_star()']
14:42:01  Rows: <agate.rows.Rows object at 0x...>
14:42:01  Count: 50000

results.rows напечатается как Python-объект (так себе). Если хочешь видеть содержимое, преобразуй в список: results.rows.values().

3. Печатать, какая ветка if сработала

{% if target.name == 'prod' %}
    {% do log("Running in PROD mode", info=True) %}
    -- full history
{% else %}
    {% do log("Running in DEV mode, filtering to 7 days", info=True) %}
    where order_date >= current_date - interval 7 day
{% endif %}

В консоли сразу понятно, какой режим.

4. Логи на уровне macro

В сложных macros — лог на input/output:

{% macro safe_divide(numerator, denominator) %}
    {% do log("safe_divide called: " ~ numerator ~ " / " ~ denominator, info=True) %}
    case when {{ denominator }} = 0 then null
         else {{ numerator }} / {{ denominator }}
    end
{% endmacro %}

Каждый раз, когда macro вызывается из модели, в лог попадёт строка. Помогает найти, где macro используется (и сколько раз).

target/compiled vs target/run

Когда модель не работает, первое — посмотреть скомпилированный SQL. dbt пишет его в две локации:

Пример: для модели models/marts/marts__orders.sql пути:

target/compiled/jaffle_shop/models/marts/marts__orders.sql
target/run/jaffle_shop/models/marts/marts__orders.sql

Что смотреть в compiled

-- target/compiled/jaffle_shop/models/marts/marts__orders.sql

select 
    order_id,
    order_date,
    total_amount
from "jaffle_shop"."main"."stg_jaffle__orders"
where order_date >= current_date - interval 7 day

Это тот SQL, который будет выполнен (без CREATE-обёртки). Можно скопировать и запустить в DuckDB CLI, чтобы понять, корректен ли результат.

Что смотреть в run

-- target/run/jaffle_shop/models/marts/marts__orders.sql

create table "jaffle_shop"."main"."marts__orders"
as (
    select 
        order_id,
        order_date,
        total_amount
    from "jaffle_shop"."main"."stg_jaffle__orders"
    where order_date >= current_date - interval 7 day
);

Это полная команда, которую dbt отправляет в warehouse. Различия с compiled — CREATE-обёртка, on-run-start/end хуки (если есть), grants.

Workflow отладки Jinja

Идеальный порядок действий при «что-то не так с моделью»:

Запомните цикл: compile -> cat compiled -> run в DuckDB -> понять, где сломалось.

Команда dbt compile

# Скомпилировать ВСЕ модели
$ dbt compile

# Только одну
$ dbt compile --select marts__orders

# Только модель + её зависимости (для проверки контекста)
$ dbt compile --select +marts__orders

dbt compile не выполняет SQL — только парсит и компилирует Jinja. Быстрее, чем dbt run, и не трогает данные.

Типовые антибаги Jinja

Bug 1: undefined variable

Compilation Error in model my_model (models/marts/my_model.sql)
  'my_var' is undefined

Причина: ссылаешься на переменную, которую не объявили ({% set my_var = ... %} не выполнился, или опечатка в имени).

Лечение: в начале файла добавь {% do log("vars: " ~ my_var, info=True) %} — увидишь, где Jinja теряет контекст.

Bug 2: ‘NoneType’ object has no attribute X

Compilation Error
  'NoneType' object has no attribute 'columns'

Причина: run_query вернул None на parse phase, ты используешь results.columns без {% if execute %} (см. прошлый урок).

Лечение: оборачивай в {% if execute %} с fallback.

Bug 3: лишние пробелы, кривой SQL

-- target/compiled
select
    
    a,
    
    b,
from t

Trailing comma — bug. Скорее всего, забыли loop.last.

Лечение:

{% for col in columns %}
    {{ col }}{% if not loop.last %},{% endif %}
{% endfor %}

Bug 4: тип не тот

TypeError: unsupported operand type(s) for +: 'int' and 'str'

В Jinja + для строк не работает. Использовать ~:

{# WRONG #}
{{ "Count: " + count }}

{# RIGHT #}
{{ "Count: " ~ count }}

Bug 5: Jinja vs SQL смешано

{# WRONG: SQL comment внутри Jinja #}
{% set x = 1 -- comment %}

{# RIGHT: Jinja comment в Jinja блоке #}
{% set x = 1 %}  {# comment #}

-- в {% %} — синтаксическая ошибка Jinja.

Полезные техники

Inspect через target.X

{% do log("Target name: " ~ target.name, info=True) %}
{% do log("Target type: " ~ target.type, info=True) %}
{% do log("Target schema: " ~ target.schema, info=True) %}
{% do log("Target threads: " ~ target.threads, info=True) %}

Полезно при дебаге profile/target.

Inspect через this

{% do log("This relation: " ~ this, info=True) %}
{% do log("This schema: " ~ this.schema, info=True) %}
{% do log("This identifier: " ~ this.identifier, info=True) %}

this доступна только внутри моделей (не в макросах). Содержит ref на текущую модель.

Inspect через graph

graph даёт доступ ко всему DAG проекта. Полезно для мета-программирования:

{% if execute %}
    {% set all_models = graph.nodes.values() | selectattr("resource_type", "equalto", "model") | list %}
    {% do log("Total models in project: " ~ all_models | length, info=True) %}
{% endif %}

Это уже advanced и пригодится не часто. Junior должен знать, что graph существует.

Pretty-print через tojson

Для сложных объектов используй filter tojson:

{% do log(my_dict | tojson, info=True) %}

Выведет JSON-представление словаря. Гораздо читаемее, чем стандартный Python __repr__.

Tradeoff: сколько логов оставлять в production

{% do log %} хорош на этапе разработки, но в production вы хотите чистый output. Варианты:

1. Удалять логи после отладки. Минус: при следующем баге пишешь заново.
2. Условный лог через var: {% if var('debug', false) %}{% do log(...) %}{% endif %}. Запуск с --vars '{debug: true}' — логи. По умолчанию — без.
3. Уровень логирования через info/debug: {% do log(..., info=False) %} пишет только в logs/dbt.log, не в консоль. Логи есть, но не засоряют stdout.

Junior-рекомендация: вариант 1 (удалять) для моделей, вариант 2 (условный) для часто отлаживаемых макросов.

Попробуй сам

Найдите в своём проекте любую модель с условной логикой ({% if %}) и добавьте в неё {% do log() %} на входе каждой ветки. Например:

{% if target.name == 'prod' %}
    {% do log("Running stg_orders in PROD: full history", info=True) %}
    -- ...
{% else %}
    {% do log("Running stg_orders in DEV: 7 days", info=True) %}
    where order_date >= current_date - interval 7 day
{% endif %}

Запустите dbt run --select stg_orders --target dev. Убедитесь, что в консоли видна правильная ветка. Затем — dbt run --select stg_orders --target prod (если у вас настроен prod target). Проверьте обратное.

Итоги

• {% do log("message", info=True) %} — основной инструмент дебага Jinja. Без info=True лог идёт только в файл, не в консоль.
• Используй ~ для конкатенации строк (не +, тот для чисел).
• target/compiled — SQL после Jinja, без обёртки. Для отладки логики.
• target/run — полный DDL с CREATE/INSERT. Для отладки materialization.
• Workflow: dbt compile --select X -> cat target/compiled/.../X.sql -> запустить руками в DuckDB.
• Антибаги: undefined variable, NoneType (забыли execute), trailing comma (loop.last), + вместо ~.
• В production либо удаляй логи, либо ставь под {% if var('debug', false) %}.

Модуль 9 закрыт. У вас есть полная картина Jinja-фундамента: синтаксис, control flow, parse vs execute, отладка. В следующем модуле мы используем эту базу, чтобы написать macros — переиспользуемые блоки Jinja, которые делают dbt-проекты сухими и поддерживаемыми.