Not all intervals are transferred at shutdown

[nspruit]

It seems like there is a bug in transferring the closed intervals to the server when WD is shut down. Any intervals that are still open are closed before shutting down WD and the remaining intervals are transferred to the server. However, not all of these intervals are actually tranferred.

For instance, see the following log:

Jan 13, 2016 2:52:17 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Starting up WatchDogLogger...
Jan 13, 2016 2:52:17 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Starting WatchDog ...
Jan 13, 2016 2:52:18 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEOpenInterval@87060c0 IDE_OPEN
Jan 13, 2016 2:52:18 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.UserActiveInterval@42eaa429 USER_ACTIVE
Jan 13, 2016 2:52:18 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.PerspectiveInterval@669bb57 PERSPECTIVE
Jan 13, 2016 2:52:18 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEActiveInterval@60ccf498 IDE_ACTIVE
Jan 13, 2016 2:52:29 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.DebugInterval@359d0007 DEBUG
Jan 13, 2016 2:52:30 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.ReadingInterval@137b9be1 READING
Jan 13, 2016 2:52:32 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.UserActiveInterval@42eaa429 USER_ACTIVE
Jan 13, 2016 2:52:32 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.ReadingInterval@137b9be1 READING
Jan 13, 2016 2:52:32 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEOpenInterval@87060c0 IDE_OPEN
Jan 13, 2016 2:52:33 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.PerspectiveInterval@669bb57 PERSPECTIVE
Jan 13, 2016 2:52:33 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEActiveInterval@60ccf498 IDE_ACTIVE
Jan 13, 2016 2:52:33 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.DebugInterval@359d0007 DEBUG
Jan 13, 2016 2:52:33 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Data length: 0.2412109375 kB
Jan 13, 2016 2:52:35 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Shutting down Plugin...

As you can see, 6 intervals are created and they are also closed before shutting down. However, only two intervals are received at the server that I run locally: IDE_OPEN and USER_ACTIVE. Therefore, the remaining four intervals seem to be lost.

P.S. Is this issues related to #122 @Inventitech?

[Inventitech]

Hm, very strange, this is new to me. Could you debug a bit into this, please?

[nspruit]

Sure, will do

[Inventitech]

👍

[nspruit]

I have some more info after debugging for a while. I've added some print statements, resulting in the following log:

Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=256m; support was removed in 8.0
Jan 13, 2016 4:41:10 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Starting up WatchDogLogger...
Jan 13, 2016 4:41:10 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Starting WatchDog ...
Jan 13, 2016 4:41:11 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEOpenInterval@1925be93 IDE_OPEN
Jan 13, 2016 4:41:11 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.UserActiveInterval@2ec3c213 USER_ACTIVE
Jan 13, 2016 4:41:11 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.PerspectiveInterval@b92cdf9 PERSPECTIVE
Jan 13, 2016 4:41:11 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEActiveInterval@464aff63 IDE_ACTIVE
Jan 13, 2016 4:41:15 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.DebugInterval@478dc028 DEBUG
Jan 13, 2016 4:41:16 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Created interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.ReadingInterval@74d2525f READING
Set before: 0
Set After: 1; Added?: true
Set before: 134
Set After: 135; Added?: true
Jan 13, 2016 4:41:19 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.UserActiveInterval@2ec3c213 USER_ACTIVE
Set before: 1
Set After: 1; Added?: false
Set before: 135
Set After: 135; Added?: false
Jan 13, 2016 4:41:19 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.ReadingInterval@74d2525f READING
Intervals to be closed: [nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEOpenInterval@1925be93, nl.tudelft.watchdog.core.logic.interval.intervaltypes.PerspectiveInterval@b92cdf9, nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEActiveInterval@464aff63, nl.tudelft.watchdog.core.logic.interval.intervaltypes.DebugInterval@478dc028]
Set before: 1
Set After: 2; Added?: true
Set before: 135
Set After: 136; Added?: true
Jan 13, 2016 4:41:19 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEOpenInterval@1925be93 IDE_OPEN
Set before: 2
Set After: 2; Added?: false
Set before: 136
Set After: 136; Added?: false
Jan 13, 2016 4:41:20 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.PerspectiveInterval@b92cdf9 PERSPECTIVE
Set before: 2
Set After: 2; Added?: false
Set before: 136
Set After: 136; Added?: false
Jan 13, 2016 4:41:20 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEActiveInterval@464aff63 IDE_ACTIVE
Set before: 2
Set After: 2; Added?: false
Set before: 136
Set After: 136; Added?: false
Jan 13, 2016 4:41:20 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: closed interval nl.tudelft.watchdog.core.logic.interval.intervaltypes.DebugInterval@478dc028 DEBUG
To transfer: [nl.tudelft.watchdog.core.logic.interval.intervaltypes.UserActiveInterval@2ec3c213, nl.tudelft.watchdog.core.logic.interval.intervaltypes.IDEOpenInterval@1925be93]
Jan 13, 2016 4:41:20 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Data length: 0.2412109375 kB
Jan 13, 2016 4:41:22 PM nl.tudelft.watchdog.core.util.WatchDogLogger logInfo
INFO: Shutting down Plugin...

So, as you can see, some intervals are not added to the set of intervals to persist. In particular, when shutting down, four intervals still need to be closed. However, only one of those intervals is actually added to the set of intervals to persist. Therefore, at the end only two intervals are transferred to the server and the other intervals are simply lost.

When an interval is not correctly added, the return value of set.add() is false. Therefore, it seems like this issue is caused by a defect in the equality checks of the intervals.

I'll look further into this bug tomorrow morning and try to fix it

[nspruit]

In addition, in the log shown above you can see that the bug does not only appear before shutting down. The ReadingInterval is also lost due to this bug, which is already closed before shutdown. This means that this seems to be a quite severe bug, as we are losing quite some data in this way.

[Inventitech]

Thanks a lot for the bug fix.