Warning: gap of negative duration

[MatthewScholefield]

Not sure what this means, but it floods the logs when running aw-server:

2018-09-23 23:37:59 [WARNING]: Gap was of negative duration (-6.016s). This error will only show once per batch.  (aw_transform.flood:28)
2018-09-23 23:38:25 [WARNING]: Gap was of negative duration (-6.016s). This error will only show once per batch.  (aw_transform.flood:28)
2018-09-23 23:38:54 [WARNING]: Gap was of negative duration (-6.016s). This error will only show once per batch.  (aw_transform.flood:28)

[johan-bjareholt]

@ErikBjare I have seen this lots of times aswell (on almost all query requests).
Do you have any idea why it is occuring, is there some specific watcher which creates events which intersects that you know of?

[ErikBjare]

@johan-bjareholt This occurs when events overlap. We would have to investigate which watcher is causing it.

[jasonszang]

Also encountering this issue.
And it seems that when this warning is flooding the log the statistics also becomes incorrect. It looks like that the server failed to process events. All statistics stopped to grow.
I'm using AW on windows with v0.8.0b6 binary release and Firefox watcher plugin.

[notslang]

I'm getting the same type of messages:

WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-2224.419s). This message will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration but could be safely merged (-2224.419s). This message will only show once per batch.  (aw_transform.flood:45)
WARNING:aw_transform.flood:Gap was of negative duration and could NOT be safely merged (-535.887s). This warning will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration and could NOT be safely merged (-535.887s). This warning will only show once per batch.  (aw_transform.flood:49)
WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-425.637s). This message will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration but could be safely merged (-425.637s). This message will only show once per batch.  (aw_transform.flood:45)
WARNING:aw_transform.flood:Gap was of negative duration and could NOT be safely merged (-1252.44s). This warning will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration and could NOT be safely merged (-1252.44s). This warning will only show once per batch.  (aw_transform.flood:49)
WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-5295.763s). This message will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration but could be safely merged (-5295.763s). This message will only show once per batch.  (aw_transform.flood:45)
WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-34205.837s). This message will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration but could be safely merged (-34205.837s). This message will only show once per batch.  (aw_transform.flood:45)
WARNING:aw_transform.flood:Gap was of negative duration and could NOT be safely merged (-550.956s). This warning will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration and could NOT be safely merged (-550.956s). This warning will only show once per batch.  (aw_transform.flood:49)
WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-290.371s). This message will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration but could be safely merged (-290.371s). This message will only show once per batch.  (aw_transform.flood:45)
WARNING:aw_transform.flood:Gap was of negative duration and could NOT be safely merged (-315.507s). This warning will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration and could NOT be safely merged (-315.507s). This warning will only show once per batch.  (aw_transform.flood:49)
WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-165.214s). This message will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration but could be safely merged (-165.214s). This message will only show once per batch.  (aw_transform.flood:45)
WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-717.051s). This message will only show once per batch.
2019-07-27 14:29:00 [WARNING]: Gap was of negative duration but could be safely merged (-717.051s). This message will only show once per batch.  (aw_transform.flood:45)
WARNING:aw_transform.flood:Gap was of negative duration but could be safely merged (-717.051s). This message will only show once per batch.
2019-07-27 14:29:02 [WARNING]: Gap was of negative duration but could be safely merged (-717.051s). This message will only show once per batch.  (aw_transform.flood:45)

It would be really nice if it told me which watcher these events were coming from.

[wasinix]

I can reproduce this error, when I try to change the default "Categorization" rules.

As soon I change something there and save it, I get error 400 in the activity tab of the dashboard and find the "Gap was of negative duration" errors in the server log.
It is enough changing the existing category Work from RegEx to "No Rule".

When changing categorization rules back to default, the error is gone.

Version used: 0.8.3. @ Windows 10

[ErikBjare]

@wasinix The error you get is unrelated to the warning that this issue is about.

For your error, a fix has been merged and it will be working in the next release: #313

[the-architech]

I am also getting these errors. My best guess is that the watchers cache the events while either the server is offline, or if the watchers were stopped then started, and the events they are trying to publish to the server are not matching the time stamp of the server. Which may explain the negative time

The warning messages go longer based on how long the server has not received communication from watchers or the watchers have not communicated with the server. I am not sure how the time is kept on the server and how the watchers track time but it is likely due to the mismatch of timing.

[johan-bjareholt]

My best guess is that the watchers cache the events while either the server is offline, or if the watchers were stopped then started, and the events they are trying to publish to the server are not matching the time stamp of the server. Which may explain the negative time

A good hypothesis, but it's not possible as event timestamps are saved before they are potentially queued up to be sent to the server so that cannot be the issue. The servers clock is always irrelevant.

It would be pretty easy to find which bucket makes this issue is we just do a query with a flood transform to each one of them, I might try this later.

[stale]

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.

[stale]

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.

[ErikBjare]

Someone mentioned this in the Discord today:

Looks like the issue might be in aw-watcher-afk.

[JoseEchave]

Someone mentioned this in the Discord today:

Looks like the issue might be in aw-watcher-afk.

Hi I have removed the duplicated, and then compared the data frames of the events, the duplicated events were mainly from the aw-watcher-afk watcher

And out of those the majority are afk events

Also, those duplications happened more in my work computer where I use VPN (not sure if that might be the reason though)

I hope this helps you somehow with the debugging

Thanks team for the wonderful tool you have created!

[MAX10541]

I have the same issue. However, I think I know exactly what caused it in my case (probably very different from the others):

I had to test the behavior of some app when the system date changes, so I was manually changing my system's date and time going back and forth into the future and the past.
AW was running all the time while I was doing that. I can confirm that the effected time range in AW that causes this issue is exactly the time I was playing with the system date.

Not sure if this is helpful to you or not though 😅 .

[daobrien]

What's the latest with this? It's been open for nearly 6 years and I still get these messages.

2024-05-30 13:48:54 [INFO ]: Received heartbeat after pulse window, inserting as new event. (bucket: aw-watcher-afk_galaxy.milky.way)  (aw_server.api:279)
2024-05-30 13:48:59 [WARNING]: Gap was of negative duration but could be safely merged (-336.987s). This message will only show once per batch.  (aw_transform.flood:46)
2024-05-30 13:48:59 [WARNING]: Gap was of negative duration but could be safely merged (-504.166s). This message will only show once per batch.  (aw_transform.flood:46)
2024-05-30 13:48:59 [WARNING]: Gap was of negative duration but could be safely merged (-1201.106s). This message will only show once per batch.  (aw_transform.flood:46)

and many more besides.
thanks