CLI Authentication fails #99

sdebruyn · 2021-02-04T09:39:02Z

I am logged in through the CLI, but I am receiving the error below in dbt debug

profiles.yml:

default:
  target: dev
  outputs:
    dev:
      type: sqlserver
      driver: 'ODBC Driver 17 for SQL Server'
      encrypt: true
      trust_cert: false
      authentication: cli
      server: "{{ env_var('HOSTNAME') }}"
      port: 1433
      database: "{{ env_var('DATABASE') }}"
      schema: "{{ env_var('SCHEMA') }}"

dbt debug:

Running with dbt=0.19.0
dbt version: 0.19.0
python version: 3.8.7
python path: /usr/local/bin/python
os info: Linux-4.19.121-linuxkit-x86_64-with-glibc2.2.5
Using profiles.yml file at /dbt/config/profiles.yml
Using dbt_project.yml file at /dbt/projects/default/dbt_project.yml

Configuration:
  profiles.yml file [OK found and valid]
  dbt_project.yml file [OK found and valid]

Required dependencies:
 - git [OK found]

Connection:
  database: <private>
  schema: <private>
  port: 1433
  UID: None
  client_id: None
  authentication: cli
  encrypt: True
  trust_cert: False
  Connection test: ERROR

dbt was unable to connect to the specified database.
The database returned the following error:

  >Database Error
  ('28000', "[28000] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Login failed for user ''. (18456) (SQLDriverConnect)")

The text was updated successfully, but these errors were encountered:

sdebruyn · 2021-02-04T10:02:50Z

Same with dbt 0.18.1

sdebruyn · 2021-02-04T10:14:27Z

Azure CLI auth itself does not seem to be the problem, I tried AzureCliCredential().get_token in a script myself and that worked.

dataders · 2021-02-04T10:20:46Z

At first glance, this does seem different than #82. Can you try authenticating with a SQL account or with authentication=ActiveDirectoryInteractive just to try and eliminate other possibilities?

Also running dbt compile will send a juicy stacktrace to logs/dbt.log

sdebruyn · 2021-02-04T10:27:10Z

Authentication using username/password works fine

dbt.log with AZ CLI auth:

