RE: Weird stream device behavior when using the IOC shell's exit function

[Mark Rivers via Tech-talk <tech-talk@aps.anl.gov>]

I just looked at the difference between asyn R4-18 and R4-33 for closing the socket.  R4-18 does not call pasynManager->lockPort in the cleanup() function, while R4-33 does.  That would explain why R4-33 has a deadlock while R4-18 does not.  The question is why the port appears to be continuously locked, and I suspect that is something that Stream is doing when it causes readIt to be called.  By printing a message with readPollmsec before the while{} as I suggested you will be able to tell if readIt is being called once with a negative timeout, or repeatedly very quickly with a positive timeout.

 

If you use asynPrint(pasynUser, ASYN_TRACE_ERROR …) to print the value then you will get a timestamp on the message and you can see how quickly readIt is being called.

 

Mark

 

 

From: tech-talk-bounces@aps.anl.gov <tech-talk-bounces@aps.anl.gov> On Behalf Of Mark Rivers via Tech-talk
Sent: Wednesday, February 6, 2019 8:32 AM
To: 'Abdalla Ahmad' <abdalla.ahmad@sesame.org.jo>; Dirk Zimoch <dirk.zimoch@psi.ch>
Cc: tech-talk@aps.anl.gov
Subject: RE: Weird stream device behavior when using the IOC shell's exit function

 

Ø  I thought the while loop is causing the block so I removed the while loop and put the poll function just like what is done in version 4.18 but I got the same behavior.

Ø  So I think that poll here never returns.

Ø  As the documentation says, poll will block if a negative timeout is provided.

Ø  So I think somehow stream device is passing a negative timeout but I could not verify the timeout value received in the readIt function.

 

You could edit that code to print the value of readPollmsec just before the while() statement.  That will tell you if stream device is passing a negative timeout.  The purpose of the loop is to retry the poll in case it terminates early with errno=EINTR.  But it will only loop for readPollsec ms at longest.

 

I suggest you also try independently changing the versions of asyn and Stream to see which has changed to cause the problem.  I suggest using these 2 configurations:

 

-          Base 3.15.6, asyn 4.16 Stream 2.8.8

-          Base 3.15.6, asyn 4.33, Stream 2.5.1

 

I have a simple StreamDevice IOC that I will test today to see if I can reproduce the problem.

 

Mark

 

 

From: Abdalla Ahmad <abdalla.ahmad@sesame.org.jo>
Sent: Wednesday, February 6, 2019 6:45 AM
To: Mark Rivers <rivers@cars.uchicago.edu>; Dirk Zimoch <dirk.zimoch@psi.ch>
Cc: tech-talk@aps.anl.gov
Subject: RE: Weird stream device behavior when using the IOC shell's exit function

 

Hello Mark

 

Just would like to share some findings:

 

I cloned the latest stream device 2.8.8 and I still get the same behavior. So I investigated the backtrace a little bit specifically the thread you mentioned it is causing the deadlock.

 

In asyn 4.33 file asyn/drvAsynSerial/drvAsynIPPort.c function "readIt", line 725 is the poll function call causing the deadlock. I thought the while loop is causing the block so I removed the while loop and put the poll function just like what is done in version 4.18 but I got the same behavior. So I think that poll here never returns.

 

As the documentation says, poll will block if a negative timeout is provided. So I think somehow stream device is passing a negative timeout but I could not verify the timeout value received in the readIt function.

 

Best Regards,

Abdalla.

 

From: Abdalla Ahmad
Sent: Wednesday, February 06, 2019 9:12 AM
To: 'Mark Rivers' <rivers@cars.uchicago.edu>
Cc: tech-talk@aps.anl.gov
Subject: RE: Weird stream device behavior when using the IOC shell's exit function

 

Hello Mark

 

This is just to confirm that I re-built the old setup on CentOS 7 x64; base 3.14.12.3, asyn 4.18 and stream 2.5.1 and everything works fine. I don't even get the asynWrite error messages.

 

Best Regards,

Abdalla.

 

From: Mark Rivers [mailto:rivers@cars.uchicago.edu]
Sent: Tuesday, February 05, 2019 5:47 PM
To: Abdalla Ahmad <abdalla.ahmad@sesame.org.jo>
Cc: tech-talk@aps.anl.gov
Subject: RE: Weird stream device behavior when using the IOC shell's exit function

 

