Describe the bug
When running dbt test
we occasionally get an 'SSL error: unsupported method' error.
dbt is running from airflow in an EC2 instance. After the error happens if we restart the process it runs fine. As far as we are aware we haven't once had the occur reoccur on retry.
Error happens maybe once or twice a week on processes that run once daily.
Only ever happens with dbt test, never seen it happen in dbt run.
Steps To Reproduce
Have not been able to reproduce the error manually.
Expected behavior
To run without an SSL error
Screenshots and log output
Heres an extract of where the error happens with debug flag on
[2021-08-17 06:23:09,311] {bash_operator.py:157} INFO - 2021-08-17 06:23:09.311283 (MainThread): Acquiring new redshift connection "master".
[2021-08-17 06:23:09,311] {bash_operator.py:157} INFO - 2021-08-17 06:23:09.311414 (MainThread): Opening a new connection, currently in state init
[2021-08-17 06:23:21,250] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.248250 (ThreadPoolExecutor-1_0): Acquiring new redshift connection "list_staging_dbt_staging".
[2021-08-17 06:23:21,250] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.248727 (ThreadPoolExecutor-1_1): Acquiring new redshift connection "list_staging_dbt_dims".
[2021-08-17 06:23:21,250] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.250831 (ThreadPoolExecutor-1_1): Opening a new connection, currently in state init
[2021-08-17 06:23:21,257] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.249071 (ThreadPoolExecutor-1_2): Acquiring new redshift connection "list_staging_dbt_seed_data".
[2021-08-17 06:23:21,264] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.249919 (ThreadPoolExecutor-1_4): Acquiring new redshift connection "list_staging_dbt".
[2021-08-17 06:23:21,264] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.262399 (ThreadPoolExecutor-1_4): Opening a new connection, currently in state init
[2021-08-17 06:23:21,278] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.250255 (ThreadPoolExecutor-1_5): Acquiring new redshift connection "list_staging_dbt_marts".
[2021-08-17 06:23:21,290] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.249580 (ThreadPoolExecutor-1_3): Acquiring new redshift connection "list_staging_dbt_facts".
[2021-08-17 06:23:21,301] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.262215 (ThreadPoolExecutor-1_2): Opening a new connection, currently in state init
[2021-08-17 06:23:21,304] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.250694 (ThreadPoolExecutor-1_0): Opening a new connection, currently in state init
[2021-08-17 06:23:21,306] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.290397 (ThreadPoolExecutor-1_5): Opening a new connection, currently in state init
[2021-08-17 06:23:21,308] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.290957 (ThreadPoolExecutor-1_1): Using redshift connection "list_staging_dbt_dims".
[2021-08-17 06:23:21,308] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.301143 (ThreadPoolExecutor-1_3): Opening a new connection, currently in state init
[2021-08-17 06:23:21,311] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.301585 (ThreadPoolExecutor-1_4): Using redshift connection "list_staging_dbt".
[2021-08-17 06:23:21,311] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.303918 (ThreadPoolExecutor-1_2): Using redshift connection "list_staging_dbt_seed_data".
[2021-08-17 06:23:21,312] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.306141 (ThreadPoolExecutor-1_0): Using redshift connection "list_staging_dbt_staging".
[2021-08-17 06:23:21,312] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.308204 (ThreadPoolExecutor-1_5): Using redshift connection "list_staging_dbt_marts".
[2021-08-17 06:23:21,312] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.308377 (ThreadPoolExecutor-1_1): On list_staging_dbt_dims: BEGIN
[2021-08-17 06:23:21,312] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.311538 (ThreadPoolExecutor-1_3): Using redshift connection "list_staging_dbt_facts".
[2021-08-17 06:23:21,312] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.311732 (ThreadPoolExecutor-1_4): On list_staging_dbt: BEGIN
[2021-08-17 06:23:21,312] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.311918 (ThreadPoolExecutor-1_2): On list_staging_dbt_seed_data: BEGIN
[2021-08-17 06:23:21,313] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.312094 (ThreadPoolExecutor-1_0): On list_staging_dbt_staging: BEGIN
[2021-08-17 06:23:21,313] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.312258 (ThreadPoolExecutor-1_5): On list_staging_dbt_marts: BEGIN
[2021-08-17 06:23:21,313] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.312510 (ThreadPoolExecutor-1_1): Connecting to Redshift using 'database' credentials
[2021-08-17 06:23:21,313] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.312705 (ThreadPoolExecutor-1_3): On list_staging_dbt_facts: BEGIN
[2021-08-17 06:23:21,313] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.312846 (ThreadPoolExecutor-1_4): Connecting to Redshift using 'database' credentials
[2021-08-17 06:23:21,314] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.312980 (ThreadPoolExecutor-1_2): Connecting to Redshift using 'database' credentials
[2021-08-17 06:23:21,314] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.313141 (ThreadPoolExecutor-1_0): Connecting to Redshift using 'database' credentials
[2021-08-17 06:23:21,314] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.313250 (ThreadPoolExecutor-1_5): Connecting to Redshift using 'database' credentials
[2021-08-17 06:23:21,314] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.313763 (ThreadPoolExecutor-1_3): Connecting to Redshift using 'database' credentials
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334000 (ThreadPoolExecutor-1_3): Got an error when attempting to open a postgres connection: 'SSL error: unsupported method
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - '
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334140 (ThreadPoolExecutor-1_1): Got an error when attempting to open a postgres connection: 'SSL error: unsupported method
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - '
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334312 (ThreadPoolExecutor-1_3): Error running SQL: BEGIN
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334425 (ThreadPoolExecutor-1_1): Error running SQL: BEGIN
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334529 (ThreadPoolExecutor-1_3): Rolling back transaction.
[2021-08-17 06:23:21,334] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334656 (ThreadPoolExecutor-1_1): Rolling back transaction.
[2021-08-17 06:23:21,335] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334804 (ThreadPoolExecutor-1_3): On list_staging_dbt_facts: No close available on handle
[2021-08-17 06:23:21,335] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.334939 (ThreadPoolExecutor-1_1): On list_staging_dbt_dims: No close available on handle
[2021-08-17 06:23:21,335] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.335141 (ThreadPoolExecutor-1_3): Error running SQL: macro list_relations_without_caching
[2021-08-17 06:23:21,335] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.335333 (ThreadPoolExecutor-1_1): Error running SQL: macro list_relations_without_caching
[2021-08-17 06:23:21,335] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.335459 (ThreadPoolExecutor-1_3): Rolling back transaction.
[2021-08-17 06:23:21,336] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.335574 (ThreadPoolExecutor-1_1): Rolling back transaction.
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.377842 (ThreadPoolExecutor-1_0): SQL status: BEGIN in 0.06 seconds
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.378061 (ThreadPoolExecutor-1_0): Using redshift connection "list_staging_dbt_staging".
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.378143 (ThreadPoolExecutor-1_0): On list_staging_dbt_staging: /* {"app": "dbt", "dbt_version": "0.16.1", "profile_name": "carnext_dwh", "target_name": "dev", "connection_name": "list_staging_dbt_staging"} /
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - tablename as name,
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - 'table' as type
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - from pg_tables
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - where schemaname ilike 'dbt_staging'
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - union all
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - viewname as name,
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - 'view' as type
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - from pg_views
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO - where schemaname ilike 'dbt_staging'
[2021-08-17 06:23:21,378] {bash_operator.py:157} INFO -
[2021-08-17 06:23:21,405] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.405686 (ThreadPoolExecutor-1_2): SQL status: BEGIN in 0.09 seconds
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.405881 (ThreadPoolExecutor-1_2): Using redshift connection "list_staging_dbt_seed_data".
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.405973 (ThreadPoolExecutor-1_2): On list_staging_dbt_seed_data: / {"app": "dbt", "dbt_version": "0.16.1", "profile_name": "carnext_dwh", "target_name": "dev", "connection_name": "list_staging_dbt_seed_data"} /
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - tablename as name,
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - 'table' as type
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - from pg_tables
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - where schemaname ilike 'dbt_seed_data'
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - union all
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - viewname as name,
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - 'view' as type
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - from pg_views
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO - where schemaname ilike 'dbt_seed_data'
[2021-08-17 06:23:21,406] {bash_operator.py:157} INFO -
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.410117 (ThreadPoolExecutor-1_5): SQL status: BEGIN in 0.10 seconds
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.410350 (ThreadPoolExecutor-1_5): Using redshift connection "list_staging_dbt_marts".
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.410491 (ThreadPoolExecutor-1_5): On list_staging_dbt_marts: / {"app": "dbt", "dbt_version": "0.16.1", "profile_name": "carnext_dwh", "target_name": "dev", "connection_name": "list_staging_dbt_marts"} /
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - tablename as name,
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - 'table' as type
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - from pg_tables
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - where schemaname ilike 'dbt_marts'
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - union all
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - viewname as name,
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - 'view' as type
[2021-08-17 06:23:21,410] {bash_operator.py:157} INFO - from pg_views
[2021-08-17 06:23:21,411] {bash_operator.py:157} INFO - where schemaname ilike 'dbt_marts'
[2021-08-17 06:23:21,411] {bash_operator.py:157} INFO -
[2021-08-17 06:23:21,421] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.421338 (ThreadPoolExecutor-1_0): SQL status: SELECT in 0.04 seconds
[2021-08-17 06:23:21,477] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.462472 (ThreadPoolExecutor-1_5): SQL status: SELECT in 0.05 seconds
[2021-08-17 06:23:21,493] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.467758 (ThreadPoolExecutor-1_2): SQL status: SELECT in 0.06 seconds
[2021-08-17 06:23:21,618] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.603308 (ThreadPoolExecutor-1_5): On list_staging_dbt_marts: ROLLBACK
[2021-08-17 06:23:21,658] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.652783 (ThreadPoolExecutor-1_2): On list_staging_dbt_seed_data: ROLLBACK
[2021-08-17 06:23:21,760] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.759903 (ThreadPoolExecutor-1_0): On list_staging_dbt_staging: ROLLBACK
[2021-08-17 06:23:21,850] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.850589 (ThreadPoolExecutor-1_4): SQL status: BEGIN in 0.54 seconds
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.850805 (ThreadPoolExecutor-1_4): Using redshift connection "list_staging_dbt".
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.850886 (ThreadPoolExecutor-1_4): On list_staging_dbt: / {"app": "dbt", "dbt_version": "0.16.1", "profile_name": "carnext_dwh", "target_name": "dev", "connection_name": "list_staging_dbt"} */
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - tablename as name,
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - 'table' as type
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - from pg_tables
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - where schemaname ilike 'dbt'
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - union all
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - select
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - 'staging' as database,
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - viewname as name,
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - schemaname as schema,
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - 'view' as type
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - from pg_views
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO - where schemaname ilike 'dbt'
[2021-08-17 06:23:21,851] {bash_operator.py:157} INFO -
[2021-08-17 06:23:21,880] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.879900 (ThreadPoolExecutor-1_4): SQL status: SELECT in 0.03 seconds
[2021-08-17 06:23:21,885] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.885352 (ThreadPoolExecutor-1_4): On list_staging_dbt: ROLLBACK
[2021-08-17 06:23:21,888] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.888201 (MainThread): Connection 'master' was properly closed.
[2021-08-17 06:23:21,888] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.888341 (MainThread): Connection 'list_staging_dbt_staging' was left open.
[2021-08-17 06:23:21,888] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.888452 (MainThread): On list_staging_dbt_staging: Close
[2021-08-17 06:23:21,888] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.888673 (MainThread): Connection 'list_staging_dbt_dims' was properly closed.
[2021-08-17 06:23:21,888] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.888782 (MainThread): Connection 'list_staging_dbt_seed_data' was left open.
[2021-08-17 06:23:21,888] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.888893 (MainThread): On list_staging_dbt_seed_data: Close
[2021-08-17 06:23:21,889] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.889097 (MainThread): Connection 'list_staging_dbt_facts' was properly closed.
[2021-08-17 06:23:21,889] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.889201 (MainThread): Connection 'list_staging_dbt' was left open.
[2021-08-17 06:23:21,889] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.889306 (MainThread): On list_staging_dbt: Close
[2021-08-17 06:23:21,889] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.889484 (MainThread): Connection 'list_staging_dbt_marts' was left open.
[2021-08-17 06:23:21,889] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.889582 (MainThread): On list_staging_dbt_marts: Close
[2021-08-17 06:23:21,889] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.889816 (MainThread): ERROR: Database Error
[2021-08-17 06:23:21,890] {bash_operator.py:157} INFO - SSL error: unsupported method
[2021-08-17 06:23:21,890] {bash_operator.py:157} INFO -
[2021-08-17 06:23:21,890] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.890042 (MainThread): Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f5458d22d30>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f5458150e80>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f54427d7ac8>]}
[2021-08-17 06:23:21,890] {bash_operator.py:157} INFO - 2021-08-17 06:23:21.890317 (MainThread): Flushing usage events
[2021-08-17 06:23:22,581] {bash_operator.py:157} INFO - 1 errors detected
[2021-08-17 06:23:22,581] {bash_operator.py:161} INFO - Command exited with return code 1
System information
Which database are you using dbt with?
The output of dbt --version
:
The operating system you're using:
CentOS Linux 7
The output of python --version
:
Python 3.6.13