Option::unwrap() panics in base_cache::Clocks::to_std_instant

[matheus23]

In my app I'm using hickory_resolver, which uses a DNS resolver, which has a cache that's implemented using moka.

I don't think it's using the API incorrectly, but moka ends up panicking sometimes. The backtrace for that is:

thread 'tokio-runtime-worker' panicked at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/moka-0.12.8/src/sync_base/base_cache.rs:899:59:
called `Option::unwrap()` on a `None` value
stack backtrace:
   0: rust_begin_unwind
             at /rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/std/src/panicking.rs:662:5
   1: core::panicking::panic_fmt
             at /rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/panicking.rs:74:14
   2: core::panicking::panic
             at /rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/panicking.rs:148:5
   3: core::option::unwrap_failed
             at /rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/option.rs:2015:5
   4: core::option::Option<T>::unwrap
             at /rustc/f6e511eec7342f59a25f7c0534f1dbea00d01b14/library/core/src/option.rs:965:21
   5: moka::sync_base::base_cache::Clocks::to_std_instant
             at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/moka-0.12.8/src/sync_base/base_cache.rs:899:22
   6: moka::sync_base::base_cache::BaseCache<K,V,S>::do_get_with_hash
             at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/moka-0.12.8/src/sync_base/base_cache.rs:327:26
   7: moka::sync_base::base_cache::BaseCache<K,V,S>::get_with_hash
             at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/moka-0.12.8/src/sync_base/base_cache.rs:226:9
   8: moka::sync::cache::Cache<K,V,S>::get
             at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/moka-0.12.8/src/sync/cache.rs:803:9
   9: hickory_resolver::dns_lru::DnsLru::get
             at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/hickory-resolver-0.25.0-alpha.4/src/dns_lru.rs:464:21
  10: hickory_resolver::caching_client::CachingClient<C>::lookup_from_cache
             at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/hickory-resolver-0.25.0-alpha.4/src/caching_client.rs:262:9
  11: hickory_resolver::caching_client::CachingClient<C>::inner_lookup::{{closure}}
             at /home/philipp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/hickory-resolver-0.25.0-alpha.4/src/caching_client.rs:183:38

(and then some more stuff involving hickory's LookupFuture, and finally application code)

I think this is more likely a bug in moka, but it might also be a bug in hickory. If you're sure it's a bug in hickory, I can close this issue and file another issue in the hickory repository.

[tatsuya6502]

Thank you for reporting the issue. It looks like a bug in moka or one of its dependencies.

I could not figure out why checked_duration_since method sometimes returns None in your app, but I stopped doing unconditional Option::unwrap there, so you should not get the panic anymore.

I added the following workaround:

https://github.com/moka-rs/moka/pull/477/files#diff-fd0ff1484465ab748157bd3c6eaae882ee1e40b4041beda4b8c29f052caf97a9L899-R912

-        origin_std + (time.checked_duration_since(origin).unwrap())
+
+        // `checked_duration_since` should always succeed here because the `origin`
+        // is set when this `Cache` is created, and the `time` is either the last
+        // modified or last accessed time of a cached entry. So `time` should always
+        // be greater than or equal to `origin`.
+        //
+        // However, this is not always true when `quanta::Instant` is used as the
+        // time source? https://github.com/moka-rs/moka/issues/472
+        //
+        // (Or do we set zero Instant to last modified/accessed time somewhere?)
+        //
+        // As a workaround, let's use zero duration when `checked_duration_since`
+        // fails.
+        origin_std + (time.checked_duration_since(origin).unwrap_or_default())

[tatsuya6502]

Reopen for the root cause analysis. Note that the workaround added by #477 should be still valid and prevent the panic to occur.

Hi @matheus23,

If possible, can you please tell us what kind of CPU did you use when you got the panic (Intel, AMD, Apple, etc)? Knowing the CPU kind can help us to reproduce the issue and figure out if this is an issue in the quanta crate or not.

I am not sure yet, but I am thinking this issue might be related to metrics-rs/quanta#61 ?

Thanks!

[matheus23]

CPU: AMD Ryzen 7 PRO 6850U with Radeon Graphics
System: NixOS Linux x86_64

EDIT: Looking at the linked issue:

Thinkpads with Ryzen mobile CPUs

Yep, this is the case here.

[matheus23]

Can confirm the 0.12.9 release fixes this issue for me 👍

[tatsuya6502]

Thank you for the CPU information and also testing v0.12.9!

I created a GH issue on quanta and will track the progress there:

• Detect unsynchronized TSCs across cores and fallback to the OS time source? metrics-rs/quanta#111