Experimental Physics and
Industrial Control System

Hi Torsten,

Just for the sake of completeness I rebuilt my whole environment from source (git):

Base R3.15.5

Motor R6-10

Asyn R4-33

pmacasyn from here (with all patches in debian/patches applied):

https://github.com/epicsdeb/pmacasyn

Here's a minimal IOC that reproduces the issue

$ cat st.cmd
#!../../bin/linux-x86_64/tpmac
< envPaths
epicsEnvSet("STREAM_PROTOCOL_PATH","${PMACUTIL}/pmacUtilApp/protocol")
epicsEnvSet("PREFIX","LABTEST:STPC01")
dbLoadDatabase("${TOP}/dbd/tpmac.dbd",0,0)
tpmac_registerRecordDeviceDriver(pdbbase)
pmacAsynIPConfigure("P0","<ip redacted>:1025")
#asynSetOption("P0",0,"disconnectOnReadTimeout","Y")
pmacCreateController("motor","P0",0,2,100,1000)
pmacCreateAxis("motor", 1)
pmacCreateAxis("motor", 2)
dbLoadTemplate("$(TOP)/db/labTest.substitutions")
iocInit()

$ cat labTest.substitutions
file "$(TOP)/db/motor.db"
{
# ADDR ---> axis #
# NOTE ---> 2 asyn ports: 1) lowel comms ("P0"), and 2) Motor Record ("motor")
pattern
{ P,             M,                   MOTOR,   PORT,    ADDR, DESC,             DTYP,        EGU,    MRES,PREC     }
{ "LABTEST:", "STPC01:M1",           "motor", "P0",    1,      "Axis 1",         asynMotor,    "mm",    0.00079375,    2     }
{ "LABTEST:", "STPC01:M2",            "motor", "P0",    2,      "Axis 2",         asynMotor,    "mm",    0.00079375,    2    }
}

$ cat db/motor.db
record(motor,"$(P)$(M)")
{
    field(DESC,"$(DESC)")
    field(DTYP,"$(DTYP)")
    field(OUT,"@asyn($(MOTOR),$(ADDR))")
    field(RTRY,"0")
  # Use of MRES is deliberate on the following line.
  # This sets the retry deadband to the smallest possible size.
  field(RDBD,$(MRES="1"))
  field(MRES,$(MRES="1"))
  field(EGU,$(EGU="None"))
  field(PREC,$(PREC="0"))
}


epics> dbl
LABTEST:STPC01:M1
LABTEST:STPC01:M2

As soon as I turn off the controller, these messages appear:

epics> 2018/02/15 10:12:19.085 P0 read pmacFlush failed - thisRead=0, eomReason=0, status=1
2018/02/15 10:12:29.095 P0 read pmacReadReady failed status=1,retval=02018/02/15 10:12:29.095 pmacController::lowLevelWriteRead: Error from pasynOctetSyncIO->writeRead. command: ???
2018/02/15 10:12:29.095 pmacController::getGlobalStatus: Error reading ???.
2018/02/15 10:12:29.095 pmacController::poll: Error reading or setting params.
2018/02/15 10:12:29.095 drvPmacAxisGetStatus: not all status values returned. Status: 0
Command :#1 ? F P
Response:2018/02/15 10:12:29.095 drvPmacAxisGetStatus: not all status values returned. Status: 0
Command :#2 ? F P
Response:2018/02/15 10:12:30.096 pmacController::getGlobalStatus: Error reading ???. nvals: -1, response:
2018/02/15 10:12:30.096 pmacController::poll: Error reading or setting params.
2018/02/15 10:12:30.096 drvPmacAxisGetStatus: not all status values returned. Status: 0
Command :#1 ? F P
Response:2018/02/15 10:12:30.096 drvPmacAxisGetStatus: not all status values returned. Status: 0
Command :#2 ? F P
Response:2018/02/15 10:12:31.096 pmacController::getGlobalStatus: Error reading ???. nvals: -1, response:
2018/02/15 10:12:31.096 pmacController::poll: Error reading or setting params.
2018/02/15 10:12:31.096 drvPmacAxisGetStatus: not all status values returned. Status: 0
Command :#1 ? F P
Response:2018/02/15 10:12:31.096 drvPmacAxisGetStatus: not all status values returned. Status: 0
Command :#2 ? F P

