Call for documentation: how does the event model work?

[nikanar]

Alright, so I started playing around with aw-client, and reading this watcher's events.

import aw_client
ac = aw_client.ActivityWatchClient("_")
ac.connect()
afk_events = ac.get_events("aw-watcher-afk_ker", 10**6)
recent_events = afk_events[:50]
recent_events.reverse()
for e in recent_events:
    print(e["timestamp"], ",", e["data"]["status"])

returns

a big log

``` 2017-07-16 07:17:04.486000+00:00 , hibernating 2017-07-16 07:26:10.397000+00:00 , not-afk 2017-07-16 07:26:10.397000+00:00 , afk 2017-07-16 07:26:11.426000+00:00 , not-afk 2017-07-16 07:32:32.052000+00:00 , afk 2017-07-16 07:42:08.010000+00:00 , afk 2017-07-16 07:42:08.010000+00:00 , not-afk 2017-07-16 07:44:32.273000+00:00 , afk 2017-07-16 08:04:17.377000+00:00 , afk 2017-07-16 08:04:17.377000+00:00 , not-afk 2017-07-16 08:24:52.358000+00:00 , afk 2017-07-16 08:40:57.009000+00:00 , afk 2017-07-16 08:40:57.009000+00:00 , not-afk 2017-07-16 09:09:43.786000+00:00 , afk 2017-07-16 14:07:19.997000+00:00 , afk 2017-07-16 14:07:19.997000+00:00 , not-afk 2017-07-16 14:07:49.129000+00:00 , afk 2017-07-16 16:19:37.189000+00:00 , afk 2017-07-16 16:19:37.189000+00:00 , not-afk 2017-07-16 16:19:45.277000+00:00 , afk 2017-07-16 16:50:56.040000+00:00 , afk 2017-07-16 16:50:56.040000+00:00 , not-afk 2017-07-16 16:52:38.301000+00:00 , afk 2017-07-16 16:56:00.650000+00:00 , afk 2017-07-16 16:56:00.650000+00:00 , not-afk 2017-07-16 17:30:10.037000+00:00 , afk 2017-07-16 17:33:25.327000+00:00 , afk 2017-07-16 17:33:25.327000+00:00 , not-afk 2017-07-16 17:55:29.364000+00:00 , afk 2017-07-16 18:04:20.395000+00:00 , afk 2017-07-16 18:04:20.395000+00:00 , not-afk 2017-07-16 20:47:11.804000+00:00 , afk 2017-07-16 20:54:19.568000+00:00 , not-afk 2017-07-16 22:56:31.960000+00:00 , not-afk 2017-07-16 23:35:50.099000+00:00 , afk 2017-07-16 23:39:27.463000+00:00 , not-afk 2017-07-16 23:40:40.589000+00:00 , afk 2017-07-16 23:48:10.283000+00:00 , not-afk 2017-07-16 23:51:58.601000+00:00 , afk 2017-07-16 23:57:09.038000+00:00 , not-afk 2017-07-16 23:57:10.046000+00:00 , afk 2017-07-17 00:02:03.486000+00:00 , not-afk 2017-07-17 00:06:06.826000+00:00 , afk 2017-07-17 00:19:02.071000+00:00 , not-afk 2017-07-17 00:20:40.235000+00:00 , afk 2017-07-17 00:24:45.588000+00:00 , not-afk 2017-07-17 00:30:40.616000+00:00 , afk 2017-07-17 00:33:55.918000+00:00 , not-afk 2017-07-17 01:22:29.849000+00:00 , afk 2017-07-17 01:27:50.428000+00:00 , not-afk ```

What am I seeing here ?

What does it mean when there are two afk, or two not-afk (atk, at the keyboard ?) events one after the other ? What is the default state ?

How comes sometimes there are afk/not-afk events at the same time ? Is this the precise moment when I last pressed something ?

What does it mean when there's a not-afka long while after an afk event ? That this is the first activity since I went away a while ago ? That would make sense. But then, the reverse, an afk event a long while after the last not-afk event ? Was this the last keypress ? For how long do I have to not touch the machine to be considered afk ?

While I did dig a bit by myself and found config.timeout which gives some hints to people willing to read code, I think answering the questions above, here first and then probably in this repos' README, would be a good start for a documentation :)

[johan-bjareholt]

I modified your code slightly to print the duration as well, try this.

#!/usr/bin/env python3
import aw_client
ac = aw_client.ActivityWatchClient("_")
ac.connect()
bucket = "aw-watcher-afk_johan-laptop2"
events = ac.get_events(bucket, 50)
events.reverse()
for e in events:
    print(e["timestamp"], ",", e["duration"], ",", e["data"]["status"])

It's hard to understand the context if you do not print the duration of the events. This is how it looks for me.

