Error on taurus addListener() while running Sardana macroexecutor

[AlejandroAMarin]

Found error while trying to activate macroexecutor in Sardana: ERROR msg: terminate called after throwing an instance of 'Tango::DevFailed' Apparently the error is related to taurus function addListener(). The error only appears on develop version of taurus, version 4.6.1 doesn't produce the error. Snippet on how to reproduce problem:

import taurus

def cb(*args):
    print(args)

attr = taurus.Attribute("sys/tg_test/1/ampli")
attr.addListener(cb)

Problem seems to disapear when calling self._activatePolling() after self._call_dev_hw_subscribe_event(True) instead of before. In function _subscribeChangeEvents()

But the _subscribeChangeEvents() function hasn't been changed from version 4.6.1 to develop version. So the real error must be elsewhere.

[cpascual]

Hi @ByRellex , I am not able to reproduce the problem using your snippet. I tried with the latest taurus code, using both python2 and python3 in two different tango environments.

Please find below my console log. Can you try something similar and let us know if you can reproduce the issue?

cpascual@pc218:~/src/taurus(develop)$ git pull
Already up-to-date.

cpascual@pc218:~/src/taurus(develop)$ git log -n1 --oneline 
c8d2f48f Merge pull request #1050 from cpascual/fixtests

cpascual@pc218:~/src/taurus(develop)$ taurus --version
taurus, version 4.6.5-alpha

cpascual@pc218:~/src/taurus(develop)$ cat test-1051.py 
import taurus

def cb(*args):
    print(args)

attr = taurus.Attribute("sys/tg_test/1/ampli")
attr.addListener(cb)

