Experimental Physics and
Industrial Control System

Hi,

 

I am working on an asynPortDriver for a Current Transducer box (CAENels) that uses tcp for configuration and monitoring purposes and udp for streaming data.

Using epics-base 3.15.6 and asyn 4.34 on a debian stretch machine.

 

 

I have a test IOC that calls drvAsynIPPortConfigure twice, as follows:

drvAsynIPPortConfigure("test-mps-ctbox-n0001", "test-mps-ctbox-n0001:10001 tcp", 0, 0, 0)

drvAsynIPPortConfigure("test-mps-ctbox-n0001_udp","test-mps-ctbox-n0001:10001:20001 udp", 0, 0, 1)

The tcp port uses remotePort=10001 and noProccessEos=0, and the udp port uses remotePort=10001, localPort 20001 and noProccessEos=1.

 

 

The driver is configured as follows:

-          ASYN_CANBLOCK and AUTO_CONNECT.

-          It uses two asynUsers, one for tcp communication and one for udp communication,

-          creates necessary asyn interfaces for tcp-based configuration and monitoring commands that call pasynOctetSyncIO->writeRead(), and are driven by passive PVs or periodic scan PVs processed every 10Hz.

-          and creates an epicsThread, to acquire the data streamed by the CT-Box, that calls pasynOctetSyncIO->read() at least twice a second (user configurable) to read blocks of 180 U64 words. A call to pasynOctetSyncIO->write() has been included in the thread after the read for testing purposes.

 

The issue is that the pasynOctetSyncIO->writeReads (using tcp) and pasynOctetSyncIO->writes(using udp) work fine most of the time, I can see all sent and received data using Wireshark, but pasynOctetSyncIO->reads(using udp) always timeout. The data is sent by the CT-Box (observed with Wireshark).

This is the observed behavior ~90% of the time. Using a TIMEOUT=2 seconds.

 

This is the IOC output for one tcp call made by a PV named FPSALARM:OUTST followed by two udp calls made by the epicsThread trying to read 1440 bytes and writing 80 bytes.

 

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1782] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 asynManager::queueLockPort locking port

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1820] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 asynManager::queueLockPort taking mutex 0x7f73dc000a10

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1822] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 asynManager::queueLockPort queueing request

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 addr -1 queueRequest priority 0 not lockHolder

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 schedule queueRequest timeout

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:886] [test-mps-ctbox-n0001,0x55d4fbfccd30,50] asynManager::portThread port=test-mps-ctbox-n0001 callback

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:940] [test-mps-ctbox-n0001,0x55d4fbfccd30,50] test-mps-ctbox-n0001 asynManager::queueLockPortCallback signaling begin event

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:945] [test-mps-ctbox-n0001,0x55d4fbfccd30,50] test-mps-ctbox-n0001 asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1835] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 asynManager::queueLockPort waiting for event

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1846] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 asynManager::queueLockPort got event from callback

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/miscellaneous/asynInterposeEos.c:263] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 flush

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:807] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001:10001 tcp flush

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:556] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001:10001 tcp write.

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:558] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001:10001 tcp write 17

FPSALARM:OUTST:?

FPSALARM:OUTST:?\r

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:666] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] wrote 17 to test-mps-ctbox-n0001:10001 tcp, return asynSuccess.

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/miscellaneous/asynInterposeEos.c:178] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 wrote

FPSALARM:OUTST:?

FPSALARM:OUTST:?\r

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/interfaces/asynOctetSyncIO.c:262] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] asynOctetSyncIO wrote:

FPSALARM:OUTST:?

FPSALARM:OUTST:?

2019/04/16 17:00:00.750 [test-mps-ctbox-n0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:686] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001:10001 tcp read.

2019/04/16 17:00:00.760 [test-mps-ctbox-n0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:756] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001:10001 tcp read 4

OK

 

OK\r\n

2019/04/16 17:00:00.760 [test-mps-ctbox-n0001,-1,0] [../../asyn/miscellaneous/asynInterposeEos.c:235] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 read 4 bytes eom=0

OK

 

OK\r\n

2019/04/16 17:00:00.760 [test-mps-ctbox-n0001,-1,0] [../../asyn/interfaces/asynOctetSyncIO.c:270] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] asynOctetSyncIO read:

OK

OK

2019/04/16 17:00:00.760 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1867] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 queueUnlockPort

2019/04/16 17:00:00.760 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1898] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 asynManager::queueUnlockPort waiting for event

2019/04/16 17:00:00.760 [test-mps-ctbox-n0001,-1,0] [../../asyn/asynDriver/asynManager.c:1901] [TEST_MPS:CTBOX_N0001,0x55d4fbfd1140,50] test-mps-ctbox-n0001 queueUnlockPort unlock mutex 0x7f73dc000a10 complete.

2019/04/16 17:00:01.212 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1782] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort locking port

