[CT-880] User stuck in Snowflake auth loop while using browserauth

[crystalro0]

Describe the bug

User is trying to run a model in CLI and is getting prompted to authenticate via externalbrowser after already being authenticated.

Steps To Reproduce

1. New user to company and is using CLI on mac (had previously used CLI on windows)
2. Installed dbt and keyring with brew
3. On CLI, environment is on dbt 1.1.1
4. On Snowflake, allow_id_token is set to true and MFA is not enabled but they do have SSO.
5. Run 1 model via CLI (ex. dbt run -s sample_model --full-refresh)

Expected behavior

No other authentication prompts once already auth'd, just model run results.

Screenshots and log output

If applicable, add screenshots or log output to help explain your problem.

System information

The output of dbt --version:

dbt 1.1.1

The operating system you're using:
MacOS

The output of python --version:
3.9.12

Additional context

Related to dbt-labs/dbt-core#2689

[jtcohen6]

Discussed with @crystalro0 @nathaniel-may offline. This is especially tricky to debug in the general case, because it's completely a function of snowflake-connector-python + macOS Keychain Access. (There's really zero code at play here that's actually in dbt-snowflake itself.) It's clear that the token isn't being cached / accessed from the keychain properly, but it's near impossible to know why without direct access to the user's machine.

Let's swing back to this one if/after we get a chance to talk to the user directly. We can list out the debugging steps we attempted, and whether they yielded any results. I'm sure this isn't the last person who will run into this issue!

[eivind-stb]

For what it's worth @jtcohen6, I'm experiencing the exact same issue with dbt 1.20, SSO to Azure AD to Snowflake, python 3.9.13. This only started after switching from a Windows-laptop to a new mac. I'll happily assist with any information.

