Atribbute value from polled attibute race condition

[ra1u]

Issue seems to be that if one registers on polled event (for example change of absolute value) it can sometimes happen that read attribute can be older that arrived event event when read after event arrival.

For example device server.py

import time
from tango.server import Device, attribute

class Clock(Device): 
    time = attribute(dtype=float)
    def read_time(self):
        # time that can not go backward
        return time.monotonic()

if __name__ == "__main__":
    Clock.run_server()

And test code client.py

import PyTango,time,os

dev='test/clock/time'
dplib1=PyTango.DeviceProxy(dev)
attr_name='time'

class Cback():
   def push_event(self,event):
       e=event.attr_value.value
       attr = dplib1.read_attribute(attr_name)
       attr_val = attr.value
       if (attr_val < e):
           print ("attr value: ", attr)
           print ("event value: ", event)
           
cback=Cback()
evtlib1=dplib1.subscribe_event(attr_name,PyTango.EventType.CHANGE_EVENT,cback)

while 1:
    time.sleep(10)

It is not expected that inside of Cback.push_event value of attr.value is less than event.attr_value.value
Hovever it can happen with output

attr value:  DeviceAttribute[
data_format = tango._tango.AttrDataFormat.SCALAR
      dim_x = 1
      dim_y = 0
 has_failed = False
   is_empty = False
       name = 'time'
    nb_read = 1
 nb_written = 0
    quality = tango._tango.AttrQuality.ATTR_VALID
r_dimension = AttributeDimension(dim_x = 1, dim_y = 0)
       time = TimeVal(tv_nsec = 0, tv_sec = 1609937499, tv_usec = 584208)
       type = tango._tango.CmdArgType.DevDouble
      value = 179511.917209007
    w_dim_x = 0
    w_dim_y = 0
w_dimension = AttributeDimension(dim_x = 0, dim_y = 0)
    w_value = None]

event value:  EventData[
     attr_name = 'tango://docker-test_tango-cs_1.docker-test_default:10000/test/clock/time/time'
    attr_value = DeviceAttribute(data_format = tango._tango.AttrDataFormat.SCALAR, dim_x = 1, dim_y = 0, has_failed = False, is_empty = False, n
ame = 'time', nb_read = 1, nb_written = 0, quality = tango._tango.AttrQuality.ATTR_VALID, r_dimension = AttributeDimension(dim_x = 1, dim_y = 0)
, time = TimeVal(tv_nsec = 0, tv_sec = 1609937499, tv_usec = 884419), type = tango._tango.CmdArgType.DevDouble, value = 179512.217415812, w_dim_
x = 0, w_dim_y = 0, w_dimension = AttributeDimension(dim_x = 0, dim_y = 0), w_value = None)
        device = Clock(test/clock/time)
           err = False
        errors = ()
         event = 'change'
reception_date = TimeVal(tv_nsec = 0, tv_sec = 1609937499, tv_usec = 884596)]

Here we can see, that time of attr (also internal timestamp) is less than time of event.
Unexpected event can appear once in few hours.

Polling period was set on 300ms and absolute change as 3 (this is just as an reference)
We used last docker version of tangocs/tango-cs for database and tangocs/tango-pytango for pytango.

[bourtemb]

Hi @ra1u ,

I guess this happens from time to time because you read very quickly the attribute just after receiving an event.
If you read fast enough, it might be that the attribute value in the polling buffer has not yet been updated when you read it.
So you're reading the previous polled value (300 ms before).
By default, when you read an attribute, if it is polled, like in your case, you will get the cached value from the polling buffer unless you do:
dplib1.set_source(DevSource.DEV)
at some point before reading the attribute to force the reading of the attribute without using the cached value from the polling buffer.
https://pytango.readthedocs.io/en/latest/client_api/device_proxy.html#tango.DeviceProxy.set_source

Hoping this helps a bit.
Reynald

[bourtemb]

I double-checked in the cppTango source code.
Indeed, the events are sent (https://github.com/tango-controls/cppTango/blob/9.3.4/cppapi/server/pollthread.cpp#L1970) before filling the polling buffer (lines following https://github.com/tango-controls/cppTango/blob/9.3.4/cppapi/server/pollthread.cpp#L1978).

So what you are observing is not surprising when we look at the current code.
If you read very fast after receiving the events, there might be some cases where the polling buffer is not yet updated when you read the attribute.
Now, the question is, why would you need to read the attribute after receiving this event if the value is already provided in the variable passed to the callback?

[ra1u]

Hi @bourtemb

We are trying to help one of our users who did ask about this. We reduced some other issue involving larger system to this point.
We just now tested what you have suggested and I believe your suggestion, should also help our user to solve his problem.

Thank you for your quick response, really appreciated.

Kind regards, Luka.