Long log

``` 2017-07-11 19:13:53.079000+00:00 , 0:12:40.080000 , afk 2017-07-11 19:26:34.161000+00:00 , 0:00:00 , afk 2017-07-11 19:26:34.161000+00:00 , 0:00:03.039000 , not-afk 2017-07-11 19:26:37.200000+00:00 , 0:15:53.349000 , afk 2017-07-11 19:42:30.549000+00:00 , 0:11:51.299120 , hibernating 2017-07-11 19:54:22.913000+00:00 , 0:00:00 , afk 2017-07-11 19:54:22.913000+00:00 , 0:09:33.739000 , not-afk 2017-07-11 20:04:00.657000+00:00 , 16:13:49.770485 , hibernating 2017-07-12 12:18:03.503000+00:00 , 0:12:48.943000 , not-afk 2017-07-12 12:30:52.446000+00:00 , 0:16:26.395000 , afk 2017-07-12 12:47:19.843000+00:00 , 0:00:00 , afk 2017-07-12 12:47:19.843000+00:00 , 0:00:37.086000 , not-afk 2017-07-12 12:47:56.929000+00:00 , 0:04:38.411000 , afk 2017-07-12 12:52:36.342000+00:00 , 0:00:00 , afk 2017-07-12 12:52:36.342000+00:00 , 0:00:49.101000 , not-afk 2017-07-12 12:53:25.443000+00:00 , 0:03:51.330000 , afk 2017-07-12 12:57:17.775000+00:00 , 0:00:00 , afk 2017-07-12 12:57:17.775000+00:00 , 0:35:38.709000 , not-afk 2017-07-12 13:32:56.484000+00:00 , 0:03:43.311000 , afk 2017-07-12 13:36:40.797000+00:00 , 0:00:00 , afk 2017-07-12 13:36:40.797000+00:00 , 0:06:53.560000 , not-afk 2017-07-12 13:43:34.357000+00:00 , 0:03:42.314000 , afk 2017-07-12 13:47:17.672000+00:00 , 0:00:00 , afk 2017-07-12 13:47:17.672000+00:00 , 0:44:36.415000 , not-afk 2017-07-12 14:31:54.087000+00:00 , 0:07:25.529000 , afk 2017-07-12 14:39:20.618000+00:00 , 0:00:00 , afk 2017-07-12 14:39:20.618000+00:00 , 0:00:23.059000 , not-afk 2017-07-12 14:39:43.677000+00:00 , 0:03:48.251000 , afk 2017-07-12 14:43:32.929000+00:00 , 0:00:00 , afk 2017-07-12 14:43:32.929000+00:00 , 0:00:25.058000 , not-afk 2017-07-12 14:43:57.987000+00:00 , 2:54:02.027531 , hibernating 2017-07-12 17:40:44.256000+00:00 , 0:06:08.493000 , not-afk 2017-07-12 17:46:52.749000+00:00 , 0:09:14.808000 , afk 2017-07-12 17:56:08.558000+00:00 , 0:00:00 , afk 2017-07-12 17:56:08.558000+00:00 , 0:07:01.536000 , not-afk 2017-07-12 18:03:10.094000+00:00 , 0:03:05.236000 , afk 2017-07-12 18:06:16.331000+00:00 , 0:00:00 , afk 2017-07-12 18:06:16.331000+00:00 , 0:37:57.812000 , not-afk 2017-07-12 18:44:15.144000+00:00 , 0:50:56.425404 , hibernating 2017-07-12 19:35:12.603000+00:00 , 0:33:28.495000 , not-afk 2017-07-12 20:08:42.100000+00:00 , 11:34:11.354582 , hibernating 2017-07-13 07:42:55.508000+00:00 , 0:26:52.996000 , not-afk 2017-07-13 08:10:01.520000+00:00 , 0:23:22.251522 , hibernating 2017-07-13 08:33:24.801000+00:00 , 0:52:58.946000 , not-afk 2017-07-13 09:26:24.749000+00:00 , 0:00:33.763687 , hibernating 2017-07-13 09:26:59.546000+00:00 , 0:05:37.423000 , not-afk 2017-07-13 09:32:36.969000+00:00 , 3 days, 7:05:09.746631 , hibernating 2017-07-16 16:37:47.759000+00:00 , 1:33:11.145000 , not-afk 2017-07-16 18:11:01.907000+00:00 , 19:45:40.359956 , hibernating 2017-07-17 13:56:43.332000+00:00 , 0:54:32.106000 , not-afk ```

In my case, every time there's a not-afk and afk evenet at the same time it's due to aw-watcher-afk asumes that you are afk when the computer wakes from suspend or you start the watcher. It might not look clean and could be fixed, but since the visualization in aw-webui only filters by the not-afk events it doesn't break anything.

