onFirstConnect() unexpected interaction with print and debug statements

[Monarda]

onFirstConnect() handler functions show differing behaviour depending on whether diagnostic print or logging debug statements are used.

In the following code seven different onFirstConnect() functions are shown. (This is a simplified version of the logic for applying a control.limitHigh to a PV.) The onFirstConnect functions only differ in their print statements. Note, however, that the final two PVs add an unused control structure which is printed.

""" Example of handler sensitivity to print statement """

from p4p.nt import NTScalar
from p4p.server import Server
from p4p.server.thread import SharedPV, Handler

class ExampleHandler1(Handler):
    """ Example of onFirstConnect without prints """
    def onFirstConnect(self, pv : SharedPV) -> None:
        current_raw = pv.current().raw
        current_raw['value'] = 5.0
        pv.post(value=current_raw)

class ExampleHandler2(Handler):
    """ Example of onFirstConnect with print of value only before change of value """
    def onFirstConnect(self, pv : SharedPV) -> None:
        current_raw = pv.current().raw
        print(current_raw['value'])
        current_raw['value'] = 5.0
        pv.post(value=current_raw)

class ExampleHandler3(Handler):
    """ Example of onFirstConnect with print of whole structure before change of value """
    def onFirstConnect(self, pv : SharedPV) -> None:
        current_raw = pv.current().raw
        print(current_raw)
        current_raw['value'] = 5.0
        pv.post(value=current_raw)

class ExampleHandler4(Handler):
    """ Example of onFirstConnect with print of value only after change of value """
    def onFirstConnect(self, pv : SharedPV) -> None:
        current_raw = pv.current().raw
        current_raw['value'] = 5.0
        print(current_raw['value'])
        pv.post(value=current_raw)

class ExampleHandler5(Handler):
    """ Example of onFirstConnect with print of whole structure after change of value """
    def onFirstConnect(self, pv : SharedPV) -> None:
        current_raw = pv.current().raw
        current_raw['value'] = 5.0
        print(current_raw)
        pv.post(value=current_raw)

class ExampleHandler6(Handler):
    """ Example of onFirstConnect with print of value only after change of value """
    def onFirstConnect(self, pv : SharedPV) -> None:
        current_raw = pv.current().raw
        print(current_raw['control'])
        current_raw['value'] = 5.0
        pv.post(value=current_raw)

class ExampleHandler7(Handler):
    """ Example of onFirstConnect with print of value only after change of value """
    def onFirstConnect(self, pv : SharedPV) -> None:
        current_raw = pv.current().raw
        current_raw['value'] = 5.0
        print(current_raw['control'])
        pv.post(value=current_raw)

pvexample1 = SharedPV(nt=NTScalar('d'), handler=ExampleHandler1(), initial=7.0)
pvexample2 = SharedPV(nt=NTScalar('d'), handler=ExampleHandler2(), initial=7.0)
pvexample3 = SharedPV(nt=NTScalar('d'), handler=ExampleHandler3(), initial=7.0)
pvexample4 = SharedPV(nt=NTScalar('d'), handler=ExampleHandler4(), initial=7.0)
pvexample5 = SharedPV(nt=NTScalar('d'), handler=ExampleHandler5(), initial=7.0)
pvexample6 = SharedPV(nt=NTScalar('d', control=True), handler=ExampleHandler6(), initial=7.0)
pvexample7 = SharedPV(nt=NTScalar('d', control=True), handler=ExampleHandler7(), initial=7.0)

Server.forever(providers=[{
    'demo:pv:t1':pvexample1,
    'demo:pv:t2':pvexample2,
    'demo:pv:t3':pvexample3,
    'demo:pv:t4':pvexample4,
    'demo:pv:t5':pvexample5,
    'demo:pv:t6':pvexample6,
    'demo:pv:t7':pvexample7,
}])

When the server code above is run the result of the first use of a PV get function for each PV is as follows:

> python -m p4p.client.cli get demo:pv:t1
demo:pv:t1 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli get demo:pv:t2
demo:pv:t2 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli get demo:pv:t3
demo:pv:t3 Thu Jan  1 00:00:00 1970 7.0
> python -m p4p.client.cli get demo:pv:t4
demo:pv:t4 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli get demo:pv:t5
demo:pv:t5 Thu Jan  1 00:00:00 1970 7.0
> python -m p4p.client.cli get demo:pv:t6
demo:pv:t6 Thu Jan  1 00:00:00 1970 7.0
> python -m p4p.client.cli get demo:pv:t7
demo:pv:t7 Thu Jan  1 00:00:00 1970 7.0

All PVs are initialised with a value of 7.0. The expected output is 5.0.

Monitor functions produce the following results when run sequentially on the same server:

> python -m p4p.client.cli monitor demo:pv:t1
demo:pv:t1 Error: Channel disconnected
demo:pv:t1 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli monitor demo:pv:t2
demo:pv:t2 Error: Channel disconnected
demo:pv:t2 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t2 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli monitor demo:pv:t3
demo:pv:t3 Error: Channel disconnected
demo:pv:t3 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t3 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli monitor demo:pv:t4
demo:pv:t4 Error: Channel disconnected
demo:pv:t4 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t4 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli monitor demo:pv:t5
demo:pv:t5 Error: Channel disconnected
demo:pv:t5 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t5 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli monitor demo:pv:t6
demo:pv:t6 Error: Channel disconnected
demo:pv:t6 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t6 Thu Jan  1 00:00:00 1970 5.0
> python -m p4p.client.cli monitor demo:pv:t7
demo:pv:t7 Error: Channel disconnected
demo:pv:t7 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t7 Thu Jan  1 00:00:00 1970 5.0

When the server code is stopped and restarted between each monitor command the following results are found:

> python -m p4p.client.cli monitor demo:pv:t1
demo:pv:t1 Error: Channel disconnected
demo:pv:t1 Thu Jan  1 00:00:00 1970 5.0
demo:pv:t1 Error: Disconnected
> python -m p4p.client.cli monitor demo:pv:t2
demo:pv:t2 Error: Channel disconnected
demo:pv:t2 Thu Jan  1 00:00:00 1970 5.0
demo:pv:t2 Error: Disconnected
> python -m p4p.client.cli monitor demo:pv:t3
demo:pv:t3 Error: Channel disconnected
demo:pv:t3 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t3 Thu Jan  1 00:00:00 1970 5.0
demo:pv:t3 Error: Disconnected
> python -m p4p.client.cli monitor demo:pv:t4
demo:pv:t4 Error: Channel disconnected
demo:pv:t4 Thu Jan  1 00:00:00 1970 5.0
demo:pv:t4 Error: Disconnected
> python -m p4p.client.cli monitor demo:pv:t5
demo:pv:t5 Error: Channel disconnected
demo:pv:t5 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t5 Thu Jan  1 00:00:00 1970 5.0
demo:pv:t5 Error: Disconnected
> python -m p4p.client.cli monitor demo:pv:t6
demo:pv:t6 Error: Channel disconnected
demo:pv:t6 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t6 Thu Jan  1 00:00:00 1970 5.0
demo:pv:t6 Error: Disconnected
> python -m p4p.client.cli monitor demo:pv:t7
demo:pv:t7 Error: Channel disconnected
demo:pv:t7 Thu Jan  1 00:00:00 1970 7.0
demo:pv:t7 Thu Jan  1 00:00:00 1970 5.0
demo:pv:t7 Error: Disconnected

Those onFirstCall functions which do not change value for the initial get emit a second change to the expected value when monitored.

The behaviour for the monitor command changes for those PVs which return 5.0 on a get, depending on whether the server was already running or was restarted between monitor commands.

The example code above has been tested with Python 3.11.2 on Windows with the following package versions installed:

Package        Version
-------------- ------------
epicscorelibs  7.0.7.99.0.2
nose2          0.15.1
numpy          1.26.4
p4p            4.1.12
pip            22.3.1
ply            3.11
pvxslibs       1.3.1
setuptools     65.5.0
setuptools-dso 2.11a2

[mdavidsaver]

My original motivation for the onFirstConnect()/onLastDisconnect() callbacks was to allow for "lazy" initialization of a SharedPV. Allowing a SharedPV with no clients to avoid maintaining a current Value, or even a defined Type. The basic pattern being for onFirstConnect to call SharedPV.open() (not post()) and onLastDisconnect to call SharedPV.close(). Constructing SharedPV(..., initial=x) is equivalent to constructing and immediately calling open(x).

Maybe a lack of imagination on my part... What are you trying to achieve in onFirstConnect when the SharedPV is already "open"?

[Monarda]

It's an apt question! You can probably guess some of the answer from the PR I've just submitted about a handler for implementing the standard Normative Type fields like control and valueAlarm. We noticed the issue above when we saw different behaviour in that code depending on whether debug output was on or off.

We're looking at using p4p to directly interface p4p PVs with hardware without an intermediate IOC. It's a well-designed library so we already have some prototypes which are looking good. But that means that we need implement some things like control in order to protect hardware. The handler submitted for review can do this but has an issue around the evaluation of initial values.

We had some discussion at our end and thought that adding an onOpen() to the handler functionality would be a better solution to the issue of ensuring that the handler logic is enforced. But that seemed like a larger request to make so we've currently implemented it with onFirstConnect. The issue with the print/logging statements had me worried that I had some more subtle mistake in the existing implementation.