2021-02-04 10:21:55.803694 (MainThread): Running with dbt=0.18.1
2021-02-04 10:21:55.898830 (MainThread): running dbt with arguments Namespace(cls=<class 'dbt.task.compile.CompileTask'>, debug=False, defer=None, exclude=None, full_refresh=False, log_cache_events=False, log_format='default', models=None, parse_only=False, partial_parse=None, profile=None, profiles_dir='/dbt/config', project_dir=None, record_timing_info=None, rpc_method='compile', selector_name=None, single_threaded=False, state=None, strict=False, target=None, test_new_parser=False, threads=None, use_cache=True, use_colors=None, vars='{}', version_check=True, warn_error=False, which='compile', write_json=True)
2021-02-04 10:21:55.904196 (MainThread): Tracking: tracking
2021-02-04 10:21:55.905857 (MainThread): Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'start', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f8c345aee20>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f8c34baf2b0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f8c345be100>]}
2021-02-04 10:21:55.934400 (MainThread): Partial parsing not enabled
2021-02-04 10:21:55.937381 (MainThread): Parsing macros/indexes.sql
2021-02-04 10:21:55.947494 (MainThread): Parsing macros/adapters.sql
2021-02-04 10:21:56.017676 (MainThread): Parsing macros/catalog.sql
2021-02-04 10:21:56.020363 (MainThread): Parsing macros/materializations/incremental/incremental.sql
2021-02-04 10:21:56.034391 (MainThread): Parsing macros/materializations/snapshot/snapshot.sql
2021-02-04 10:21:56.036275 (MainThread): Parsing macros/materializations/snapshot/strategies.sql
2021-02-04 10:21:56.045778 (MainThread): Parsing macros/materializations/seed/seed.sql
2021-02-04 10:21:56.054093 (MainThread): Parsing macros/core.sql
2021-02-04 10:21:56.060336 (MainThread): Parsing macros/adapters/common.sql
2021-02-04 10:21:56.130213 (MainThread): Parsing macros/schema_tests/unique.sql
2021-02-04 10:21:56.134515 (MainThread): Parsing macros/schema_tests/not_null.sql
2021-02-04 10:21:56.138566 (MainThread): Parsing macros/schema_tests/relationships.sql
2021-02-04 10:21:56.142120 (MainThread): Parsing macros/schema_tests/accepted_values.sql
2021-02-04 10:21:56.146670 (MainThread): Parsing macros/etc/is_incremental.sql
2021-02-04 10:21:56.149575 (MainThread): Parsing macros/etc/datetime.sql
2021-02-04 10:21:56.162945 (MainThread): Parsing macros/etc/get_custom_schema.sql
2021-02-04 10:21:56.166432 (MainThread): Parsing macros/etc/get_custom_database.sql
2021-02-04 10:21:56.169508 (MainThread): Parsing macros/etc/get_custom_alias.sql
2021-02-04 10:21:56.171534 (MainThread): Parsing macros/etc/query.sql
2021-02-04 10:21:56.173610 (MainThread): Parsing macros/materializations/helpers.sql
2021-02-04 10:21:56.186931 (MainThread): Parsing macros/materializations/incremental/helpers.sql
2021-02-04 10:21:56.190140 (MainThread): Parsing macros/materializations/incremental/incremental.sql
2021-02-04 10:21:56.198844 (MainThread): Parsing macros/materializations/view/create_or_replace_view.sql
2021-02-04 10:21:56.206479 (MainThread): Parsing macros/materializations/view/view.sql
2021-02-04 10:21:56.215826 (MainThread): Parsing macros/materializations/table/table.sql
2021-02-04 10:21:56.226691 (MainThread): Parsing macros/materializations/snapshot/snapshot.sql
2021-02-04 10:21:56.270964 (MainThread): Parsing macros/materializations/snapshot/snapshot_merge.sql
2021-02-04 10:21:56.274372 (MainThread): Parsing macros/materializations/snapshot/strategies.sql
2021-02-04 10:21:56.297836 (MainThread): Parsing macros/materializations/seed/seed.sql
2021-02-04 10:21:56.328736 (MainThread): Parsing macros/materializations/common/merge.sql
2021-02-04 10:21:56.358101 (MainThread): Partial parsing not enabled
2021-02-04 10:21:56.405741 (MainThread): Acquiring new sqlserver connection "model.default.dbt_example".
2021-02-04 10:21:56.616198 (MainThread): Found 1 model, 0 tests, 0 snapshots, 0 analyses, 153 macros, 0 operations, 0 seed files, 0 sources
2021-02-04 10:21:56.617803 (MainThread): 
2021-02-04 10:21:56.618959 (MainThread): Acquiring new sqlserver connection "master".
2021-02-04 10:21:56.621278 (ThreadPoolExecutor-0_0): Acquiring new sqlserver connection "list_lynxcare_omop".
2021-02-04 10:21:56.632990 (ThreadPoolExecutor-0_0): Using sqlserver connection "list_lynxcare_omop".
2021-02-04 10:21:56.634323 (ThreadPoolExecutor-0_0): On list_lynxcare_omop: select
      table_catalog as [database],
      table_name as [name],
      table_schema as [schema],
      case when table_type = 'BASE TABLE' then 'table'
           when table_type = 'VIEW' then 'view'
           else table_type
      end as table_type

    from information_schema.tables
    where table_schema like 'omop'
      and table_catalog like 'lynxcare'
  
2021-02-04 10:21:56.635621 (ThreadPoolExecutor-0_0): Opening a new connection, currently in state init
2021-02-04 10:21:56.636489 (ThreadPoolExecutor-0_0): Using connection string: DRIVER={ODBC Driver 17 for SQL Server};SERVER=privateservername.database.windows.net,1433;Database=lynxcare;Encrypt=Yes
2021-02-04 10:21:57.059246 (ThreadPoolExecutor-0_0): Could not connect to db: ('28000', "[28000] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Login failed for user ''. (18456) (SQLDriverConnect)")
2021-02-04 10:21:57.061514 (ThreadPoolExecutor-0_0): Error running SQL: select
      table_catalog as [database],
      table_name as [name],
      table_schema as [schema],
      case when table_type = 'BASE TABLE' then 'table'
           when table_type = 'VIEW' then 'view'
           else table_type
      end as table_type

    from information_schema.tables
    where table_schema like 'omop'
      and table_catalog like 'lynxcare'
  
