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: CAEN R1470ET HVPS - Asyn + Stream Device auto connect does not recover communication |
From: | Mark Rivers via Tech-talk <tech-talk at aps.anl.gov> |
To: | "'Paduan Donadio, Marcio'" <marcio at slac.stanford.edu> |
Cc: | "tech-talk at aps.anl.gov" <tech-talk at aps.anl.gov> |
Date: | Tue, 1 Sep 2020 22:34:16 +0000 |
Hi Paduan, Ø
It looks like the equipment stops answering but Asyn still shows that the connection is opened and when it writes to the port the result is Asyn success. If the device crashes or otherwise becomes unresponsive without properly closing the socket it will take a long time before the client (the drvAsynTCP driver) gets informed of this. The messages it sends
just queue up in the TCP stack on either the client or the server. This just the way that TCP works. That is why disconnectOnReadTimeout was added to asyn, and in general it is a good thing to use. That way whenever the device reply times out asyn will
close the socket and, if autoconnect is enabled, try to reopen the connection to the device. Ø
If we close and open the port again, communication is reestablished.
What do you mean by that? How did you do it? Ø
I’ve tried disconnectOnReadTimeout. Asyn disconnected after it, but then neither auto-connect or manual connection were able to open the connection again. The system is still in this condition as
we were not authorized to reboot the IOC, yet. I don’t understand why the disconnectOnReadTimeout disconnection would be any different from whatever you did when you said you “close and open the port again”. That sounds like a truly dead device. Can you ping the CAEN device? Can you open a manual telnet connection to it on port 1470, which seems to be the port you are using? Those are both things you can try
without restarting the IOC. Do you believe that restarting the IOC will fix the problem, or do you think you will need to power-cycle the CAEN? I don’t understand this sequence: 2020/08/28 14:15:55.193 hvm-ltuh-mc01:1470 write 29 $BD:0,CMD:MON,CH:5,PAR:VSET 2020/08/28 14:15:55.289 hvm-ltuh-mc01:1470 read 26 #BD:00,CMD:OK,VAL:3000.0 2020/08/28 14:16:00.266 HVM:LTUH:200:ASYN: exception 3, asynExceptionTraceMask 2020/08/28 14:16:00.283 HV0 set Eos 0 2020/08/28 14:16:00.323 asynManager::portThread port=HV0 callback 2020/08/28 14:16:00.393 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:00.472 HV0 schedule queueRequest timeout 2020/08/28 14:16:00.534 asynManager::portThread port=HV0 callback 2020/08/28 14:16:00.604 hvm-ltuh-mc01:1470 read. 2020/08/28 14:16:00.657 HV0 get Eos 0 You said “Communication was ok, until it stopped and we set some masks to diagnose:”. But communication does not appear to have stopped before you set those masks? It had been less than 5 seconds since the
last successful read, correct? Was there some other reason the asynTrace was turned on then? asynReport after using disconnectOnReadTimeout: Cexp@ioc-ltuh-mc02>asynReport(4) HV0 multiDevice:No canBlock:Yes autoConnect:Yes enabled:Yes connected:No numberConnects 146 That shows that it has connected 146 times. Did you connect manually 146 times? That seems unlikely, so it seems that perhaps disconnectOnReadTimeout was doing what it is supposed to do, i.e. getting a read
timeout, disconnecting and reconnecting? Mark From: Tech-talk <tech-talk-bounces at aps.anl.gov>
On Behalf Of Paduan Donadio, Marcio via Tech-talk Hello, all. I hope you can help me to decipher a scenario with an Ethernet device, Asyn, and Stream Device. It looks like the equipment stops answering but Asyn still shows that the connection is opened and when it writes
to the port the result is Asyn success. Auto-connect does not act, I guess that is because Asyn is happy with the connection. If we close and open the port again, communication is reestablished. I’ve tried disconnectOnReadTimeout. Asyn disconnected after it,
but then neither auto-connect or manual connection were able to open the connection again. The system is still in this condition as we were not authorized to reboot the IOC, yet. Detailed data: Asyn R4-32 Stream Device 2.8.9 ----------------------------------------------------------------------- Communication was ok, until it stopped and we set some masks to diagnose: 2020/08/28 14:15:55.020 hvm-ltuh-mc01:1470 write 29 $BD:0,CMD:MON,CH:4,PAR:VSET 2020/08/28 14:15:55.116 hvm-ltuh-mc01:1470 read 26 #BD:00,CMD:OK,VAL:4500.0 2020/08/28 14:15:55.193 hvm-ltuh-mc01:1470 write 29 $BD:0,CMD:MON,CH:5,PAR:VSET 2020/08/28 14:15:55.289 hvm-ltuh-mc01:1470 read 26 #BD:00,CMD:OK,VAL:3000.0 2020/08/28 14:16:00.266 HVM:LTUH:200:ASYN: exception 3, asynExceptionTraceMask 2020/08/28 14:16:00.283 HV0 set Eos 0 2020/08/28 14:16:00.323 asynManager::portThread port=HV0 callback 2020/08/28 14:16:00.393 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:00.472 HV0 schedule queueRequest timeout 2020/08/28 14:16:00.534 asynManager::portThread port=HV0 callback 2020/08/28 14:16:00.604 hvm-ltuh-mc01:1470 read. 2020/08/28 14:16:00.657 HV0 get Eos 0 2020/08/28 14:16:00.696 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:00.775 HV0 set Eos 0 2020/08/28 14:16:00.816 HV0 schedule queueRequest timeout 2020/08/28 14:16:00.878 hvm-ltuh-mc01:1470 write. 2020/08/28 14:16:00.931 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:01.010 wrote 29 to hvm-ltuh-mc01:1470, return asynSuccess. 2020/08/28 14:16:01.090 HV0 schedule queueRequest timeout 2020/08/28 14:16:01.152 HV0 set Eos 0 2020/08/28 14:16:01.192 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:01.271 HV0 schedule queueRequest timeout 2020/08/28 14:16:01.333 HV0 addr -1 queueRequest priority 0 from lockHolder 2020/08/28 14:16:01.413 HV0 schedule queueRequest timeout 2020/08/28 14:16:01.474 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:01.554 HV0 schedule queueRequest timeout 2020/08/28 14:16:01.615 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:01.694 HV0 schedule queueRequest timeout 2020/08/28 14:16:01.756 asynManager::portThread port=HV0 callback 2020/08/28 14:16:01.825 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:01.905 HV0 get Eos 0 2020/08/28 14:16:01.945 HV0 schedule queueRequest timeout 2020/08/28 14:16:02.008 HV0 set Eos 2 2020/08/28 14:16:02.053 HVM:LTUH:200:ASYN: exception 3, asynExceptionTraceMask 2020/08/28 14:16:02.136 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:02.215 hvm-ltuh-mc01:1470 read. 2020/08/28 14:16:02.267 HV0 schedule queueRequest timeout 2020/08/28 14:16:02.330 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:02.408 HV0 schedule queueRequest timeout 2020/08/28 14:16:02.470 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:02.548 HV0 schedule queueRequest timeout 2020/08/28 14:16:05.582 HVM:LTUH:200:ASYN: exception 3, asynExceptionTraceMask 2020/08/28 14:16:05.612 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:05.679 HV0 schedule queueRequest timeout 2020/08/28 14:16:05.740 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:05.819 HV0 schedule queueRequest timeout 2020/08/28 14:16:05.881 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:05.960 HV0 schedule queueRequest timeout 2020/08/28 14:16:06.021 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:06.100 HV0 schedule queueRequest timeout 2020/08/28 14:16:06.162 HV0 set Eos 0 2020/08/28 14:16:06.202 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:06.282 HV0 schedule queueRequest timeout 2020/08/28 14:16:06.343 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:06.422 HV0 schedule queueRequest timeout 2020/08/28 14:16:06.484 asynManager::portThread port=HV0 callback 2020/08/28 14:16:06.554 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:06.633 HV0 schedule queueRequest timeout 2020/08/28 14:16:06.695 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:06.773 HV0 schedule queueRequest timeout 2020/08/28 14:16:06.835 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:06.914 HV0 schedule queueRequest timeout 2020/08/28 14:16:06.975 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:07.055 HV0 schedule queueRequest timeout (…) 2020/08/28 14:16:31.102 HVM:LTUH:200:ASYN: exception 3, asynExceptionTraceMask 2020/08/28 14:16:31.125 HV0 set Eos 0 2020/08/28 14:16:31.160 asynManager::portThread port=HV0 callback 2020/08/28 14:16:31.229 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:31.309 HV0 schedule queueRequest timeout 2020/08/28 14:16:31.370 asynManager::portThread port=HV0 callback 2020/08/28 14:16:31.440 hvm-ltuh-mc01:1470 read. 2020/08/28 14:16:31.493 HV0 get Eos 0 2020/08/28 14:16:31.533 HV0 set Eos 0 2020/08/28 14:16:31.573 hvm-ltuh-mc01:1470 write. 2020/08/28 14:16:31.626 wrote 29 to hvm-ltuh-mc01:1470, return asynSuccess. 2020/08/28 14:16:31.706 HV0 addr -1 queueRequest priority 0 not lockHolder 2020/08/28 14:16:31.786 HV0 set Eos 0 ----------------------------------------------------------------------- Cexp@ioc-ltuh-mc02>asynReport(4) HV0 multiDevice:No canBlock:Yes autoConnect:Yes enabled:Yes connected:Yes numberConnects 3 nDevices 0 nQueued 49 blocked:No asynManagerLock:No synchronousLock:Yes exceptionActive:No exceptionUsers 170 exceptionNotifys 0 traceMask:0xb traceIOMask:0x7 traceInfoMask:0x1 interposeInterfaceList asynOctet pinterface 0x2e48048 drvPvt 0x2930310 interfaceList asynCommon pinterface 0x2d5175c drvPvt 0x2926f60 asynOption pinterface 0x2d51768 drvPvt 0x2926f60 asynOctet pinterface 0x2927040 drvPvt 0x2926f60 Port hvm-ltuh-mc01:1470: Connected fd: 16 Characters written: 31886349 Characters read: 18628310 Asyn report a few minutes later: Cexp@ioc-ltuh-mc02>asynReport(4) HV0 multiDevice:No canBlock:Yes autoConnect:Yes enabled:Yes connected:Yes numberConnects 3 nDevices 0 nQueued 49 blocked:No asynManagerLock:No synchronousLock:Yes exceptionActive:No exceptionUsers 170 exceptionNotifys 0 traceMask:0xb traceIOMask:0x7 traceInfoMask:0x1 interposeInterfaceList asynOctet pinterface 0x2e48048 drvPvt 0x2930310 interfaceList asynCommon pinterface 0x2d5175c drvPvt 0x2926f60 asynOption pinterface 0x2d51768 drvPvt 0x2926f60 asynOctet pinterface 0x2927040 drvPvt 0x2926f60 Port hvm-ltuh-mc01:1470: Connected fd: 16 Characters written: 31887627 Characters read: 18628310 ----------------------------------------------------------------------- After manually reopening the connection, the device restart sending characters (this was in another day): 2020/08/31 12:11:57.446 hvm-ltuh-mc01:1470 write 29 $BD:0,CMD:MON,CH:0,PAR:VSET $BD:0,CMD:MON,CH:0,PAR:VSET\r\n 24 42 44 3a 30 2c 43 4d 44 3a 4d 4f 4e 2c 43 48 3a 30 2c 50 41 52 3a 56 53 45 54 0d 0a 2020/08/31 12:11:58.600 hvm-ltuh-mc01:1470 write 29 $BD:0,CMD:MON,CH:5,PAR:VMON $BD:0,CMD:MON,CH:5,PAR:VMON\r\n 24 42 44 3a 30 2c 43 4d 44 3a 4d 4f 4e 2c 43 48 3a 35 2c 50 41 52 3a 56 4d 4f 4e 0d 0a 2020/08/31 12:11:59.765 hvm-ltuh-mc01:1470 write 29 $BD:0,CMD:MON,CH:1,PAR:VSET $BD:0,CMD:MON,CH:1,PAR:VSET\r\n 24 42 44 3a 30 2c 43 4d 44 3a 4d 4f 4e 2c 43 48 3a 31 2c 50 41 52 3a 56 53 45 54 0d 0a 2020/08/31 12:11:59.926 hvm-ltuh-mc01:1470 read 26 #BD:00,CMD:OK,VAL:0800.0 #BD:00,CMD:OK,VAL:0800.0\r\n 23 42 44 3a 30 30 2c 43 4d 44 3a 4f 4b 2c 56 41 4c 3a 30 38 30 30 2e 30 0d 0a 2020/08/31 12:12:00.122 hvm-ltuh-mc01:1470 write 29 $BD:0,CMD:MON,CH:0,PAR:STAT $BD:0,CMD:MON,CH:0,PAR:STAT\r\n 24 42 44 3a 30 2c 43 4d 44 3a 4d 4f 4e 2c 43 48 3a 30 2c 50 41 52 3a 53 54 41 54 0d 0a 2020/08/31 12:12:00.345 hvm-ltuh-mc01:1470 read 25 #BD:00,CMD:OK,VAL:00001 #BD:00,CMD:OK,VAL:00001\r\n This is how Asyn report looks like one things are going well: Cexp@ioc-ltuh-mc02>asynReport(4) HV0 multiDevice:No canBlock:Yes autoConnect:Yes enabled:Yes connected:Yes numberConnects 4 nDevices 0 nQueued 3 blocked:No asynManagerLock:No synchronousLock:Yes exceptionActive:No exceptionUsers 170 exceptionNotifys 0 traceMask:0x1 traceIOMask:0x1 traceInfoMask:0x1 interposeInterfaceList asynOctet pinterface 0x2e48048 drvPvt 0x2930310 interfaceList asynCommon pinterface 0x2d5175c drvPvt 0x2926f60 asynOption pinterface 0x2d51768 drvPvt 0x2926f60 asynOctet pinterface 0x2927040 drvPvt 0x2926f60 Port hvm-ltuh-mc01:1470: Connected fd: 16 Characters written: 32245553 Characters read: 18922078 ----------------------------------------------------------------------- Dbpr when things are bad: Cexp@ioc-ltuh-mc02>dbpr("HVM:LTUH:200:BoardName","4") ACKS: INVALID ACKT: YES APST: On Change ASG : ASP : PTR 0x3651f20 BKLNK: ELL 1 [0x2ea1e00 .. 0x2ea1e00] BKPT: 00 DESC: BoardName DISA: 0 DISP: 0 DISS: NO_ALARM DISV: 1 DPVT: PTR 0x35bbea0 DSET: PTR 0x2e4882c DTYP: stream EVNT: FLNK: CONSTANT INP : INST_IO @caenN1470.proto readstring(0,BDNAME,HVM:LTUH:200) HV0 LCNT: 0 LSET: PTR 0x2fa7680 MLIS: ELL 2 [0x39950b8 .. 0x3994f00] MLOK: 03 50 22 90 MPST: On Change NAME: HVM:LTUH:200:BoardName NSEV: NO_ALARM NSTA: NO_ALARM OLDSIMM: NO OVAL: R1470ET PACT: 1 PHAS: 0 PINI: NO PPN : PTR 0x0 PPNR: PTR 0x0 PRIO: LOW PROC: 0 PUTF: 0 RDES: PTR 0x2be1910 RPRO: 0 RSET: PTR 0x2e498e0 SCAN: Passive SDIS: CONSTANT SDLY: -1 SEVR: INVALID SIML: CONSTANT SIMM: NO SIMPVT: PTR 0x0 SIMS: NO_ALARM SIOL: CONSTANT SPVT: PTR 0x0 SSCN: <nil> STAT: TIMEOUT SVAL: TIME: 2020-08-31 13:09:47.237075064 TPRO: 0 TSE : 0 TSEL: CONSTANT UDF : 0 UDFS: INVALID VAL : R1470ET ----------------------------------------------------------------------- Dbpr after using disconnectOnReadTimeout: Cexp@ioc-ltuh-mc02>dbpr("HVM:LTUH:200:BoardName","4") ACKS: INVALID ACKT: YES APST: On Change ASG : ASP : PTR 0x3651f20 BKLNK: ELL 1 [0x2ea1e00 .. 0x2ea1e00] BKPT: 00 DESC: BoardName DISA: 0 DISP: 0 DISS: NO_ALARM DISV: 1 DPVT: PTR 0x35bbea0 DSET: PTR 0x2e4882c DTYP: stream EVNT: FLNK: CONSTANT INP : INST_IO @caenN1470.proto readstring(0,BDNAME,HVM:LTUH:200) HV0 LCNT: 0 LSET: PTR 0x2fa7680 MLIS: ELL 2 [0x39950b8 .. 0x3994f00] MLOK: 03 50 22 90 MPST: On Change NAME: HVM:LTUH:200:BoardName NSEV: NO_ALARM NSTA: NO_ALARM OLDSIMM: NO OVAL: R1470ET PACT: 0 PHAS: 0 PINI: NO PPN : PTR 0x0 PPNR: PTR 0x0 PRIO: LOW PROC: 0 PUTF: 0 RDES: PTR 0x2be1910 RPRO: 0 RSET: PTR 0x2e498e0 SCAN: Passive SDIS: CONSTANT SDLY: -1 SEVR: INVALID SIML: CONSTANT SIMM: NO SIMPVT: PTR 0x0 SIMS: NO_ALARM SIOL: CONSTANT SPVT: PTR 0x0 SSCN: <nil> STAT: COMM SVAL: TIME: 2020-08-31 13:14:51.686086457 TPRO: 0 TSE : 0 TSEL: CONSTANT UDF : 0 UDFS: INVALID VAL : R1470ET asynReport after using disconnectOnReadTimeout: Cexp@ioc-ltuh-mc02>asynReport(4) HV0 multiDevice:No canBlock:Yes autoConnect:Yes enabled:Yes connected:No numberConnects 146 nDevices 0 nQueued 28 blocked:No asynManagerLock:No synchronousLock:Yes exceptionActive:No exceptionUsers 170 exceptionNotifys 0 traceMask:0x1 traceIOMask:0x1 traceInfoMask:0x1 interposeInterfaceList asynOctet pinterface 0x2e48048 drvPvt 0x2930310 interfaceList asynCommon pinterface 0x2d5175c drvPvt 0x2926f60 asynOption pinterface 0x2d51768 drvPvt 0x2926f60 asynOctet pinterface 0x2927040 drvPvt 0x2926f60 Port hvm-ltuh-mc01:1470: Disconnected fd: -1 Characters written: 34072265 Characters read: 20373454 ----------------------------------------------------------------------- Turning off disconnectOnReadTimeout and trying to manually disconnect didn’t work anymore: 2020/08/31 14:32:29.651 Can't connect to hvm-ltuh-mc01:1470: Connection timed out HV0 -1 autoConnect could not connect 2020/08/31 14:33:44.717 Can't connect to hvm-ltuh-mc01:1470: Connection timed out HV0 -1 autoConnect could not connect 2020/08/31 14:44:13.743 HVM:LTUH:200:ASYN: queueRequest failed 2020/08/31 14:44:13.745 HVM:LTUH:200:ASYN: queueRequest failed 2020/08/31 14:44:15.565 HVM:LTUH:200:ASYN: queueRequest failed 2020/08/31 14:44:15.567 HVM:LTUH:200:ASYN: queueRequest failed 2020/08/31 14:44:21.023 HVM:LTUH:200:ASYN: special queueRequest timeout 2020/08/31 14:44:27.077 HVM:LTUH:200:ASYN: special queueRequest timeout 2020/08/31 14:45:19.767 Can't connect to hvm-ltuh-mc01:1470: Connection timed out HV0 -1 autoConnect could not connect 2020/08/31 14:46:34.831 Can't connect to hvm-ltuh-mc01:1470: Connection timed out HV0 -1 autoConnect could not connect |