Regarding config.timeout, we rewrote the watchers and aw-server a few months ago to work as heartbeats, and if a heartbeat is missed by more than the timeout time it will create a new event instead of expanding the existing one.

[nikanar]

Aah, right, I entirely missed the duration property, and indeed, it clarifies the picture.

So if I understand correctly, afk events of duration 0:00:00 are glitches mostly, and once we remove them, leaving hibernation aside, only remain a series of alternating afk/not/afk/not events, where if e0 and e1 are consecutive events, we have e0.timestamp + e0.duration == e1.timestamp .
Then I don't need to understand the config, because this gives the whole picture.

If it is so, then 0-duration events look like a small issue to me, but I can move forward with that knowledge. Thanks :)

---

But I see in my log that there is one occurrence of two consecutive not-afk events, which there isn't in yours. Running it again, there's such a thing again :

2017-07-16 18:04:20.395000+00:00 , 2:42:51.409000 , not-afk
2017-07-16 20:47:11.804000+00:00 , 0:07:07.764000 , afk
2017-07-16 20:54:19.568000+00:00 , 1:08:34.161000 , not-afk
2017-07-16 22:56:31.960000+00:00 , 0:39:18.139000 , not-afk
2017-07-16 23:35:50.099000+00:00 , 0:03:37.364000 , afk
2017-07-16 23:39:27.463000+00:00 , 0:01:13.126000 , not-afk
2017-07-16 23:40:40.589000+00:00 , 0:07:29.694000 , afk
[... afk/not/afk/not, good.]

What happened between 20:54+1:08 = 22:02 and 22:56 ? That's probably 17-18h in my timezone, other logs say I was not-afk. AW crashed, probably, but wouldn't restarting the watcher introduce a 0-duration afk event ?

Going further down the log yields yet more ugly series of events :

Another log, with durations, for you to explain, please. It's possible that several aw-watcher processes were alive at the same time for a short while (I tend to avoid it, but it happens).

``` 2017-07-14 17:58:24.598000+00:00 , 0:27:26.646000 , not-afk 2017-07-14 18:25:51.244000+00:00 , 0:06:09.640000 , afk 2017-07-14 18:32:01.885000+00:00 , 0:00:00 , afk 2017-07-14 18:32:01.885000+00:00 , 0:37:54.936000 , not-afk 2017-07-14 19:14:29.761000+00:00 , 0:03:23.509000 , not-afk 2017-07-14 19:24:42.399000+00:00 , 0:06:01.657000 , not-afk 2017-07-14 19:30:44.056000+00:00 , 0:04:32.453000 , afk 2017-07-14 19:35:17.510000+00:00 , 0:00:00 , afk 2017-07-14 19:35:17.510000+00:00 , 0:05:41.033000 , not-afk 2017-07-14 19:48:40.904000+00:00 , 0:03:08.379000 , not-afk 2017-07-14 19:55:05.394000+00:00 , 0:01:45.662000 , not-afk 2017-07-14 20:08:51.753000+00:00 , 0:04:03.461000 , not-afk 2017-07-14 20:17:01.156000+00:00 , 0:03:17.564000 , not-afk 2017-07-14 20:36:01.193000+00:00 , 0:02:38.159000 , not-afk 2017-07-14 20:42:24.074000+00:00 , 0:00:12.104000 , not-afk 2017-07-14 21:28:39+00:00 , 0:00:45.166000 , not-afk 2017-07-14 21:35:52.674000+00:00 , 0:01:33.249000 , not-afk 2017-07-14 21:41:06.704000+00:00 , 0:00:08.088000 , not-afk 2017-07-14 21:47:58.883000+00:00 , 0:02:49.631000 , not-afk 2017-07-14 21:50:50.518000+00:00 , 0:06:32.060306 , hibernating 2017-07-14 21:57:23.655000+00:00 , 0:00:27.043000 , not-afk 2017-07-14 21:57:50.698000+00:00 , 0:01:27.185701 , hibernating 2017-07-14 21:59:18.939000+00:00 , 0:08:26.776000 , not-afk 2017-07-14 22:07:51.724000+00:00 , 4:29:12.043762 , hibernating 2017-07-15 02:37:04.792000+00:00 , 0:08:19.757000 , not-afk 2017-07-15 02:45:24.549000+00:00 , 0:03:19.337000 , afk 2017-07-15 02:48:44.888000+00:00 , 0:03:00.298331 , afk 2017-07-15 02:48:44.888000+00:00 , 0:00:00 , afk 2017-07-15 02:48:44.888000+00:00 , 0:00:00 , not-afk 2017-07-15 02:51:46.223000+00:00 , 3:34:49.910000 , afk 2017-07-15 06:26:37.135000+00:00 , 0:00:00 , afk 2017-07-15 06:26:37.135000+00:00 , 0:02:21.365000 , not-afk 2017-07-15 06:28:58.500000+00:00 , 3:06:29.947000 , afk 2017-07-15 09:35:29.448000+00:00 , 0:00:00 , afk 2017-07-15 09:35:29.448000+00:00 , 0:00:37.148000 , not-afk ```