2021-02-04 10:21:57.063108 (ThreadPoolExecutor-0_0): Rolling back transaction.
2021-02-04 10:21:57.064461 (ThreadPoolExecutor-0_0): On list_lynxcare_omop: No close available on handle
2021-02-04 10:21:57.065690 (ThreadPoolExecutor-0_0): Error running SQL: macro list_relations_without_caching
2021-02-04 10:21:57.066664 (ThreadPoolExecutor-0_0): Rolling back transaction.
2021-02-04 10:21:57.068234 (MainThread): Connection 'master' was properly closed.
2021-02-04 10:21:57.069375 (MainThread): Connection 'list_lynxcare_omop' was properly closed.
2021-02-04 10:21:57.070312 (MainThread): ERROR: Database Error
  ('28000', "[28000] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Login failed for user ''. (18456) (SQLDriverConnect)")
2021-02-04 10:21:57.071571 (MainThread): Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f8c34430430>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f8c343d0af0>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7f8c3435fc10>]}
2021-02-04 10:21:57.073190 (MainThread): Flushing usage events

dataders · 2021-02-04T10:36:28Z

@JCZuurmond any idea here?

JCZuurmond · 2021-02-04T11:18:58Z

I think the login fails because the user does not have the right permissions to access the SQL server.

You can confirm this by going to query editor in the SQL database and click on the continue as <account name>. I expect that you will get the same error message: Login failed for user.

You should create contained users in the database to allow your user to make the connection via AD login.

sdebruyn · 2021-02-04T12:03:17Z

@JCZuurmond I can login using the same account in Azure Data Studio and in the online query explorer. My account belongs to an AD group which is set as AD admin for that server.

JCZuurmond · 2021-02-04T12:08:34Z

hmm, and is the login done correctly? it says Login failed for user ''. There is an empty string for where the user name should be ''

sdebruyn · 2021-02-04T12:11:32Z

Yes, as far as I can see. Wouldn't theAzureCliCredential().get_token("https://database.windows.net//.default") fail otherwise?

az account show
{
  "environmentName": "AzureCloud",
  "homeTenantId": "private",
  "id": "private",
  "isDefault": true,
  "managedByTenants": [
    {
      "tenantId": "private"
    }
  ],
  "name": "private",
  "state": "Enabled",
  "tenantId": "private",
  "user": {
    "name": "sam.debruyn@private",
    "type": "user"
  }
}

JCZuurmond · 2021-02-04T12:17:58Z

Ok, I'll have a look later today to see if I can recreate this error. Thanks for the additional context

JCZuurmond · 2021-02-04T18:22:21Z

Hi @sdebruyn, I did not start recreating your issue yet. Before that could you try one more simple thing: change cli in your profile with CLI. It is case sensitive and it misses to login because of that.

dataders · 2021-02-04T19:19:51Z

change cli in your profile with CLI. It is case sensitive and it misses to login because of that.

@JCZuurmond thanks for all you help here. we should probably make a PR to remove the case-sensitivity.

@sdebruyn thanks for being patient while we figure this out. my only other idea (before we ask you to install the package in developer mode to get better logs) would be to see what happens if you use ActiveDirectoryPassword or ActiveDirectoryInteractive. Also, are you using SQL Server? or Azure SQL db?

sdebruyn · 2021-02-04T19:26:51Z

Spot on. Using CLI works like a charm.

dataders · 2021-02-05T00:43:43Z

closing as @sdebruyn's issue is resolved, but opening #100 for a future PR

dataders mentioned this issue Feb 5, 2021

make CLI authentication case-insensitive #100

Closed

dataders closed this as completed Feb 5, 2021

RiviqVH mentioned this issue Dec 20, 2021

Cannot authenticate with CLI from VSCode devcontainer #192

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CLI Authentication fails #99

CLI Authentication fails #99

sdebruyn commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

dataders commented Feb 4, 2021 •

edited

Loading

sdebruyn commented Feb 4, 2021

dataders commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021 •

edited

Loading

sdebruyn commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021

dataders commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

dataders commented Feb 5, 2021

CLI Authentication fails #99

CLI Authentication fails #99

Comments

sdebruyn commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

dataders commented Feb 4, 2021 • edited Loading

sdebruyn commented Feb 4, 2021

dataders commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021 • edited Loading

sdebruyn commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021

JCZuurmond commented Feb 4, 2021

dataders commented Feb 4, 2021

sdebruyn commented Feb 4, 2021

dataders commented Feb 5, 2021

dataders commented Feb 4, 2021 •

edited

Loading

JCZuurmond commented Feb 4, 2021 •

edited

Loading