search

epics-modules / asyn

EPICS module for driver and device support
http://epics-modules.github.io/asyn/
Other
37 stars 75 forks source link

ioctestIPServer prints thousands of drvAsynIPServerPort accept errors after IOC exit #199

Closed jlmuir closed 8 months ago

jlmuir commented 9 months ago

After exiting ioctestIPServer, a "Software caused connection abort" error message gets printed to the standard error stream

2023/12/15 16:09:01.998 drvAsynIPServerPort: accept error on �ª��: fd=5, Software caused connection abort

followed by tens of "Socket operation on non-socket" error messages

2023/12/15 16:09:01.998 drvAsynIPServerPort: accept error on (null): fd=0, Socket operation on non-socket

followed by another "Software caused connection abort" error message, but for a different file descriptor (maybe the other server?)

2023/12/15 16:09:01.999 drvAsynIPServerPort: accept error on �����: fd=4, Software caused connection abort

followed by thousands more of the "Socket operation on non-socket" error messages

2023/12/15 16:09:01.999 drvAsynIPServerPort: accept error on (null): fd=0, Socket operation on non-socket

Here's an example terminal session:

$ cd iocBoot/ioctestIPServer
$ ../../bin/darwin-aarch64/testIPServer st.cmd
< envPaths
Can't open envPaths: No such file or directory
dbLoadDatabase("../../dbd/testIPServer.dbd")
testIPServer_registerRecordDeviceDriver(pdbbase)
#The following command starts a server on port 5001
drvAsynIPServerPortConfigure("P5001","localhost:5001",2,0,0,0)
serverAddr: 0.0.0.0:5001
serverPort: 5001
drvAsynIPServerPortConfigure("P5002","localhost:5002",1,0,0,0)
serverAddr: 0.0.0.0:5002
serverPort: 5002
#asynSetTraceFile("P5001",-1,"")
asynSetTraceIOMask("P5001",-1,0x2)
#asynSetTraceMask("P5001",-1,0xff)
dbLoadRecords("../../db/testIPServer.db", "P=testIPServer:")
iocInit()
Starting iocInit
############################################################################
## EPICS R7.0.7
## Rev. 2023-11-28T21:51-0600
## Rev. Date build date/time:
############################################################################
iocRun: All initialization complete
ipEchoServer("P5001")
seq("ipSNCServer", "P=testIPServer:, PORT=P5002")
sevr=info Sequencer release 2.2.9, compiled Fri Dec 15 15:36:22 2023
sevr=info Spawning sequencer program "ipSNCServer", thread 0x600003684000: "ipSNCServer"
sevr=info ipSNCServer[0]: all channels connected & received 1st monitor
epics> exit
2023/12/15 16:09:01.998 drvAsynIPServerPort: accept error on �ª��: fd=5, Software caused connection abort
2023/12/15 16:09:01.998 drvAsynIPServerPort: accept error on (null): fd=0, Socket operation on non-socket
[previous line repeated tens of times sans timestamp differences]
2023/12/15 16:09:01.999 drvAsynIPServerPort: accept error on �����: fd=4, Software caused connection abort
2023/12/15 16:09:01.999 drvAsynIPServerPort: accept error on (null): fd=0, Socket operation on non-socket
[previous line repeated thousands of times sans timestamp differences]

Platform:

jlmuir commented 9 months ago

I just tested against EPICS 7.0.8, and I get the same behavior.

MarkRivers commented 9 months ago

If you look at the IOC startup you will see this error message:

Can't open envPaths: No such file or directory

That is probably because you did not change ARCH in ioctestIPServer/Makefile to match your EPICS_HOST_ARCH, so it did not create envPaths.

MarkRivers commented 9 months ago

I cannot reproduce this issue when I run it on linux-x86_64:


(base) [epics@corvette ioctestIPServer]$ ../../bin/linux-x86_64/testIPServer st.cmd
< envPaths
epicsEnvSet("IOC","ioctestIPServer")
epicsEnvSet("TOP","/home/epics/devel/asyn-4-43")
epicsEnvSet("SUPPORT","/corvette/home/epics/devel")
epicsEnvSet("IPAC","/corvette/home/epics/devel/ipac-2-16")
epicsEnvSet("SNCSEQ","/corvette/home/epics/devel/seq-2-2-5")
epicsEnvSet("CALC","/corvette/home/epics/devel/calc-3-7-4")
epicsEnvSet("SSCAN","/corvette/home/epics/devel/sscan-2-11-5")
epicsEnvSet("EPICS_BASE","/corvette/usr/local/epics-devel/base-7.0.7")
dbLoadDatabase("../../dbd/testIPServer.dbd")
testIPServer_registerRecordDeviceDriver(pdbbase)
#The following command starts a server on port 5001
drvAsynIPServerPortConfigure("P5001","localhost:5001",2,0,0,0)
serverAddr: 0.0.0.0:5001
serverPort: 5001
drvAsynIPServerPortConfigure("P5002","localhost:5002",1,0,0,0)
serverAddr: 0.0.0.0:5002
serverPort: 5002
#asynSetTraceFile("P5001",-1,"")
asynSetTraceIOMask("P5001",-1,0x2)
#asynSetTraceMask("P5001",-1,0xff)
dbLoadRecords("../../db/testIPServer.db", "P=testIPServer:")
iocInit()
Starting iocInit
############################################################################
## EPICS R7.0.7
## Rev. R7.0.7-dirty
## Rev. Date Git: 2022-09-07 13:50:35 -0500
############################################################################
cas WARNING: Configured TCP port was unavailable.
cas WARNING: Using dynamically assigned TCP port 41677,
cas WARNING: but now two or more servers share the same UDP port.
cas WARNING: Depending on your IP kernel this server may not be
cas WARNING: reachable with UDP unicast (a host's IP in EPICS_CA_ADDR_LIST)
iocRun: All initialization complete
ipEchoServer("P5001")
seq("ipSNCServer", "P=testIPServer:, PORT=P5002")
sevr=info Sequencer release 2.2.5, compiled Mon Oct  2 12:22:39 2023
sevr=info Spawning sequencer program "ipSNCServer", thread 0x2071050: "ipSNCServer"
sevr=info ipSNCServer[0]: all channels connected & received 1st monitor
epics>
epics> exit
(base) [epics@corvette ioctestIPServer]$ ../../bin/linux-x86_64/testIPServer st.cmd
< envPaths
epicsEnvSet("IOC","ioctestIPServer")
epicsEnvSet("TOP","/home/epics/devel/asyn-4-43")
epicsEnvSet("SUPPORT","/corvette/home/epics/devel")
epicsEnvSet("IPAC","/corvette/home/epics/devel/ipac-2-16")
epicsEnvSet("SNCSEQ","/corvette/home/epics/devel/seq-2-2-5")
epicsEnvSet("CALC","/corvette/home/epics/devel/calc-3-7-4")
epicsEnvSet("SSCAN","/corvette/home/epics/devel/sscan-2-11-5")
epicsEnvSet("EPICS_BASE","/corvette/usr/local/epics-devel/base-7.0.7")
dbLoadDatabase("../../dbd/testIPServer.dbd")
testIPServer_registerRecordDeviceDriver(pdbbase)
#The following command starts a server on port 5001
drvAsynIPServerPortConfigure("P5001","localhost:5001",2,0,0,0)
serverAddr: 0.0.0.0:5001
serverPort: 5001
drvAsynIPServerPortConfigure("P5002","localhost:5002",1,0,0,0)
serverAddr: 0.0.0.0:5002
serverPort: 5002
#asynSetTraceFile("P5001",-1,"")
asynSetTraceIOMask("P5001",-1,0x2)
#asynSetTraceMask("P5001",-1,0xff)
dbLoadRecords("../../db/testIPServer.db", "P=testIPServer:")
iocInit()
Starting iocInit
############################################################################
## EPICS R7.0.7
## Rev. R7.0.7-dirty
## Rev. Date Git: 2022-09-07 13:50:35 -0500
############################################################################
cas WARNING: Configured TCP port was unavailable.
cas WARNING: Using dynamically assigned TCP port 39483,
cas WARNING: but now two or more servers share the same UDP port.
cas WARNING: Depending on your IP kernel this server may not be
cas WARNING: reachable with UDP unicast (a host's IP in EPICS_CA_ADDR_LIST)
iocRun: All initialization complete
ipEchoServer("P5001")
seq("ipSNCServer", "P=testIPServer:, PORT=P5002")
sevr=info Sequencer release 2.2.5, compiled Mon Oct  2 12:22:39 2023
sevr=info Spawning sequencer program "ipSNCServer", thread 0x1bddee0: "ipSNCServer"
sevr=info ipSNCServer[0]: all channels connected & received 1st monitor
epics>
epics> exit
(base) [epics@corvette ioctestIPServer]$
MarkRivers commented 9 months ago

When I run it on Windows I see 2 errors after typing "exit", but not a constant stream of errors:

J:\epics\devel\asyn\iocBoot\ioctestIPServer>..\..\bin\windows-x64-static\testIPServer.exe st.cmd
< envPaths
epicsEnvSet("IOC","ioctestIPServer")
epicsEnvSet("TOP","J:/epics/devel/asyn")
epicsEnvSet("SUPPORT","J:/epics/devel")
epicsEnvSet("IPAC","J:/epics/devel/ipac-2-16")
epicsEnvSet("SNCSEQ","J:/epics/devel/seq-2-2-5")
epicsEnvSet("CALC","J:/epics/devel/calc-3-7-4")
epicsEnvSet("SSCAN","J:/epics/devel/sscan-2-11-5")
epicsEnvSet("EPICS_BASE","H:/epics-devel/base-7.0.7")
dbLoadDatabase("../../dbd/testIPServer.dbd")
testIPServer_registerRecordDeviceDriver(pdbbase)
#The following command starts a server on port 5001
drvAsynIPServerPortConfigure("P5001","localhost:5001",2,0,0,0)
serverAddr: 0.0.0.0:5001
serverPort: 5001
drvAsynIPServerPortConfigure("P5002","localhost:5002",1,0,0,0)
serverAddr: 0.0.0.0:5002
serverPort: 5002
#asynSetTraceFile("P5001",-1,"")
asynSetTraceIOMask("P5001",-1,0x2)
#asynSetTraceMask("P5001",-1,0xff)
dbLoadRecords("../../db/testIPServer.db", "P=testIPServer:")
iocInit()
Starting iocInit
############################################################################
## EPICS R7.0.7
## Rev. R7.0.7-dirty
## Rev. Date Git: 2022-09-07 13:50:35 -0500
############################################################################
iocRun: All initialization complete
ipEchoServer("P5001")
seq("ipSNCServer", "P=testIPServer:, PORT=P5002")
sevr=info Sequencer release 2.2.5, compiled Mon Oct 17 10:51:39 2022
sevr=info Spawning sequencer program "ipSNCServer", thread 00000260DE86D4F0: "ipSNCServer"
sevr=info ipSNCServer[0]: all channels connected & received 1st monitor
epics>
epics> exit
2023/12/20 16:44:11.396 drvAsynIPServerPort: accept error on ☻: fd=484, No error
2023/12/20 16:44:11.398 drvAsynIPServerPort: accept error on P: fd=320, No error
2023/12/20 16:44:11.399
J:\epics\devel\asyn\iocBoot\ioctestIPServer>
jlmuir commented 9 months ago

Just to be clear, the stream of error messages eventually stops, but only after printing thousands of them.

jlmuir commented 9 months ago

I didn't think that having envPaths would make a difference, but just to rule that out, I changed Makefile to contain ARCH = darwin-aarch64, ran make in that directory, and then ran the test again, and I still get the thousands of error messages on exit. So, since you're not seeing it on linux-x86_64, maybe an issue specific to darwin-aarch64?

MarkRivers commented 9 months ago

So, since you're not seeing it on linux-x86_64, maybe an issue specific to darwin-aarch64?

Yes, I think so. Since I don't have a Mac for testing, you may have to debug this yourself. I'll be happy to review a pull request.

FreddieAkeroyd commented 9 months ago

https://github.com/epics-modules/asyn/pull/200 might help, i think you have a cleanup race condition

jlmuir commented 8 months ago

Yes, #200 solves this. Since it has just been merged, I'm closing this issue. Thanks!