RE: Asyn not automatically reconnecting

["Daykin, Evan" <daykin@frib.msu.edu>]

Sure,

Database:

record(asyn, "_$(HWUNIT):asyn") #resolves to PORT name
{
  field(PORT, "$(HWUNIT)")
  field(IEOS, "\n")
  field(OEOS, "\n")
  field(ASG,  "$(ASGEXPERT)")
}

record(ai, "TEST:POWR_RD_FWD")
{
  field(DESC, "AMP_PWR_FORWARD value")
  field(DTYP, "stream")
  field(SCAN, "5 second")
  field(EGU, "W")
  field(INP,  "@HBH-RF-Amp.proto getAmpValue(AMP_PWR_FORWARD,1) TEST-RF-DCU-N0001")
  info(archive, " ")
}

Protocol file:

Terminator = LF;
ReplyTimeout = 2000;

#-----------------------------------------------------------------------
getUnitError {
  ExtraInput = Ignore;
  out "GET ERROR AMP \$1";
  in  "%64c";
}

#-----------------------------------------------------------------------
clearAmpError {
  out "CLEAR ERROR AMP \$1";
  in  "OK ERROR LIST cleared";
}

#-----------------------------------------------------------------------
resetAmp {
  ExtraInput = Ignore;
  out "RESET AMP \$1";
  in "OK";
}

#-----------------------------------------------------------------------
getAmpOn {
  ExtraInput = Ignore;
  out "GET PWR AMP \$1";
  in "POWER AMP \$1 %{OFF|ON}";
}

#-----------------------------------------------------------------------
setAmpOn {
  ExtraInput = Ignore;
  out "SET PWR AMP \$1 %{OFF|ON}";
  in "OK";
}

#-----------------------------------------------------------------------
getAmpValue {
  ExtraInput = Ignore;
  out "GET VALUE \$1 AMP \$2";
  in "VALUE \$1 AMP \$2 %g";
}

#-----------------------------------------------------------------------
getAmpThreshold {
  ExtraInput = Ignore;
  out "GET THRESHOLD \$1 AMP \$2";
  in "THRESHOLD \$1 AMP \$2 %g";
}

setAmpThreshold {
  ExtraInput = Ignore;
  out "SET THRESHOLD \$1 AMP \$2 %g";
  in "OK";
##  @init { getAmpThreshold; }
}

#-----------------------------------------------------------------------
getAmpPhase {
  out "GET PHASE AMP \$1";
  in "PHASE AMP \$1 %d";
}

setAmpPhase {
  out "SET PHASE AMP \$1 %d";
  in "OK";
}

#-----------------------------------------------------------------------
getDrawerPhase {
  out "GET PHASE DRAWER \$1";
  in "PHASE DRAWER \$1 %d";
}

setDrawerPhase {
  out "SET PHASE DRAWER \$1 %d";
  in "OK";
}
#-----------------------------------------------------------------------
getDrawerValue {
  out "GET VALUE \$1 AMP \$2 DRAWER \$3";
  in "VALUE \$1 AMP \$2 DRAWER \$3 %g";
}

getDrawerValueInt {
  out "GET VALUE \$1 AMP \$2 DRAWER \$3";
  in "VALUE \$1 AMP \$2 DRAWER \$3 %d";
}

#-----------------------------------------------------------------------
getDrawerThreshold {
  out "GET THRESHOLD \$1 AMP \$2 DRAWER \$3";
  in "THRESHOLD \$1 AMP \$2 DRAWER \$3 %g";
}

setDrawerThreshold {
  out "SET THRESHOLD \$1 AMP \$2 DRAWER \$3 %g";
  in "OK";
}
#-----------------------------------------------------------------------
getPalletValue {
  ExtraInput = Ignore;
  out "GET VALUE \$1 AMP \$2 DRAWER \$3 PALLET \$4";
  in "VALUE \$1 AMP \$2 DRAWER \$3 PALLET \$4 %g";
}

#-----------------------------------------------------------------------
getPalletThreshold {
  ExtraInput = Ignore;
  out "GET THRESHOLD \$1 AMP \$2 DRAWER \$3 PALLET \$4";
  in "THRESHOLD \$1 AMP \$2 DRAWER \$3 PALLET \$4 %g";
}