You can now use asynSetTraceIOMask and asynSetTraceMask to monitor the communication.  If you enable that before you type “exit” we can see what is happening.

 

I view the problem exiting the IOC as an annoyance but not something that has to be fixed immediately.  You can always just type CTRL-C.

 

Mark

 

 

From: Abdalla Ahmad <abdalla.ahmad@sesame.org.jo>
Sent: Tuesday, February 5, 2019 8:17 AM
To: Mark Rivers <rivers@cars.uchicago.edu>
Cc: tech-talk@aps.anl.gov
Subject: Re: Weird stream device behavior when using the IOC shell's exit function

 

Well I never thought of checking the client, I will test it and come back.

I forgot to mention that the device is being controlled through standard telnet port 23. Does it make a difference for stream device to work with a well known port number?

Get Outlook for Android

 

 

On Tue, Feb 5, 2019 at 4:14 PM +0200, "Mark Rivers" <rivers@cars.uchicago.edu> wrote:

Is your device working correctly, or is it timing out? I wonder if the exit problem is because Stream is polling constantly and never releasing the lock so the epicsExit thread can never run?

Mark

Sent from my iPhone

> On Feb 5, 2019, at 7:23 AM, Abdalla Ahmad  wrote:

> 

> Hello Mark

> 

> Including asyn.dbd file did the trick. Looking forward for your thoughts on the exit issue.

> 

> Thank you for your time.

> Abdalla.

> 

> -----Original Message-----

> From: Mark Rivers [mailto:rivers@cars.uchicago.edu] 

> Sent: Tuesday, February 05, 2019 3:19 PM

> To: Abdalla Ahmad 

> Cc: tech-talk@aps.anl.gov

> Subject: Re: Weird stream device behavior when using the IOC shell's exit function

> 

> OK, I understand the problem with the missing asyn commands.  You do have these commands in your help output:

> 

> 

> drvAsynIPPortConfigure          drvAsynIPServerPortConfigure

> drvAsynSerialPortConfigure

> 

> 

> That tells me that your application dbd file is including drvAsynIPPort.dbd and drvAsynSerialPort.dbd, but it is not including asyn.dbd.  It also explains why it used to work, and now it does not.  Previously drvAsynIPPort.dbd and drvAsynSerialPort.dbd themselves included asyn.dbd.  However, recent EPICS base releases no longer allow a dbd file to be loaded more than once, so asyn.dbd was removed from drvAsynIPPort.dbd and drvAsynSerialPort.dbd.  Now your application must explicitly include asyn.dbd.

> 

> 

> I think this is independent of the IOC exiting issue, but please include asyn.dbd and see if you still have that problem.

> 

> 

> Mark

> 

> 

> 

> ________________________________

> From: Abdalla Ahmad 

> Sent: Tuesday, February 5, 2019 6:34 AM

> To: Mark Rivers

> Cc: tech-talk@aps.anl.gov

> Subject: RE: Weird stream device behavior when using the IOC shell's exit function

> 

> Hi Mark

> 

> I attached the help output in help.txt. For the database nothing is I/O scanned, standard 1 second rate as in the attached database. I also checked the protocol file but nothing seems strange.

> 

> While writing the email I thought of increasing the scan rate to 5 seconds and it works. I still get the same asynError in write but the IOC eventually exits. Even if it exits gracefully now, it is still a problem because we need the scan rate to match the IMG ones. As I told you before it used to work on the old setup without any problems. Is there anything we can investigate?

> 

> Best Regards,

> Abdalla.

> 

> -----Original Message-----

> From: Mark Rivers [mailto:rivers@cars.uchicago.edu]

> Sent: Tuesday, February 05, 2019 2:20 PM

> To: Abdalla Ahmad 

> Cc: tech-talk@aps.anl.gov

> Subject: Re: Weird stream device behavior when using the IOC shell's exit function

> 

> Hi Abdalla,

> 

> 

> Your IOC is clearly built OK with asyn because you have threads that are in asyn functions.

> 

> 

> Thread 13 (Thread 0x7fffed943700 (LWP 29173)):

> #0  0x00007ffff6034f0d in poll () from /lib64/libc.so.6

> #1  0x00007ffff7926c14 in readIt (drvPvt=0x70eb30, pasynUser=0x79e4a8, data="" ">", maxchars=2048, nbytesTransfered=0x7fffed942ba0, gotEom=0x7fffed942b90)

>    at ../../asyn/drvAsynSerial/drvAsynIPPort.c:726

> #2  0x00007ffff7930886 in readIt (drvPvt=0x70fbb0, pasynUser=0x79e4a8, data="" ">", maxchars=, nbytesTransfered=0x7fffed942ba0, eomReason=0x7fffed942b90)

>    at ../../asyn/interfaces/asynOctetBase.c:233

> #3  0x00007ffff793a563 in readIt (ppvt=0x70fcb0, pasynUser=0x79e4a8, data="" ">", maxchars=63, nbytesTransfered=0x7fffed942ca0, eomReason=0x7fffed942c70)

>    at ../../asyn/miscellaneous/asynInterposeEos.c:231

> #4  0x00007ffff7bab5f5 in AsynDriverInterface::readHandler (this=this@entry=0x79e2e0) at ../AsynDriverInterface.cc:960

> #5  0x00007ffff7bacd08 in handleRequest (pasynUser=) at ../AsynDriverInterface.cc:1503

> #6  0x00007ffff791c9f3 in portThread (pport=0x70ece0) at ../../asyn/asynDriver/asynManager.c:902

> #7  0x00007ffff6b6f7fc in start_routine (arg=0x70f290) at ../../../src/libCom/osi/os/posix/osdThread.c:403

> #8  0x00007ffff5d2ce25 in start_thread () from /lib64/libpthread.so.0

> #9  0x00007ffff603fbad in clone () from /lib64/libc.so.6

> 

> 

> 

> Thread 12 (Thread 0x7fffeda44700 (LWP 29172)):

> #0  0x00007ffff5d30995 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0

> #1  0x00007ffff6b71f3b in epicsEventWait (pevent=0x70d520) at ../../../src/libCom/osi/os/posix/osdEvent.c:103

> #2  0x00007ffff6b6b029 in epicsEventMustWait (id=) at ../../../src/libCom/osi/epicsEvent.cpp:125

> #3  0x00007ffff791c40c in portThread (pport=0x70d050) at ../../asyn/asynDriver/asynManager.c:788

> #4  0x00007ffff6b6f7fc in start_routine (arg=0x70d590) at ../../../src/libCom/osi/os/posix/osdThread.c:403

> #5  0x00007ffff5d2ce25 in start_thread () from /lib64/libpthread.so.0

> #6  0x00007ffff603fbad in clone () from /lib64/libc.so.6

> 

> I don't understand why the asyn iocsh commands would not be available.

> 

> 

> Please send the complete output of the iocsh "help" command.

> 

> 

> The hang at shutdown appears to be caused by this thread:

> 

> 

> Thread 1 (Thread 0x7ffff7fda740 (LWP 29161)):

> #0  0x00007ffff5d3351d in __lll_lock_wait () from /lib64/libpthread.so.0

> #1  0x00007ffff5d2ee36 in _L_lock_870 () from /lib64/libpthread.so.0

> #2  0x00007ffff5d2ed2f in pthread_mutex_lock () from /lib64/libpthread.so.0

> #3  0x00007ffff6b71a76 in mutexLock (id=0x70ef60) at ../../../src/libCom/osi/os/posix/osdMutex.c:46

> #4  epicsMutexOsdLock (pmutex=0x70ef60) at ../../../src/libCom/osi/os/posix/osdMutex.c:130

> #5  0x00007ffff7917e9b in lockPort (pasynUser=0x710668) at ../../asyn/asynDriver/asynManager.c:1741

> #6  0x00007ffff7925876 in cleanup (arg=0x70eb30) at ../../asyn/drvAsynSerial/drvAsynIPPort.c:246

> #7  0x00007ffff6b65ce3 in epicsExitCallAtExitsPvt (pep=) at ../../../src/libCom/misc/epicsExit.c:95

> #8  epicsExitCallAtExits () at ../../../src/libCom/misc/epicsExit.c:113

> #9  0x00007ffff6b66088 in epicsExit (status=0) at ../../../src/libCom/misc/epicsExit.c:181

> #10 0x000000000040544d in main (argc=, argv=) at ../iocMain.cpp:21

> 

> 

> So the epicsExit function is hung up in the drvAsynIPPort::cleanup function.  It has called lockPort, but cannot get that mutex.

> 

> 

> No other thread is waiting for a mutex, so it is not a traditional deadlock.  But it seems that some other thread does have that mutex and is blocking the epicsExit thread from continuing.

> 

> 

> It is probably this thread, which is in StreamDevice.

> 

> 

> Thread 13 (Thread 0x7fffed943700 (LWP 29173)):

> #0  0x00007ffff6034f0d in poll () from /lib64/libc.so.6

> #1  0x00007ffff7926c14 in readIt (drvPvt=0x70eb30, pasynUser=0x79e4a8, data="" ">", maxchars=2048, nbytesTransfered=0x7fffed942ba0, gotEom=0x7fffed942b90)

>    at ../../asyn/drvAsynSerial/drvAsynIPPort.c:726

> #2  0x00007ffff7930886 in readIt (drvPvt=0x70fbb0, pasynUser=0x79e4a8, data="" ">", maxchars=, nbytesTransfered=0x7fffed942ba0, eomReason=0x7fffed942b90)

>    at ../../asyn/interfaces/asynOctetBase.c:233

> #3  0x00007ffff793a563 in readIt (ppvt=0x70fcb0, pasynUser=0x79e4a8, data="" ">", maxchars=63, nbytesTransfered=0x7fffed942ca0, eomReason=0x7fffed942c70)

>    at ../../asyn/miscellaneous/asynInterposeEos.c:231

> #4  0x00007ffff7bab5f5 in AsynDriverInterface::readHandler (this=this@entry=0x79e2e0) at ../AsynDriverInterface.cc:960

> #5  0x00007ffff7bacd08 in handleRequest (pasynUser=) at ../AsynDriverInterface.cc:1503

> #6  0x00007ffff791c9f3 in portThread (pport=0x70ece0) at ../../asyn/asynDriver/asynManager.c:902

> #7  0x00007ffff6b6f7fc in start_routine (arg=0x70f290) at ../../../src/libCom/osi/os/posix/osdThread.c:403

> #8  0x00007ffff5d2ce25 in start_thread () from /lib64/libpthread.so.0

> #9  0x00007ffff603fbad in clone () from /lib64/libc.so.6

> 

> 

> Do you have StreamDevice records that are I/O Intr scanned?

> 

> 

> Mark

> 

> 

> 

> 

> ________________________________

> From: Abdalla Ahmad 

> Sent: Tuesday, February 5, 2019 5:53 AM

> To: Mark Rivers

> Cc: tech-talk@aps.anl.gov

> Subject: RE: Weird stream device behavior when using the IOC shell's exit function

> 

> 

> Hi Mark

> 

> 

> 

> No command available which starts with asyn. I cloned the latest asyn from github with the same behavior.

> 

> For the gdb part, attached is the stack trace from gdb for all pending threads.

> 

> 

> 

> Best Regards,

> 

> Abdalla.

> 

> 

> 

> From: Mark Rivers [mailto:rivers@cars.uchicago.edu]

> Sent: Monday, February 04, 2019 4:52 PM

> To: Abdalla Ahmad 

> Cc: tech-talk@aps.anl.gov

> Subject: RE: Weird stream device behavior when using the IOC shell's exit function

> 

> 

> 

> At the iocsh prompt when the IOC is still running type the command

> 

> 

> 

> help

> 

> 

> 

> It should show a complete list of commands that the iocsh understands.  See which ones start with "asyn".

> 

> 

> 

> Mark

> 

> 

> 

> 

> 

> From: Abdalla Ahmad <abdalla.ahmad@sesame.org.jo>

> Sent: Monday, February 4, 2019 8:44 AM

> To: Mark Rivers <rivers@cars.uchicago.edu>

> Cc: tech-talk@aps.anl.gov

> Subject: Re: Weird stream device behavior when using the IOC shell's exit function

> 

