Negative time on Activity view

[ErikBjare]

I've never seen this before:

Running aw-server-rust (master branch). Tried toggling off AFK filtering and audible-as-active, but no difference.

Don't have time to investigate, but thought I'd at least report it.

[kewde]

@ErikBjare

I've investigated this issue, it's because of the flood function. https://github.com/ActivityWatch/aw-server-rust/blob/b5c722f63d095c92f123c72e2d7fe66c942859f9/aw-transform/src/flood.rs#L32

The duration get an insane negative value because the gap is negative, which when added results to the duration turns the duration negative. I'm very certain of this because my logs are stuffed with the following:

[2021-11-15 11:05:05][[33mWARN[0m][aw_transform::flood]: Gap was of negative duration (-PT1330.318Ss) and could NOT be safely merged. This error will only show once per batch.
[2021-11-15 11:05:05][[33mWARN[0m][aw_transform::flood]: Gap was of negative duration (-PT2269.698Ss), but could be safely merged. This error will only show once per batch.
[2021-11-15 11:05:05][[33mWARN[0m][aw_transform::flood]: Gap was of negative duration (-PT3600Ss) and could NOT be safely merged. This error will only show once per batch.

This is also breaking the UI overview as follows:

This might be related to #239, could it be duplicate events that cause this?

[kewde]

@ErikBjare

I can also confirm that there are many duplicate rows within the afkwatcher bucket:

select distinct starttime, endtime, data from events WHERE bucketrow = 1
Result: 1516 rows returned in 8ms

There are 1516 unique rows within the events table for the afkwatcher.

If looking for just non-distinct rows:

select starttime, endtime, data from events WHERE bucketrow = 1
Result: 1686 rows returned in 4ms

But removing the duplicaties did not seem to resolve the issue.

[kewde]

Hi @ErikBjare

I can verify that it's the afk watcher, I suspect it might be fixed with the 1ms addition. https://github.com/ActivityWatch/aw-watcher-afk/commit/7ce0d6b389ed87acdf7ad0876b9372c769b63f66

I see quite a a lot of duplicate AFK events that are overlapping, even with non-afk events.

[ErikBjare]

@kewde Thanks for the thorough research! (good point with the SQL queries)

I don't think duplicate events can cause this per se, but they might be a symptom of the underlying problem (heartbeats not being applied correctly, or out of order). All occurrences of the "Gap was of negative duration" warning are really caused by a bug somewhere, but they are mostly harmless, so we haven't historically had the motivation to go after them (in hindsight, this may have been an oversight).

I was just discussing something somewhat related in https://github.com/ActivityWatch/activitywatch/issues/626#issuecomment-969209885

[kewde]

@ErikBjare

You're right, it's the unsafe merges for overlapping events, not the duplicate events that make it display this behavior. I have no idea what the root cause is but FWIW here's how the issue comes to show:

For example for some odd reason there is an AFK event that is 13 hours longs but it overlaps with the real events.

A very large negative gap is created because the start of e2 is BEFORE the end of e1 by 13 hours.

let gap = e2.timestamp - e1.calculate_endtime();

https://github.com/ActivityWatch/aw-server-rust/blob/b5c722f63d095c92f123c72e2d7fe66c942859f9/aw-transform/src/flood.rs#L43

This next line assumes that gap is a positive number, or in other words it assumes there is space between two events. But this logic doesn't apply for overlapping events with negative values because it will always be true.

if gap < pulsetime {

https://github.com/ActivityWatch/aw-server-rust/blob/b5c722f63d095c92f123c72e2d7fe66c942859f9/aw-transform/src/flood.rs#L45

This just pops the cherry and causes the insane negative durations.

e1.duration = e1.duration + (gap / 2);

https://github.com/ActivityWatch/aw-server-rust/blob/b5c722f63d095c92f123c72e2d7fe66c942859f9/aw-transform/src/flood.rs#L75

[ErikBjare]

Just occurred again:

Should really look into what you wrote @kewde. Perhaps you can help @johan-bjareholt?

[ZennfI]

Problem is still occurring. aw-server-rust seems to have a bad time when it tries to merge afk events. The only fix I have found is to manually clean the sqlite db (delete duplicates, merge events), which is fastidious. I don't know if it is really linked to the rust server version or with the afk watcher. But, I am thinking of switching back to the python server because I never had this problem with it (though the web dashboard is really slow).

[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.