push_change_event() - events stop being issued after some time

[mkomel]

We've noticed a problem where the events from some of our device servers stop coming to the clients some time after startup.
By troubleshooting and testing we were able to create a minimalistic setup with which we can reliably reproduce the problem: simpledevice.zip

The zip file contains a simple device server and two types of clients (one is PyTango-based, the other written in c++ by using tango libraries.. we experience the same issue with both).
The device server contains a single DevULong attribute simplepushedvalue, which is actively being pushed from code via push_change_event(). The attribute is configured with set_event_abs_change("1") and set_change_event(true, true); (note that the result is the same if we use set_change_event(true, false); ).
The sample should be set up with 2 device server instances, each one with a single device:

• device server instance simple1 => simple/test/1
• device server instance simple2 => simple/test/2

After starting both device server instances, the client (or both clients) should be started, which will show the events as they come in.
Approximately after 8-9minutes (interestingly it is reliably after cca.8-9minutes), the events from one of the device servers will stop coming to the client (at least this is how we experience the issue).
It's interesting to note that if the affected device server is then stopped, the client will correctly detect API_EventTimeout. And if that device server is then restarted, the events will again correctly start to arrive to the client (but then again, after cca.8-9 minutes the problem reappears, although not necessarily on the same device server).

We are using Tango 9.2.5, omniorb 4.1.6, zmq 4.2.1 (all Ubuntu apt packages) on Ubuntu 17.10.

To summarize, we can reproduce the issue with broken events if:

• client subscribes to an attribute which is not polled, but rather manually pushed from code
• client subscribes on at least two devices from two separate device server instances (if only one device server instance hosts both devices, we do not observe this problem)

[mkomel]

Additional piece of information:

by observing the traffic (with wireshark) between the device servers and the client, we can still see packets going from source to destination for both device servers, even after the client stops registering events from one of them.
I guess this is then an indication that something must be wrong on the client side (both, PyTango and c++ client).

[bourtemb]

Thank you very much for the detailed bug report, Matej,
I can reproduce the problem on an Ubuntu 17.10 Virtual machine. This will help us to understand the origin of the bug.

[mkomel]

After some more testing we have found out that this is actually not specific to attributes which are manually pushed.
The same happens also on normal polled attributes, if they have set_event_abs_change or set_event_rel_change set (so that the Tango framework will by itself trigger events).
Also, the time that it takes for the problem to occur depends on the frequency of polling/pushing.

I'm attaching here an updated sample: simpledevice.zip
this time with an additional DevULong attribute simplepolledvalue, with a 100ms polling rate and abs_change set to 1. In the device server, the pushing part of the previous attribute simplepushedvalue is commented out, to exclude the possibility that this in some way causes the problem.
With 100ms polling rate (and therefore event rate), the problem can be observed on the clients after cca. 2 minutes.

[bourtemb]

When we increase the events frequency by 5, then the problems happens about 5 times faster than before...
This is interesting... I tested again with your first example, running the client on an Ubuntu 17.10 VM.
The server instances were running on one of our Debian Jessie hosts.
I reduced the sleep between 2 push_change_event in the device thread to 100 ms.
I ran in parallel one client on Ubuntu and one on Jessie (omniorb 4.2.1 patched + ZMQ 4.0.5).
The client on Ubuntu showed the problem after about 2 minutes while the other client on Jessie didn't have any issue.
I dumped the TCP packets exchanged between our Jessie host and the Ubuntu 17.10 VM and I noticed that the events were actually still sent (and received) on the network for the 2 Tango devices the client subscribed to...
It is still not clear what is triggering this problem for the moment... Deeper investigations will be needed...

[mkomel]

It turns out the problem is a specific ZMQ version which is 4.2.1 on Ubuntu 17.10 (when installed via apt package manager).
When testing with ZMQ 4.2.2 and 4.2.5 (built from sources), this problem cannot be observed. (NOTE: I also tested with ZMQ 4.2.1 built from sources to see if perhaps there is a problem with the Ubuntu package, but the problem can be observed regardless).