Response:

After 20 min (see below), I powered the controller back on, but the messages continued.

As Mark mentioned, it seems that Linux takes some time to shutdown the socket. My previous tests (using pasynManager->isConnected to probe for connection status) seemed to show that it takes ~15min on this particular system for isConnected to go from 1 to 0. It also seems that by turning the controller back on isConnected goes from 0 to 1. So my current suspicion is in agreement with Mark's comments: something might be off in the interpose code.


I will continue investigating.

Thanks!

Bruno

On Thu, Feb 15, 2018 at 2:15 AM, Torsten Bögershausen <[email protected]> wrote:

On 12/02/18 20:45, Bruno Martins wrote:

Hi Mark,

We're using tpmac-asyn 3.10.12, asyn R4-32.

Hej Bruno,
what is tpmac-asyn 3.10.12 ?

The printouts you are pointing out ("command: #2 ? F P") seem to come from
.../epicsdeb/pmacasyn/pmacApp/pmacAsynMotorPortSrc/pmacAxis.cpp

Which seems to be a classic model 3 driver (?).

I am unsure which SW you are running.

Could you send us the whole st.cmd ?
And may be a receipe how to get the modules you are using,
tpmac-asyn, which motor. Are you using git clone ? Or wget ?

Regarding pmacAsynIPConfigure, it immediately calls drvAsynIPPortConfigure: https://github.com/epicsdeb/pmacasyn/blob/master/pmacApp/pmacAsynIPPortSrc/pmacAsynIPPort.c#L184 <https://github.com/epicsdeb/pmacasyn/blob/master/pmacApp/pmacAsynIPPortSrc/pmacAsynIPPort.c#L184>


You're right that the return code is asynError (from queueLockPort [asynManager.c:1832]) but queueRequest returns asynDisconnected [asynManager.c:1505]. I added more debugging.


I noticed two things:

1. If the IOC starts with the controller powered off, the above messages are printed. asyn/tpmac correctly knows the device is disconnected, but there's no attempt at a reconnection, so powering it on doesn't do anything. Here's the report in this case:

asynManager::queueLockPort queueRequest failed: port P0 not connected
2018/02/12 14:05:56.201 pmacController::lowLevelWriteRead: Error from pasynOctetSyncIO->writeRead. command: #2 ? F P
2018/02/12 14:05:56.201 drvPmacAxisGetStatus: not all status values returned. Status: 3

epics> asynReport 5 P0
P0 multiDevice:No canBlock:Yes autoConnect:Yes
     enabled:Yes connected:No numberConnects 0
     nDevices 0 nQueued 18 blocked:No
     asynManagerLock:No synchronousLock:Yes
     exceptionActive:No exceptionUsers 11 exceptionNotifys 0
     traceMask:0x1 traceIOMask:0x0 traceInfoMask:0x1
     interposeInterfaceList
         asynOctet pinterface 0x7fcf1ca2c900 drvPvt 0xf5c060
     interfaceList
         asynCommon pinterface 0x7fcf1ca29650 drvPvt 0xf579e0
         asynOption pinterface 0x7fcf1ca29670 drvPvt 0xf579e0
         asynOctet pinterface 0xf57b00 drvPvt 0xf579e0
     Port 10.41.104.10:1025 <http://10.41.104.10:1025>: Disconnected
                     fd: -1
     Characters written: 0
        Characters read: 0


2. If the IOC starts with the controller powered on, everything works as expected:

epics> asynReport 5 P0
P0 multiDevice:No canBlock:Yes autoConnect:Yes
     enabled:Yes connected:Yes numberConnects 1
     nDevices 0 nQueued 0 blocked:No
     asynManagerLock:No synchronousLock:No
     exceptionActive:No exceptionUsers 11 exceptionNotifys 0
     traceMask:0x1 traceIOMask:0x0 traceInfoMask:0x1
     interposeInterfaceList
         asynOctet pinterface 0x7fafe57dc900 drvPvt 0x1aa6090
     interfaceList
         asynCommon pinterface 0x7fafe57d9650 drvPvt 0x1aa1a10
         asynOption pinterface 0x7fafe57d9670 drvPvt 0x1aa1a10
         asynOctet pinterface 0x1aa1b30 drvPvt 0x1aa1a10
     Port 10.41.104.10:1025 <http://10.41.104.10:1025>: Connected
                     fd: 7
     Characters written: 9787
        Characters read: 5345


Then when we yank the power from the controller:

asynManager::queueLockPort queueRequest timed out
2018/02/12 14:33:03.069 pmacController::lowLevelWriteRead: Error from pasynOctetSyncIO->writeRead. command: #1 ? F P
2018/02/12 14:33:03.069 drvPmacAxisGetStatus: not all status values returned. Status: 3

epics> asynReport 5 P0
P0 multiDevice:No canBlock:Yes autoConnect:Yes
     enabled:Yes connected:Yes numberConnects 1
     nDevices 0 nQueued 18 blocked:No
     asynManagerLock:No synchronousLock:Yes
     exceptionActive:No exceptionUsers 11 exceptionNotifys 0
     traceMask:0x1 traceIOMask:0x0 traceInfoMask:0x1
     interposeInterfaceList
         asynOctet pinterface 0x7fafe57dc900 drvPvt 0x1aa6090
     interfaceList
         asynCommon pinterface 0x7fafe57d9650 drvPvt 0x1aa1a10
         asynOption pinterface 0x7fafe57d9670 drvPvt 0x1aa1a10
         asynOctet pinterface 0x1aa1b30 drvPvt 0x1aa1a10
     Port 10.41.104.10:1025 <http://10.41.104.10:1025>: Connected
                     fd: 7
     Characters written: 26671
        Characters read: 11150


So it still thinks it is connected, even after quite some time.



I tried enabling the disconnectOnReadTimeout option, it yielded a weird behavior: with the motor controller powered ON, the IOC seems to start fine but then seems to disconnect from the controller by itself:

asynManager::queueLockPort queueRequest failed: port P0 not connected
2018/02/12 14:40:38.972 pmacController::lowLevelWriteRead: Error from pasynOctetSyncIO->writeRead. command: #1 ? F P
2018/02/12 14:40:38.972 drvPmacAxisGetStatus: not all status values returned. Status: 3

epics> asynReport 5 P0
P0 multiDevice:No canBlock:Yes autoConnect:Yes
     enabled:Yes connected:No numberConnects 1
     nDevices 0 nQueued 21 blocked:No
     asynManagerLock:No synchronousLock:Yes
     exceptionActive:No exceptionUsers 11 exceptionNotifys 0
     traceMask:0x1 traceIOMask:0x0 traceInfoMask:0x1
     interposeInterfaceList
         asynOctet pinterface 0x7f5c7df24900 drvPvt 0x8f21a0
     interfaceList
         asynCommon pinterface 0x7f5c7df21650 drvPvt 0x8edb20
         asynOption pinterface 0x7f5c7df21670 drvPvt 0x8edb20
         asynOctet pinterface 0x8edc40 drvPvt 0x8edb20
     Port 10.41.104.10:1025 <http://10.41.104.10:1025>: Disconnected
                     fd: -1
     Characters written: 848
        Characters read: 470



Bruno

On Mon, Feb 12, 2018 at 1:32 PM, Mark Rivers <[email protected] <mailto:[email protected]du>> wrote:

    Hi Bruno,____

    __ __

    I think your startup script contains this command, correct?____

    __ __

    pmacAsynIPConfigure(portName, hostInfo)____

    __ __

    This means that the pmac driver is not directly communicating with the
    drvAsynIPPort driver supplied with asyn.  It is talking to the port created
    with the above command, which implements the asynInterposeInterface between
    the pmac motor driver and the underlying drvAsynIPPort driver.  I have not
    studied that code carefully, but it is possible that it is doing something
    to prevent the reconnect feature from working correctly.____

    __ __

    I have tested the asyn autoreconnect feature quite a bit recently, when I
    was trying to reduce the number of error messages that are printed when a
    device is powered off and then back on again.  For example, look at the
    Modbus R2-10 release notes:____

    __ __

    http://cars9.uchicago.edu/software/epics/modbusReleaseNotes.html
    <http://cars9.uchicago.edu/software/epics/modbusReleaseNotes.html>____

    __ __

    Mark____

    __ __

    __ __

    *From:*[email protected]nl.gov <mailto:tech-talk-bounces@aps.anl.gov>
    [mailto:tech-talk-bounces@aps.anl.gov
    <mailto:tech-talk-bounces@aps.anl.gov>] *On Behalf Of *Mark Rivers
    *Sent:* Monday, February 12, 2018 12:10 PM
    *To:* 'Bruno Martins' <[email protected]
    <mailto:[email protected]>>; [email protected]
    <mailto:[email protected]>
    *Cc:* [email protected] <mailto:[email protected]>
    *Subject:* RE: PMAC asyn autoconnect issue____

    __ __

    Hi Bruno,____

    __ __

    What version of asyn are you using?____

    __ __

    What version of tpmac are you using?____

    __ __

    __Ø__2018/02/12 12:00:14.826 pmacController::lowLevelWriteRead: Error from
    pasynOctetSyncIO->writeRead. command: #2 ? F P
    2018/02/12 12:00:14.826 drvPmacAxisGetStatus: not all status values
    returned. Status: 3
    Command :#2 ? F P____

    __ __

    Note that Status: 3 is asynError, not asynDisconnected.____

    __ __

    Are you sure that asyn really thinks the port is disconnected at this
    time?  You should run asynReport on that port to see whether asyn thinks it
    is disconnected or not.____

    __ __

    One problem is that when you power-off an IP device on Linux it takes quite
    a while before the OS decides the socket is disconnected.  Before that time
    it returns an error like “Resource temporarily unavailable”.  During this
    time asyn will not try to reconnect, because it thinks it is still
    connected.____

    __ __

    This behavior is one reason that the drvAsynIPPort driver was enhanced in
    R4-29 to support the disconnectOnReadTimeout option.  If this option is
    enabled then the port will automatically disconnect whenever there is a
    read timeout.____

    __ __

    Mark____

    __ __

    __ __

    *From:*[email protected]nl.gov <mailto:tech-talk-bounces@aps.anl.gov>
    [mailto:tech-talk-bounces@aps.anl.gov
    <mailto:tech-talk-bounces@aps.anl.gov>] *On Behalf Of *Bruno Martins
    *Sent:* Monday, February 12, 2018 11:34 AM
    *To:* [email protected] <mailto:[email protected]>
    *Cc:* [email protected] <mailto:[email protected]>
    *Subject:* PMAC asyn autoconnect issue____

    __ __

    Hi,____

    I've been investigating an issue with the PMAC driver regarding
    reconnection via Ethernet. When the controller is powered off the IOC
    starts emitting messages like the following (as expected):

    2018/02/12 12:00:14.826 pmacController::lowLevelWriteRead: Error from
    pasynOctetSyncIO->writeRead. command: #2 ? F P
    2018/02/12 12:00:14.826 drvPmacAxisGetStatus: not all status values
    returned. Status: 3
    Command :#2 ? F P____

    __ __

    __ __

    However, when the controller is powered on again, the IOC does not
    re-establish the connection (even though noAutoConnect is set to zero).____

    This is the sequence of calls that lead to these messages:____

    lowLevelWriteRead calls pasynOctetSyncIO->writeRead
    pasynOctetSyncIO->writeRead calls pasynManager->queueLockPort____

    pasynManager->queueLockPort calls pasynManager->queueRequest____

    queueRequest sets checkPortConnect = TRUE____

    __ __

    Since the port is disconnected, queueRequest returns an error
    https://github.com/epics-modules/asyn/blob/87e784335736de782980b7600bd7d6e42179511a/asyn/asynDriver/asynManager.c#L1505
    <https://github.com/epics-modules/asyn/blob/87e784335736de782980b7600bd7d6e42179511a/asyn/asynDriver/asynManager.c#L1505>____

    If checkPortConnected was FALSE autoConnectDevice would be called later on
    and a new connection would be attempted. But for this particular call chain
    checkPortConnected is always set to TRUE.____

    Now, since queueRequest fails a request is never queued and
    pasynManager->portThread's autoConnectDevice is also not reached.

    ____

    So my question is how to properly configure/trigger an auto connect?____

    __ __

    __ __

    PS.: I found this old thread that might be related:

    https://epics.anl.gov/tech-talk/2012/msg01216.php
    <https://epics.anl.gov/tech-talk/2012/msg01216.php>

    ____

    __ __

    Thanks!____



    Bruno____