Caché not working with mongodb

[aguedob]

Hi all!

Not sure if is a bug or just a problem related to my data, but cache is not working for me. Checking logs I see the same error in every question that should be cached:

2022-10-13 13:35:55,894 INFO query-processor.card :: Question's average execution duration is 1.7 s; using 'magic' TTL of 3.4 mins 💾
2022-10-13 13:35:56,071 INFO middleware.cache :: Query took 157.0 ms to run; minimum for cache eligibility is 0.0 ns
2022-10-13 13:35:56,072 INFO middleware.cache :: Caching results for next time for query with hash "40e576cc". 💾
2022-10-13 13:35:56,072 ERROR middleware.cache :: Error saving query results to cache: backing-map
java.lang.NoSuchFieldException: backing-map
        at java.base/java.lang.Class.getField(Unknown Source)
        at taoensso.nippy$fn__25232$fn__25233$fn__25234.invoke(nippy.clj:1209)
        at taoensso.nippy$fn__25232$fn__25233.invoke(nippy.clj:1207)
        at clojure.lang.PersistentVector.reduce(PersistentVector.java:343)
        at clojure.core$reduce.invokeStatic(core.clj:6885)
        at clojure.core$reduce.invoke(core.clj:6868)

Any idea? Thanks in advance

[flamber]

Hi @aguedob
Post "Diagnostic Info" from Admin > Troubleshooting.
Looks very related to https://github.com/metabase/metabase/issues/19501 and https://github.com/metabase/metabase/issues/11995

[aguedob]

{
  "browser-info": {
    "language": "en-GB",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.0 Safari/605.1.15",
    "vendor": "Apple Computer, Inc."
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.16.1+1",
    "java.vendor": "Eclipse Adoptium",
    "java.vendor.url": "https://adoptium.net/",
    "java.version": "11.0.16.1",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.16.1+1",
    "os.name": "Linux",
    "os.version": "3.10.0-1160.76.1.el7.x86_64",
    "user.language": "en",
    "user.timezone": "GMT"
  },
  "metabase-info": {
    "databases": [
      "postgres",
      "mongo"
    ],
    "hosting-env": "unknown",
    "application-database": "postgres",
    "application-database-details": {
      "database": {
        "name": "PostgreSQL",
        "version": "11.10"
      },
      "jdbc-driver": {
        "name": "PostgreSQL JDBC Driver",
        "version": "42.5.0"
      }
    },
    "run-mode": "prod",
    "version": {
      "date": "2022-09-29",
      "tag": "v0.44.4",
      "branch": "release-x.44.x",
      "hash": "382d728"
    },
    "settings": {
      "report-timezone": null
    }
  }
}

[flamber]

@aguedob It would require understanding your fields (the types) or query to be able to reproduce, since caching is working for the questions I've just tested against.

[aguedob]

I have created a very simple collection in mongo and a simple question in Metabase to verify that was not document-related. I still have the same error while caching. Check the screenshots:

Here is my collection in mongo:

This is a screenshot for the data model:

And here you have the question I've created. Just a simple list of all data:

[flamber]

@aguedob Please provide the collection in plain text, so it is possible to try to reproduce.

[aguedob]

Sure:

datars:PRIMARY> db.test_col.find()
{ "_id" : ObjectId("63481d83b8fc3a1b5ebf3156"), "item" : "journal", "qty" : 25 }
{ "_id" : ObjectId("63481d83b8fc3a1b5ebf3157"), "item" : "mat", "qty" : 85 }
{ "_id" : ObjectId("63481d83b8fc3a1b5ebf3158"), "item" : "mousepad", "qty" : 25 }

[aguedob]

I started in trace mode and managed to get more information before the error occur. Just in case it helps you:

