Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"poisoned lock: another task failed inside" #405

Open
EtaoinWu opened this issue Aug 29, 2023 · 6 comments
Open

"poisoned lock: another task failed inside" #405

EtaoinWu opened this issue Aug 29, 2023 · 6 comments

Comments

@EtaoinWu
Copy link

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
Copy link
Member

ErikBjare commented Aug 29, 2023

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
Copy link
Author

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
Copy link
Author

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
Copy link
Member

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
Copy link
Author

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
Copy link
Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants