Experimental Physics and
Industrial Control System

"Daykin, Evan" <[email protected]> · Fri, 2 Mar 2018 19:26:38 +0000

I changed over to the most recent git revision of StreamDevice, same behavior- the port knows it is not connected, but still doesn't reconnect.

Is there any significance to 'synchronousLock' being set to Yes here?

TEST-RF-DCU-N0001 multiDevice:No canBlock:Yes autoConnect:Yes
    enabled:Yes connected:No numberConnects 1
    nDevices 0 nQueued 1 blocked:No
    asynManagerLock:No synchronousLock:Yes
    exceptionActive:No exceptionUsers 2 exceptionNotifys 0
    traceMask:0x0 traceIOMask:0x7 traceInfoMask:0xf
    interposeInterfaceList
        asynOctet pinterface 0x7f65466eb900 drvPvt 0x24a7950
    interfaceList
        asynCommon pinterface 0x7f65466e7650 drvPvt 0x24a4060
        asynOption pinterface 0x7f65466e7670 drvPvt 0x24a4060
        asynOctet pinterface 0x24a4180 drvPvt 0x24a4060
    Port test-rf-dcu-n0001.cts:5001: Disconnected
                    fd: -1
    Characters written: 224
       Characters read: 278

> It appears that the IP name of the IOC is test-rf-dcu-n0001.cts ?  Is that true?  Is the .cts actually part of this host's name?  If so, does that violate the rules for valid host names?

No, .cts is the TLD of our isolated test network; the actual hostname is just test-rf-dcu-n0001.

-----Original Message-----
From: Mark Rivers [mailto:[email protected]] 
Sent: Friday, March 02, 2018 9:28 AM
To: Daykin, Evan <[email protected]>; Torsten Bögershausen <[email protected]>; [email protected]
Subject: Re: Asyn not automatically reconnecting

Hi Evan,

Can you do the following when you are in that state:

- Turn off the message blast with

asynSetTraceMask $(HWUNIT) 0 0

- Get a report on the state of the driver with:

asynReport 10 $(HWUNIT)

I want to see if the port thinks it is connected or not.

One thing I notice:

> [../../asyn/drvAsynSerial/drvAsynIPPort.c:674] [TEST-RF-DCU-N0001,0x260d420,50] test-rf-dcu-n0001.cts:5001 read.

It appears that the IP name of the IOC is test-rf-dcu-n0001.cts ?  Is that true?  Is the .cts actually part of this host's name?  If so, does that violate the rules for valid host names?

https://en.wikipedia.org/wiki/Hostname#Restrictions_on_valid_hostnames

Mark

________________________________
From: Daykin, Evan <[email protected]>
Sent: Friday, March 2, 2018 7:49 AM
To: Mark Rivers; Torsten Bögershausen; [email protected]
Subject: RE: Asyn not automatically reconnecting

Just the last one. It repeats on the order of hundreds of times a second.

-----Original Message-----
From: Mark Rivers [mailto:[email protected]]
Sent: Thursday, March 01, 2018 4:56 PM
To: Daykin, Evan <[email protected]>; Torsten Bögershausen <[email protected]>; [email protected]
Subject: RE: Asyn not automatically reconnecting

> 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)

What repeats forever?  Both of these lines or just the second one?  Does it repeat very fast?  How many times/second?

Mark

> -----Original Message-----
> From: Daykin, Evan [mailto:[email protected]]
> Sent: Thursday, March 01, 2018 3:34 PM
> To: Mark Rivers <[email protected]>; Torsten Bögershausen 
> <[email protected]>; [email protected]
> Subject: RE: Asyn not automatically reconnecting
>
> 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:[email protected]]
> Sent: Thursday, March 01, 2018 4:06 PM
> To: Daykin, Evan <[email protected]>; Torsten Bögershausen 
> <[email protected]>; [email protected]
> 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:[email protected]]
> > Sent: Thursday, March 01, 2018 3:04 PM
> > To: Mark Rivers <[email protected]>; Torsten Bögershausen 
> > <[email protected]>; [email protected]
> > 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:[email protected]]
> > Sent: Tuesday, February 27, 2018 4:57 PM
> > To: Daykin, Evan <[email protected]>; Torsten Bögershausen 
> > <[email protected]>; [email protected]
> > 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 <[email protected]>
> > Sent: Tuesday, February 27, 2018 3:53 PM
> > To: Torsten Bögershausen; Mark Rivers; [email protected]
> > 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:[email protected]]
> > Sent: Tuesday, February 27, 2018 3:37 PM
> > To: Daykin, Evan <[email protected]>; Mark Rivers 
> > <[email protected]>; tech- [email protected]
> > 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  ?

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System