2019/04/16 17:00:01.212 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1820] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort taking mutex 0x7f73d0000fa0

2019/04/16 17:00:01.213 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1822] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort queueing request

2019/04/16 17:00:01.213 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp addr -1 queueRequest priority 0 not lockHolder

2019/04/16 17:00:01.213 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp schedule queueRequest timeout

2019/04/16 17:00:01.213 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:886] [test-mps-ctbox-n0001_udp,0x55d4fbfcf460,50] asynManager::portThread port=test-mps-ctbox-n0001_udp callback

2019/04/16 17:00:01.213 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:940] [test-mps-ctbox-n0001_udp,0x55d4fbfcf460,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback signaling begin event

2019/04/16 17:00:01.213 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:945] [test-mps-ctbox-n0001_udp,0x55d4fbfcf460,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2019/04/16 17:00:01.213 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1835] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort waiting for event

2019/04/16 17:00:01.214 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1846] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort got event from callback

2019/04/16 17:00:01.214 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:686] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001:10001:20001 udp read.

2019/04/16 17:00:03.215 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1867] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp queueUnlockPort

2019/04/16 17:00:03.215 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1898] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueUnlockPort waiting for event

2019/04/16 17:00:03.216 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1901] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp queueUnlockPort unlock mutex 0x7f73d0000fa0 complete.

sevr=info 2019-04-16 17:00:03.216 asyndvrctboxTask[140135778531072]: *** TEST_MPS:CTBOX_N0001:[dataAcquisitionTask] error calling read, status=1, error=test-mps-ctbox-n0001:10001:20001 udp timeout: Resource temporarily unavailable ***

 

2019/04/16 17:00:03.217 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1782] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort locking port

2019/04/16 17:00:03.217 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1820] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort taking mutex 0x7f73d0000fa0

2019/04/16 17:00:03.218 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1822] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort queueing request

2019/04/16 17:00:03.218 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp addr -1 queueRequest priority 0 not lockHolder

2019/04/16 17:00:03.218 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp schedule queueRequest timeout

2019/04/16 17:00:03.219 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:886] [test-mps-ctbox-n0001_udp,0x55d4fbfcf460,50] asynManager::portThread port=test-mps-ctbox-n0001_udp callback

2019/04/16 17:00:03.219 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:940] [test-mps-ctbox-n0001_udp,0x55d4fbfcf460,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback signaling begin event

2019/04/16 17:00:03.219 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:945] [test-mps-ctbox-n0001_udp,0x55d4fbfcf460,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2019/04/16 17:00:03.219 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1835] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort waiting for event

2019/04/16 17:00:03.220 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1846] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort got event from callback

2019/04/16 17:00:03.220 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:556] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001:10001:20001 udp write.

2019/04/16 17:00:03.221 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:558] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001:10001:20001 udp write 80

 

\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000

2019/04/16 17:00:03.227 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:666] [asyndvrctboxTask,0x55d4fbfd19a0,50] wrote 80 to test-mps-ctbox-n0001:10001:20001 udp, return asynSuccess.

2019/04/16 17:00:03.228 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/interfaces/asynOctetSyncIO.c:198] [asyndvrctboxTask,0x55d4fbfd19a0,50] asynOctetSyncIO wrote:

 

\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000

2019/04/16 17:00:03.234 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1867] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp queueUnlockPort

2019/04/16 17:00:03.234 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1898] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp asynManager::queueUnlockPort waiting for event

2019/04/16 17:00:03.235 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1901] [asyndvrctboxTask,0x55d4fbfd19a0,50] test-mps-ctbox-n0001_udp queueUnlockPort unlock mutex 0x7f73d0000fa0 complete.

 

Strace shows that the poll() call, in readIt() function (drvAsynIPPort.c line 714) timeout

poll([{fd=5, events=POLLIN}], 1, 2000)  = 0 (Timeout)

recvfrom(5, 0x7f73d0000920, 1440, 0, 0x7f73e74cab90, [16]) = -1 EAGAIN (Resource temporarily unavailable)

While the call to writeIt succeeds.

poll([{fd=5, events=POLLOUT}], 1, 2000) = 1 ([{fd=5, revents=POLLOUT}])

sendto(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 80, 0, {sa_family=AF_INET, sin_port=htons(10001), sin_addr=inet_addr("10.41.218.251")}, 16) = 8

 

 

The other ~10%, tcp calls timeout and udp read and writes succeed (not very common).

 

 

My question is, is my approach correct? If not which would be the appropriate approach to implement an asynPortDriver for a device that uses tcp and udp over the same remote port.

 

Thanks,

Enrique

 

 

Enrique Bernal Ruiz Controls Engineer II Facility for Rare Isotope Beams Michigan State University 640 South Shaw Lane East Lansing, MI 48824, USA Email: [email protected]