setPalletThreshold {
  ExtraInput = Ignore;
  out "SET THRESHOLD \$1 AMP \$2 DRAWER \$3 PALLET \$4 %g";
  in "OK";
##  @init { getPalletThreshold; }
}

#-----------------------------------------------------------------------
getFirmwareVersionDCU {
  out "GET VALUE VERSION_SOFTWARE AMP \$1";
  in "VALUE VERSION_SOFTWARE AMP \$1 %s";
}

getFirmwareVersionDrawer {
  out "GET VALUE VERSION_SOFTWARE AMP \$1 DRAWER \$2";
  in "VALUE VERSION_SOFTWARE AMP \$1 DRAWER \$2 %s";
}

getFirmwareVersionPallet {
  out "GET VALUE VERSION_SOFTWARE AMP \$1 DRAWER \$2 PALLET \$3";
  in "VALUE VERSION_SOFTWARE AMP \$1 DRAWER \$2 PALLET \$3 %s";
}

Asyn IO output (properly functioning):
2018/03/01 16:17:49.155 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1560] [TEST-RF-DCU-N0001,0x6d72f0,50] TEST-RF-DCU-N0001 addr -1 queueRequest priority 0 from lockHolder
2018/03/01 16:17:49.155 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [TEST-RF-DCU-N0001,0x6d72f0,50] TEST-RF-DCU-N0001 schedule queueRequest timeout
2018/03/01 16:17:49.155 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:886] [TEST-RF-DCU-N0001,0x6d72f0,50] asynManager::portThread port=TEST-RF-DCU-N0001 callback
2018/03/01 16:17:49.155 [TEST-RF-DCU-N0001,-1,0] [../../asyn/miscellaneous/asynInterposeEos.c:337] [TEST-RF-DCU-N0001,0x6d72f0,50] TEST-RF-DCU-N0001 get Eos 0

2018/03/01 16:17:49.155 [TEST-RF-DCU-N0001,-1,0] [../../asyn/miscellaneous/asynInterposeEos.c:295] [TEST-RF-DCU-N0001,0x6d72f0,50] TEST-RF-DCU-N0001 set Eos 1


\n

0a
2018/03/01 16:17:49.155 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:674] [TEST-RF-DCU-N0001,0x6d72f0,50] test-rf-dcu-n0001.cts:5001 read.
2018/03/01 16:17:50.320 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:203] [TEST-RF-DCU-N0001,0x6d72f0,50] Close test-rf-dcu-n0001.cts:5001 connection (fd 6): Read error
2018/03/01 16:17:50.320 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynRecord/asynRecord.c:905] [TEST-RF-DCU-N0001,0x6d72f0,50] _TEST-RF-DCU-N0001:asyn: exception 0, asynExceptionConnect
2018/03/01 16:17:50.319943 TEST-RF-DCU- TEST:POWR_RD_FWD: asynError in read: test-rf-dcu-n0001.cts:5001 read error: Connection reset by peer
2018/03/01 16:17:50.319959 TEST-RF-DCU- TEST:POWR_RD_FWD: I/O error after reading 0 bytes: ""
2018/03/01 16:17:50.319981 TEST-RF-DCU- TEST:POWR_RD_FWD: Protocol aborted
2018/03/01 16:17:50.320 [TEST-RF-DCU-N0001,-1,0] [../../asyn/miscellaneous/asynInterposeEos.c:295] [TEST-RF-DCU-N0001,0x6d72f0,50] TEST-RF-DCU-N0001 set Eos 0

