https://linen.dev logo
Join Slack
Powered by
hi elementary team, I might need some help in debu...
# community-support
d
hi elementary team, I might need some help in debugging this invocation id issue we're having. It's occurring after we've tried to upgrade our elementary version from 0.15.2 to 0.19.0. We're already only invoking the dbt source command before the upload in our airflow dag and all the other suggestions the elementary-ai bot suggests, so wanted to follow up here if anyone has any ideas what to try next. I'll post the relevant logs in thread https://elementary-community.slack.com/archives/C08HW57FGN9/p1750884381626099
✅ 1
truncated logs
Copy code
dbt-elementary-dbt-source-freshness-y2yq1z44
 ▶ Log message source details
[2025-06-25, 19:34:26 UTC] {local_task_job_runner.py:123} ▶ Pre task execution logs
[2025-06-25, 19:34:26 UTC] {subprocess.py:78} INFO - Tmp dir root location: /tmp
[2025-06-25, 19:34:26 UTC] {subprocess.py:88} INFO - Running command: ['/usr/bin/bash', '-c', 'cd /opt/airflow/dbt_e2_pipelines && dbt --no-use-colors source freshness --exclude tag:disabled --profiles-dir /opt/airflow/ --profile databricks --target e2_prod && ret=$? && edr run-operation upload-source-freshness --profiles-dir /opt/airflow/ --project-dir /opt/airflow/dbt_e2_pipelines --profile-target e2_prod && ret=$? && exit $ret']
[2025-06-25, 19:34:26 UTC] {subprocess.py:99} INFO - Output:
[2025-06-25, 19:34:28 UTC] {subprocess.py:106} INFO - 19:34:28  Running with dbt=1.10.2
[2025-06-25, 19:34:29 UTC] {subprocess.py:106} INFO - WARNING:thrift.transport.sslcompat:using legacy validation callback
[2025-06-25, 19:34:30 UTC] {subprocess.py:106} INFO - /home/airflow/.local/lib/python3.12/site-packages/pydantic/_internal/_config.py:345: UserWarning: Valid config keys have changed in V2:
[2025-06-25, 19:34:30 UTC] {subprocess.py:106} INFO - * 'allow_population_by_field_name' has been renamed to 'populate_by_name'
[2025-06-25, 19:34:30 UTC] {subprocess.py:106} INFO -   warnings.warn(message, UserWarning)
[2025-06-25, 19:34:30 UTC] {subprocess.py:106} INFO - 19:34:30  Registered adapter: databricks=1.10.4
[2025-06-25, 19:34:32 UTC] {subprocess.py:106} INFO - 19:34:32  Unable to do partial parsing because config vars, config profile, or config target have changed
[2025-06-25, 19:35:04 UTC] {subprocess.py:106} INFO - 19:35:04  [WARNING][PropertyMovedToConfigDeprecation]: Deprecated functionality
[2025-06-25, 19:35:04 UTC] {subprocess.py:106} INFO - Found `freshness` as a top-level property of `core` in file
[2025-06-25, 19:35:04 UTC] {subprocess.py:106} INFO - `models/silver/core/core_sources.yml`. The `freshness` top-level property should
[2025-06-25, 19:35:04 UTC] {subprocess.py:106} INFO - be moved into the `config` of `core`.
[2025-06-25, 19:35:11 UTC] {subprocess.py:106} INFO - 19:35:11  Found 655 models, 28 snapshots, 3954 data tests, 2 operations, 250 sources, 1597 macros, 31 unit tests
[2025-06-25, 19:35:11 UTC] {subprocess.py:106} INFO - 19:35:11
[2025-06-25, 19:35:11 UTC] {subprocess.py:106} INFO - 19:35:11  Concurrency: 30 threads (target='e2_prod')
[2025-06-25, 19:35:11 UTC] {subprocess.py:106} INFO - 19:35:11
[2025-06-25, 19:35:12 UTC] {subprocess.py:106} INFO - 19:35:12  1 of 1 START hook: elementary.on-run-start.0 ................................... [RUN]
[2025-06-25, 19:35:12 UTC] {subprocess.py:106} INFO - 19:35:12  1 of 1 OK hook: elementary.on-run-start.0 ...................................... [OK in 0.03s]
[2025-06-25, 19:35:12 UTC] {subprocess.py:106} INFO - 19:35:12
[2025-06-25, 19:35:12 UTC] {subprocess.py:106} INFO - 19:35:12  1 of 92 START freshness of client_events.all_math_game_events .................. [RUN]
[2025-06-25, 19:35:12 UTC] {subprocess.py:106} INFO - 19:35:12  2 of 92 START freshness of core.growthbook_data_sources ........................ [RUN]
[2025-06-25, 19:35:12 UTC] {subprocess.py:106} INFO - 19:35:12  3 of 92 START freshness of core.growthbook_experiments ......................... [RUN]
[2025-06-25, 19:35:12 UTC] {subprocess.py:106} INFO - 19:35:12  4 of 92 START freshness of core.growthbook_metrics ............................. [RUN]
[2

...

[2025-06-25, 19:36:16 UTC] {subprocess.py:106} INFO - 19:36:16
[2025-06-25, 19:36:31 UTC] {subprocess.py:106} INFO - 19:36:31  1 of 1 START hook: elementary.on-run-end.0 ..................................... [RUN]
[2025-06-25, 19:36:31 UTC] {subprocess.py:106} INFO - 19:36:31  1 of 1 OK hook: elementary.on-run-end.0 ........................................ [OK in 15.37s]
[2025-06-25, 19:36:35 UTC] {subprocess.py:106} INFO - 19:36:35
[2025-06-25, 19:36:35 UTC] {subprocess.py:106} INFO - 19:36:35  Finished running 2 project hooks, 92 sources in 0 hours 1 minutes and 24.21 seconds (84.21s).
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - 19:36:37
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - 19:36:37  Failure in source students_answers_daily_aggregate (models/silver/education/education_sources.yml)
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - 19:36:37    Status: error
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - 19:36:37  Done.
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - 19:36:37  [WARNING][DeprecationsSummary]: Deprecated functionality
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - Summary of encountered deprecations:
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - - PropertyMovedToConfigDeprecation: 16 occurrences
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - To see all deprecation instances instead of just the first occurrence of each,
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - run command again with the `--show-all-deprecations` flag. You may also need to
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - run with `--no-partial-parse` as some deprecations are only encountered during
[2025-06-25, 19:36:37 UTC] {subprocess.py:106} INFO - parsing.
[2025-06-25, 19:36:39 UTC] {subprocess.py:110} INFO - Command exited with return code 1
[2025-06-25, 19:36:39 UTC] {taskinstance.py:3313} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.12/site-packages/airflow/models/taskinstance.py", line 768, in _execute_task
    result = _execute_callable(context=context, **execute_callable_kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.12/site-packages/airflow/models/taskinstance.py", line 734, in _execute_callable
    return ExecutionCallableRunner(
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.12/site-packages/airflow/utils/operator_helpers.py", line 252, in run
    return self.func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.12/site-packages/airflow/models/baseoperator.py", line 424, in wrapper
    return func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.12/site-packages/airflow/operators/bash.py", line 276, in execute
    raise AirflowException(
airflow.exceptions.AirflowException: Bash command failed. The command returned a non-zero exit code 1.
[2025-06-25, 19:36:39 UTC] {taskinstance.py:1226} INFO - Marking task as FAILED. dag_id=dbt_elementary, task_id=dbt_source_freshness, run_id=manual__2025-06-25T19:19:11.596969+00:00, execution_date=20250625T191911, start_date=20250625T193426, end_date=20250625T193639
[2025-06-25, 19:36:39 UTC] {taskinstance.py:1564} INFO - Executing callback at index 0: generic_task_error_callback
[2025-06-25, 19:36:39 UTC] {error_util.py:85} ERROR - Error in dbt_elementary DAG
[2025-06-25, 19:36:39 UTC] {logging_mixin.py:190} WARNING - /home/airflow/.local/lib/python3.12/site-packages/airflow/metrics/datadog_logger.py:172 RemovedInAirflow3Warning: The basic metric validator will be deprecated in the future in favor of pattern-matching.  You can try this now by setting config option metrics_use_pattern_match to True.
[2025-06-25, 19:36:39 UTC] {metrics.py:19} INFO - Successfully uploaded metric operation_error with tags ["dag_tags:['engineering', 'databricks_e2']", 'operation_type:task', 'dag_id:dbt_elementary', 'task_id:dbt_source_freshness'].
[2025-06-25, 19:36:39 UTC] {taskinstance.py:341} ▶ Post task execution logs
g
Hi @David Shi, Do you have the 
source_freshness_run_project_hooks: true
flag set in your 
dbt_project.yml
? If so, the source freshness results are already uploaded by the Elementary dbt package, which means you won’t be able to upload them again using 
edr run-operation
. If you still prefer to upload them manually with the 
edr
command, you can remove the flag from your 
dbt_project.yml
. However, I recommend keeping the flag in place.
👀 1
d
Hi Guy blob wave , I don't see that flag being set explicitly in our project file, but taking a quick look at the dbt docs, it may default to true. So maybe we will be able to skip this command. Just to confirm my understanding whenever 
dbt source freshness
would be run this would update the 
elementary.dbt_source_freshness_results
table automatically? https://docs.getdbt.com/reference/global-configs/behavior-changes#project-hooks-with-source-freshness
g
Exactly. Note that the default value of this configuration changed only recently (in dbt Core 1.10.0), which is likely why you’ve started encountering these errors.
🙏 1
d
thanks for helping investigate, upgrading is always a bit tricky with these subtle interactions, I should be good if I set the flag to false for now, but sounds like we'll be able to simplify our edr report workflow
✅ 1
26 Views
Open in Slack
PreviousNext
Powered by