1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 <2018> 2019 2020 2021 2022 2023 2024 | Index | 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 <2018> 2019 2020 2021 2022 2023 2024 |
<== Date ==> | <== Thread ==> |
---|
Subject: | Re: PMAC asyn autoconnect issue |
From: | Bruno Martins <[email protected]> |
To: | Torsten Bögershausen <[email protected]> |
Cc: | "[email protected]" <[email protected]>, "[email protected]" <[email protected]> |
Date: | Thu, 15 Feb 2018 12:03:06 -0500 |
Here's a minimal IOC that reproduces the issuepmacasyn from here (with all patches in debian/patches applied):Asyn R4-33Motor R6-10Base R3.15.5Hi Torsten,Just for the sake of completeness I rebuilt my whole environment from source (git):
https://github.com/epicsdeb/pmacasyn
$ 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:M2As 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 PResponse: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!
BrunoOn 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/pma <https://github.com/epicsdeb/pcAsynIPPortSrc/pmacAsynIPPort. c#L184 macasyn/blob/master/pmacApp/pm >acAsynIPPortSrc/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 Port 10.41.104.10:1025 <http://10.41.104.10:1025>: Disconnected
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
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 Port 10.41.104.10:1025 <http://10.41.104.10:1025>: Connected
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
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 Port 10.41.104.10:1025 <http://10.41.104.10:1025>: Disconnected
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
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 Command :#2 ? F P____
pasynOctetSyncIO->writeRead. command: #2 ? F P
2018/02/12 12:00:14.826 drvPmacAxisGetStatus: not all status values
returned. Status: 3
__ __
__ __
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/87e784335736de782 980b7600bd7d6e42179511a/asyn/a synDriver/asynManager.c#L1505
<https://github.com/epics-modules/asyn/blob/87e784335736de78 2980b7600bd7d6e42179511a/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____