Re: Filtering messages print on the IOC shell console

["Johnson, Andrew N. via Tech-talk" <tech-talk at aps.anl.gov>]

On Apr 9, 2020, at 6:48 PM, Mark Rivers <rivers at cars.uchicago.edu> wrote:

As expected the taskDelay command itself is garbled but it then allows time for the rest of the error messages to appear before the next vxWorks shell command is executed.

 

dbLoadTemplate "DAC.template"

value = filename="..0/dbStatic/dbLexRout = ines.c" line numb0xer=264

S_nfsLib_NF0

#fflush(epicsGetStderr())

peninNOENT dbRead otaskDelay(120)

g file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db

I color-coded the quoted text above (you will have to view this message as HTML to follow this) and discovered something interesting that I hadn’t noticed before: It’s not just that different messages are getting mixed together, we seem to have the text of a single message being scrambled and parts of it lost. The brown text all comes from the VxWorks shell and is in order. The rest is from a single call to errPrintf() which is getting scrambled. Here is one instance of that error message from later on, as it should appear:

filename="../dbStatic/dbLexRoutines.c" line number=264

S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db

The red and blue text come from that message, but there are some characters completely missing – “SERR_” is nowhere to be found (that’s 5 characters) and also the first 5 characters in blue are also being output before they should.

If, as Eric Norum says, stderr should be flushing each character then why does stderr output appear in the middle of the following vxWorks commands? 

The implication is that this has nothing to do with flushing stderr. So how is it being output? Here’s the call to errPrintf() from dbLexRoutines line 264:

            errPrintf(0, __FILE__, __LINE__,

                "dbRead opening file %s",pinputFile->filename);

It’s passing in a status of 0, which tells errPrinf() to read errno for the actual error. The errPrintf() code (in modules/libcom/src/error/errlog.c checks that we aren’t inside an ISR and finds out whether it can block or not. I’m expecting isOkToBlock to be true, but actually … (see below). We ask errSymLookup() to copy a string representation of the error value into our name buffer. The next if () condition will be true when the IOC is in the process of shutting down, or when our thread is allowed to block and we haven’t been silenced by some earlier call to eltc(0). First it finds the console output stream, which should be stderr in this case, then it sends the message to that stream in several parts – filename and line-number, the error symbol, the message string, and a newline. The stream is then flushed.

We’re not done yet with errPrintf(), but I have one suggestion that Mark may want to try, just for an experiment: Before your startup script calls dbLoadTemplate(), try doing

errlogSetConsole(epicsGetStdout())

I’m not expecting that to fix the problem, but it should switch the message to come out on stdout instead or stderr, which might tell us something about the effect that line-buffering the output stream would have. If it has no effect that may hint that the messages are being queued through the errlog queue instead of being printed immediately. It’s a pity that the format strings being passed to fprintf() are identical to the ones lower down, so I can’t be 100% sure that these errors are being printed by this code; maybe Mark could also add the following calls to the script as well so we can confirm what it normally returns for the VxWorks shell task, and set it if necessary:

epicsThreadIsOkToBlock()
epicsThreadSetOkToBlock(1)

Actually looking at the code in Base, the only calls to epicsThreadSetOkToBlock(1) come from iocsh (just before it starts reading command strings) and from one of the components of iocInit(), and it looks like the default value is 0, so I’m wondering if that last call might actually fix the original problem.

Just saw Freddie’s message, which roughly agrees with my connection here. I suggest we try this before I do any more analysis of why the above messages were re-ordered.

- Andrew

-- 

Complexity comes for free, simplicity you have to work for.