dbt deps hanging for hours

[walshie4]

Describe the bug

In our dbt hourly job we run dbt deps to prepare the environment. Recently one of these calls ran for 20+ hours without exiting causing us to have to cancel the job and all queued behind it.

debug log

2021-03-16 22:16:30.233096 (MainThread): Running with dbt=0.18.0
2021-03-16 22:16:30.419286 (MainThread): running dbt with arguments Namespace(cls=<class 'dbt.task.deps.DepsTask'>, debug=False, defer=None, log_cache_events=False, log_format='default', partial_parse=None, profile='user', profiles_dir='/tmp/jobs/16076742/.dbt', project_dir=None, record_timing_info=None, rpc_method='deps', single_threaded=False, state=None, strict=False, target='default', test_new_parser=False, use_cache=True, use_colors=None, vars='{}', warn_error=False, which='deps', write_json=True)
2021-03-16 22:16:30.419762 (MainThread): Tracking: tracking
2021-03-16 22:16:30.428720 (MainThread): Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f497ec5beb0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f4995b28340>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f497ebea640>]}
2021-03-16 22:16:30.429537 (MainThread): Set downloads directory='/tmp/dbt-downloads-00_woskw'
2021-03-16 22:16:30.431098 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/index.json
2021-03-16 22:16:30.660592 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/index.json 200
2021-03-16 22:16:30.661170 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils.json
2021-03-16 22:16:30.875229 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils.json 200
2021-03-16 22:16:31.019027 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils/0.6.1.json
2021-03-16 22:16:31.256770 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils/0.6.1.json 200
2021-03-16 22:16:31.261008 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/codegen.json
2021-03-16 22:16:31.466288 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/codegen.json 200
2021-03-16 22:16:31.469089 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/codegen/0.3.0.json
2021-03-16 22:16:31.707643 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/codegen/0.3.0.json 200
2021-03-16 22:16:31.710224 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/audit_helper.json
2021-03-16 22:16:31.961567 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/audit_helper.json 200
2021-03-16 22:16:31.964420 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/audit_helper/0.3.0.json
2021-03-16 22:16:32.174589 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/audit_helper/0.3.0.json 200
2021-03-16 22:16:32.178468 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/calogica/dbt_expectations.json
2021-03-16 22:16:32.486733 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/calogica/dbt_expectations.json 200
2021-03-16 22:16:32.490320 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/calogica/dbt_expectations/0.2.1.json
2021-03-16 22:16:32.709086 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/calogica/dbt_expectations/0.2.1.json 200
2021-03-16 22:16:32.712931 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils.json
2021-03-16 22:16:32.938283 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils.json 200
2021-03-16 22:16:32.951697 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils/0.6.1.json
2021-03-16 22:16:33.256579 (MainThread): Response from registry: GET https://hub.getdbt.com/api/v1/fishtown-analytics/dbt_utils/0.6.1.json 200
2021-03-16 22:16:33.257373 (MainThread): Making package registry request: GET https://hub.getdbt.com/api/v1/calogica/dbt_date.json
2021-03-17 18:49:53.170015 (MainThread): Flushing usage events
2021-03-17 18:49:53.421241 (MainThread): 

Steps To Reproduce

In as much detail as possible, please provide steps to reproduce the issue. Sample data that triggers the issue, example model code, etc is all very helpful here.

Expected behavior

dbt deps would exit with success or failure within a few minutes at most.

Screenshots and log output

See log in collapse section above

System information

Which database are you using dbt with?

• postgres
• redshift
• bigquery
• snowflake
• other (specify: ____________)

The output of dbt --version:

0.18.0

The operating system you're using:

dbt cloud

The output of python --version:

unsure, dbt cloud

Additional context

Add any other context about the problem here.

This is running in dbt Cloud

[jtcohen6]

@walshie4 Thanks for opening, and for sharing the debug logs! While it's impossible to know exactly what that request hung for hours, the fix here feels pretty straightforward. We should specify a reasonable timeout within requests.get (whether 5, 30, or 60s):

https:/fishtown-analytics/dbt/blob/77c10713a325d2bee91d1822951ce5d91ccc3278/core/dbt/clients/registry.py#L42-L50

Then within the _wrap_exceptions wrapper, we'd want to catch both requests.exceptions.ConnectionError and requests.exceptions.Timeout as cause for retry:

https:/fishtown-analytics/dbt/blob/77c10713a325d2bee91d1822951ce5d91ccc3278/core/dbt/clients/registry.py#L31

Is this a fix you'd be interested in contributing? :)

[walshie4]

Sure thing, was hoping it would be something this simple. 🙌

[TeddyCr]

@jtcohen6 wondering if this has been implemented or not as I'd be interested in picking it up. 😄

[jtcohen6]

@TeddyCr Not yet implemented! If you want it, you got it :)

[TeddyCr]

@jtcohen6 perfect, I'll tackle that one!

[TeddyCr]

@jtcohen6 I have implemented the changes based on your feedback above. Any recommendation to test the implementantion? My initial thought was to implement a unit test in test/unit/ to make sure def _get() raises the correct error if the server has not send a response after 60 seconds.

[jtcohen6]

My initial thought was to implement a unit test in test/unit/ to make sure def _get() raises the correct error if the server has not send a response after 60 seconds.

That makes a lot of sense to me! There's a bunch of deps-related unit tests over in test_deps.py.

[jtcohen6]

Resolved by #3275