https://linen.dev logo
Join Slack
Powered by
Hello, I'm troubleshooting a surprising issue on `...
# community-support
c
Hello, I'm troubleshooting a surprising issue on 
report
(and 
send-report
) I'm running 
edr send-report --days-back 7 --env prod --s3-bucket-name my_bucket
in a custom docker and it fails with:
Copy code
2023-12-27T10:21:27.957Z 2023-12-27 10:20:22 ā€” INFO ā€” Running dbt --log-format json run-operation elementary.log_macro_results --args {"macro_name": "elementary_cli.get_test_results", "macro_args": {"days_back": 7, "invocations_per_test": 720, "disable_passed_test_metrics": false}} --project-dir /usr/local/lib/python3.11/site-packages/elementary/monitor/dbt_project
2023-12-27T10:21:27.957Z 2023-12-27 10:21:26 ā€” ERROR ā€” Could not generate the report - Error: Failed to run dbt command.
2023-12-27T10:21:27.957Z Please reach out to our community for help with this issue.
2023-12-27T10:21:27.957Z NoneType: None
However here what's very intriguing: I can't reproduce it on my own laptop (vs failing ECS) with same credentials, command and environment variables šŸ¤Æ What's even more surprising is that if I run 
dbt run --select elementary --vars '{"elementary_full_refresh": "true"}
then it works on ECS but the next day after it starts failing again. I'm running edr 0.13.2 and dbt package 0.13.1. Last run query by dbt is 
/* {"app": "dbt", "dbt_version": "1.7.4", "profile_name": "elementary", "target_name": "prod", "connection_name": "macro_log_macro_results"} */
and the query is successful. Do you have an idea what could be failing? I would have guessed it's on the 
edr
Python code but I can't really figure out unless I really deep dive šŸ¤”
e
Hi @Christophe Oudar and happy new year šŸ¾ If you could extract the dbt.log from your docker file it would help, it usually contains the underlying error. Can you try to do that?
c
Hey @Ella Katz, thanks for looking at it šŸ™Œ Happy New year too šŸŽ‰ Sure I've also logged it and I couldn't figure out from that log too! Theses are the last logs lines. Both linked jobs at the end are successful.
last_logs_lines_elementary_crash.txt
Any chance you could update the error handling in the python client (
edr
) so that it could dump the Stacktrace of the error? It could be very helpful to debug šŸ™‚
e
Hi @Christophe Oudar, Can you try to check out the edr.log file as well? you'll find it in the path: 
edt_target/edr.log
c
Of course, I dumped it as well and I also couldn't figure it šŸ™‚
crashing_elementary_edr.log
e
OK so the way edr works is we have an internal dbt project that feches the report / alert data, and that dbt project has logs too šŸ™‚ according to your edr.log you can find those logs at: 
/usr/local/lib/python3.11/site-packages/elementary/monitor/dbt_project/logs
can you try to see if there's anything of value there?
c
Ok I missed those ones, I'll have to do some changes on my end to catch those šŸ˜…
Ok so I guess I can 
cat /usr/local/lib/python3.11/site-packages/elementary/monitor/dbt_project/logs/dbt.log
to retrieve those expected logs right?
e
yeah but first i'd list the files in 
logs
because sometimes the log file can split into multiple files
c
Well I guess I should be safe in a single run no šŸ™‚ ?
(I'm running in a dockerized environment)
e
haha yeah
c
For some reasons, the logs don't appear to be there. I'm trying to figure out why
I've found:
Copy code
root@507de05f6d4f:/usr/app/logs# find / -name "dbt.log"
/usr/app/edr_target/dbt.log
/usr/app/logs/dbt.log
I've following data but again not hint of failures
Copy code
root@507de05f6d4f:/usr/app/logs# more dbt.log 
13:16:58.113303 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb
30b98ac50>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30bced750>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30bf20ad0>]}


============================== 13:16:58.119522 | 5d6da427-e474-4bdf-aec6-88ab8a80eeb8 ==============================
13:16:58.119522 [info ] [MainThread]: Running with dbt=1.7.3
13:16:58.120097 [debug] [MainThread]: running dbt with arguments {'printer_width': '80', 'indirect_selection': 'eager', 'log_cache_events': 'False', 'write_json': 'True', 'partial_parse': 'True', 'cac
he_selected_only': 'False', 'warn_error': 'None', 'fail_fast': 'False', 'version_check': 'True', 'log_path': '/usr/app/logs', 'debug': 'False', 'profiles_dir': '/usr/app/', 'use_colors': 'True', 'use_exp
erimental_parser': 'False', 'no_print': 'None', 'quiet': 'False', 'log_format': 'default', 'static_parser': 'True', 'introspect': 'True', 'invocation_command': 'dbt deps', 'target_path': 'None', 'warn_er
ror_options': 'WarnErrorOptions(include=[], exclude=[])', 'send_anonymous_usage_stats': 'True'}
13:16:58.243398 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'project_id', 'label': '5d6da427-e474-4bdf-aec6-88ab8a80eeb8', 'context': [<snowplow_tracker.self_describing_json.Sel
fDescribingJson object at 0x7fb30b9ff050>]}
13:16:58.244473 [debug] [MainThread]: Set downloads directory='/tmp/dbt-downloads-dkypqfiz'
13:16:58.245042 [debug] [MainThread]: Making package index registry request: GET <https://hub.getdbt.com/api/v1/index.json>
13:16:58.266714 [debug] [MainThread]: Response from registry index: GET <https://hub.getdbt.com/api/v1/index.json> 200
13:16:58.268382 [debug] [MainThread]: Making package registry request: GET <https://hub.getdbt.com/api/v1/dbt-labs/codegen.json>
13:16:58.285552 [debug] [MainThread]: Response from registry: GET <https://hub.getdbt.com/api/v1/dbt-labs/codegen.json> 200
13:16:58.288430 [debug] [MainThread]: Making package registry request: GET <https://hub.getdbt.com/api/v1/dbt-labs/dbt_utils.json>
13:16:58.305585 [debug] [MainThread]: Response from registry: GET <https://hub.getdbt.com/api/v1/dbt-labs/dbt_utils.json> 200
13:16:58.310794 [debug] [MainThread]: Making package registry request: GET <https://hub.getdbt.com/api/v1/elementary-data/elementary.json>
13:16:58.331236 [debug] [MainThread]: Response from registry: GET <https://hub.getdbt.com/api/v1/elementary-data/elementary.json> 200
13:16:58.353432 [info ] [MainThread]: Updating lock file in file path: /usr/app/package-lock.yml
13:16:58.356664 [debug] [MainThread]: Set downloads directory='/tmp/dbt-downloads-gyuwykyy'
13:16:58.367044 [info ] [MainThread]: Installing dbt-labs/codegen
13:16:58.588969 [info ] [MainThread]: Installed from version 0.10.0
13:16:58.589407 [info ] [MainThread]: Updated version available: 0.12.1
13:16:58.589915 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'package', 'label': '5d6da427-e474-4bdf-aec6-88ab8a80eeb8', 'property_': 'install', 'context': [<snowplow_tracker.sel
f_describing_json.SelfDescribingJson object at 0x7fb30bfa2210>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30bc23c90>]}
13:16:58.590374 [info ] [MainThread]: Installing dbt-labs/dbt_utils
13:16:58.906988 [info ] [MainThread]: Installed from version 1.1.1
13:16:58.907440 [info ] [MainThread]: Up to date!
13:16:58.907863 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'package', 'label': '5d6da427-e474-4bdf-aec6-88ab8a80eeb8', 'property_': 'install', 'context': [<snowplow_tracker.sel
f_describing_json.SelfDescribingJson object at 0x7fb30b9cfdd0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30b97eed0>]}
13:16:58.908268 [info ] [MainThread]: Installing elementary-data/elementary
13:16:59.256451 [info ] [MainThread]: Installed from version 0.13.0
13:16:59.256913 [info ] [MainThread]: Updated version available: 0.13.1
13:16:59.257292 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'package', 'label': '5d6da427-e474-4bdf-aec6-88ab8a80eeb8', 'property_': 'install', 'context': [<snowplow_tracker.sel
f_describing_json.SelfDescribingJson object at 0x7fb30b85e850>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30bf10f10>]}
13:16:59.261072 [info ] [MainThread]: 
13:16:59.261430 [info ] [MainThread]: Updates available for packages: ['dbt-labs/codegen', 'elementary-data/elementary']                 
Update your versions in packages.yml, then run dbt deps
13:16:59.262676 [debug] [MainThread]: Resource report: {"command_name": "deps", "command_success": true, "command_wall_clock_time": 1.1954536, "process_user_time": 2.285536, "process_kernel_time": 0.3
58124, "process_mem_max_rss": "107228", "process_in_blocks": "1120", "process_out_blocks": "8104"}
13:16:59.263206 [debug] [MainThread]: Command `dbt deps` succeeded at 13:16:59.263079 after 1.20 seconds
13:16:59.263545 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30
b97f310>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30b98aad0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fb30bc72310>]}
13:16:59.263922 [debug] [MainThread]: Flushing usage events
e
Just to understand your setup a little better, is this the same docker that is running your dbt pipeline? And are you rebuilding the docker every day? After you run 
dbt run --select elementary --vars '{"elementary_full_refresh": "true"}
does it work until the docker is rebuilt or simply when a day goes by, without any change? Also, based on another thread I found, can you try running without the 
days_back
parameter?
c
I've 2 images: ā€¢ dedicated docker for running dbt (as I'm sometimes building against cutting edge, like a nightly since I'm a dbt contributor). The image contains the dbt elementary package and my model. On deployment, it runs 
dbt run --target=prod -s elementary
to update the model. ā€¢ I've another docker dedicated to run 
edr
which is just installing elementary CLI. Then I mount my dbt project too in that docker. I don't rebuild the docker, every time, I'm just rebuilding them when I update my dbt project (and I just rebuild the downstream image, not the base image with dbt or elementary installation).
After you run 
dbt run --select elementary --vars '{"elementary_full_refresh": "true"}
does it work until the docker is rebuilt or simply when a day goes by, without any change?
It's working for a day or more (see screenshot, I ran the full refresh on the 15th). There was no change on the docker between the time it failed (no update between 15th & 19th but failed on the 18). Sure, I can try without the day_back params šŸ‘
Ok same outcome with only 
edr send-report --env prod --s3-bucket-name <my_bucket>
o
Hi @Christophe Oudar, care to try setting the 
--executions-limit
flag to 100?
c
Sure, I'll give it a try
Sorry for the delay, I run it and had the same error output. The last log doesn't have reference to that setting though
Copy code
[job-launch] 14:30:34.246 INFO  [io-compute-blocker-0] jobLogger - 2024-01-08T14:30:28.222Z 2024-01-08 14:30:28 ā€” INFO ā€” Running dbt --log-format json run-operation elementary.log_macro_results --args {"macro_name": "elementary_cli.get_models_runs", "macro_args": {"days_back": 7, "exclude_elementary": true}} --project-dir /usr/local/lib/python3.11/site-packages/elementary/monitor/dbt_project 
[job-launch] 14:31:45.154 INFO  [io-compute-blocker-0] jobLogger - 2024-01-08T14:31:34.346Z 2024-01-08 14:31:34 ā€” ERROR ā€” Could not generate the report - Error: Failed to run dbt command.
2024-01-08T14:31:34.346Z Please reach out to our community for help with this issue.
while some do:
Copy code
[job-launch] 14:29:23.074 INFO  [io-compute-blocker-0] jobLogger - 2024-01-08T14:29:11.308Z 2024-01-08 14:29:11 ā€” INFO ā€” Running dbt --log-format json run-operation elementary.log_macro_results --args {"macro_name": "elementary_cli.get_source_freshness_results", "macro_args": {"days_back": 7, "invocations_per_test": 100}} --project-dir /usr/local/lib/python3.11/site-packages/elementary/monitor/dbt_project
I tried with 
--executions-limit
set to 0 as well and it's also failing. I guess the single solution I've in mind is to try to fork the project, put debug logs around the code I suspect to fail and see if I'm right to pinpoint to issue.
I revisited the problem and solved it: I raised my ECS container RAM from 0.5GB to 2GB. I feel bad for not trying earlier šŸ™ˆ
34 Views
Open in Slack
PreviousNext
Powered by