Activitywatch: AFK and window watcher suddenly stopped logging

[ErikBjare]

I have no idea what caused this, but they both stopped logging on the same day.

My last window event was at 2018-01-19T07:47:07.749000+00:00 (+7s duration) and my last AFK event was at 2018-01-19T17:23:51.631000+00:00 (+7min duration).

The logs for aw-watcher-afk show nothing weird (just a bunch of "Became AFK"/"No longer AFK" messages), but the aw-watcher-window looks a bit weird at least.

2018-01-17 16:09:10 [INFO ]: Running watcher with poll time 1.0 seconds  (aw_watcher_window.main:35)
2018-01-17 16:09:10 [INFO ]: aw-watcher-window has started  (aw_watcher_window.main:44)
2018-01-17 16:09:20 [INFO ]: Connection to aw-server established  (aw_client.client:281)
2018-01-17 16:09:20 [INFO ]: Loaded 11 failed requests from queuefile  (aw_client.client:266)
2018-01-20 17:48:22 [WARNING]: Failed to send request to aw-server, will queue requests until connection is available.  (aw_client.client:305)
2018-01-20 17:48:43 [INFO ]: Connection to aw-server established  (aw_client.client:281)
2018-01-20 17:48:43 [INFO ]: Loaded 55285 failed requests from queuefile  (aw_client.client:266)

I find it weird that all those failed requests were loaded from the queuefile yet the log doesn't say anything events not getting through to the server? Perhaps something that should have ended up in the log didn't? (Such as a thread crash)

The 2018-01-20 17:48 messages were around the time when I noticed and then restarted aw-server. I then shortly after restarted aw-watcher-window which probably lead to all the events being lost because they did not get sent after restart. Probably an issue in the failed request queue that needs fixing.

[ErikBjare]

Okay, this just happened again. Really annoying.

Since it happens to both aw-watcher-afk and aw-watcher-window around the same time (and not to aw-watcher-web) I'm assuming there's some problem in the aw-client code. It happens on the latest testing version as well (suspiciously around the same time), so it has not been fixed in the upcoming 0.8.

I restarted aw-server, and got a similar message about the \

This time I had the console open for aw-qt --testing (latest commit) but there is no stacktrace or other indication that anything has gone wrong in aw-client.

[johan-bjareholt]

By looking at the RequestQueue in aw-client I can easily see a couple of possible race conditions, we should probably take a look at the implementation again.

[ErikBjare]

Aaaand it happened again... Have you experienced something similar @johan-bjareholt? It has only happened on my new laptop...

[johan-bjareholt]

I have never experienced this no, odd...

[ErikBjare]

Seems to only happen soon after waking the laptop after a longer duration of sleep. Been digging a bit in aw-client but I must admit I'm not quite sure what could cause this...

Which race conditions did you think about?

Edit: A related issue with aw-client is that the queue doesn't seem to get saved, which really makes this bug much more troublesome.

[ErikBjare]

Downgraded priority since this has only happened to me on one machine and I'm unable to reliably replicate.

[ErikBjare]

Okay, I just discovered a very peculiar behavior here. Looks like events actually keep getting updated, it just happens extremely slowly. (1s added to the latest window event in the database every ~15 seconds)

[johan-bjareholt]

Maybe something similar to when the events in windows were very far behind (sometimes hours)? Or was that fixed? Just a guess.

[ErikBjare]

Yeah, could be related to #94

[ErikBjare]

lol, this just keeps getting weirder. Had the same issue today while in school (about an hour delay for window events) but didn't remember to restart ActivityWatch. Put my computer back to hybrid-suspend (as always), resumed at home ~1h later and to my surprise aw-server had >80% CPU utilization. Suddenly all the events started coming in at incredible speeds. It has almost caught up now.

What the fuck is going on...

Anyway, started writing proper tests for the RequestQueue (which is the likely culprit) in https://github.com/ActivityWatch/aw-client/pull/28/commits/c70aabca44c6043a7b4190ac22b333f7c51ec525 (PR: https://github.com/ActivityWatch/aw-client/pull/28).

[ErikBjare]

Been running master + the persist-queue PR for aw-client for a while now and the issue persists. However, with the persist-queue PR I can now at least manually restart the watchers (causing the queue to empty at a good pace) without losing any data, so that's nice.

[ErikBjare]

I haven't noticed this in a long while, and I'm the only one that have ever experienced this, so I'm closing.