Error reported during Metabase sync task, sync not completing missing things like binning

Get Help
#1

Hi all. I’m getting an error reported in the logs during the Metabase sync job and the job isn’t doing all it’s steps.

For instance I’m not getting fingerprints calculated which impacts loads of things for the end users, they can’t get number binning, or auto type detection (category etc.).

The error looks like:

Jun 20 11:50:05 ERROR metabase.sync.util :: Error running sync step: Multiple methods in multimethod 'fingerprinter' match dispatch value: [:type/DateTime :type/FK] -> [:type/DateTime :type/*] and [:type/* :type/FK], and neither is preferred
    ("clojure.lang.MultiFn.findAndCacheBestMethod(MultiFn.java:179)"
    "clojure.lang.MultiFn.getMethod(MultiFn.java:150)"
    "clojure.lang.MultiFn.getFn(MultiFn.java:154)"
    "clojure.lang.MultiFn.invoke(MultiFn.java:229)"
    "--> sync.analyze.fingerprint.fingerprinters$fingerprint_fields$iter__38695__38699$fn__38700$fn__38701.invoke(fingerprinters.clj:212)"
    "sync.analyze.fingerprint.fingerprinters$fingerprint_fields$iter__38695__38699$fn__38700.invoke(fingerprinters.clj:211)"
    "sync.analyze.fingerprint.fingerprinters$fingerprint_fields.invokeStatic(fingerprinters.clj:211)"
    "sync.analyze.fingerprint.fingerprinters$fingerprint_fields.invoke(fingerprinters.clj:208)"
    "sync.analyze.fingerprint$fn__43876$fingerprint_table_BANG___43881$fn__43882.invoke(fingerprint.clj:44)"
    "sync.analyze.fingerprint$fn__43876$fingerprint_table_BANG___43881.invoke(fingerprint.clj:40)"
    "sync.analyze.fingerprint$fn__44049$fingerprint_fields_BANG___44054$fn__44055.invoke(fingerprint.clj:161)"
    "sync.analyze.fingerprint$fn__44049$fingerprint_fields_BANG___44054.invoke(fingerprint.clj:157)"
    "sync.analyze.fingerprint$fn__44075$fingerprint_fields_for_db_BANG___44080$fn__44081$fn__44082$iter__44083__44087$fn__44088$fn__44089.invoke(fingerprint.clj:171)"
    "sync.analyze.fingerprint$fn__44075$fingerprint_fields_for_db_BANG___44080$fn__44081$fn__44082$iter__44083__44087$fn__44088.invoke(fingerprint.clj:170)"
    "sync.analyze.fingerprint$fn__44075$fingerprint_fields_for_db_BANG___44080$fn__44081$fn__44082.invoke(fingerprint.clj:170)"
    "util.date$call_with_effective_timezone.invokeStatic(date.clj:88)"
    "util.date$call_with_effective_timezone.invoke(date.clj:77)"
    "sync.analyze.fingerprint$fn__44075$fingerprint_fields_for_db_BANG___44080$fn__44081.invoke(fingerprint.clj:169)"
    "sync.analyze.fingerprint$fn__44075$fingerprint_fields_for_db_BANG___44080.invoke(fingerprint.clj:164)"
    "sync.analyze$make_analyze_steps$fn__44221.invoke(analyze.clj:110)"
    "sync.util$fn__36514$run_step_with_metadata__36519$fn__36523$fn__36525.invoke(util.clj:356)"
    "sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invokeStatic(util.clj:104)"
    "sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invoke(util.clj:98)"
    "sync.util$with_start_and_finish_debug_logging.invokeStatic(util.clj:121)"
    "sync.util$with_start_and_finish_debug_logging.invoke(util.clj:118)"
    "sync.util$fn__36514$run_step_with_metadata__36519$fn__36523.invoke(util.clj:353)"
    "sync.util$fn__36514$run_step_with_metadata__36519.invoke(util.clj:348)"
    "sync.util$fn__36706$run_sync_operation__36711$fn__36712$fn__36713.invoke(util.clj:441)"
    "sync.util$fn__36706$run_sync_operation__36711$fn__36712.invoke(util.clj:441)"
    "sync.util$fn__36706$run_sync_operation__36711.invoke(util.clj:435)"
    "sync.analyze$fn__44233$analyze_db_BANG___44238$fn__44239$fn__44240.invoke(analyze.clj:127)"
    "sync.util$do_with_error_handling.invokeStatic(util.clj:149)"
    "sync.util$do_with_error_handling.invoke(util.clj:144)"
    "sync.util$do_with_error_handling.invokeStatic(util.clj:147)"
    "sync.util$do_with_error_handling.invoke(util.clj:144)"
    "driver$fn__16646.invokeStatic(driver.clj:644)"
    "driver$fn__16646.invoke(driver.clj:644)"
    "sync.util$sync_in_context$fn__36420.invoke(util.clj:140)"
    "sync.util$with_db_logging_disabled$fn__36417.invoke(util.clj:131)"
    "sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invokeStatic(util.clj:104)"
    "sync.util$with_start_and_finish_logging_SINGLEQUOTE_.invoke(util.clj:98)"
    "sync.util$with_start_and_finish_logging$fn__36406.invoke(util.clj:116)"
    "sync.util$with_sync_events$fn__36401.invoke(util.clj:90)"
    "sync.util$with_duplicate_ops_prevented$fn__36392.invoke(util.clj:69)"
    "sync.util$do_sync_operation.invokeStatic(util.clj:168)"
    "sync.util$do_sync_operation.invoke(util.clj:165)"
    "sync.analyze$fn__44233$analyze_db_BANG___44238$fn__44239.invoke(analyze.clj:124)"
    "sync.analyze$fn__44233$analyze_db_BANG___44238.invoke(analyze.clj:119)"
    "task.sync_databases.SyncAndAnalyzeDatabase.execute(sync_databases.clj:42)")

I’ve logged a ticket in github https://github.com/metabase/metabase/issues/10038 but haven’t had much feedback. I’ve tried to figure out if it’s a specific field causing this but can’t quite put all the pieces together to get the answer.

Anyone got any ideas about how I can either work around or fix this?

#2

Hi @notrom

My first guess is something in the Data Model that creates this error.
Are you using a DateTime column as a Primary Key (Entity Key) or Foreign Key anywhere in the tables that fail (or in the referenced tables)?
Admin > Data Model > (database) > (table) > (field) :gear:

Is it only some tables that fails the scan? Or specific fields?

Are you using 0.32.9 now? Not that I think it’s going to make any difference with this error.
Which version of SQL Server?

#3

Hi, thanks for responding.

Yes I have a table with DateTime as the primary key. This is referenced from multiple other tables as a Foreign Key.

I don’t see anything in the logs that tells me specifically which table the sync is failing on, if I had that I could probably work around this issue in some way. Is there a runtime flag or similar that I can enable for more verbose logging? However on the database that’s failing to sync none of the metabase_field.last_analyzed dates are changing so I don’t think any of the tables are updating.

Yes I’m seeing this v0.32.9.

SQL Server 2014 SP2.

Thanks

#4

@notrom
Okay, I’ve been trying to find an issue that talks about using DateTime as a Primary/Foreign Key causes problems, but I just cannot find it.
So since I don’t remember the full context from the comments, I’m hesitant to say that’s the problem, but I’m pretty sure that is causing the troubles.

#5

Thanks. the only issue I could about a datetime PK/FK problems was the one I logged and referenced above :slight_smile:

I think you’re right about it being an issue in the data model, some area’s of Metabase do everything correctly with the PK/FK link though which is good. The link works as expected in the query builder and we use it liberally to deal with some of the non-standard reporting periods our organisation uses (“Fiscal Thirds” anyone? I think we made that one up …)

I’m reluctant to remove the date PK links yet as we do use them in the front end, it would be great if they would be supported in the back end sync too.

Cheers

#7

Fixed in https://github.com/metabase/metabase/pull/10621

Thanks!

#8

This just happened to us and we’re on the latest version of metabase 0.35.3. Postgres db would not sync, BigQuery does. Error log shows the usual “fingerprint” step error, doesn’t seem to affect anything, plus a failure on sync step. I added a new version of the postgres db and it sync’d fine. Still couldn’t get the old one to until i found this thread. I looked for all pk’s and found one that was a date. I changed it from a PK constraint to a regular index and voila, the sync started working again.

Postgres query for checking pk’s for ref:

       kcu.table_name,
       tco.constraint_name,
       kcu.ordinal_position as position,
       kcu.column_name as key_column
from information_schema.table_constraints tco
join information_schema.key_column_usage kcu 
     on kcu.constraint_name = tco.constraint_name
     and kcu.constraint_schema = tco.constraint_schema
     and kcu.constraint_name = tco.constraint_name
where tco.constraint_type = 'PRIMARY KEY'
order by kcu.table_schema,
         kcu.table_name,
         position;```
Postgres New Columns Not Showing
#9

@trent_pepper Just to make sure I understand you correctly, you’re saying that Metabase fails to sync/scan on Postgres (perhaps other databases too) if the primary key is a date column (I’m guessing any timestamp type would cause this) ?
Could you post the error message, if you still have it?

@sbelak Do you know why this could happen. I don’t remember any issues about this. You want one for this?

#10

@flamber, I double checked and the primary key contained two timestamp fields (postgres). I don’t remember if this changed at some point but what seems odds is that adding a new “database” will sync, meaning it can work. My guess is that it only stopped working because the constraint was added at some point after the initial sync. We also upgraded to 0.35.3 from maybe 0.33 just a couple weeks ago. So unfortunately a few moving parts makes this harder to troubleshoot. The error message was also vague - in the log it just said “STARTING: step ‘sync-tables”, then “step failed”. I tried to find in the postgres pg_stat_activity but only found the SELECT on the information schema.

#11

Could you show me the exact error & what /api/field/:id returns for the offending fields.

#12

I too am seeing numerous instances of the same fingerprint error with a Postgres DB. I also have numerous date fields as PK & FK in the DB (too many to test if removing the constraints resolves the issue)
For example…

[21dc7d99-e1cf-4606-8f5e-1d96532f8ac1] 2020-05-15T20:55:32+09:00 INFO metabase.sync.util STARTING: step 'fingerprint-fields' for postgres Database 2 'bitool'
[21dc7d99-e1cf-4606-8f5e-1d96532f8ac1] 2020-05-15T20:55:32+09:00 ERROR metabase.sync.util Error generating fingerprint for Field 56 'TURNOVER'

If I perform a GET for /api/field/56 … I see the following json…

{
   "description":null,
   "database_type":"float8",
   "table_id":45,
   "table":{
      "description":null,
      "entity_type":"entity/CompanyTable",
      "schema":"public",
      "db":{
         "description":null,
         "features":[
            "full-join",
            "basic-aggregations",
            "standard-deviation-aggregations",
            "expression-aggregations",
            "percentile-aggregations",
            "foreign-keys",
            "right-join",
            "left-join",
            "native-parameters",
            "nested-queries",
            "expressions",
            "set-timezone",
            "regex",
            "case-sensitivity-string-filter-options",
            "binning",
            "inner-join",
            "advanced-math-expressions"
         ],
         "cache_field_values_schedule":"0 0 6 * * ? *",
         "timezone":"UTC",
         "auto_run_queries":true,
         "metadata_sync_schedule":"0 0 * * * ? *",
         "name":"**NAME**",
         "caveats":null,
         "is_full_sync":true,
         "updated_at":"2020-05-15T06:34:39.895231Z",
         "details":{
            "additional-options":null,
            "ssl":true,
            "password":"**MetabasePass**",
            "let-user-control-scheduling":true,
            "port":5432,
            "dbname":"**DBName**",
            "host":"**DBHost**",
            "tunnel-enabled":false,
            "user":"**DBUser**"
         },
         "is_sample":false,
         "id":2,
         "is_on_demand":false,
         "options":null,
         "engine":"postgres",
         "created_at":"2020-05-15T06:34:39.668145Z",
         "points_of_interest":null
      },
      "show_in_getting_started":false,
      "name":"company_ft",
      "caveats":null,
      "fields_hash":"95tf0vzMs6NBTQH4ugNaGA==",
      "rows":null,
      "updated_at":"2020-05-15T06:38:24.160788Z",
      "entity_name":null,
      "active":true,
      "id":45,
      "db_id":2,
      "visibility_type":null,
      "display_name":"company_ft",
      "created_at":"2020-05-15T06:34:40.334527Z",
      "points_of_interest":null
   },
   "special_type":null,
   "name":"TURNOVER",
   "fingerprint_version":0,
   "has_field_values":"none",
   "settings":null,
   "caveats":null,
   "fk_target_field_id":null,
   "dimensions":[

   ],
   "updated_at":"2020-05-15T11:42:06.219133Z",
   "active":true,
   "parent_id":null,
   "id":56,
   "last_analyzed":null,
   "position":0,
   "visibility_type":"normal",
   "preview_display":true,
   "display_name":"TURNOVER",
   "name_field":null,
   "fingerprint":null,
   "created_at":"2020-05-15T06:34:40.591993Z",
   "base_type":"type/Float",
   "points_of_interest":null
}
#13

Just tagging @sbelak so he gets notified about this fingerprint problem with DATE as PK and FK

#14

@flamber thanks.
@sbelak note a possibly related issue I have seen is when a dashboard is published as an Embed. Some of the dashboard filter fields return a “not found” error when the Embed calls the metabase field api /api/field/123 to retrieve their definitions. This results in the dashboard dropdown appearing as a text field.

#15

@notreallyhere Let’s keep things separate. Please open a new topic for dashboard filter dropdown problem. It sounds like it could be one of these issues:
https://github.com/metabase/metabase/issues/11007
https://github.com/metabase/metabase/issues/8472

#16

@notreallyhere does the field company_ft include any “weird” values such as NaN or Infinity? Either way it looks to be a number, so unrelated to PK issue.

@trent_pepper could you share the precise error you are seeing?

#17

@sbelak Ah yes some of the float8 columns have NaN in them. I’ll get those converted to proper nulls and see if that fixes it. Thank you for the suggestion.

#18

@notreallyhere Then this PR will likely fix the sync for you:
https://github.com/metabase/metabase/pull/12573 - will likely land in 0.36.0

1 Like
#19

Unfortunately the only message i could find in the log file was “STARTING: step ‘sync-tables”, then “step failed”. We have not had the issue again since i removed this primary key.

#20

@trent_pepper Can you post the full log from sync+scan start to end? You can manually start the sync+scan process via Admin > Databases > your-bq-database