2018/03/01 16:17:50.325 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [timerQueue,0x6d5fd0,60] TEST-RF-DCU-N0001 addr -1 queueRequest priority 3 not lockHolder
2018/03/01 16:17:50.325 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:807] [TEST-RF-DCU-N0001,0x6d72f0,50] asynManager connect queueCallback port:TEST-RF-DCU-N0001
2018/03/01 16:17:50.325 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:402] [TEST-RF-DCU-N0001,0x6d72f0,50] Open connection to test-rf-dcu-n0001.cts:5001  reason:0  fd:-1
2018/03/01 16:17:50.326 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:508] [TEST-RF-DCU-N0001,0x6d72f0,50] Opened connection to test-rf-dcu-n0001.cts:5001
2018/03/01 16:17:50.326 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynRecord/asynRecord.c:905] [TEST-RF-DCU-N0001,0x6d72f0,50] _TEST-RF-DCU-N0001:asyn: exception 0, asynExceptionConnect
2018/03/01 16:17:54.153 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [scan-5,0x718ec0,61] TEST-RF-DCU-N0001 addr -1 queueRequest priority 0 not lockHolder
2018/03/01 16:17:54.153 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [scan-5,0x718ec0,61] TEST-RF-DCU-N0001 schedule queueRequest timeout
2018/03/01 16:17:54.153 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:886] [TEST-RF-DCU-N0001,0x6d72f0,50] asynManager::portThread port=TEST-RF-DCU-N0001 callback
2018/03/01 16:17:54.153 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [TEST-RF-DCU-N0001,0x6d72f0,50] TEST-RF-DCU-N0001 addr -1 queueRequest priority 0 not lockHolder
2018/03/01 16:17:54.153 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [TEST-RF-DCU-N0001,0x6d72f0,50] TEST-RF-DCU-N0001 schedule queueRequest timeout
2018/03/01 16:17:54.154 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:886] [TEST-RF-DCU-N0001,0x6d72f0,50] asynManager::portThread port=TEST-RF-DCU-N0001 callback
2018/03/01 16:17:54.154 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:674] [TEST-RF-DCU-N0001,0x6d72f0,50] test-rf-dcu-n0001.cts:5001 read.
2018/03/01 16:17:54.154 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:744] [TEST-RF-DCU-N0001,0x6d72f0,50] test-rf-dcu-n0001.cts:5001 read 50
FRIB Control Unit (0.4.8 GU Jan  2 2018 21:32:44)

Asyn output (not working):

2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [scan-5,0x264e600,61] TEST-RF-DCU-N0001 addr -1 queueRequest priority 0 not lockHolder
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [scan-5,0x264e600,61] TEST-RF-DCU-N0001 schedule queueRequest timeout
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:886] [TEST-RF-DCU-N0001,0x260d420,50] asynManager::portThread port=TEST-RF-DCU-N0001 callback
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1565] [TEST-RF-DCU-N0001,0x260d420,50] TEST-RF-DCU-N0001 addr -1 queueRequest priority 0 not lockHolder
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:1576] [TEST-RF-DCU-N0001,0x260d420,50] TEST-RF-DCU-N0001 schedule queueRequest timeout
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynDriver/asynManager.c:886] [TEST-RF-DCU-N0001,0x260d420,50] asynManager::portThread port=TEST-RF-DCU-N0001 callback
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:674] [TEST-RF-DCU-N0001,0x260d420,50] test-rf-dcu-n0001.cts:5001 read.
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:744] [TEST-RF-DCU-N0001,0x260d420,50] test-rf-dcu-n0001.cts:5001 read 0

2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:203] [TEST-RF-DCU-N0001,0x260d420,50] Close test-rf-dcu-n0001.cts:5001 connection (fd 18): Read from broken connection
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/asynRecord/asynRecord.c:905] [TEST-RF-DCU-N0001,0x260d420,50] _TEST-RF-DCU-N0001:asyn: exception 0, asynExceptionConnect
2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/miscellaneous/asynInterposeEos.c:235] [TEST-RF-DCU-N0001,0x260d420,50] TEST-RF-DCU-N0001 read

2018/03/01 16:29:14.902 [TEST-RF-DCU-N0001,-1,0] [../../asyn/drvAsynSerial/drvAsynIPPort.c:674] [TEST-RF-DCU-N0001,0x260d420,50] test-rf-dcu-n0001.cts:5001 read. (Repeats forever)


-----Original Message-----
From: Mark Rivers [mailto:rivers@cars.uchicago.edu] 
Sent: Thursday, March 01, 2018 4:06 PM
To: Daykin, Evan <daykin@frib.msu.edu>; Torsten Bögershausen <torsten.bogershausen@esss.se>; tech-talk@aps.anl.gov
Subject: RE: Asyn not automatically reconnecting