> 

> 

> Hello Mark

> 

> I will apply the gdb tip and get back to you. For the asyn commands, I don't see any asyn command when I type exit.

> 

> Get Outlook for Android

> 

> 

> 

> 

> 

> On Mon, Feb 4, 2019 at 4:33 PM +0200, "Mark Rivers" <rivers@cars.uchicago.edu> wrote:

> 

> Hi Abdalla,

> 

> 

> 

>> asynError in write. Asyn driver says: device:port disconnected.

> 

> 

> 

> During IOC shutdown asyn does close all TCP ports.  However, record processing should have already been shut down, so I don't understand why you are getting that message from Stream.

> 

> 

> 

> Another problem we are facing with this new setup is that I can't find some asyn IOC shell function like asynTraceMask for example. The IOC is configured properly in RELEASE and src/Makefile. Is there anything we miss in the new setup?

> 

> 

> 

>> But eventually the IOC exits. For the gamma controllers we get something really strange.

> 

>> There a point in the database where the IOC never exits, the exit command just freezes and Ctrl-C is the only way to shut down the IOC.

> 

> 

> 

> I don't think I have seen that with Stream on any version of Stream/asyn/base that I have used.  That includes base 3.14.12, 3.15.5, 7.0.2.

> 

> 

> 

> If you run the IOC with gdb then when you type exit and it hangs do the following:

> 

> 

> 

> - Type Ctrl-C

> 

> - Enter the gdb command

> 

> thread apply all bt

> 

> 

> 

> That will show you the current stack trace for all threads.  You can then see what is blocking the threads.

> 

> 

> 

>> Another problem we are facing with this new setup is that I can't find some asyn IOC shell function like asynTraceMask for example.

> 

>> The IOC is configured properly in RELEASE and src/Makefile. Is there anything we miss in the new setup?

> 

> 

> 

> The command is not "asynTraceMask" it is "asynSetTraceMask" or "asynSetTraceIOMask".

> 

> 

> 

> What asyn commands do you see if you type "help" at the iocsh prompt?

> 

> 

> 

> Mark

> 

> 

> 

> ________________________________________

> 

> From: tech-talk-bounces@aps.anl.gov  on behalf of Abdalla Ahmad via Tech-talk

> 

> Sent: Monday, February 4, 2019 1:41 AM

> 

> To: tech-talk@aps.anl.gov

> 

> Subject: Weird stream device behavior when using the IOC shell's exit function

> 

> 

> 

> Hi

> 

> 

> 

> We are using the following setup to test control of the agilent XGS gauge controllers and Gamma ion pump controllers:

> 

> 1.       EPICS Base 3.15.6

> 

> 2.       Asyn R4-33

> 

> 3.       Stream R2-7-7c

> 

> 

> 

> For agilent controllers we get the following error:

> 

> 

> 

> asynError in write. Asyn driver says: device:port disconnected.

> 

> 

> 

> But eventually the IOC exits. For the gamma controllers we get something really strange. There a point in the database where the IOC never exits, the exit command just freezes and Ctrl-C is the only way to shut down the IOC. For now I can see that this behavior occurs because more DB substitutions are configured which means more PVs and more controllers. But that was not the case when we had:

> 

> 1.       EPICS Base 3.14.12.3

> 

> 2.       Asyn R4-18

> 

> 3.       Stream R2-5-1

> 

> 

> 

> Where the IOC exits with no errors or freezing. Should we upgrade our support modules or change the EPICS base?

> 

> 

> 

> Another problem we are facing with this new setup is that I can't find some asyn IOC shell function like asynTraceMask for example. The IOC is configured properly in RELEASE and src/Makefile. Is there anything we miss in the new setup?

> 

> 

> 

> Best Regards,

> 

> 

> 

> Abdalla Ahmad

> 

> Control Engineer

> 

> SESAME

> 

> Allan, Jordan.

> 

> Tel: (+962-5) 3511348 , ext. 265

> 

> Fax: (+962-5) 3511423

> 

> Mob: (+962-7)88183296

> 

> http://www.sesame.org.jo/

> 

> 

</rivers@cars.uchicago.edu</rivers@cars.uchicago.edu</abdalla.ahmad@sesame.org.jo