Random timestamp in INTERFACE_CHANGE_EVENT subscription

Hello everyone,

This is a follow-up regarding an issue I reported in the official forum. I've encountered a weird behavior when subscribing to certain event types. Let's say I have a Tango device running on a server (Ubuntu 20.04 LTS) and I use pytango.DeviceProxy to subscribe to different events. When subscribing to normal "CHANGE" events on a given attribute, everything works fine:

>>> dm.subscribe_event("dishMode", tango.EventType.CHANGE_EVENT, EM())
2024-09-16 17:24:30.802752
change
35
>>> dm.subscribe_event("dishMode", tango.EventType.CHANGE_EVENT, EM())
2024-09-16 17:24:32.197378
change
36
>>> dm.subscribe_event("dishMode", tango.EventType.CHANGE_EVENT, EM())
2024-09-16 17:24:33.627955
change
37

However, if I subscribe to "INTERFACE_CHANGE_EVENT" specifically I get completely random timestamps, with past and future dates, as you can see below:

>>> dsm.subscribe_event(tango.EventType.INTERFACE_CHANGE_EVENT, tango.utils.EventCallback())
utils::_get_value()
1970-09-18 23:52:16 MID_DSH_0119/LMC/DS_MANAGER <UNKNOWN> INTR_CHANGE None
1
>>> dsm.subscribe_event(tango.EventType.INTERFACE_CHANGE_EVENT, tango.utils.EventCallback())
utils::_get_value()
1970-09-17 09:52:32 MID_DSH_0119/LMC/DS_MANAGER <UNKNOWN> INTR_CHANGE None
2
>>> dsm.subscribe_event(tango.EventType.INTERFACE_CHANGE_EVENT, tango.utils.EventCallback())
utils::_get_value()
1970-09-19 04:38:40 MID_DSH_0119/LMC/DS_MANAGER <UNKNOWN> INTR_CHANGE None
3

I am using Tango v9.3.4 with pytango 9.4.1. The issue occurs both locally and remotely (subscribing from different hosts). I attach the code to reproduce, with a minimal Tango device created with Pogo, and a check_subscription.py script. It would be great if you could take a look and shed some light on the issue.

Many thanks in advance,

Cristobal

tango-bug-timestamp.zip

Hi @cbordiu. Thanks the bug report - it seems interesting.

I am using Tango v9.3.4 with pytango 9.4.1

I'm not sure I understand. Do you have two different environments? The C++ device server compiled with cppTango 9.3.4. And the client running with PyTango 9.4.1? (PyTango 9.4.x needs to be compiled against cppTango 9.4.x).

Can you run python -c "import tango; print(tango.utils.info())" in your Python environment, and report the output?

It should be no problem if the client and server are using different versions of cppTango and/or PyTango.

Hi @ajoubertza and apologies for the confusion. Yes, what I meant is that the device server uses cppTango 9.3.4 and the pytango client uses 9.4.1 (in the "real" setup the client is supposed to be running on another host, etc). Here's the output:

PyTango 9.4.1 (9, 4, 1)\nPyTango compiled with:\n Python : 3.8.16\n Numpy : 1.17.3\n Tango : 9.4.1\n Boost : 1.80.0\n\nPyTango runtime is:\n Python : 3.8.10\n Numpy : 1.24.3\n Tango : 9.4.1\n\nPyTango running on:\nuname_result(system='Linux', node='lmc', release='5.15.0-116-generic', version='#126~20.04.1-Ubuntu SMP Mon Jul 1 15:40:07 UTC 2024', machine='x86_64', processor='x86_64')\n"

Thanks for the details.

I can recreate the issue even with the newest versions of cppTango and PyTango. The bug appears to be in cppTango which is not setting the internal reception_date variable when constructing DevIntrChangeEventData objects. I think we have the same problem with the DataReadyEventData objects.

With the following diff to cppTango event.cpp, the client-side reception time is printed correctly.

diff --git a/src/client/event.cpp b/src/client/event.cpp
index b7921ee..a1bda24 100644
--- a/src/client/event.cpp
+++ b/src/client/event.cpp
@@ -4078,6 +4078,7 @@ DevIntrChangeEventData::DevIntrChangeEventData(DeviceProxy *dev,

         a_list_var._retn();
     }
+    set_time();
 }

 DevIntrChangeEventData::DevIntrChangeEventData(DeviceProxy *dev,
@@ -4101,6 +4102,7 @@ DevIntrChangeEventData::DevIntrChangeEventData(DeviceProxy *dev,
         cmd_list = *c_list;
         att_list = *a_list;
     }
+    set_time();
 }

 //+------------------------------------------------------------------------

Code to test:

import tango
proxy = tango.DeviceProxy('sys/tg_test/1')
proxy.subscribe_event(tango.EventType.INTERFACE_CHANGE_EVENT, tango.utils.EventCallback())

Old output:

1970-01-01 01:00:00 SYS/TG_TEST/1 <UNKNOWN> INTR_CHANGE None

New output:

2024-10-11 11:56:52.821642 SYS/TG_TEST/1 <UNKNOWN> INTR_CHANGE None

I'm going to move this issue to the cppTango repo.

@cbordiu Thanks for following up here. @ajoubertza And thanks for the analysis, fix and moving it here.

We'll take over.

Thanks @ajoubertza and @t-b for the quick response!

moved from pytango#633 (moved)

changed milestone to %11.0.0

changed milestone to %10.1.0

assigned to @t-b

added Bug label

mentioned in merge request !1356

mentioned in merge request pytango!793 (merged)