asynDisconnected status

[bfrk]

We have a problem with a device that sends (only) unsolicited data (on a serial interface, accessed via terminal server). We process the record via SCAN="I/O Intr" and we have this simple protocol file:

ReadTimeout = 1200;
PollPeriod = 100;
InTerminator = "#";
ExtraInput = Ignore;

inDisplay {
  in "DISPLAY:=%dBA:=%(\$1)d";
}

When the terminalserver becomes disconnected the IOC issues messages at a rate that, at least to me, looks like "as fast as possible". Here is an excerpt:

[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618156 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618165 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618195 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618203 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618212 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618236 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618257 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618272 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618301 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618313 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618328 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618358 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618369 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618377 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618408 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618423 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618435 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618459 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618472 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618480 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618506 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618514 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618524 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jan 27 13:08:49 2025]2025/01/27 13:08:49.618549 RADDZ4R RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:

Note how the timestamps from streamDevice are all within the same millisecond(!)

I have looked at the interface code between asyn and streamDevice. While I have no explanation for the (apparent) endless loop here, I did notice that the asynDisconnected status is returned only by asyn's queueRequest method, whereas streamDevice seems to expect it being returned from the read and write methods.

[dirk-zimoch]

What is your asyn version? And EPICS base version as well, so that I can try to reproduce this as good as possible.
Also what sort of terminal server do you use? Is it the terminal server that goes offline or is it the serial device?

[dirk-zimoch]

You have not seen a message from the exceptionHandler, have you? (With debug output turned on.)

[dirk-zimoch]

Maybe it helps if I check the connection status after an I/O error. And not restart "I/O Intr" records immediately after such an error.
BTW: Do you use an IP port or a VXI11 port?

[dirk-zimoch]

You can try to add in readHandler(), case asynError: the line
pasynManager->isConnected(pasynUser, &connected);
just before if (!connected). Maybe the same in writeHandler() too.
Then the connected status would not rely on the exceptionHandler() updating conencted before the read() or write() call returns.

[bfrk]

At the moment I do not have a test setup for this, sorry for that, which means I cannot easily play with parameters ATM. I will try to create one next week.

base: R3-15-8
asyn: R4-45
streamDevice: R2-8-24

The terminal server is a MOXA, it is accessed via plain TCP/IP. This is from the startup script:

drvAsynIPPortConfigure RADDZ4R serialc1s15g.ctl.bessy.de:4004

You have not seen a message from the exceptionHandler, have you? (With debug output turned on.)

The excerpt is from a failure a few months ago. I chose it specifically because it does not have any other messages in it, so it is easier to see what is going on. In the meantime more devices have been added (and perhaps asyn settings, too). The most recent failure has more messages but is pretty confusing, here is another excerpt:

[Mon Jun  2 14:21:32 2025]RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478815 RADDZ2B RADDZ2B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478831 RADDZ4R RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478860 RADDZ2B RADDZ2B:inVal: asynError in read: serialc1s15g.ctl
.bessy.de:4002 disconnected:
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478871 RADDZ4R RADDZ4R:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478877 RADDZ3B RADDZ3B:inVal: I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478951 RADDZ3B RADDZ3B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478934 2025/06/02 14:21:32.478933 RADDZ4R RADDZ2B RADDZ2B:inVal: 
I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479001 RADDZ2B RADDZ2B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478821 RADDZ1B RADDZ1B:inVal: I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.478984 RADDZ3B RADDZ3B:inVal: asynError in read: serialc1s15g.ctl
.bessy.de:4003 disconnected:
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479033 RADDZ1B RADDZ1B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected:
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479050 2025/06/02 14:21:32.479083 RADDZ2B RADDZ4R RADDZ4R:inVal: 
I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479090 RADDZ1B RADDZ1B:inVal: asynError in read: serialc1s15g.ctl
.bessy.de:4001 disconnected:
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479128 RADDZ4R RADDZ2B:inVal: asynError in read: serialc1s15g.ctl
.bessy.de:4002 disconnected:
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479171 RADDZ2B RADDZ2B:inVal: I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]RADDZ4R:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479150 2025/06/02 14:21:32.479108 RADDZ1B RADDZ1B:inVal: I/O erro
r after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]RADDZ3B 2025/06/02 14:21:32.479190 2025/06/02 14:21:32.479220 RADDZ4R RADDZ3B:inVal: 
I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]RADDZ2B RADDZ4R:inVal: asynError in read: serialc1s15g.ctl.bessy.de:4004 disconnected
:
[Mon Jun  2 14:21:32 2025]RADDZ2B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479263 RADDZ3B RADDZ3B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479303 RADDZ2B RADDZ2B:inVal: asynError in read: serialc1s15g.ctl
.bessy.de:4002 disconnected:
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479323 RADDZ2B RADDZ2B:inVal: I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479279 2025/06/02 14:21:32.479234 2025/06/02 14:21:32.479344 RADD
Z2B RADDZ2B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]RADDZ4R RADDZ1B 2025/06/02 14:21:32.479396 RADDZ3B RADDZ3B:inVal: asynError in read: 
serialc1s15g.ctl.bessy.de:4003 disconnected:
[Mon Jun  2 14:21:32 2025]RADDZ4R:inVal: I/O error after reading 0 bytes: ""
[Mon Jun  2 14:21:32 2025]RADDZ1B:inVal: Protocol aborted
[Mon Jun  2 14:21:32 2025]2025/06/02 14:21:32.479393 RADDZ2B RADDZ2B:inVal: asynError in read: serialc1s15g.ctl
.bessy.de:4002 disconnected:

This particular kind of device is the only one where we have observed this behavior.

I will try your suggestion next week. Thanks!

[bfrk]

It was not easy to reproduce this problem in my test setup. Pulling the network plug or turning the MOXA off doesn't even result in a disconnect, as far as asyn is concerned. In fact, I had to search the internet for a tool that can force a TCP disconnect in cases where there is no traffic at all. Even when I finally found one (killcx) and used that to kill the TCP connection (after unplugging the MOXA), I saw the error messages only after I hit Ctrl-C on the IOC shell. I guess when the problem happened in production, it may have taken quite a long time until something internally timed out, leading to the same behaviour as with the SIGINT in my test setup.

Anyway, your proposed fix, despite looking quite promising to me, did not fix this. I am still getting

2025/06/16 19:00:44.563300 DOSI1V DOSI1V:inVal: asynError in read: box12.acc.bessy.de:4001 disconnected:
2025/06/16 19:00:44.563368 DOSI1V DOSI1V:inVal: I/O error after reading 0 bytes: ""
2025/06/16 19:00:44.563389 DOSI1V DOSI1V:inVal: Protocol aborted
2025/06/16 19:00:44.563490 DOSI1V DOSI1V:inVal: asynError in read: box12.acc.bessy.de:4001 disconnected:
2025/06/16 19:00:44.563522 DOSI1V DOSI1V:inVal: I/O error after reading 0 bytes: ""
2025/06/16 19:00:44.563542 DOSI1V DOSI1V:inVal: Protocol aborted
[... alltogether 2640 lines i.e. 880 repetitions ...]

I think this means that the added line pasynManager->isConnected(pasynUser, &connected); does not set connected to false. I find this rather strange.

[dirk-zimoch]

In drvAsynIPPort.c readIt(), I can see the message "<deviceName> disconnected:" being written if the file descriptor is INVALID_SOCKET (-1). Apart from never connected sockets, the file descriptor is only reset to INVALID_SOCKET in closeConnection() which also sends an exceptionDisconnect() which in turn would set the port's connected state to FALSE and then inform the asynUser (here StreamDevice's exceptionHandler()) . At least that is the flow for for ports without the flags FLAG_CONNECT_PER_TRANSACTION. Ports with FLAG_CONNECT_PER_TRANSACTION (i.e. http ports) would never write "<deviceName> disconnected:", which means that is not the case here.

The asynManager only sets connected (back) to TRUE in exceptionConnect() which is called by drvAsynIPPort.c asynCommonConnect() if connectIt() returned asynSuccess. It does so only after setting the file descriptor to a positive result of epicsSocketCreate() (which then has to pass some other setup too).

So, I cannot see how the file descriptor can ever end up being INVALID_SOCKET without the port's connected flag being FALSE.

[bfrk]

I agree with your analysis. This is really quite mysterious.

Some more data: terminating the TCP connection with killcx is not needed to reproduce. I can reliably get the observed behavior by unplugging the MOXA (network cable) and then hitting Ctrl-C. My guess is that what we have been observing in production was triggered when, after about 2 hours of inactivity, the TCP connection finally gets shut down.

This is what the output looks like with asynSetTraceMask DOSI1V -1 0x0031 (all relevant bits set):

2025/06/17 16:37:56.243 box12.acc.bessy.de:4001 read.
2025/06/17 16:37:56.243 DOSI1V read from low-level driver returned 3
2025/06/17 16:37:56.242897 DOSI1V DOSI1V:inVal: asynError in read: box12.acc.bessy.de:4001 disconnected:
2025/06/17 16:37:56.242907 DOSI1V DOSI1V:inVal: I/O error after reading 0 bytes: ""
2025/06/17 16:37:56.242917 DOSI1V DOSI1V:inVal: Protocol aborted
2025/06/17 16:37:56.243 DOSI1V set Eos 0

2025/06/17 16:37:56.243 DOSI1V addr -1 queueRequest priority 0 not lockHolder
2025/06/17 16:37:56.243 asynManager::portThread port=DOSI1V callback
2025/06/17 16:37:56.243 DOSI1V get Eos 0

