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: | Current transducer Box asynPortDriver using tcp and udp timing out |
From: | "Bernal Ruiz, Enrique via Tech-talk" <[email protected]> |
To: | "[email protected]" <[email protected]> |
Date: | Tue, 16 Apr 2019 21:52:58 +0000 |
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
|