"poisoned lock: another task failed inside"

[EtaoinWu]

I'm using the latest release of AW (0.12.2) on Windows 11 (22H2 build 22621.2215) with aw-server-rust enabled. Lately whenever I open up the web UI and check any day under "activity" I got this in the logs for aw-server-rust:

[2023-08-29 17:31:41][INFO][aw_server]: Using DB at path "C:\\Users\\etaoi\\AppData\\Local\\activitywatch\\aw-server-rust\\sqlite.db"
[2023-08-29 17:31:41][INFO][aw_server]: Cannot find assets "./aw-webui/dist/"
[2023-08-29 17:31:41][INFO][aw_server]: Using aw-webui assets at path "C:\\Program Files (x86)\\ActivityWatch\\aw-server-rust\\./static/"
[2023-08-29 17:31:41][INFO][aw_server::endpoints]: Starting aw-server-rust at 127.0.0.1:5600
[2023-08-29 17:32:51][ERROR][_]: No matching routes for GET /manifest.json.
[2023-08-29 17:32:51][WARN][_]: No 404 catcher registered. Using Rocket default.
[2023-08-29 17:33:34][ERROR][_]: Handler query panicked.
[2023-08-29 17:33:34][WARN][_]: A panic is treated as an internal server error.
[2023-08-29 17:33:34][WARN][_]: No 500 catcher registered. Using Rocket default.
[2023-08-29 17:33:37][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-08-29 17:33:39][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-08-29 17:33:40][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
[2023-08-29 17:33:41][WARN][aw_server::endpoints::bucket]: Taking datastore lock failed, returning 504: poisoned lock: another task failed inside
(the previous warning repeats for dozens of times)

The same warning (Taking datastore lock failed, returning 504: poisoned lock: another task failed inside) also appears (multiple times) on the web UI. All the After the problem occurs, I cannot use "Timeline" as well.

However, after a clean start of aw-server-rust, I can still view the "timeline" without error of a time range that includes the days that caused the error at "Activity".

My sqlite database is like 200MB, and it obviously contains my privacy, so I am unable to share it.

[ErikBjare]

Ouch, so sorry about this. Can you try a pre-release like v0.12.3b6? It is possible that the underlying bug has been fixed since v0.12.2.

Note

Unfortunately, v0.12.3b7 and v0.12.3b8 have issues on windows: ActivityWatch/activitywatch#936, caused by me being overly eager to upgrade Python version used for building in ActivityWatch/activitywatch#931.

[EtaoinWu]

With v0.12.2, running aw-qt -v solves the issue; however if I switch back to running it without the verbose flag, the problem persists. (Fortunately, the database is not corrupted.)

With v0.12.3b6, I got a different result (but still unexpected). "Timeline" still works, but "Activity" still doesn't -- it outputs a subset of my activity for one specific day (yesterday), and "no data" for all other days.

Secondly, no more rust lock errors in logs:

[2023-08-29 22:49:23][INFO][aw_server]: Using DB at path "C:\\Users\\etaoi\\AppData\\Local\\activitywatch\\aw-server-rust\\sqlite.db"
[2023-08-29 22:49:23][INFO][aw_server::dirs]: Cannot find assets "./aw-webui/dist/"
[2023-08-29 22:49:23][INFO][aw_server]: Using aw-webui assets at path "C:\\Program Files (x86)\\ActivityWatch\\aw-server-rust\\./static/"
[2023-08-29 22:49:23][INFO][aw_server::endpoints]: Starting aw-server-rust at 127.0.0.1:5600
[2023-08-29 22:49:23][WARN][rocket::launch]: Rocket has launched from http://127.0.0.1:5600
[2023-08-29 22:49:42][INFO][rocket_cors::_]: Verifying origin: http://localhost:5600
[2023-08-29 22:49:42][INFO][rocket_cors::_]: Origin has an exact match
[2023-08-29 22:49:43][INFO][rocket_cors::_]: Verifying origin: http://localhost:5600
[2023-08-29 22:49:43][INFO][rocket_cors::_]: Origin has an exact match
[2023-08-29 22:49:43][INFO][rocket_cors::_]: Verifying origin: http://localhost:5600
[2023-08-29 22:49:43][INFO][rocket_cors::_]: Origin has an exact match
[2023-08-29 22:49:44][WARN][rocket::server::_]: Remote left: channel closed.
[2023-08-29 22:49:44][INFO][rocket_cors::_]: Verifying origin: http://localhost:5600
[2023-08-29 22:49:44][INFO][rocket_cors::_]: Origin has an exact match

The verbose flag -v fixes v0.12.3b6 as well.

[EtaoinWu]

With v0.12.2, running aw-qt -v solves the issue

The verbose flag -v fixes v0.12.3b6 as well.

I tried some more times, and am currently not sure if starting with the verbose flag can actually solve the problem. Now it doesn't work anymore.

[johan-bjareholt]

If it doesn't work with 0.12.3b7, can you run aw-server-rust with the environment variable RUST_BACKTRACE=1 set? You might need to run it outside of aw-qt also to get the backtrace.

[EtaoinWu]

With set RUST_BACKTRACE=full and set RUST_LOG=debug, and after disabling all watchers, I can get the following backtrace:

thread 'rocket-worker-thread' panicked at 'called `Option::unwrap()` on a `None` value', aw-transform\src\period_union.rs:30:46
stack backtrace:
   0:     0x7ff7ba793412 - <unknown>
   1:     0x7ff7ba7adcbb - <unknown>
   2:     0x7ff7ba78c61a - <unknown>
   3:     0x7ff7ba79315b - <unknown>
   4:     0x7ff7ba795a89 - <unknown>
   5:     0x7ff7ba79570b - <unknown>
   6:     0x7ff7ba796320 - <unknown>
   7:     0x7ff7ba79606b - <unknown>
   8:     0x7ff7ba793e2f - <unknown>
   9:     0x7ff7ba795d60 - <unknown>
  10:     0x7ff7ba908465 - <unknown>
  11:     0x7ff7ba90851c - <unknown>
  12:     0x7ff7ba4c371a - <unknown>
  13:     0x7ff7ba4830f7 - <unknown>
  14:     0x7ff7ba4639f5 - <unknown>
  15:     0x7ff7ba462af1 - <unknown>
  16:     0x7ff7ba4617a5 - <unknown>
  17:     0x7ff7ba4397dc - <unknown>
  18:     0x7ff7ba3fe2c2 - <unknown>
  19:     0x7ff7ba31282b - <unknown>
  20:     0x7ff7ba30ad4a - <unknown>
  21:     0x7ff7ba2aeef5 - <unknown>
  22:     0x7ff7ba30032d - <unknown>
  23:     0x7ff7ba6f7537 - <unknown>
  24:     0x7ff7ba6f6742 - <unknown>
  25:     0x7ff7ba71a906 - <unknown>
  26:     0x7ff7ba6f61bf - <unknown>
  27:     0x7ff7ba707685 - <unknown>
  28:     0x7ff7ba70a61a - <unknown>
  29:     0x7ff7ba71f630 - <unknown>
  30:     0x7ff7ba71de11 - <unknown>
  31:     0x7ff7ba706888 - <unknown>
  32:     0x7ff7ba6f254f - <unknown>
  33:     0x7ff7ba79ab9c - <unknown>
  34:     0x7ffb32b1257d - BaseThreadInitThunk
  35:     0x7ffb3378aa68 - RtlUserThreadStart

This happens before the log [ERROR][_]: Handler query panicked.

[EtaoinWu]

Just for your info, I currently three watchers -- stock aw_watcher_window, the official browser addon for chromium, and my own aw-watcher-winlock which detects windows lock status and report it as AFK.

I have exported data generated by my own watcher, and found that it contains overlapping reports like:

Expand JSON

[
  {
    "id": 902212,
    "timestamp": "2023-08-29T15:49:18.529Z",
    "duration": 30.014,
    "data": { "status": "not-afk" }
  },
  {
    "id": 901517,
    "timestamp": "2023-08-29T14:32:49.530Z",
    "duration": 4255.686,
    "data": { "status": "not-afk" }
  },
  {
    "id": 901511,
    "timestamp": "2023-08-29T14:14:24.144Z",
    "duration": 60.004912,
    "data": { "status": "afk" }
  },
  {
    "id": 901512,
    "timestamp": "2023-08-29T14:14:24.143Z",
    "duration": 1105.386,
    "data": { "status": "afk" }
  },
  {
    "id": 900405,
    "timestamp": "2023-08-29T11:58:31.905Z",
    "duration": 8152.238,
    "data": { "status": "not-afk" }
  },
  {
    "id": 900397,
    "timestamp": "2023-08-29T11:13:05.428Z",
    "duration": 60.005447,
    "data": { "status": "afk" }
  },
  {
    "id": 900398,
    "timestamp": "2023-08-29T11:13:05.427Z",
    "duration": 2726.477,
    "data": { "status": "afk" }
  }
]

However, the official aw-watcher-afk has a similar behavior:

Expand JSON

[
  {
    "id": 713091,
    "timestamp": "2023-07-16T04:04:25.551Z",
    "duration": 192.519,
    "data": {
      "status": "afk"
    }
  },
  {
    "id": 713092,
    "timestamp": "2023-07-16T04:04:25.540Z",
    "duration": 25935.54,
    "data": {
      "status": "afk"
    }
  },
  {
    "id": 713089,
    "timestamp": "2023-07-16T04:03:38.032Z",
    "duration": 47.518,
    "data": {
      "status": "not-afk"
    }
  }
]

That's just my observation. I'm not sure if this will mess up with sorting and merging periods.