2025/06/17 16:37:56.243 DOSI1V set Eos 1

2025/06/17 16:37:56.243 box12.acc.bessy.de:4001 read.
2025/06/17 16:37:56.243 DOSI1V read from low-level driver returned 3
2025/06/17 16:37:56.242975 DOSI1V DOSI1V:inVal: asynError in read: box12.acc.bessy.de:4001 disconnected:
2025/06/17 16:37:56.242985 DOSI1V DOSI1V:inVal: I/O error after reading 0 bytes: ""
2025/06/17 16:37:56.242997 DOSI1V DOSI1V:inVal: Protocol aborted
2025/06/17 16:37:56.243 DOSI1V set Eos 0

2025/06/17 16:37:56.243 DOSI1V addr -1 queueRequest priority 0 not lockHolder
2025/06/17 16:37:56.243 asynManager::portThread port=DOSI1V callback
2025/06/17 16:37:56.243 DOSI1V get Eos 0

2025/06/17 16:37:56.243 DOSI1V set Eos 1

BTW, note that one or two seconds after disconnecting the plug, I see the same messages from asyn (but NOT those from streamDevice), albeit in the expected rate i.e. one cycle every 100ms (the PollPeriod). It is also the case that after plugging the cable back in, everything recovers just fine (via asyn auto-reconnect).

[dirk-zimoch]

I will try to setup up a Moxa here to reproduce. May take a while. Next week or so.

[bfrk]

I just realized that our IOCs have a signal handler for SIGTERM, SIGINT, and SIGQUIT that calls epicsExit(). Furthermore, drvAsynIPPort.c installs an atExit handler that closes the socket and then sets it to INVALID_SOCKET. When I disable our signal handler, I no longer get the error messages after disconnect and then killing the IOC. I also checked that calling epicsExit(0) from the IOC shell is enough to trigger the behavior, even if the MOXA remains connected. However, if there is actual traffic, the epicsExit usually hangs (probably in asyn->lockPort), whereas if there is no traffic (e.g. the device itself is turned off) you are likely to get the error message storm before the IOC terminates.

So far I have not been able to reproduce the problem without directly or indirectly calling epicsExit. Pulling the network plug and waiting until the connection times out does not trigger the behavior.

[dirk-zimoch]

In that case I better stop polling for „I/O Intr“ when exit starts.

[dirk-zimoch]

Currently, I cannot reproduce the problem.

My asyn setup:
drvAsynIPPortConfigure 'moxa1' '129.129.130.83:4001'

I have one record

record (stringin,"DZ:ASYNC")
{
    field(DTYP, "stream")
    field(INP, "@iointr.proto asyncread moxa1")
    field(SCAN, "I/O Intr")
}

With the protocol

InTerminator = CR;
asyncread {
    in "% s";
}

The ioc starts and connects normally:

epics> dbior drvAsyn 1
Driver: drvAsyn
moxa1 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 2 exceptionNotifys 0
    traceMask:0x1 traceIOMask:0x0 traceInfoMask:0x1
    Port 129.129.130.83:4001: Connected

Writing to the serial port works:

$ echo Hello > /dev/ttyUSB0

I see it on the IOC:

epics> dbgf DZ:ASYNC
DBF_STRING:         "Hello"

Now, I switch the Moxa off (or pull the network cable).
The IOC does not see that. Asyn still reports the port as "Connected". No errors, no record processing, no debug output.
Even netstat reports the socket as ESTABLISHED:

$ netstat -tn | grep -F 129.129.130.83
tcp        0      0 129.129.130.190:37446   129.129.130.83:4001     ESTABLISHED

So, from the kernel point of view, the Moxa is still connected. It is simply not sending anything.
I will leave it like this over the weekend. Maybe it will time out eventually.

[dirk-zimoch]

Neither drvAsynIPPort.c nor epicsSocketCreate() sets socket option SO_KEEPALIVE and Linux does not enable it by default. Thus it is not surprising that we never see the socket closing. Thus, I have no idea how to reproduce what you are seeing.

[bfrk]

As I wrote earlier, I, too, have trouble reproducing what we have seen in our production system. For all I know, shutdown of the TCP connection may have been triggered by our IT group doing work on network components (switches, routers). Or some other random event like a loss of power in some areas. I fear such conditions can not easily be reproduced in a simple test setup.

I can, however, reliably reproduce the exact same behavior by running epicsExit from the shell (after registering it with the IOC shell). If you find out why this (apparently) triggers some kind of endless loop, and perhaps find a fix, then this will most probably solve the (hard to reproduce) problem we have seen in production as well.

[dirk-zimoch]

Shouldn't calling exit from the ioc shell do the same? At least it does not trigger strange things. But I will try to register epicsExit and see what happens then.