BEAST alarms w/ incorrect timestamp

[mdavidsaver]

We have seen several instances of alarms appearing in the Alarm Table view with incorrect time stamps and were finally able to capture and document one. Screen shots to follow.

The PV in question was being archived, so we know that the alarm which occurred at "2014/01/24 15:04:25" was the only alarm between 17:44 on the 23rd and 24th. I also know that this time is correct (I caused the alarm). However, the Alarm Table shows an Alarm Time of "2014/01/24 08:55:24".

[mdavidsaver]

Alarm table showing alarm at "2014/01/24 08:55:24".

Data browser plot showing disconnect at "2014/01/24 15:04:25.259534615".

[mdavidsaver]

This is seen with several versions of the alarm client (css-nsls2 3.1.6 and 3.2.13a).

[mdavidsaver]

converting to POSIX time "2014/01/24 08:55:24" and "2014/01/24 15:04:25" are 1390571724.0 and 1390593865.0. The difference is 22141.0 (6.15 hours), while our timezone offset is 18000 (5 hours). I've also checked and the system clock on the machine running the alarm server is correctly synced.

[kasemir]

Do you have alarm logging (jms2rdb) set up to see the history of the alarm system state changes? That should show when the original alarm was received, and what happened to it then, maybe causing updates of the alarm state.
Was the compete alarm configuration reloaded during this time, since others at BNL were debugging JMS issues?

[mdavidsaver]

Do you have alarm logging (jms2rdb) set up to see the history of the alarm system state changes?

No. We've never had this set up.

Was the compete alarm configuration reloaded during this time, since others at BNL were debugging JMS issues?

I do not believe it was.

[mdavidsaver]

Is it possible that this issue is being caused by improper handling of timestamps on CA disconnect events?

We've just had another instance of this issue with a number of PVs which became momentarily disconnected. Some analog and some binary.

By chance I notice that the erroneous alarm time matches with the previous up with the timestamp reported by the channel archiver for the sample before the disconnect of most of the binary PVs. All of these PVs had an update at about the same time due to a network disruption about 4 hours earlier. Here is one example

BR:A3-VA{CCG:2}Sts:Rly1PLC-Sts
2014-03-25 10:16:16.226827 Relay On
2014-03-25 10:16:16.551952 Relay On
2014-03-25 14:53:28.793302 Relay On INVALID READ
2014-03-25 14:55:21.904817 Relay On
2014-03-25 18:29:54.223340 Relay Off Disconnected
2014-03-25 18:34:35.035431 Relay On

The analog PVs have all updated many times since then, so can't be explained by simple re-use of the most recent timestamp...

[mdavidsaver]

The alarms occurred at ~18:30, but with a reported time of ~14:55.

[kasemir]

erroneous alarm time matches with ...the sample before the disconnect
Excellent observation. I can look into this.

[mdavidsaver]

The analog PVs have all updated many times since then, so can't be
explained by simple re-use of the most recent timestamp...

But no alarms since, so the 14:55 update would be the most recent seen
by the alarm server. This could be as simple as reuse of the last
received time.

[kasemir]

OK, I found it.
Yes, it's using the last value received .. from the PVManager.
The PVManager sends a value update that has UNDEFINED severity, Disconnected as a message, with a time stamp that reflects the last valid value.

Before PVManager, I would get
a) A valid value with time stamp
b) A disconnect notification, then using the current time

With PVManager, it turns out I can get
a) A value with a time stamp, which I then use
b) An error notification, where I then use the current time
… but disconnects can now happen two ways:
As a "timeout" error, where I'll use the current time and all is correct,
or as a value update with UNDEFINED status and an outdated time stamp.

Should this be fixed in the PVManager?
Vvalue updates should include the time of the update, and for disconnected that means the time when the value disconnected?

Or is the PVManager perfect, and I need to check its time stamp: Time.isTimeValid()== true, but we happen to know that if SeverityLevel == UNDEFINED && alarmName() == "Disconnected", at least for now for Channel Access, the time stamp is not the time of the disconnect?

[kasemir]

Here's a snapshot that shows how 'Probe' also gets the timestamp of the last valid update (10:17) for the UNDEFINED/Disconnect, while camonitor shows the actual time of the disconnect (10:19).
The alarm system thus behaves the same as Probe because it uses the time stamp that it gets from the PVManager.

[epics-jenkins]

I have added an issue:
diirt/diirt#22
and will change the behavior of the CA datasource to give the disconnection time for UNDEFINED(Disconnected). I am not sure whether this will fix all cases of this issue, but that's the plan!

I'll first implement it in the development branch, and then we can understand if and how to backport.