Snowflake broken in 0.48.1

dsil · January 8, 2024, 6:31pm

Here's the only query it ran that specifically mentions the table we manually activated:

SELECT TRUE AS "_" FROM "PROD_MOZART_DWH"."NOTION"."NOTION_USERS_8589935787" WHERE 1 <> 1 LIMIT 0

It had execution_status 'SUCCESS'

It also ran another 5600+ queries during the sync - is there something specific I should look for?

dsil · January 8, 2024, 6:32pm

Happy to hop on a zoom if that would be useful

Also maybe relevant - we created a 2nd Database in Metabase, with the exact same credentials to the same Snowflake DB, and that one works totally fine, all the tables are active that should be, and triggering metabase syncs keeps them active.

dsil · January 8, 2024, 8:49pm

Here's some of the relevant Metabase logs from the sync where it wrongly marked that table back to active=false, namely [83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:32-08:00 INFO metabase.sync.sync-metadata.tables Marking tables as inactive: (Table 'NOTION.NOTION_USERS_8589935787')

[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:31-08:00 INFO metabase.sync.util STARTING: Sync metadata for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:31-08:00 INFO metabase.sync.util STARTING: step 'sync-dbms-version' for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:31-08:00 INFO metabase.sync.util FINISHED: step 'sync-dbms-version' for snowflake Database 2 'Snowflake' (38.9 ms)
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:31-08:00 INFO metabase.sync.util STARTING: step 'sync-timezone' for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:32-08:00 INFO metabase.sync.util FINISHED: step 'sync-timezone' for snowflake Database 2 'Snowflake' (92.3 ms)
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:32-08:00 INFO metabase.sync.sync-metadata.sync-timezone :snowflake database 2 default timezone is "America/Los_Angeles"
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:32-08:00 INFO metabase.sync.util STARTING: step 'sync-tables' for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:32-08:00 INFO metabase.sync.sync-metadata.tables Marking tables as inactive: (Table  'NOTION.NOTION_USERS_8589935787')
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:32-08:00 INFO metabase.sync.util FINISHED: step 'sync-tables' for snowflake Database 2 'Snowflake' (237.3 ms)
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:32-08:00 INFO metabase.sync.util STARTING: step 'sync-fields' for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:47-08:00 INFO metabase.sync.util FINISHED: step 'sync-fields' for snowflake Database 2 'Snowflake' (14.9 s)
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:47-08:00 INFO metabase.sync.util STARTING: step 'sync-fks' for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:52-08:00 INFO metabase.sync.util FINISHED: step 'sync-fks' for snowflake Database 2 'Snowflake' (5.6 s)
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:52-08:00 INFO metabase.sync.util STARTING: step 'sync-metabase-metadata' for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:52-08:00 INFO metabase.sync.util FINISHED: step 'sync-metabase-metadata' for snowflake Database 2 'Snowflake' (575.3 µs)
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:52-08:00 INFO metabase.sync.util FINISHED: step 'sync-table-privileges' for snowflake Database 2 'Snowflake' (254.5 µs)
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:52-08:00 INFO metabase.sync.util STARTING: step 'sync-table-privileges' for snowflake Database 2 'Snowflake'
[83da2d55-53ae-4cac-81c2-39dd9ce25f4e] 2024-01-08T10:12:52-08:00 INFO metabase.sync.util FINISHED: Sync metadata for snowflake Database 2 'Snowflake' (20.9 s)

Luiggi · January 10, 2024, 2:17am

Can you run

SELECT TRUE AS "_" FROM "PROD_MOZART_DWH"."NOTION"."NOTION_USERS_8589935787" WHERE 1 <> 1 LIMIT 0

from within the Metabase SQL editor and see what it returns?

dsil · January 10, 2024, 4:23am

Luiggi · January 10, 2024, 2:24pm

@dsil are you syncing all the schemas or you're cherry picking? I want to see the connection page in Metabase

dsil · January 10, 2024, 2:32pm

We're syncing "All except" a few schemas.

dsil · January 12, 2024, 12:53am

Maybe useful - we put a version 47.7 instance on the same postgres app database, and triggering a sync in the 47.7 reactivates all the tables appropriately. Then a sync in the 48.2 version deactivates them again.

Luiggi · January 12, 2024, 4:19am

alright, we think we found the bug and we believe it's not our fault. I made a custom JAR with the change in case anyone wants to test it

here's also a container image paoliniluis/metabase-snowflake-fix-v48:latest

this is based on v48 and it should NOT be considered a release version, it's just to test. If this change works then we'll push this into v48.4

Luiggi · January 12, 2024, 8:01pm

No one?

Luiggi · January 15, 2024, 12:17pm

Alright, I'm considering this issue fixed

awp · January 15, 2024, 6:56pm

We tried the build you provided and it didn't fix the issue. What information do you need from us to investigate?

As far as I can tell from the logs, it makes the attempt to sync over database info, but then it's still just the one schema's tables that show up in Browse. No new schemas show up.

[aa84a19a-9e23-4d0c-bb17-2d4013d3ac81] 2024-01-12T17:00:00-08:00 INFO metabase.task.sync-databases Starting sync task for Database 2.
[aa84a19a-9e23-4d0c-bb17-2d4013d3ac81] 2024-01-12T17:00:07-08:00 ERROR org.quartz.core.JobRunShell Job DEFAULT.metabase.task.sync-and-analyze.job threw an unhandled Exception:
java.lang.NullPointerException
[aa84a19a-9e23-4d0c-bb17-2d4013d3ac81] 2024-01-12T17:00:07-08:00 ERROR org.quartz.core.ErrorLogger Job (DEFAULT.metabase.task.sync-and-analyze.job threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: java.lang.NullPointerException]
at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
Caused by: java.lang.NullPointerException

Luiggi · January 15, 2024, 7:43pm

so you started the version I pushed and you forced a sync, is that correct?

no new schemas or tables popped up

awp · January 15, 2024, 8:01pm

Yes that's right. We triggered a sync from the admin database controls, and no new schemas or tables showed up

unohealth · January 16, 2024, 4:40am

sorry, holiday weekend in the US. Will see what we can do with this tomorrow if I can get the resources.

unohealth · January 16, 2024, 6:59pm

I am actually unable to test this out because of the PHI-protection policies we have with our customers—we've agreed that we will not deploy beta versions of third-party software that touches PHI data. Sorry about that. But if it's not working for @awp I assume it doesn't work for us

awp · January 16, 2024, 9:38pm

@Luiggi what would you like us to try next or what additional data do you need?

Luiggi · January 17, 2024, 4:10am

I just pushed new versions of the JAR here:

and also the container: paoliniluis/metabase-snowflake-fix-v48:latest (remember that as I'm using an mutable tag you need to do docker pull ... again!)

dsil · January 17, 2024, 7:46pm

Great, thank you -

We are trying the new image and running into some problems. The "Sync database schema now" button does not seem to do anything. I see corresponding POST /api/database/2/sync_schema 200 in the logs, but there is no subsequent Starting sync task for Database 2 which is how I have been identifying the sync attempts. This issue was present in the first version of your image as well. Previously we were able to see a sync attempt by waiting for the daily scheduled sync, which did seem to still run. I tried to accelerate this process by toggling the scheduled sync to hourly, however now that doesn't seem to be running either. I see this message in the logs indicating that the toggle occurred:

[850a5ce0-29ca-4397-b800-6e8127f2a0c4] 2024-01-17T09:43:34-08:00 INFO metabase.models.database :snowflake Database 'Snowflake' sync/analyze schedules have changed! 
 Sync metadata was: '0 0 1 * * ? *' is now: '0 0 * * * ? *' 
 Cache FieldValues was: '0 0 1 1 * ? *', is now: '0 0 1 1 * ? *'

but again, no subsequent Starting sync task for Database 2 . It's been 2 hours as of writing since I toggled that.I do still see it attempting to sync database 3 (the one we added since the upgrade, which has the correct tables. It is still configured to sync daily). However, that failed with this error:

[850a5ce0-29ca-4397-b800-6e8127f2a0c4] 2024-01-17T09:16:00-08:00 INFO metabase.task.sync-databases Starting sync task for Database 3.
[850a5ce0-29ca-4397-b800-6e8127f2a0c4] 2024-01-17T09:16:08-08:00 ERROR org.quartz.core.JobRunShell Job DEFAULT.metabase.task.sync-and-analyze.job threw an unhandled Exception: 
java.lang.NullPointerException
	at java.base/java.util.regex.Matcher.getTextLength(Unknown Source)
	at java.base/java.util.regex.Matcher.reset(Unknown Source)
	at java.base/java.util.regex.Matcher.<init>(Unknown Source)
	at java.base/java.util.regex.Pattern.matcher(Unknown Source)
	at metabase.driver.sync$schema_patterns__GT_filter_fn_STAR_$fn__80810.invoke(sync.clj:45)
	at metabase.driver.sync$include_schema_QMARK_.invokeStatic(sync.clj:76)
	at metabase.driver.sync$include_schema_QMARK_.invoke(sync.clj:66)
	at metabase.driver.snowflake$fn__128206$fn__128207$fn__128211$fn__128213.invoke(snowflake.clj:433)
	at clojure.core$filter$fn__5958$fn__5959.invoke(core.clj:2822)
	at clojure.java.jdbc$init_reduce_rs.invokeStatic(jdbc.clj:1205)
	at clojure.java.jdbc$init_reduce_rs.invoke(jdbc.clj:1197)
	at clojure.java.jdbc$reducible_result_set_STAR_$reify__28159.reduce(jdbc.clj:1227)
	at clojure.core$reduce.invokeStatic(core.clj:6885)
	at clojure.core$reduce.invoke(core.clj:6868)
	at clojure.java.jdbc$query_reducer$fn__28165$fn__28168.invoke(jdbc.clj:1262)
	at clojure.java.jdbc$execute_query_with_params.invokeStatic(jdbc.clj:1091)
	at clojure.java.jdbc$execute_query_with_params.invoke(jdbc.clj:1084)
	at clojure.java.jdbc$db_query_with_resultset_STAR_.invokeStatic(jdbc.clj:1106)
	at clojure.java.jdbc$db_query_with_resultset_STAR_.invoke(jdbc.clj:1093)
	at clojure.java.jdbc$reducible_query$reify__28182.reduce(jdbc.clj:1357)
	at clojure.core$transduce.invokeStatic(core.clj:6946)
	at clojure.core$into.invokeStatic(core.clj:6962)
	at clojure.core$into.invoke(core.clj:6950)
	at metabase.driver.snowflake$fn__128206$fn__128207$fn__128211.invoke(snowflake.clj:429)
	at metabase.driver.sql_jdbc.execute$fn__78692$fn__78693.invoke(execute.clj:388)
	at metabase.driver.sql_jdbc.execute$fn__78657$_AMPERSAND_f__78658.invoke(execute.clj:334)
	at metabase.driver.sql_jdbc.execute$fn__78657$fn__78661.invoke(execute.clj:317)
	at metabase.driver.sql_jdbc.execute$fn__78692.invokeStatic(execute.clj:382)
	at metabase.driver.sql_jdbc.execute$fn__78692.invoke(execute.clj:380)
	at clojure.lang.MultiFn.invoke(MultiFn.java:244)
	at metabase.driver.snowflake$fn__128206$fn__128207.invoke(snowflake.clj:421)
	at metabase.query_processor.store$do_with_metadata_provider.invokeStatic(store.clj:169)
	at metabase.query_processor.store$do_with_metadata_provider.invoke(store.clj:150)
	at metabase.query_processor.store$do_with_metadata_provider.invokeStatic(store.clj:158)
	at metabase.query_processor.store$do_with_metadata_provider.invoke(store.clj:150)
	at metabase.driver.snowflake$fn__128206.invokeStatic(snowflake.clj:418)
	at metabase.driver.snowflake$fn__128206.invoke(snowflake.clj:414)
	at clojure.lang.MultiFn.invoke(MultiFn.java:234)
	at metabase.sync.fetch_metadata$fn__81252$_AMPERSAND_f__81253.invoke(fetch_metadata.clj:15)
	at metabase.sync.fetch_metadata$fn__81252$fn__81255.invoke(fetch_metadata.clj:12)
	at metabase.sync.sync_metadata$fn__82263$_AMPERSAND_f__82264.invoke(sync_metadata.clj:61)
	at metabase.sync.sync_metadata$fn__82263$fn__82268.invoke(sync_metadata.clj:58)
	at metabase.task.sync_databases$sync_and_analyze_database_STAR__BANG_.invokeStatic(sync_databases.clj:94)
	at metabase.task.sync_databases$sync_and_analyze_database_STAR__BANG_.invoke(sync_databases.clj:77)
	at metabase.task.sync_databases$sync_and_analyze_database_BANG_.invokeStatic(sync_databases.clj:113)
	at metabase.task.sync_databases$sync_and_analyze_database_BANG_.invoke(sync_databases.clj:101)
	at metabase.task.sync_databases.SyncAndAnalyzeDatabase.execute(sync_databases.clj:118)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
[850a5ce0-29ca-4397-b800-6e8127f2a0c4] 2024-01-17T09:16:08-08:00 ERROR org.quartz.core.ErrorLogger Job (DEFAULT.metabase.task.sync-and-analyze.job threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: java.lang.NullPointerException]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
Caused by: java.lang.NullPointerException
	at java.base/java.util.regex.Matcher.getTextLength(Unknown Source)
	at java.base/java.util.regex.Matcher.reset(Unknown Source)
	at java.base/java.util.regex.Matcher.<init>(Unknown Source)
	at java.base/java.util.regex.Pattern.matcher(Unknown Source)
	at metabase.driver.sync$schema_patterns__GT_filter_fn_STAR_$fn__80810.invoke(sync.clj:45)
	at metabase.driver.sync$include_schema_QMARK_.invokeStatic(sync.clj:76)
	at metabase.driver.sync$include_schema_QMARK_.invoke(sync.clj:66)
	at metabase.driver.snowflake$fn__128206$fn__128207$fn__128211$fn__128213.invoke(snowflake.clj:433)
	at clojure.core$filter$fn__5958$fn__5959.invoke(core.clj:2822)
	at clojure.java.jdbc$init_reduce_rs.invokeStatic(jdbc.clj:1205)
	at clojure.java.jdbc$init_reduce_rs.invoke(jdbc.clj:1197)
	at clojure.java.jdbc$reducible_result_set_STAR_$reify__28159.reduce(jdbc.clj:1227)
	at clojure.core$reduce.invokeStatic(core.clj:6885)
	at clojure.core$reduce.invoke(core.clj:6868)
	at clojure.java.jdbc$query_reducer$fn__28165$fn__28168.invoke(jdbc.clj:1262)
	at clojure.java.jdbc$execute_query_with_params.invokeStatic(jdbc.clj:1091)
	at clojure.java.jdbc$execute_query_with_params.invoke(jdbc.clj:1084)
	at clojure.java.jdbc$db_query_with_resultset_STAR_.invokeStatic(jdbc.clj:1106)
	at clojure.java.jdbc$db_query_with_resultset_STAR_.invoke(jdbc.clj:1093)
	at clojure.java.jdbc$reducible_query$reify__28182.reduce(jdbc.clj:1357)
	at clojure.core$transduce.invokeStatic(core.clj:6946)
	at clojure.core$into.invokeStatic(core.clj:6962)
	at clojure.core$into.invoke(core.clj:6950)
	at metabase.driver.snowflake$fn__128206$fn__128207$fn__128211.invoke(snowflake.clj:429)
	at metabase.driver.sql_jdbc.execute$fn__78692$fn__78693.invoke(execute.clj:388)
	at metabase.driver.sql_jdbc.execute$fn__78657$_AMPERSAND_f__78658.invoke(execute.clj:334)
	at metabase.driver.sql_jdbc.execute$fn__78657$fn__78661.invoke(execute.clj:317)
	at metabase.driver.sql_jdbc.execute$fn__78692.invokeStatic(execute.clj:382)
	at metabase.driver.sql_jdbc.execute$fn__78692.invoke(execute.clj:380)
	at clojure.lang.MultiFn.invoke(MultiFn.java:244)
	at metabase.driver.snowflake$fn__128206$fn__128207.invoke(snowflake.clj:421)
	at metabase.query_processor.store$do_with_metadata_provider.invokeStatic(store.clj:169)
	at metabase.query_processor.store$do_with_metadata_provider.invoke(store.clj:150)
	at metabase.query_processor.store$do_with_metadata_provider.invokeStatic(store.clj:158)
	at metabase.query_processor.store$do_with_metadata_provider.invoke(store.clj:150)
	at metabase.driver.snowflake$fn__128206.invokeStatic(snowflake.clj:418)
	at metabase.driver.snowflake$fn__128206.invoke(snowflake.clj:414)
	at clojure.lang.MultiFn.invoke(MultiFn.java:234)
	at metabase.sync.fetch_metadata$fn__81252$_AMPERSAND_f__81253.invoke(fetch_metadata.clj:15)
	at metabase.sync.fetch_metadata$fn__81252$fn__81255.invoke(fetch_metadata.clj:12)
	at metabase.sync.sync_metadata$fn__82263$_AMPERSAND_f__82264.invoke(sync_metadata.clj:61)
	at metabase.sync.sync_metadata$fn__82263$fn__82268.invoke(sync_metadata.clj:58)
	at metabase.task.sync_databases$sync_and_analyze_database_STAR__BANG_.invokeStatic(sync_databases.clj:94)
	at metabase.task.sync_databases$sync_and_analyze_database_STAR__BANG_.invoke(sync_databases.clj:77)
	at metabase.task.sync_databases$sync_and_analyze_database_BANG_.invokeStatic(sync_databases.clj:113)
	at metabase.task.sync_databases$sync_and_analyze_database_BANG_.invoke(sync_databases.clj:101)
	at metabase.task.sync_databases.SyncAndAnalyzeDatabase.execute(sync_databases.clj:118)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	... 1 more

Luiggi · January 17, 2024, 9:28pm

How many tables, schemas does your database have?