The problem seems to be somewhat linked to the high water mark setting for incoming messages (ZMQ_RCVHWM) and most likely to the way how zmq handles incoming packets buffers. By default this value is 1000, and this is exactly the number of events that the client will take from the first publisher (NOTE: it will normally receive and accept events from the second publisher to which it connected; the problem as described in previous posts happens only when the client subscribes to more than one publisher). By reducing the hwm value to e.g. 10, the issue can be observed much faster, since the client will only accept 10 events from the first publisher.
(NOTE: hwm can be manually tweaked in libtango in zmqeventconsumer.cpp in ZmqEventConsumer::process_ctrl, under case ZMQ_CONNECT_EVENT).

Since the problem is not specific to libtango, it can be easily reproduced by a minimalistic zmq publisher/subscriber example, which I'm attaching here: zeromq.zip
The zip file contains client.cpp and server.cpp, which after being built can be used as follows:

• start server as ./server 5556
• start second server as ./server 5557
• start client as ./client 5556 5557

Client will subscribe to both servers, setting ZMQ_RCVHWM to a very low value (=10). Client will normally accept events from the second server but will only accept exactly 10 events from the first server, and will afterwards either drop or not try to receive any new events from it (with netstat -a --tcp it can then be observed how the Recv-Q for this specific client<->publisher connection starts to increase. This confirms that event packets are in fact coming to the client, but it looks like the client just does not accept or take the packets out of the receive buffers).
This is clearly a bug in that specific ZMQ version and I'm quite surprised that I didn't find any bug reports about it over there.

I'm not sure what should be done with this. I'm wondering whether it makes sense to file a defect on ZMQ project at this point, since later minor releases 4.2.2 and 4.2.5 seem to resolve this problem (although only implicitly, since they do not mention anything related to it in Release notes).
But still it is a serious problem for any environment using this specific version of ZMQ and also for Tango, since it cannot work well in Ubuntu 17.10 (perhaps also in some other distributions?) if everything is installed via package manager.

[mkomel]

I have traced the problem down to how setting/changing hwm values is handled in zeromq 4.2.1.
More specifically, when manually setting ZMQ_RCVHWM the recalculation of lwm is done, which is causing problems there (lwm is calculated=0), and zeromq consequently does not process any messages.
The following commit then solved the problem: link

Regarding the odd thing about the strange effect being visible only on messages from the first connected server (and not also on the second one):
Tango is invoking event_sub_sock->setsockopt(ZMQ_RCVHWM, ...) before invoking event_sub_sock->connect(endpoint)
But zeromq will only apply change of such options to already binded sockets. This means that when a client subscribes to two (or more) servers, the following (pseudo)sequence occurs:

• about to connect to server 1
• attempt to set ZMQ_RCVHWM for server 1 (but zeromq will ignore this call, since there is no socket bound yet)
• connect/bind to server 1 (this one will therefore have hwm settings as default, since previous call did not have any effect on it)
• about to connect to server 2
• attempt to set ZMQ_RCVHWM for server 2 (but zeromq will just apply this to ALL sockets which have been connected to so far... this means only to server 1)
• effect is that the lwm/hwm recalculation will only be performed on the socket for server 1, but since the recalculation is erroneous (resulting in lwm=0), the client will just not process any incoming messages (as soon as the hwm threshold is reached).

If setting ZMQ_RCVHWM would be set only once (after the second connection is established), the recalculation would be done for both connections, but this would only result in events from both servers to stop arriving (when used with Zeromq 4.2.1).

I would therefore suggest the following:

• either correct Tango code (in zmqeventconsumer.cpp) to invoke event_sub_sock->setsockopt(ZMQ_RCVHWM, ...) after event_sub_sock->connect(endpoint)
• or just remove this manual setting of hwm (since it seems to be currently incorrect in Tango anyway). Side effect of this second option would be that Tango would then work ok also with Zeromq 4.2.1 (since no hwm recalculation would be done)

[Ingvord]

+1 for

or just remove this manual setting of hwm (since it seems to be currently incorrect in Tango anyway). Side effect of this second option would be that Tango would then work ok also with Zeromq 4.2.1 (since no hwm recalculation would be done)