The login-request (every pop-up browser-window claims the identity was confirmed: Your identity was confirmed and propagated to Snowflake dbt. You can close this window now and go back where you started from.

[JimMcKenzieSmith]

I'm also having this issue.

• This was working on a previous Mac. I upgraded to a new Mac and this started happening.
• dbt core 1.2.0 (latest)
• snowflake plugin 1.2.0 (latest)
• Python version 3.8.9
• keyring is installed
• alter account set allow_id_token = true is set on Snowflake (same as before) with the externalbrowser config on the profile (as I said, it still works great on my old Macbook, and I still have my old Macbook for debugging if that would help?!)

I've inspected dbt.log. It seems to be opening a new connection over and over again for each test that is trying to run, instead of reusing the same connection. Here is some log output for one of the threads (this cycles over and over for each test). In my case, I have 10 threads, and each of the threads is unable to reuse their connection. So, I end up with hundreds of browser tabs that open instead of just 10. I masked our column and table names with **** for confidentiality:

20:18:03.317310 [debug] [Thread-5  ]: Began running node test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a
20:18:03.321283 [info ] [Thread-5  ]: 88 of 122 START test dbt_expectations_expect_column_values_to_be_of_type_****__number  [RUN]
20:18:03.331279 [debug] [Thread-5  ]: Acquiring new snowflake connection "test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a"
20:18:03.334920 [debug] [Thread-5  ]: Began compiling node test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a
20:18:03.336249 [debug] [Thread-5  ]: Compiling test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a
20:18:03.346220 [debug] [Thread-5  ]: Using snowflake connection "test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a"
20:18:03.346786 [debug] [Thread-5  ]: On test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a: /* {"app": "dbt", "dbt_version": "1.2.0", "profile_name": "snowflake_data_transformation", "target_name": "dev", "node_id": "test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a"} */
20:18:03.347187 [debug] [Thread-5  ]: Opening a new connection, currently in state closed
20:18:05.846210 [debug] [Thread-5  ]: SQL status: SUCCESS 46 in 2.5 seconds
20:18:05.879990 [debug] [Thread-5  ]: Writing injected SQL for node "test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a"
20:18:05.887660 [debug] [Thread-5  ]: finished collecting timing info
20:18:05.887881 [debug] [Thread-5  ]: Began executing node test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a
20:18:05.889726 [debug] [Thread-5  ]: Writing runtime SQL for node "test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a"
20:18:05.897788 [debug] [Thread-5  ]: Using snowflake connection "test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a"
20:18:05.898073 [debug] [Thread-5  ]: On test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a: /* {"app": "dbt", "dbt_version": "1.2.0", "profile_name": "snowflake_data_transformation", "target_name": "dev", "node_id": "test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a"} */
20:18:06.482789 [debug] [Thread-5  ]: SQL status: SUCCESS 1 in 0.58 seconds
20:18:06.483651 [debug] [Thread-5  ]: finished collecting timing info
20:18:06.483756 [debug] [Thread-5  ]: On test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a: Close
20:18:06.698643 [info ] [Thread-5  ]: 88 of 122 PASS dbt_expectations_expect_column_values_to_be_of_type_****__number  [PASS in 3.37s]
20:18:06.701148 [debug] [Thread-5  ]: Finished running node test.****.dbt_expectations_expect_column_values_to_be_of_type_****__number.80365b549a

Then Thread-5 goes into another cycle and gets a new connection instead of reusing:

20:18:06.701962 [debug] [Thread-5  ]: Began running node test.****.field_is_unique_****.ae3cd8dc26
20:18:06.702969 [info ] [Thread-5  ]: 98 of 122 START test field_is_unique_**** ................. [RUN]
20:18:06.703746 [debug] [Thread-5  ]: Acquiring new snowflake connection "test.****.field_is_unique_****.ae3cd8dc26"
...

Is there something I could compare on my old Macbook to see what is going on?

[JimMcKenzieSmith]

UPDATE: Upgrading from Python 3.8.9 to 3.9.13 fixed this for me.

[eivind-stb]

Update from me as well: Installing keyring fixed this for me.

[plashgarlou99]

It seems the homebrew install doesn’t bring over some of the dependencies, I uninstalled and instead installed with pip and now it’s working.

[dsillman2000]

I'm experiencing the SSO auth hanging and I didn't install anything with brew, all through pip (suggesting it is an issue with the package? or its interaction with other tools?). My environment:
OS: WSL on Windows 10
Python version: 3.10.5
DBT version: 1.2.1
I hang on dbt test. It is inescapable when using multiple threads, but sometimes (non-deterministically) it is avoidable by setting --threads 1. Either the SSO auth itself in my external browser will hang without redirecting or the auths will pass and DBT hangs. The last log message seen is always Opening a new connection, currently in state init.

[plashgarlou99]

@dsillman2000, I am not sure about windows but I believe they suggested using Python 3.9 and not 10. I would try that. Also I would try a different browser to see if it fixes the issue. Best of luck.

[miguelbirdie]

Update from me: Installing dbt-snowflake using pip instead of brew works for me. It also needed to install ciff manually following this

[yingqiaozheng]

Same update as @miguelbirdie . uninstall dbt via brew, then pip install, all good. Thank you so much @miguelbirdie

[stevenhoelscher]

I ran into this issue recently and thought it might be worthwhile to share my findings.

My Python environment

• Homebrew-managed pyenv
• virtualenv managed by pyenv
• Python version 3.9.15

dbt-snowflake==1.3.0
snowflake-connector-python==2.7.12
keyring==23.11.0

The problem ended up being masked by this try-except. The error log for me was the following:

Could not retrieve ID_TOKEN from secure storage : Can't get password from keychain: (-25293, 'Security Auth Failure: make sure python is signed with codesign util')

I was able to replicate it using the same Python interpreter that dbt was using:

>>> import keyring
>>> keyring.get_password('<snowflake_url>:<account>:SNOWFLAKE-PYTHON-DRIVER:ID_TOKEN', '<account>')

One way to fix this is to ensure the right Python interpreter has access to this secret, or grant broad access. I'll leave this security considerations blurb here.

On MacOS:

1. Open KeyChain Access
2. Search for Snowflake
3. Right click on the secret and click Get Info
4. Go to Access Control and make any changes necessary

[Fleid]

I will go ahead and close this one, this looks settled.
Please re-open or ping me if need be.

[EstelleBarnoud]

Posting this for new folks stumbling on the same issue for which the above didn't fix — found a solution fixing it while keeping my Homebrew install ⬇️

Solution

Run the dbt debug to get your Python path (showing my current versions as well if it can help):

dbt version: 1.3.0
python version: 3.9.15
python path: /opt/homebrew/Cellar/dbt-snowflake/1.3.0/libexec/bin/python
os info: macOS-12.5.1-arm64-arm-64bit

Get to your Python path (replace if different):

cd /opt/homebrew/Cellar/dbt-snowflake/1.3.0/libexec/bin

Install or reinstall keyring here - this package ensures that MacOS chain is triggered instead of browser auth

./pip install keyring

Explanation

When using brew, your default Python interpreter is NOT the one used by dbt (you can run the command which python3 to get it) ⇒ pip3 install keyring didn’t fix the “right” package
I went on debugging by using the dbt Python interpreter:

cd /opt/homebrew/Cellar/dbt-snowflake/1.3.0/libexec/bin
# see if keyring is correctly installed
./pip show keyring
# --> YES

# open the python interpreter to debug further
./python
>>> import keyring

and stumbled upon this error: ModuleNotFoundError: No module named 'importlib_metadata'
→ which was probably solved meanwhile with an issue similar to this one
So just reinstalling the package with the right interpreter did the magic.

At the end it all came down to external dependencies 😅 Still posting the debugging method so people can reproduce for potential other types of error – @Fleid FYI