10-13 15:16:25 TRACE util.i18n :: Translated "Opened new MongoDB connection." for site locale "en" -> "Opened new MongoDB connection."
10-13 15:16:25 DEBUG mongo.util :: Opened new MongoDB connection.
10-13 15:16:25 TRACE mongo.execute :: Renaming columns in results ["_id" "item" "qty"] -> ["_id" "item" "qty"]
10-13 15:16:25 TRACE util.i18n :: Translating "Formatting rows with results timezone ID {0}" for user locale "en" (site locale "en") -> "Formatting rows with results timezone ID GMT"
10-13 15:16:25 DEBUG middleware.format-rows :: Formatting rows with results timezone ID GMT
10-13 15:16:25 TRACE cache.impl :: Freezing {:cols [{:name "_id"} {:name "item"} {:name "qty"}], :cache-version 3, :last-ran #t "2022-10-13T15:16:25.592261Z[GMT]"}
10-13 15:16:25 TRACE cache.impl :: Freezing [#object[org.bson.types.ObjectId 0x6645c3b4 "63481d83b8fc3a1b5ebf3156"] "journal" 25]
10-13 15:16:25 TRACE cache.impl :: Freezing [#object[org.bson.types.ObjectId 0x24f9a4ab "63481d83b8fc3a1b5ebf3158"] "mousepad" 25]
10-13 15:16:25 TRACE cache.impl :: Freezing [#object[org.bson.types.ObjectId 0x32711e8b "63481d83b8fc3a1b5ebf3157"] "mat" 85]
10-13 15:16:25 TRACE query-processor.reducible :: All rows consumed.
10-13 15:16:25 TRACE cache.impl :: Freezing {:data {:cols ({:description nil, :semantic_type :type/PK, :table_id 173, :coercion_strategy nil, :name "_id", :settings nil, :source :fields, :field_ref [:field 2172 nil], :effective_type :type/MongoBSONID, :nfc_path nil, :parent_id nil, :id 2172, :visibility_type :normal, :display_name "ID", :fingerprint nil, :base_type :type/MongoBSONID} {:description nil, :semantic_type :type/Description, :table_id 173, :coercion_strategy nil, :name "item", :settings nil, :source :fields, :field_ref [:field 2173 nil], :effective_type :type/Text, :nfc_path nil, :parent_id nil, :id 2173, :visibility_type :normal, :display_name "Item", :fingerprint {:global {:distinct-count 3, :nil% 0.0}, :type {:type/Text {:percent-json 0.0, :percent-url 0.0, :percent-email 0.0, :percent-state 0.0, :average-length 6.0}}}, :base_type :type/Text} {:description nil, :semantic_type :type/Quantity, :table_id 173, :coercion_strategy nil, :name "qty", :settings nil, :source :fields, :field_ref [:field 2174 nil], :effective_type :type/Integer, :nfc_path nil, :parent_id nil, :id 2174, :visibility_type :normal, :display_name "Qty", :fingerprint {:global {:distinct-count 2, :nil% 0.0}, :type {:type/Number {:min 25.0, :q1 25.0, :q3 71.51530771650467, :max 85.0, :sd 34.64101615137755, :avg 45.0}}}, :base_type :type/Integer}), :native_form {:projections ("_id" "item" "qty"), :query [{"$project" #ordered/map (["_id" "$_id"] ["item" "$item"] ["qty" "$qty"])} {"$limit" 2000}], :collection "test_col", :mbql? true}, :results_timezone "GMT"}}
10-13 15:16:25 TRACE cache.impl :: Caught error when freezing object
java.lang.NoSuchFieldException: backing-map
        at java.lang.Class.getField(Unknown Source) ~[?:?]
        at taoensso.nippy$fn__25232$fn__25233$fn__25234.invoke(nippy.clj:1209) ~[metabase.jar:?]
        at taoensso.nippy$fn__25232$fn__25233.invoke(nippy.clj:1207) ~[metabase.jar:?]
        at clojure.lang.PersistentVector.reduce(PersistentVector.java:343) ~[metabase.jar:?]
        at clojure.core$reduce.invokeStatic(core.clj:6885) ~[metabase.jar:?]
        .... 

[flamber]

@aguedob I've created an issue for this:
https://github.com/metabase/metabase/issues/25915 - upvote by clicking on the first post