Experimental Physics and
Industrial Control System

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: Current transducer Box asynPortDriver using tcp and udp timing out
From:	Mark Rivers via Tech-talk <[email protected]>
To:	"'Bernal Ruiz, Enrique'" <[email protected]>
Cc:	"[email protected]" <[email protected]>
Date:	Wed, 17 Apr 2019 17:12:33 +0000

Hi Enrique,

Sorry I forgot to CC tech-talk on my reply yesterday, but the complete thread is below.

I don’t understand why asyn is able to receive the udp messages when tcp is disabled, but not if it is enabled. Perhaps someone else has an idea?

Do you actually need to send udp messages on port 10001? If not, then you might try changing this line:

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

to this, i.e. configure to send on 20001 as well, but don’t actually send anything.

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

I don’t think that will make a difference, but if there is a bug in our driver it might.

Also if you send me your driver code, or a link to Github if it is there, I will be happy to see if I can spot a problem.

Mark

From: Bernal Ruiz, Enrique <[email protected]>
Sent: Wednesday, April 17, 2019 9:54 AM
To: Mark Rivers <[email protected]>
Subject: RE: Current transducer Box asynPortDriver using tcp and udp timing out

Hi Mark,

Thanks for your quick reply.

The output for asynReport 10 test-mps-ctbox-n0001_udp is as follows:

asynReport 10 test-mps-ctbox-n0001_udp

test-mps-ctbox-n0001_udp 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 0 exceptionNotifys 0

traceMask:0xff traceIOMask:0xb traceInfoMask:0xff

interposeInterfaceList

asynOctet pinterface 0x7effaa877240 drvPvt 0x55c9fa45cc90

interfaceList

asynCommon pinterface 0x7effaa8747b0 drvPvt 0x55c9fa45bdc0

asynOption pinterface 0x7effaa8747d0 drvPvt 0x55c9fa45bdc0

asynOctet pinterface 0x55c9fa45bee0 drvPvt 0x55c9fa45bdc0

Port test-mps-ctbox-n0001:10001:20001 udp: Connected

fd: 5

Characters written: 80

Characters read: 0

I do not see anything wrong on the asynReport command output

And my IOC is listening on that udp port, L

bernalru@bernalru:~$ sudo netstat -tulpn | grep 20001

udp 0 0 0.0.0.0:20001 0.0.0.0:* 10439/../../bin/lin

bernalru@bernalru:~$ top –H –u bernalru

10439 bernalru 20 0 620004 8652 6420 S 0.0 0.8 0:00.07 st.cmd

If I disable all tcp communications and only enable udp com, I can see all the streamed data that comes from the box.

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1782] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort locking port

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1820] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort taking mutex 0x7f44b4001090

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1822] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort queueing request

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp addr -1 queueRequest priority 0 not lockHolder

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp schedule queueRequest timeout

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1835] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort waiting for event

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:886] [test-mps-ctbox-n0001_udp,0x5632e8758db0,50] asynManager::portThread port=test-mps-ctbox-n0001_udp callback

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:940] [test-mps-ctbox-n0001_udp,0x5632e8758db0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback signaling begin event

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:945] [test-mps-ctbox-n0001_udp,0x5632e8758db0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1846] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort got event from callback

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:686] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001:10001:20001 udp read.

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:748] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001:10001:20001 udp (from 10.41.218.251:10001) read 1440

}1\a\000i\204\032:~1\a\000\017\024\3759\1771\a\000\243\3425:\2001\a\000\251\351\022:\2011\a\000\016\2037:\2021\a\000\245\0052:\2031\a\000y\365\v:\2041\a\000\224\245.:\2051\a\000\017D\034:\2061\a\000R.(:

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/interfaces/asynOctetSyncIO.c:224] [asyndvrctboxTask,0x5632e875be00,50] asynOctetSyncIO read:

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1867] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp queueUnlockPort

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1898] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueUnlockPort waiting for event

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1901] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp queueUnlockPort unlock mutex 0x7f44b4001090 complete.

2019/04/17 10:35:01.678 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp schedule queueRequest timeout

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:940] [test-mps-ctbox-n0001_udp,0x5632e8758db0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback signaling begin event

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:945] [test-mps-ctbox-n0001_udp,0x5632e8758db0,50] test-mps-ctbox-n0001_udp asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1846] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueLockPort got event from callback

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:556] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001:10001:20001 udp write.

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:558] [asyndvrctboxTask,0x5632e875be00,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/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:666] [asyndvrctboxTask,0x5632e875be00,50] wrote 80 to test-mps-ctbox-n0001:10001:20001 udp, return asynSuccess.

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/interfaces/asynOctetSyncIO.c:198] [asyndvrctboxTask,0x5632e875be00,50] asynOctetSyncIO wrote:

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1867] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp queueUnlockPort

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1898] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp asynManager::queueUnlockPort waiting for event

2019/04/17 10:35:01.679 [test-mps-ctbox-n0001_udp,-1,0] [../../asyn/asynDriver/asynManager.c:1901] [asyndvrctboxTask,0x5632e875be00,50] test-mps-ctbox-n0001_udp queueUnlockPort unlock mutex 0x7f44b4001090 complete.

And

asynReport 10 test-mps-ctbox-n0001_udp

test-mps-ctbox-n0001_udp 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 0 exceptionNotifys 0

traceMask:0xff traceIOMask:0xb traceInfoMask:0xff

interposeInterfaceList

asynOctet pinterface 0x7f44cfb9f240 drvPvt 0x5632e875a030

interfaceList

asynCommon pinterface 0x7f44cfb9c7b0 drvPvt 0x5632e8756870

asynOption pinterface 0x7f44cfb9c7d0 drvPvt 0x5632e8756870

asynOctet pinterface 0x5632e8756990 drvPvt 0x5632e8756870

Port test-mps-ctbox-n0001:10001:20001 udp: Connected

fd: 4

Characters written: 3280

Characters read: 59040

bernalru@bernalru:~$ sudo netstat -tulpn | grep 20001

udp 214272 0 0.0.0.0:20001 0.0.0.0:* 11283/../../bin/lin

bernalru@bernalru:~$ top –H –u bernalru

11283 bernalru 20 0 615204 7924 6364 S 0.0 0.8 0:00.02 st.cmd

Any idea on how can I debug my application or anywhere I can have a look on asyn code?

Thanks for the help Mark.

Regards,

Enrique

From: Mark Rivers <[email protected]>
Sent: Tuesday, April 16, 2019 7:50 PM
To: Bernal Ruiz, Enrique <[email protected]>
Subject: RE: Current transducer Box asynPortDriver using tcp and udp timing out

Hi Enrique,

It seems that what you are trying to do should work.

I am not sure anyone has used drvAsynIPPort to read UDP non-broadcast UDP messages, but perhaps they have.

I know for sure that it works for reading UDP broadcast messages, because I recently tested it and posted results in this tech-talk message:

https://epics.anl.gov/tech-talk/2019/msg00515.php

It seems that poll() is timing out on that fd.

Can you send the output of the following iocsh command that will show information about the asyn driver:

asynReport 10 test-mps-ctbox-n0001_udp

Also send the output of this command which will show if the system sees that process listening for udp messages on port 20001.

sudo netstat -tulpn | grep 20001

Mark

From: [email protected] <[email protected]> On Behalf Of Bernal Ruiz, Enrique via Tech-talk
Sent: Tuesday, April 16, 2019 4:53 PM
To: [email protected]
Subject: Current transducer Box asynPortDriver using tcp and udp timing out

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:?

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\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\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:

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

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:

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]