cpascual@pc218:~/src/taurus(develop)$ python test-1051.py 
(TangoAttribute(tango://controls02.cells.es:10000/sys/tg_test/1/ampli), 2, TangoAttrValue{'_TangoAttrValue__attrName': 'tango://controls02.cells.es:10000/sys/tg_test/1/ampli', 'wvalue': <Quantity(0.0, 'meter')>, '_attrRef': <weakproxy at 0x7f933e0ec4c8 to TangoAttribute at 0x7f933e12a7d0>, 'rvalue': <Quantity(0.0, 'meter')>, '_TangoAttrValue__attrType': 1, '_pytango_dev_attr': DeviceAttribute(data_format = tango._tango.AttrDataFormat.SCALAR, dim_x = 1, dim_y = 0, has_failed = False, is_empty = False, name = 'ampli', nb_read = 1, nb_written = 1, quality = tango._tango.AttrQuality.ATTR_VALID, r_dimension = AttributeDimension(dim_x = 1, dim_y = 0), time = TimeVal(tv_nsec = 0, tv_sec = 1579767442, tv_usec = 5102), type = tango._tango.CmdArgType.DevDouble, value = 0.0, w_dim_x = 1, w_dim_y = 0, w_dimension = AttributeDimension(dim_x = 1, dim_y = 0), w_value = 0.0), 'time': TimeVal(tv_nsec = 0, tv_sec = 1579767442, tv_usec = 5102), 'error': None, 'config': <weakproxy at 0x7f933e0ec4c8 to TangoAttribute at 0x7f933e12a7d0>, 'quality': <AttrQuality.ATTR_VALID: 0>})

cpascual@pc218:~/src/taurus(develop)$ python3 test-1051.py 
(TangoAttribute(tango://controls02.cells.es:10000/sys/tg_test/1/ampli), 2, TangoAttrValue{'rvalue': <Quantity(0.0, 'meter')>, 'time': TimeVal(tv_nsec = 0, tv_sec = 1579767451, tv_usec = 812246), '_TangoAttrValue__attrType': 1, 'config': <weakproxy at 0x7f9606bb25e8 to TangoAttribute at 0x7f9607a6cf60>, '_pytango_dev_attr': DeviceAttribute(data_format = tango._tango.AttrDataFormat.SCALAR, dim_x = 1, dim_y = 0, has_failed = False, is_empty = False, name = 'ampli', nb_read = 1, nb_written = 1, quality = tango._tango.AttrQuality.ATTR_VALID, r_dimension = AttributeDimension(dim_x = 1, dim_y = 0), time = TimeVal(tv_nsec = 0, tv_sec = 1579767451, tv_usec = 812246), type = tango._tango.CmdArgType.DevDouble, value = 0.0, w_dim_x = 1, w_dim_y = 0, w_dimension = AttributeDimension(dim_x = 1, dim_y = 0), w_value = 0.0), 'quality': <AttrQuality.ATTR_VALID: 0>, 'error': None, 'wvalue': <Quantity(0.0, 'meter')>, '_attrRef': <weakproxy at 0x7f9606bb25e8 to TangoAttribute at 0x7f9607a6cf60>, '_TangoAttrValue__attrName': 'tango://controls02.cells.es:10000/sys/tg_test/1/ampli'})

cpascual@pc218:~/src/taurus(develop)$ docker-compose -f ~/src/taurus/ci/tango_docker-compose.yml up -d
ci_tango-db_1 is up-to-date
Starting ci_tango-cs_1
Creating ci_tango-test_1

cpascual@pc218:~/src/taurus(develop)$ TANGO_HOST=localhost:10000 python test-1051.py
(TangoAttribute(tango://localhost:10000/sys/tg_test/1/ampli), 2, TangoAttrValue{'_TangoAttrValue__attrName': 'tango://localhost:10000/sys/tg_test/1/ampli', 'wvalue': <Quantity(0.0, 'dimensionless')>, '_attrRef': <weakproxy at 0x7f4d8eba6310 to TangoAttribute at 0x7f4d8ec05450>, 'rvalue': <Quantity(0.0, 'dimensionless')>, '_TangoAttrValue__attrType': 1, '_pytango_dev_attr': DeviceAttribute(data_format = tango._tango.AttrDataFormat.SCALAR, dim_x = 1, dim_y = 0, has_failed = False, is_empty = False, name = 'ampli', nb_read = 1, nb_written = 1, quality = tango._tango.AttrQuality.ATTR_VALID, r_dimension = AttributeDimension(dim_x = 1, dim_y = 0), time = TimeVal(tv_nsec = 0, tv_sec = 1579768002, tv_usec = 297973), type = tango._tango.CmdArgType.DevDouble, value = 0.0, w_dim_x = 1, w_dim_y = 0, w_dimension = AttributeDimension(dim_x = 1, dim_y = 0), w_value = 0.0), 'time': TimeVal(tv_nsec = 0, tv_sec = 1579768002, tv_usec = 297973), 'error': None, 'config': <weakproxy at 0x7f4d8eba6310 to TangoAttribute at 0x7f4d8ec05450>, 'quality': <AttrQuality.ATTR_VALID: 0>})

cpascual@pc218:~/src/taurus(develop)$ TANGO_HOST=localhost:10000 python3 test-1051.py
(TangoAttribute(tango://localhost:10000/sys/tg_test/1/ampli), 2, TangoAttrValue{'_TangoAttrValue__attrType': 1, 'wvalue': <Quantity(0.0, 'dimensionless')>, '_TangoAttrValue__attrName': 'tango://localhost:10000/sys/tg_test/1/ampli', '_pytango_dev_attr': DeviceAttribute(data_format = tango._tango.AttrDataFormat.SCALAR, dim_x = 1, dim_y = 0, has_failed = False, is_empty = False, name = 'ampli', nb_read = 1, nb_written = 1, quality = tango._tango.AttrQuality.ATTR_VALID, r_dimension = AttributeDimension(dim_x = 1, dim_y = 0), time = TimeVal(tv_nsec = 0, tv_sec = 1579768014, tv_usec = 673884), type = tango._tango.CmdArgType.DevDouble, value = 0.0, w_dim_x = 1, w_dim_y = 0, w_dimension = AttributeDimension(dim_x = 1, dim_y = 0), w_value = 0.0), 'config': <weakproxy at 0x7fd760ad8278 to TangoAttribute at 0x7fd760ac8a90>, 'quality': <AttrQuality.ATTR_VALID: 0>, '_attrRef': <weakproxy at 0x7fd760ad8278 to TangoAttribute at 0x7fd760ac8a90>, 'rvalue': <Quantity(0.0, 'dimensionless')>, 'error': None, 'time': TimeVal(tv_nsec = 0, tv_sec = 1579768014, tv_usec = 673884)})

[reszelaz]

It happens only if the server is shutdown:

zreszela@pc255:~> ps -ef | grep TangoTest
zreszela 20309 20115  0 09:49 pts/1    00:00:00 grep --color=auto TangoTest
zreszela@pc255:~> cd workspace/taurus
zreszela@pc255:~/workspace/taurus (develop)> git pull
Already up-to-date.
zreszela@pc255:~/workspace/taurus (develop)> ipython3
Python 3.5.3 (default, Sep 27 2018, 17:25:39) 
Type "copyright", "credits" or "license" for more information.

IPython 5.1.0 -- An enhanced Interactive Python.
?         -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help      -> Python's own help system.
object?   -> Details about 'object', use 'object??' for extra details.

In [1]: import taurus
   ...: 
   ...: def cb(*args):
   ...:     print(args)
   ...: 
   ...: attr = taurus.Attribute("sys/tg_test/1/ampli")
   ...: attr.addListener(cb)
   ...: 
terminate called after throwing an instance of 'Tango::DevFailed'
Aborted

[cpascual]

Thanks @reszelaz , I managed to reproduce now (but only with python3):

cpascual@pc218:~/src/taurus(develop)$ docker-compose -f ~/src/taurus/ci/tango_docker-compose.yml pause tango-test
Pausing ci_tango-test_1 ... done

cpascual@pc218:~/src/taurus(develop)$ docker ps
CONTAINER ID        IMAGE                                          COMMAND                  CREATED             STATUS                  PORTS                      NAMES
40a8faf4fbf8        tangocs/tango-test:9.3.3-rc1                   "/usr/bin/supervis..."   3 minutes ago       Up 3 minutes (Paused)                              ci_tango-test_1
ac07387431df        tangocs/tango-cs:9.3.2-alpha.1-no-tango-test   "/bin/sh -c '/usr/..."   3 minutes ago       Up 3 minutes            0.0.0.0:10000->10000/tcp   ci_tango-cs_1
1a36fccb8b73        tangocs/mysql:9.2.2                            "docker-entrypoint..."   4 minutes ago       Up 3 minutes            0.0.0.0:9999->3306/tcp     ci_tango-db_1

cpascual@pc218:~/src/taurus(develop)$ TANGO_HOST=localhost:10000 python3 test-1051.py
terminate called after throwing an instance of 'Tango::DevFailed'
Aborted

cpascual@pc218:~/src/taurus(develop)$ TANGO_HOST=localhost:10000 python2 test-1051.py
(TangoAttribute(tango://localhost:10000/sys/tg_test/1/ampli), 3, DevFailed(args = (DevError(desc = 'TRANSIENT CORBA system exception: TRANSIENT_CallTimedout', origin = 'Connection::connect', reason = 'API_CorbaException', severity = tango._tango.ErrSeverity.ERR), DevError(desc = 'Failed to connect to device sys/tg_test/1', origin = 'Connection::connect', reason = 'API_CantConnectToDevice', severity = tango._tango.ErrSeverity.ERR), DevError(desc = 'Failed to execute read_attributes_asynch on device sys/tg_test/1', origin = 'DeviceProxy::read_attributes_asynch()', reason = 'API_CommandFailed', severity = tango._tango.ErrSeverity.ERR))))
TimerLoop 1    WARNING  2020-01-23 10:13:59,477 TaurusPollingTimer[3000].Timer on _pollAttributes: loop function took more than loop interval (3.0s)
(TangoAttribute(tango://localhost:10000/sys/tg_test/1/ampli), 3, DevFailed(args = (DevError(desc = "Can't subscribe to event for device tango://localhost:10000/sys/tg_test/1\nCheck that device server is running...", origin = 'EventConsumer::connect_event()', reason = 'API_CantConnectToDevice', severity = tango._tango.ErrSeverity.ERR),)))
(TangoAttribute(tango://localhost:10000/sys/tg_test/1/ampli), 3, DevFailed(args = (DevError(desc = "Can't subscribe to event for device tango://localhost:10000/sys/tg_test/1\nCheck that device server is running...", origin = 'EventConsumer::connect_event()', reason = 'API_CantConnectToDevice', severity = tango._tango.ErrSeverity.ERR),)))

[cpascual]

... but now it also happens for 4.6.1:

cpascual@pc218:~/src/taurus(develop)$ git checkout 4.6.1
Note: checking out '4.6.1'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by performing another checkout.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -b with the checkout command again. Example:

  git checkout -b <new-branch-name>

HEAD is now at c54baa70... Merge pull request #990 from cpascual/hotfix-4.6.1

cpascual@pc218:~/src/taurus((4.6.1))$ TANGO_HOST=localhost:10000 python3 test-1051.py
terminate called after throwing an instance of 'Tango::DevFailed'
Aborted

[reszelaz]

For me it works correctly on 4.6.1:

zreszela@pc255:~/workspace/taurus (develop)> git checkout 4.6.1
Note: checking out '4.6.1'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by performing another checkout.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -b with the checkout command again. Example:

  git checkout -b <new-branch-name>

HEAD is now at c54baa70... Merge pull request #990 from cpascual/hotfix-4.6.1
zreszela@pc255:~/workspace/taurus ((4.6.1))> ipython3
Python 3.5.3 (default, Sep 27 2018, 17:25:39) 
Type "copyright", "credits" or "license" for more information.

IPython 5.1.0 -- An enhanced Interactive Python.
?         -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help      -> Python's own help system.
object?   -> Details about 'object', use 'object??' for extra details.

In [1]: import taurus
   ...: 
   ...: def cb(*args):
   ...:     print(args)
   ...: 
   ...: attr = taurus.Attribute("sys/tg_test/1/ampli")
   ...: attr.addListener(cb)
   ...: 
(TangoAttribute(tango://pc255.cells.es:10000/sys/tg_test/1/ampli), 3, DevFailed(args = (DevError(desc = 'Failed to connect to device sys/tg_test/1\nThe connection request was delayed.\nThe last connection request was done less than 1000 ms ago', origin = 'Connection::reconnect', reason = 'API_CantConnectToDevice', severity = tango._tango.ErrSeverity.ERR),)))
(TangoAttribute(tango://pc255.cells.es:10000/sys/tg_test/1/ampli), 3, DevFailed(args = (DevError(desc = "Can't subscribe to event for device tango://pc255.cells.es:10000/sys/tg_test/1\nCheck that device server is running...", origin = 'EventConsumer::connect_event()', reason = 'API_CantConnectToDevice', severity = tango._tango.ErrSeverity.ERR),)))
Out[1]: True

In [2]: (TangoAttribute(tango://pc255.cells.es:10000/sys/tg_test/1/ampli), 3, DevFailed(args = (DevError(desc = "Can't subscribe to event for device tango://pc255.cells.es:10000/sys/tg_test/1\nCheck that devic)
(TangoAttribute(tango://pc255.cells.es:10000/sys/tg_test/1/ampli), 3, DevFailed(args = (DevError(desc = "Can't subscribe to event for device tango://pc255.cells.es:10000/sys/tg_test/1\nCheck that device server)

[cpascual]

Curious... It also works for me with in interactive mode (both with python3 and with ipython3), but not in non-interactive mode (neither with python3 nor ipython3)

[cpascual]

digging a bit more together with @ByRellex, we confirmed that this is not systematic. It looks like a race condition.

[MikeFalowski]

I'm not sure if it can be in any way related but I had the same issue terminate called after throwing an instance of 'Tango::DevFailed' in older versions of MAX IV svgsynoptic.

What I recall it start happening at least since Taurus version 4.3 and in most way it was fixed by changing mode from concurrent to serial (commit fixing this).

It was happening mostly when there was many Tango devices connected, especially at the application start or during movement of the view (many Tango subscriptions and resubscriptions) but maybe it was the time when I was looking the most.

I would mostly not care after fix but with serial mode application freezes until all subscriptions are done. With many, many attributes it takes some time.

I hope this can help somehow and hope not to mislead too much.

[cpascual]

I am revisiting this before the Jul20 release and I am unable to reproduce it with the latest develop (commit 99c1fd1).

Info on versions: I am using the latest PyTango and Tango conda packages for the client... (note pytango 9.3.2, from my channel!)

(py3qt5) cpascual@pt168:~/src/taurus(fix-1051)$ conda list |grep tango
cpptango                  9.3.4rc6             h6bb024c_0    tango-controls
itango                    0.1.6                    pypi_0    pypi
omniorb                   4.2.2            py37h6bb024c_0    tango-controls
pytango                   9.3.2            py37h6bb024c_1    cpascual  

... and tango 9.3.4-rc4 for the server ,

So, I am assuming for now that whatever the problem, it got fixed with the latest (py)tango. I'll leave this still open for some days in case someone manages to reproduce it, but I'll close it otherwise for the Jul20 release.