Can you post the database, protocol file, and asynTrace output with all asynTrace bits on?

> -----Original Message-----
> From: Daykin, Evan [mailto:daykin@frib.msu.edu]
> Sent: Thursday, March 01, 2018 3:04 PM
> To: Mark Rivers <rivers@cars.uchicago.edu>; Torsten Bögershausen 
> <torsten.bogershausen@esss.se>; tech-talk@aps.anl.gov
> Subject: RE: Asyn not automatically reconnecting
> 
> 
> I have tried a database with only a couple of records, and the behavior persists.
> 
> -----Original Message-----
> From: Mark Rivers [mailto:rivers@cars.uchicago.edu]
> Sent: Tuesday, February 27, 2018 4:57 PM
> To: Daykin, Evan <daykin@frib.msu.edu>; Torsten Bögershausen 
> <torsten.bogershausen@esss.se>; tech-talk@aps.anl.gov
> Subject: Re: Asyn not automatically reconnecting
> 
> Can you try a very simple database with just one or two records 
> talking to your server.  See if that works when the server shuts down 
> gracefully.  If it does, but it fails with lots of records then we have a clue where to look.
> 
> 
> Mark
> 
> 
> 
> ________________________________
> From: Daykin, Evan <daykin@frib.msu.edu>
> Sent: Tuesday, February 27, 2018 3:53 PM
> To: Torsten Bögershausen; Mark Rivers; tech-talk@aps.anl.gov
> Subject: RE: Asyn not automatically reconnecting
> 
> >Sorry if this is the wrong question, but what is asyn 4.33-2 ?
> >"git tag" mentions R4-33, not "-2".
> 
> That's the revision in our debian repo, it is asyn 4-33.
> 
> > So from asyn everything seems to be OK.
> Maybe this is streamdevice and/or our vendor's software. We will investigate both avenues.
> 
> -----Original Message-----
> From: Torsten Bögershausen [mailto:torsten.bogershausen@esss.se]
> Sent: Tuesday, February 27, 2018 3:37 PM
> To: Daykin, Evan <daykin@frib.msu.edu>; Mark Rivers 
> <rivers@cars.uchicago.edu>; tech- talk@aps.anl.gov
> Subject: Re: Asyn not automatically reconnecting
> 
> 
> 
> On 23/02/18 15:17, Daykin, Evan wrote:
> > Hi Mark,
> >
> > Thanks for the reply. We are using asyn 4.33-2 and Stream 2.6-3. The 
> > protocol file has a ReplyTimeout of 2000ms.
> 
> Sorry if this is the wrong question, but what is asyn 4.33-2 ?
> "git tag" mentions R4-33, not "-2".
> 
> And to answer the other question:
>  >Here's something interesting: asyn behaves correctly for us *only* 
> when the  >client application is killed with SIGKILL, rather than 
> SIGTERM. This results  >in TCP retransmissions and/or refused 
> connections, then normal operation after >a short while.  Is it possible asyn is [un]intentionally not retrying the >connection if it is closed gracefully?
> 
> 
> The code that I see producing "Read from broken connection" is this:
> 
>      /* If recv() returns 0 on a SOCK_STREAM (TCP) socket, the connection has closed */
>      if ((thisRead == 0) && (tty->socketType == SOCK_STREAM)) {
>          epicsSnprintf(pasynUser->errorMessage,pasynUser->errorMessageSize,
>                        "%s connection closed",
>                        tty->IPDeviceName);
>          closeConnection(pasynUser,tty,"Read from broken connection");
> 
> ----------
> And then
> closeConnection(asynUser *pasynUser,ttyController_t *tty,const char *why) {
>      asynPrint(pasynUser, ASYN_TRACE_FLOW,
>                "Close %s connection (fd %d): %s\n", tty->IPDeviceName, 
> tty->fd, why);
> 
> So from asyn everything seems to be OK.
> 
> It seems that the problem described here:
>  >2018/02/23 09:51:47.089 test-rf-dcu-n0001.cts:5001 read.
>  >The last line then repeats rapidly forever.
> 
> is caused by the caller into asyn, which is streamdevice ?
> There seem to be some improvements in streamdevice, but I am not familiar with the code.
> 
> Dirk, does there ring a bell  ?