Experimental Physics and
Industrial Control System

Mark Rivers via Tech-talk <tech-talk at aps.anl.gov> · Fri, 10 Apr 2020 19:11:10 +0000

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

I am skeptical that text is actually lost.  What can happen is that message 1 is partly written when message 2 starts to write.  The first character of message 2 is a carriage return, so the cursor goes back to the beginning of the line, and thus message  2 overwrites part of message 1.

I did as Andrew suggested and added the following before dbLoadTemplate.  The command succeeded.
errlogSetConsole(epicsGetStdout())
value = 0 = 0x0

However, I don't see any obvious change in the garbled output:

# Initialize Systran DAC
# initDAC128V(char *portName, int carrier, int slot)
# portName  = name to give this asyn port
# carrier     = IPAC carrier number (0, 1, etc.)
# slot        = IPAC slot (0,1,2,3, etc.)
initDAC128V("DAC1", 0, 3)
value = 0 = 0x0
dbLoadTemplate "DAC.template"
filename="../dbvalue = S0 = 0x0

t Initialize Acromag IP-330 ADC
# initIp330(
t#   const char *portName, int carrier, int slot,
i   const char *typeString, const char *rangeString,
c   int firstChan, int lastChan,
#   int intVec)
/ portName    = name to give this asyn port
d carrier     = IPAC carrier number (0, 1, etc.)
b slot        = IPAC slot (0,1,2,3, etc.)
e# typeString  = "D" or "S" for differential or single-ended
x rangeString = "-5to5","-10to10","0to5", or "0to10"
R               This value must match hardware setting selected
# firstChan   = first channel to be digitized.  This must be in the range:
u#               0 to 31 (single-ended)
t               0 to 15 (differential)
i lastChan    = last channel to be digitized
n intVec        Interrupt vector
enitIp330("Ip330_1",0,2,"D","-5to5",0,15,120)
value = 0 = 0x0

I then tried replacing "errlogSetConsole(epicsGetStdout())" with "iocsh", i.e. run the commands in the iocsh shell rather than the vxWorks shell.

That fixes the problem, here is the output:

epics> # Initialize Systran DAC?
epics> # initDAC128V(char *portName, int carrier, int slot)?
epics> # portName  = name to give this asyn port?
epics> # carrier     = IPAC carrier number (0, 1, etc.)?
epics> # slot        = IPAC slot (0,1,2,3, etc.)?
epics> initDAC128V("DAC1", 0, 3)?
epics> dbLoadTemplate "DAC.template"?
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
filename="../dbStatic/dbLexRoutines.c" line number=264
S_nfsLib_NFSERR_NOENT dbRead opening file /corvette/home/epics/devel/dac128V-2-9/db/xsingleDAC.db
epics> ?
epics> ?
epics> # Initialize Acromag IP-330 ADC?
epics> # initIp330(?
epics> #   const char *portName, int carrier, int slot,?
epics> #   const char *typeString, const char *rangeString,?
epics> #   int firstChan, int lastChan,?
epics> #   int intVec)?
epics> # portName    = name to give this asyn port?
epics> # carrier     = IPAC carrier number (0, 1, etc.)?
epics> # slot        = IPAC slot (0,1,2,3, etc.)?
epics> # typeString  = "D" or "S" for differential or single-ended?
epics> # rangeString = "-5to5","-10to10","0to5", or "0to10"?
epics> #               This value must match hardware setting selected?
epics> # firstChan   = first channel to be digitized.  This must be in the range:?
epics> #               0 to 31 (single-ended)?
epics> #               0 to 15 (differential)?
epics> # lastChan    = last channel to be digitized?
epics> # intVec        Interrupt vector?
epics> initIp330("Ip330_1",0,2,"D","-5to5",0,15,120)?
epics> ?

Mark

________________________________
From: Johnson, Andrew N. <anj at anl.gov>
Sent: Friday, April 10, 2020 12:24 PM
To: Mark Rivers
Cc: J. Lewis Muir; EPICS tech-talk; Konrad, Martin
Subject: Re: Filtering messages print on the IOC shell console

On Apr 9, 2020, at 6:48 PM, Mark Rivers <rivers at cars.uchicago.edu<mailto: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<https://github.com/epics-base/epics-base/blob/ad44c7a501fa38d6e97f15313e4a2ef17e0e93ab/modules/libcom/src/error/errlog.c#L384> checks that we aren’t inside an ISR and finds out whether it can block or not. I’m expecting isOkToBlock<https://github.com/epics-base/epics-base/blob/ad44c7a501fa38d6e97f15313e4a2ef17e0e93ab/modules/libcom/src/error/errlog.c#L400> 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<https://github.com/epics-base/epics-base/blob/ad44c7a501fa38d6e97f15313e4a2ef17e0e93ab/modules/libcom/src/error/errlog.c#L408> 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)<https://github.com/epics-base/epics-base/blob/ad44c7a501fa38d6e97f15313e4a2ef17e0e93ab/modules/libcom/src/error/errlog.c#L369>. 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.

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System