More time reported than actual usage

[ErikBjare]

• [x] I am on the latest ActivityWatch version.

• [x] I have searched the issues of this repo and believe that this is not a duplicate.

• OS name and version: Arch Linux

• ActivityWatch version: v0.11.0 (rust) and master (aw-server-python)

Describe the bug

Incorrect time reported by aw-server (long stretch of AFK time was incorrectly included).

I exported the buckets and imported into aw-server-rust, which reported the correct time.

I'm assuming this is originally an issue with negative gaps arising from the heartbeat, the resulting events of which are not handled correctly in aw-server-python during flooding.

To Reproduce

Not yet sure how to reproduce.

Expected behavior

Time would be correctly reported.

Documentation

Note how aw-server-python spams a lot more than aw-server-rust.

aw-server-python logs from a standard Activity query:

2021-07-01 14:09:23 [WARNING]: Gap was negative but could be safely merged (-13697.784s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:23 [WARNING]: Gap was negative and could NOT be safely merged (-3299.374s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:23 [WARNING]: Gap was negative and could NOT be safely merged (-17430.965s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:23 [WARNING]: Gap was negative and could NOT be safely merged (-17434.787s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:23 [WARNING]: Gap was negative but could be safely merged (-90.99s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-15404.006s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-10525.176769s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-17700.514s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-185.146656s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-22499.96s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-46264.473s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-43804.859s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-225.186657s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-9531.942s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-185.137312s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-15422.322s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-3327.664003s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-11550.794s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-10684.987s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-18918.895s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-185.136619s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-23840.324s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative but could be safely merged (-811.350929s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-45969.923s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-27116.948s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-18499.34s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:24 [WARNING]: Gap was negative and could NOT be safely merged (-17430.965s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:26 [WARNING]: Gap was negative but could be safely merged (-3310.693s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:26 [WARNING]: Gap was negative but could be safely merged (-456.917s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:27 [WARNING]: Gap was negative but could be safely merged (-119.197s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:27 [WARNING]: Gap was negative and could NOT be safely merged (-111.03s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:27 [WARNING]: Gap was negative and could NOT be safely merged (-53.098s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:28 [WARNING]: Gap was negative and could NOT be safely merged (-106.023s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:28 [WARNING]: Gap was negative and could NOT be safely merged (-3014.439s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:28 [WARNING]: Gap was negative and could NOT be safely merged (-60.729s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:29 [WARNING]: Gap was negative and could NOT be safely merged (-62.047s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:29 [WARNING]: Gap was negative and could NOT be safely merged (-11.861s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:29 [WARNING]: Gap was negative and could NOT be safely merged (-3428.054s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:29 [WARNING]: Gap was negative and could NOT be safely merged (-12.883s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:30 [WARNING]: Gap was negative and could NOT be safely merged (-18.88s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:30 [WARNING]: Gap was negative and could NOT be safely merged (-16.828s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:30 [WARNING]: Gap was negative and could NOT be safely merged (-33.148s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:30 [WARNING]: Gap was negative and could NOT be safely merged (-32.249s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:30 [WARNING]: Gap was negative but could be safely merged (-90.99s). Will only warn once per batch.  (aw_transform.flood:116)
2021-07-01 14:09:31 [WARNING]: Gap was negative and could NOT be safely merged (-2.169s). Will only warn once per batch.  (aw_transform.flood:126)
2021-07-01 14:09:31 [WARNING]: Gap was negative and could NOT be safely merged (-3.65s). Will only warn once per batch.  (aw_transform.flood:126)

aw-server-rust logs from a standard Activity query:

[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT0.029Ss) and could NOT be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT17700.514Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT5750.916Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT0.093Ss) and could NOT be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT0.001Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT6150.373Ss) and could NOT be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT1954.677Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT0.001Ss) and could NOT be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT0.001Ss) and could NOT be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT3919.230Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT865.807Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT15761.708Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT10363.291Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT0.001Ss) and could NOT be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT1874.841Ss), but could be safely merged. This error will only show once per batch.
[2021-07-01 14:05:37][WARN][aw_transform::flood]: Gap was of negative duration (-PT0.001Ss) and could NOT be safely merged. This error will only show once per batch.

Screenshots

aw-server-python, with bad data:

aw-server-python, with bad data and no AFK filtering:

aw-server-rust, with bad data (imported from aw-server-python):

I also tried importing data from testing buckets into the prod instance (after renaming the buckets their hostnames), but did not find any issue there.

Additional context

Something similar has probably been reported before, I'm noting this instance in particular as I have data for it.

[bschwehn]

Hi,

I also sometimes get active times reported that are unrealistic.

I looked into the sql lite db today below are the entries for today. The not-afk times look good, but there are weird clusters of afk entries that don't seem right. For example there are 14 entries around 09:24:27, even more around 09:47:35.

Now I don't know what the normal storage for this data is supposed to look like, but this looks strange. Also some completely duplicate entries like at 09:47:35.425000+00:00

Server Logs has similar entries as in your description and also entries like

2021-09-13 04:52:42 [INFO ]: Received heartbeat after pulse window, inserting as new event. (bucket: aw-watcher-afk_PCNAME) (aw_server.api:264)

This is on windows v0.11.0, using aw-server. I have now switched to aw-server-rust and will watch if this makes a difference.

sqlite> select * from eventmodel where bucket_id = 2 and timestamp > date('now', 'start of day');
895870|2|2021-09-13 08:01:08.668000+00:00|5000.343|{"status": "not-afk"}
896346|2|2021-09-13 09:24:26.963000+00:00|250.718|{"status": "afk"}
896347|2|2021-09-13 09:24:27.226000+00:00|185.719|{"status": "afk"}
896348|2|2021-09-13 09:24:27.214000+00:00|190.719|{"status": "afk"}
896349|2|2021-09-13 09:24:27.192000+00:00|195.734|{"status": "afk"}
896350|2|2021-09-13 09:24:27.163000+00:00|200.75|{"status": "afk"}
896351|2|2021-09-13 09:24:27.148000+00:00|205.75|{"status": "afk"}
896352|2|2021-09-13 09:24:27.128000+00:00|210.75|{"status": "afk"}
896353|2|2021-09-13 09:24:27.104000+00:00|215.766|{"status": "afk"}
896354|2|2021-09-13 09:24:27.072000+00:00|220.781|{"status": "afk"}
896355|2|2021-09-13 09:24:27.057000+00:00|225.781|{"status": "afk"}
896356|2|2021-09-13 09:24:27.030000+00:00|230.797|{"status": "afk"}
896357|2|2021-09-13 09:24:27.007000+00:00|235.813|{"status": "afk"}
896358|2|2021-09-13 09:24:26.989000+00:00|240.813|{"status": "afk"}
896359|2|2021-09-13 09:24:26.963000+00:00|250.718|{"status": "afk"}
896360|2|2021-09-13 09:28:37.681000+00:00|1138.276|{"status": "not-afk"}
896475|2|2021-09-13 09:47:35.442000+00:00|583.442|{"status": "afk"}
896476|2|2021-09-13 09:47:35.469000+00:00|518.193|{"status": "afk"}
896477|2|2021-09-13 09:47:35.442000+00:00|573.431|{"status": "afk"}
896478|2|2021-09-13 09:47:35.425000+00:00|643.571|{"status": "afk"}
896479|2|2021-09-13 09:47:35.502000+00:00|458.038|{"status": "afk"}
896480|2|2021-09-13 09:47:35.490000+00:00|478.103|{"status": "afk"}
896481|2|2021-09-13 09:47:35.490000+00:00|478.103|{"status": "afk"}
896482|2|2021-09-13 09:47:35.469000+00:00|518.193|{"status": "afk"}
896483|2|2021-09-13 09:47:35.469000+00:00|523.203|{"status": "afk"}
896484|2|2021-09-13 09:47:35.436000+00:00|593.462|{"status": "afk"}
896485|2|2021-09-13 09:47:35.435000+00:00|603.473|{"status": "afk"}
896486|2|2021-09-13 09:47:35.521000+00:00|422.961|{"status": "afk"}
896487|2|2021-09-13 09:47:35.516000+00:00|432.977|{"status": "afk"}
896488|2|2021-09-13 09:47:35.502000+00:00|458.038|{"status": "afk"}
896489|2|2021-09-13 09:47:35.482000+00:00|498.157|{"status": "afk"}
896490|2|2021-09-13 09:47:35.482000+00:00|503.172|{"status": "afk"}
896491|2|2021-09-13 09:47:35.482000+00:00|503.172|{"status": "afk"}
896492|2|2021-09-13 09:47:35.455000+00:00|533.22|{"status": "afk"}
896493|2|2021-09-13 09:47:35.452000+00:00|548.239|{"status": "afk"}
896494|2|2021-09-13 09:47:35.452000+00:00|548.239|{"status": "afk"}
896495|2|2021-09-13 09:47:35.446000+00:00|558.258|{"status": "afk"}
896496|2|2021-09-13 09:47:35.442000+00:00|573.431|{"status": "afk"}
896497|2|2021-09-13 09:47:35.442000+00:00|583.442|{"status": "afk"}
896498|2|2021-09-13 09:47:35.435000+00:00|613.491|{"status": "afk"}
896499|2|2021-09-13 09:47:35.435000+00:00|613.491|{"status": "afk"}
896500|2|2021-09-13 09:47:35.435000+00:00|618.505|{"status": "afk"}
896501|2|2021-09-13 09:47:35.428000+00:00|633.549|{"status": "afk"}
896502|2|2021-09-13 09:47:35.425000+00:00|653.597|{"status": "afk"}
896503|2|2021-09-13 09:47:35.425000+00:00|653.597|{"status": "afk"}
896504|2|2021-09-13 09:47:35.425000+00:00|663.597|{"status": "afk"}
896505|2|2021-09-13 09:47:35.425000+00:00|663.597|{"status": "afk"}
896506|2|2021-09-13 09:47:35.521000+00:00|422.961|{"status": "afk"}
896507|2|2021-09-13 09:47:35.516000+00:00|432.977|{"status": "afk"}
896508|2|2021-09-13 09:47:35.510000+00:00|437.985|{"status": "afk"}
896509|2|2021-09-13 09:47:35.508000+00:00|443|{"status": "afk"}
896510|2|2021-09-13 09:47:35.502000+00:00|453.022|{"status": "afk"}
896511|2|2021-09-13 09:47:35.492000+00:00|463.063|{"status": "afk"}
896512|2|2021-09-13 09:47:35.490000+00:00|473.094|{"status": "afk"}
896513|2|2021-09-13 09:47:35.484000+00:00|483.11|{"status": "afk"}
896514|2|2021-09-13 09:47:35.482000+00:00|493.141|{"status": "afk"}
896515|2|2021-09-13 09:47:35.469000+00:00|513.192|{"status": "afk"}
896516|2|2021-09-13 09:47:35.455000+00:00|533.22|{"status": "afk"}
896517|2|2021-09-13 09:47:35.452000+00:00|543.239|{"status": "afk"}
896518|2|2021-09-13 09:47:35.446000+00:00|558.258|{"status": "afk"}
896519|2|2021-09-13 09:47:35.442000+00:00|568.271|{"status": "afk"}
896520|2|2021-09-13 09:47:35.436000+00:00|593.462|{"status": "afk"}
896521|2|2021-09-13 09:47:35.435000+00:00|603.473|{"status": "afk"}
896523|2|2021-09-13 09:47:35.429000+00:00|623.516|{"status": "afk"}
896524|2|2021-09-13 09:47:35.428000+00:00|633.549|{"status": "afk"}
896525|2|2021-09-13 09:47:35.425000+00:00|643.571|{"status": "afk"}
896526|2|2021-09-13 09:58:39.022000+00:00|3419.215|{"status": "not-afk"}
896902|2|2021-09-13 10:55:38.222000+00:00|1542.809|{"status": "afk"}
896903|2|2021-09-13 10:55:38.222000+00:00|784.086|{"status": "afk"}
896904|2|2021-09-13 10:55:38.222000+00:00|779.077|{"status": "afk"}
896905|2|2021-09-13 11:21:21.019000+00:00|496.194|{"status": "afk"}
896906|2|2021-09-13 11:21:21.019000+00:00|394.139|{"status": "afk"}
896907|2|2021-09-13 11:21:21.019000+00:00|404.15|{"status": "afk"}
896908|2|2021-09-13 11:21:21.019000+00:00|409.156|{"status": "afk"}
896909|2|2021-09-13 11:21:21.019000+00:00|409.156|{"status": "afk"}
896910|2|2021-09-13 11:21:21.019000+00:00|414.167|{"status": "afk"}
896911|2|2021-09-13 11:21:21.019000+00:00|424.185|{"status": "afk"}
896912|2|2021-09-13 11:21:21.019000+00:00|384.125|{"status": "afk"}
896913|2|2021-09-13 11:21:21.019000+00:00|424.185|{"status": "afk"}
896914|2|2021-09-13 11:21:21.019000+00:00|384.125|{"status": "afk"}
896916|2|2021-09-13 11:29:37.210000+00:00|5123.654|{"status": "not-afk"}
896917|2|2021-09-13 11:29:37.210000+00:00|27.28|{"status": "not-afk"}
897213|2|2021-09-13 12:55:00.850000+00:00|194.491|{"status": "afk"}
897214|2|2021-09-13 12:58:15.341000+00:00|7580.666|{"status": "not-afk"}
897886|2|2021-09-13 15:04:35.991000+00:00|2398.407|{"status": "afk"}
897887|2|2021-09-13 15:04:35.991000+00:00|295.74|{"status": "afk"}
897888|2|2021-09-13 15:04:35.991000+00:00|300.758|{"status": "afk"}
897889|2|2021-09-13 15:04:35.991000+00:00|305.763|{"status": "afk"}
897890|2|2021-09-13 15:04:35.991000+00:00|305.763|{"status": "afk"}
897891|2|2021-09-13 15:04:35.991000+00:00|315.777|{"status": "afk"}
897892|2|2021-09-13 15:04:35.991000+00:00|315.777|{"status": "afk"}
897893|2|2021-09-13 15:04:35.991000+00:00|285.716|{"status": "afk"}
897895|2|2021-09-13 15:44:34.385000+00:00|2898.714|{"status": "not-afk"}
897896|2|2021-09-13 15:44:34.385000+00:00|91.997|{"status": "not-afk"}
897900|2|2021-09-13 15:44:34.385000+00:00|147.249|{"status": "not-afk"}
897901|2|2021-09-13 15:44:34.385000+00:00|162.168|{"status": "not-afk"}
897902|2|2021-09-13 15:44:34.385000+00:00|177.131|{"status": "not-afk"}
897903|2|2021-09-13 15:44:34.385000+00:00|56.978|{"status": "not-afk"}
898136|2|2021-09-13 16:32:53.085000+00:00|238.866|{"status": "afk"}
898139|2|2021-09-13 16:36:51.951000+00:00|736.243|{"status": "not-afk"}

[johan-bjareholt]

Seems wrong to merge https://github.com/ActivityWatch/aw-watcher-afk/pull/51 in the watcher if the error seems to be in the server IMO. Let's hope that https://github.com/ActivityWatch/aw-core/pull/105 fixed it so we can revert the watcher change.

[ErikBjare]

@johan-bjareholt I think https://github.com/ActivityWatch/aw-watcher-afk/pull/51 addresses a different problem than the one observed in this issue, which https://github.com/ActivityWatch/aw-core/pull/105 does not fix.

~~The issue (as I currently understand it) that the watcher PR addresses arises when two events have the exact same endtime. When this is the case, the "last event" is undefined, since they both look just as recent.~~ Edit: Looks like both implementations sort by starttime, which is definitely different, but still similar. For example, if two events somehow have the same starttime, this undefined "last event" bug would still be present. I wrote the below before I realized this, so not sure how much sense it still makes.

What may then happen is that the first event (the one which stretches into the past) gets picked up as the most recent event (and not the zero-duration one that was actually most recent). If the event data differs from the first event, the heartbeat algorithm then decides "this event is different", and happily inserts a new event instead of merging with the previous.

In a worse case, the incoming heartbeat might have the same data as the first event (but different from the second), and if the server then picks up the first event as the most recent, then it will merge those (if pulsetime permits) and there'll be a lone event stuck within a larger event (which will lead to "Gap was of negative duration" warnings).

This undefined "last event" issue should be present in both aw-server-python and aw-server-rust. However, I think it might occur far less often with aw-server-rust: since it caches the most recent heartbeat, most of the time no lookup is needed. It could still fail spectacularly though (since events might get queued by the watcher, and not sent until the server restarts, at which point the cache is cold).

We certainly need better tests for catching bugs that lead to overlapping events like this, especially during collection. Basically all occurrences of "Gap was of negative duration" should be considered bugs, and it's still unclear to me if the bug is in the server or the watcher (wild guess: perhaps something weird with the queue?).

There might be more things at play here, but https://github.com/ActivityWatch/aw-watcher-afk/pull/51 significantly reduces the things that can go wrong (making this easier to debug in the future), at practically no cost. You could argue it's just sweeping the problem under the rug (which it kinda is) but it was a very pragmatic PR that quickly solved that particular aspect of the problem, making it easier to look into the others (like https://github.com/ActivityWatch/activitywatch/issues/602, which affects aw-server-rust as well).

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[brayo-pip]

I am getting a related issue on my windows pc, the time tracker reports way less time than I spent active in a day. I have no idea what could be causing it. I'm on the latest version.