[ErikBjare]

Alright. So here's what I think happened, please let me know if you think I'm wrong.

In the first case, it does indeed look like aw-watcher-afk crashed. The 0-duration AFK event is probably not always created (it shouldn't be created at all anyway).

I looked through the code of aw-watcher-afk and instantly found several things that could make things less bug prone and easier to read/analyse overall. The AFK watcher has been a source of problems in the past, reducing complexity there would definitely be worthwhile.

Regarding the second issue, I notice that the timestamp + duration do not add up to the next timestamp for many of the events. This causes me to believe the same thing has happened there: aw-watcher-afk crashed or was restarted. I can't rule out the possibility that it was a bug caused by multiple running watchers, but I find it unlikely given the mechanics of our heartbeat API.

For some of the events however, I have no explanation. I'd go through them in more detail if I wasn't writing this on my phone while on vacation. Heh.

That being said, I think it's worth getting to the bottom of the aw-watcher-afk issues you've brought to light here. I just need to not be on a hotel in Rome to do it :)

[nikanar]

Additional question is "what happens when logging is abruptly interrupted ?", like killall aw-qt. Up to when are the buckets correct ? The crash moment or the start of the last event ? Does something remain in an interupted state, and what happens to it when AW is restarted ?

[johan-bjareholt]

@nikanar We try to never assume anything in the watchers (such as if someone is afk now, we do not assume that they will be afk for 10 more seconds or something like that). And due to how heartbeats work, as soon as something crashes it stops logging so the data should always be correct. However, since the watchers only report to aw-server every X seconds, the last X seconds before a shutdown or crash will go unreported in aw-server (But since the reporting is 15s at max unless you change your config, we do not see this as an issue).

[ErikBjare]

@nikanar Can we close this?

If there is any specific documentation you feel would be useful, please give me a brief list and I'll see what I can do.

[nikanar]

What follows is made up of shots in the dark based on my expectations. Please review closely! (and move where it belongs)

---

Q : How to programmatically use this ActivityWatch thing ? A : Look in the aw-client repository.

Q : How to understand the data that is stored ? A : Get some events with

ac = aw_client.ActivityWatchClient("")
ac.connect()
events = ac.get_events(<bucket_name>)

Events from the aw-watcher-afk bucket have the fields ['timestamp'], ['duration'], and ['data']['status']. The status can be one of afk, not-afk, or hibernating. If e0 and e1 are consecutive events, you should expect e0['timestamp'] + e0['duration'] == e1['timestamp'] (within some milliseconds) and report issues when it is not the case. Actually this is only true for aw-watcher-afk, because aw-watcher-window doesn't record anything when afk or asleep.

In principle, afk and not-afk events alternate, but there are currently many edge cases where it doesn't happen.

Not two events should cover the same moment, but right now in some cases hibernating events overlap entirely with some afk events.

Q : How to determine bucket name ? A : <name of watcher> (one of aw-watcher-afk or aw-watcher-window) + _ + <name of your machine> (how to determine ? look in "activity" tab)

Q : What happens when AW is down or crashes ? A : Stored data up to the crash is not corrupted (up to few seconds before). When AW is restarted, it will first register a not-afk event. Several not-afk can come one after the other if AW is interrupted in between. No data will be stored when AW is off.

Q : What happens when my computer is off or asleep ? A : When asleep, aw-watcher-afk will record a "hibernating" event. aw-watcher-window will record nothing, i.e. some event's timestamp+duration will not match the following event's timestamp. When turned off, no data is logged. (is this true ? does the afk watcher record "hibernating" ? if not, why not ?)

Q : Some events have 0 duration. What does this mean ? A : It's a glitch (caused by 3 consecutive heartbeats having different data ?).

---

And I guess it should mostly go in the aw-client README, with some things being specific to watcher-afk or -window (like the 100% expected coverage of time and the "unknown"/None windows I didn't mention), maybe these can be repeated in their respective README/docs.

[ErikBjare]

@nikanar Thanks a lot!

I don't want information duplicated or spread out in a bunch of READMEs so I added that to the documentation (https://github.com/ActivityWatch/activitywatch/commit/c05dac061b50db46801e28dc2ad08f14a55a082e) and will link to it from the aw-client README.

I committed in your name and will make some further modifications myself.

Closing now.

[ErikBjare]

Oh, and you might find this funny @nikanar.