Experimental Physics and
Industrial Control System

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