ActivityWatch/aw-server-rust

Taking datastore lock failed, returning 504: poisoned lock: another task failed inside

BelKed opened this issue · 7 comments

BelKed commented

On aw-server-rust sometimes appears an error Taking datastore lock failed, returning 504: poisoned lock: another task failed inside. I guess it happens when I want to load the data from the database using the web interface and at the same time, some watcher writes data to the database...

Screenshot 2023-02-04 at 20 17 43

[2023-02-04 20:15:28][[31mERROR[0m][_]: Handler [37mquery[0m panicked.
[2023-02-04 20:15:28][[33mWARN[0m][_]: A panic is treated as an internal server error.
[2023-02-04 20:15:28][[33mWARN[0m][_]: No [1;34m500[0m catcher registered. Using Rocket default.
[2023-02-04 20:15:28][[33mWARN[0m][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-04 20:15:31][[33mWARN[0m][aw_server::endpoints::query]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-04 20:15:31][[33mWARN[0m][aw_server::endpoints::query]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
…

ActivityWatch v0.12.2b1

johan-bjareholt commented

The issue occurs before that log appears, when the error message "Handler [37mquery[0m panicked." Is printed. However, the logs provided don't show enough info to be able to track down the issue unfortunately. Could you try to run aw-server-rust with the environment variable RUST_BACKTRACE=1 set and reproduce the issue? That should be able to pinpoint the root cause.

BelKed commented

Here you go:

…
[2023-02-05 19:29:48][WARN][aw_transform::flood]: Gap was of negative duration and could NOT be safely merged (-PT33.986Ss). This warning will only show once per batch.
[2023-02-05 19:29:48][WARN][aw_transform::flood]: Gap was of negative duration (-PT25.798Ss), but could be safely merged. This error will only show once per batch.
[2023-02-05 19:29:48][WARN][aw_transform::flood]: Gap was of negative duration (-PT261.503Ss), but could be safely merged. This error will only show once per batch.
[2023-02-05 19:29:48][WARN][aw_transform::flood]: Gap was of negative duration and could NOT be safely merged (-PT0.127999999Ss). This warning will only show once per batch.
thread 'rocket-worker-thread' panicked at 'called `Option::unwrap()` on a `None` value', aw-transform/src/filter_keyvals.rs:45:42
stack backtrace:
   0: _rust_begin_unwind
   1: core::panicking::panic_fmt
   2: core::panicking::panic
   3: aw_transform::filter_keyvals::filter_keyvals_regex
   4: aw_query::functions::qfunctions::filter_keyvals_regex
   5: aw_query::interpret::interpret_expr
   6: aw_query::interpret::interpret_expr
   7: aw_query::interpret::interpret_prog
   8: aw_query::query
   9: aw_server::endpoints::query::query::into_info::monomorphized_function::{{closure}}
  10: rocket::server::<impl rocket::rocket::Rocket<rocket::phase::Orbit>>::route::{{closure}}
  11: rocket::server::hyper_service_fn::{{closure}}::{{closure}}
  12: tokio::runtime::task::core::Core<T,S>::poll
  13: tokio::runtime::task::harness::Harness<T,S>::poll
  14: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
  15: tokio::runtime::scheduler::multi_thread::worker::Context::run
  16: tokio::macros::scoped_tls::ScopedKey<T>::set
  17: tokio::runtime::scheduler::multi_thread::worker::run
  18: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
  19: tokio::runtime::task::core::Core<T,S>::poll
  20: tokio::runtime::task::harness::Harness<T,S>::poll
  21: tokio::runtime::blocking::pool::Inner::run
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
[2023-02-05 19:29:48][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:29:48][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:29:48][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:29:48][WARN][aw_server::endpoints::query]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:29:48][ERROR][_]: Handler query panicked.
[2023-02-05 19:29:48][WARN][_]: A panic is treated as an internal server error.
[2023-02-05 19:29:48][WARN][_]: No 500 catcher registered. Using Rocket default.
[2023-02-05 19:29:48][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:29:48][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:29:48][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:29:48][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
…
BelKed commented

And, with RUST_BACKTRACE=full:

$ RUST_BACKTRACE=full /Applications/ActivityWatch.app/Contents/MacOS/aw-server-rust
[2023-02-05 19:32:35][INFO][aw_server]: Using DB at path "/Users/BelKed/Library/Application Support/activitywatch/aw-server-rust/sqlite.db"
[2023-02-05 19:32:35][INFO][aw_server]: Cannot find assets "./aw-webui/dist/"
[2023-02-05 19:32:35][INFO][aw_server]: Using aw-webui assets at path "/Applications/ActivityWatch.app/Contents/Resources/aw_server_rust/static/"
[2023-02-05 19:32:35][INFO][aw_server::endpoints]: Starting aw-server-rust at 127.0.0.1:5600
[2023-02-05 19:32:40][WARN][aw_transform::flood]: Gap was of negative duration and could NOT be safely merged (-PT33.986Ss). This warning will only show once per batch.
[2023-02-05 19:32:40][WARN][aw_transform::flood]: Gap was of negative duration (-PT25.798Ss), but could be safely merged. This error will only show once per batch.
[2023-02-05 19:32:40][WARN][aw_transform::flood]: Gap was of negative duration (-PT261.503Ss), but could be safely merged. This error will only show once per batch.
[2023-02-05 19:32:40][WARN][aw_transform::flood]: Gap was of negative duration and could NOT be safely merged (-PT0.127999999Ss). This warning will only show once per batch.
thread 'rocket-worker-thread' panicked at 'called `Option::unwrap()` on a `None` value', aw-transform/src/filter_keyvals.rs:45:42
stack backtrace:
   0:        0x10791d506 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::ha44bd311cfda0c56
   1:        0x10793a45a - core::fmt::write::h46db775de422abff
   2:        0x107917bec - std::io::Write::write_fmt::h231bd871f6642ed8
   3:        0x10791d2ea - std::sys_common::backtrace::print::hb651e3a74d35c35c
   4:        0x10791ea73 - std::panicking::default_hook::{{closure}}::h176350f18e13915d
   5:        0x10791e7c8 - std::panicking::default_hook::hb968ea7a8ffd4e93
   6:        0x10791f1af - std::panicking::rust_panic_with_hook::hebe2782c51c73aac
   7:        0x10791ef33 - std::panicking::begin_panic_handler::{{closure}}::h372a006b6060262d
   8:        0x10791d9a8 - std::sys_common::backtrace::__rust_end_short_backtrace::heaea59646150c826
   9:        0x10791ec3d - _rust_begin_unwind
  10:        0x107963f23 - core::panicking::panic_fmt::h3cac4750fc780d4b
  11:        0x107963fb7 - core::panicking::panic::h43cf0e6258393524
  12:        0x1074a9f97 - aw_transform::filter_keyvals::filter_keyvals_regex::h5b430bc67a94e092
  13:        0x1074537ab - aw_query::functions::qfunctions::filter_keyvals_regex::h9cba0385ca9f2e5d
  14:        0x107461c06 - aw_query::interpret::interpret_expr::h77f17ae74fad24e5
  15:        0x107460c8e - aw_query::interpret::interpret_expr::h77f17ae74fad24e5
  16:        0x10746016b - aw_query::interpret::interpret_prog::h57d309b448eb4974
  17:        0x107464bc0 - aw_query::query::h83d9af7cbb6dd9ef
  18:        0x1073cb9bf - aw_server::endpoints::query::query::into_info::monomorphized_function::{{closure}}::h23b1fe0d2ea20d84
  19:        0x1072d2722 - rocket::server::<impl rocket::rocket::Rocket<rocket::phase::Orbit>>::route::{{closure}}::h87219c64aba39409
  20:        0x1072ce227 - rocket::server::hyper_service_fn::{{closure}}::{{closure}}::hf9a5b3650dcb2812
  21:        0x107339bc1 - tokio::runtime::task::core::Core<T,S>::poll::h28b368f5c490691b
  22:        0x10732253c - tokio::runtime::task::harness::Harness<T,S>::poll::h6116e889baa313d8
  23:        0x1078a1abc - tokio::runtime::scheduler::multi_thread::worker::Context::run_task::ha9bc4b3d8c357e2b
  24:        0x1078a1001 - tokio::runtime::scheduler::multi_thread::worker::Context::run::h0480c66300842585
  25:        0x10787dc19 - tokio::macros::scoped_tls::ScopedKey<T>::set::hce903ba6449392c9
  26:        0x1078a0bd2 - tokio::runtime::scheduler::multi_thread::worker::run::h498a1d016f0ddff9
  27:        0x10788eaf8 - tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut::h70a60e74d47c5c38
  28:        0x107882820 - tokio::runtime::task::core::Core<T,S>::poll::h739008e80d5d0b2f
  29:        0x10787732b - tokio::runtime::task::harness::Harness<T,S>::poll::h1b322d26c89eb1ba
  30:        0x1078a6280 - tokio::runtime::blocking::pool::Inner::run::h3bcafd5cdee27c85
  31:        0x107879a75 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5139b2736cbfe4d6
  32:        0x10789d8ae - core::ops::function::FnOnce::call_once{{vtable.shim}}::h8bc53e8b8dceef0b
  33:        0x107921497 - std::sys::unix::thread::Thread::new::thread_start::h1bca6a3e6b0bdb6b
  34:     0x7ff81c95f4e1 - __pthread_start
[2023-02-05 19:32:40][ERROR][_]: Handler query panicked.
[2023-02-05 19:32:40][WARN][_]: A panic is treated as an internal server error.
[2023-02-05 19:32:40][WARN][_]: No 500 catcher registered. Using Rocket default.
[2023-02-05 19:32:40][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:32:40][WARN][aw_server::endpoints::query]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:32:40][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:32:40][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-02-05 19:32:41][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
…
BelKed commented

From what I can see, the code fails here:
https://github.com/ActivityWatch/aw-server-rust/blob/master/aw-transform/src/filter_keyvals.rs#L45

Seems like event.data.get(key).as_str() is None, which results in an error.

johan-bjareholt commented

Thanks a lot @BelKed for reporting with the detailed logs.

I have a fix ready #345, so should be fixed for the next ActivityWatch release!

  • 👍1
BelKed commented

I've installed the "nightly" version from CI with a fix for this issue, and I can verify the bug is gone.
Thanks for fixing the problem :)

  • 🎉2
ShootingKing-AM commented

I have the same error log but with backtrace pointing to a different location,

thread 'rocket-worker-thread' panicked at 'called `Option::unwrap()` on a `None` value', aw-transform\src\period_union.rs:30:26

aw-server-rust/aw-transform/src/period_union.rs

Line 30 in b5b451d

let last_event = events_union.last().unwrap();

I have replaced the rust binary of the newest release but still the errors persists :(