[bourtemb]

Thank you very much Matej for the time spent digging into this issue.

I would not remove this manual setting of HWM. This was introduced for a good reason. There might be some use cases where we would like to get a higher water mark than the default one.
There is a section in the Tango documentation about this:
http://tango-controls.readthedocs.io/en/latest/development/advanced/reference.html?highlight=hwm#tuning-the-event-system-buffers-hwm

There are some references to the problem you are mentioning.
What appeared after a bit of investigation is that the behaviour changed in ZeroMQ.
In the past, this setting was effective only after the creation of the socket and before the bind and connect, as you can see in this libzmq issue comment: zeromq/libzmq#1416 (comment)

They changed that at some point in order to allow it after the bind (zeromq/libzmq#1426) but the documentation doesn't say that this option will now take effect only after bind/connect and the tests from this Pull request are actually suggesting that both cases are supported.

I think we should keep this option to be able to set the HWM. Of course it is not as simple as removing the option but it's also less extreme. I think we need to find a way to make it work on the versions of ZMQ which are not behaving well.
If we don't find a solution rapidly, we could at least add something in the documentation in order to warn the users about this problem with ZMQ 4.2.1 (and maybe some other buggy versions).
An easy work-around is to use ZMQ >= 4.2.2.

[mkomel]

You are right, actually by taking another look I can see that it's true that changing HWM can be done either before or after the bind/connect. Both options should end with the same result. The problem with 4.2.1 is in the erroneous recalculation of lwm/hwm when changing HWM is done after the bind/connect.
In my test examples this is manifested when setsockopt(ZMQ_RCVHWM, ..) is called before the second connect (and after the first one). This triggers the bad recalculation on the 1st connection pipe, while the 2nd one will get a correctly applied hwm setting via its constructor.

One simple (but not perfect) "workaround" on the Tango side would be to try to set hwm setting only once (before the first connect call).
For example check for currently effective ZMQ_RCVHWM before applying a new one and invoke event_sub_sock->setsockopt(ZMQ_RCVHWM, ..) only in case the new hwm would differ from the currently effective one. This should not break anything, but would prevent Tango to trigger the hwm recalculation in ZMQ for cases when the hwm would just be reapplied with the same value.
Subsequent hwm changes (via "event system tunning") would still unavoidably trigger that recalculation.
This could then be stated somewhere as: event system tunning does not work with ZMQ 4.2.1 (+ I think also ZMQ 4.2.0).

[bourtemb]

I share your analysis and I agree this would be an easy fix which would work in 99.9999% of the use cases.
I had a deeper look at the Tango code related to HWM tuning (I looked only at the client side for the moment) and it seems like this is not something which is too dynamic anyway.
If the client sets the TANGO_EVENT_BUFFER_HWM environment variable, this value will always be used for this client and will not change.
If the client uses ApiUtil::set_event_buffer_hwm() method to change the high water mark, it can do it only once (following calls will be ignored) and this value is taken into account only if TANGO_EVENT_BUFFER_HWM environment variable is not defined.
If the client is not setting TANGO_EVENT_BUFFER_HWM environment variable and is not using ApiUtil::set_event_buffer_hwm() method in the code, it will get the high water mark setting from the device server it tries to connect to (ZmqEventSubscriptionChange method called when subscribe_event() methods are invoked). The device server will return the hard coded default value (1000) or the value of the CtrlSystem/EventBufferHwm free property if this one is defined. The remote device server retrieves the value of the free property only during the admin device initialization, so if this device server is not restarted, the value of the hwm returned by the admin device when ZmqEventSubscriptionChange is invoked won't change, and even if it is restarted, this value won't change 99.9999% of the cases because most of the users don't change this CtrlSystem/EventBufferHwm free property so often.
I think the users can easily live with the fix you are suggesting. And if they are using a buggy ZMQ version and they decide to change the CtrlSystem/EventBufferHwm free property, they will have to restart their clients in order to get the events working properly and the new value taken into account.