Experimental Physics and
Industrial Control System

"J. Lewis Muir" <[email protected]> · Thu, 12 Jun 2008 12:42:52 -0400

On 5/5/08 11:27 AM, J. Lewis Muir wrote:
> On 5/2/08 5:55 PM, Jeff Hill wrote:
>> Hello Lewis,
>>
>> FWIW, I had a look at the main trunk in CVS and it appears that most CA
>> messages print using the following member function - which either calls
>> the user's message printing callback or else calls the "vfprintf (
>> stderr, ... )" function in the C standard library.
>>
>> int ca_client_context :: varArgsPrintFormated (
>>     const char *pformat, va_list args ) const // X aCC 361
>> {
>>     caPrintfFunc * pFunc;
>>     {
>>         Guard guard ( this->mutex );
>>         pFunc = this->pVPrintfFunc;
>>     }
>>     if ( pFunc ) {
>>         return ( *pFunc ) ( pformat, args );
>>     }
>>     else {
>>         return :: vfprintf ( stderr, pformat, args );
>>     }
>> }
> 
> Hi, Jeff.
> 
> Thanks for your response.
> 
> I might be misunderstanding things or maybe things have changed in CVS,
> but in 3.14.9 in
> 
>   src/ca/ca_client_context.cpp
> 
> there is
> 
>   ca_client_context::ca_client_context (bool enablePreemptiveCallback) :
>     createdByThread ( epicsThreadGetIdSelf () ),
>     ca_exception_func ( 0 ), ca_exception_arg ( 0 ),
>     pVPrintfFunc ( errlogVprintf ), fdRegFunc ( 0 ), fdRegArg ( 0 ),
>     pndRecvCnt ( 0u ), ioSeqNo ( 0u ), callbackThreadsPending ( 0u ),
>     localPort ( 0 ), fdRegFuncNeedsToBeCalled ( false ),
>     noWakeupSincePend ( true )
>   {
>     ...
>   }
> 
> So it looks like the errlogVprintf function from the IOC error logging
> facility is being used by default since there's the
> "pVPrintfFunc(errlogVprintf)" call, and unless this->pVPrintfFunc later
> gets set to null, varArgsPrintFormated will never use the vfprintf.
> 
> If this is how CVS still behaves and if CA by default is only supposed
> to write error messages to stderr, then either errlogVprintf from the
> IOC error logging facility must obey this constraint or CA needs to be
> changed to not use errlogVprintf by default.
> 
>> I also recall that during the preparation of R3.14 it was a huge hassle
>> that the code could not own a lock when it was calling the CA message
>> generating function (because it's not a good idea to hold a lock when
>> calling the user's callback to avoid deadlocks). So in certain tricky
>> situations I compromised and called "errPrintf()". Furthermore, after a
>> quick look in the source, it would appear that the errlog system *is*
>> printing to stdout. So that might explain how certain error messages are
>> ending up on stdout.
>>
>> LOCAL void errlogThread(void)
>> {
>>     listenerNode *plistenerNode;
>>     int          noConsoleMessage;
>>     char         *pmessage;
>>
>>     epicsAtExit(exitHandler,0);
>>     while(TRUE) {
>> 	epicsEventMustWait(pvtData.waitForWork);
>>         if(pvtData.atExit) break;
>>         while((pmessage = msgbufGetSend(&noConsoleMessage))) {
>>             if(pvtData.atExit) break;
>> 	    epicsMutexMustLock(pvtData.listenerLock);
>> 	    if(pvtData.toConsole && !noConsoleMessage) {
>>                 fprintf(stdout,"%s",pmessage);
>>                 fflush(stdout);
>>             }
>> 	    plistenerNode = (listenerNode *)ellFirst(
>>               &pvtData.listenerList);
>> 	    while(plistenerNode) {
>> 		(*plistenerNode->listener)(plistenerNode->pPrivate,
>>                   pmessage);
>> 		plistenerNode = (listenerNode *)ellNext(
>>                   &plistenerNode->node);
>> 	    }
>>             epicsMutexUnlock(pvtData.listenerLock);
>> 	    msgbufFreeSend();
>> 	}
>>         if(pvtData.atExit) break;
>>         if(epicsEventTryWait(pvtData.flush)!=epicsEventWaitOK) continue;
>>         epicsThreadSleep(.2); /*just wait an extra .2 seconds*/
>>         epicsEventSignal(pvtData.waitForFlush);
>>     }
>>     errlogCleanup();
>>     epicsEventSignal(pvtData.waitForExit);
>> }
> 
> I too looked at EPICS 3.14.9 base
> 
>   libCom/error/errlog.c
> 
> and indeed it prints to stdout in a number of places.  I see the
> following functions printing to stdout
> 
>   errlogPrintf
>   errlogSevPrintf
>   errPrintf
>   errlogThread
>   msgbufFreeSend
>   errlogRemoveListener
> 
> I'm fairly certain that msgbufFreeSend and errlogRemoveListener should
> not be printing to stdout since those cases are clearly just error
> messages.  That's a simple change.
> 
> However, I'm not sure about the rest.  I would be happy to submit a
> patch to make errlog.c only print to stderr.  However, I'm not sure of
> the intent of this logging facility.  Obviously the name would indicate
> that everything it logs is an error.  If this is truly the intent, then
> I think it's reasonable to change it to only print to stderr.  However,
> if the name is kind of out of date and it's really meant to be a general
> logging facility, not necessarily just for logging errors, then I'm not
> sure how others would feel if all messages went to stderr.  I'd be fine
> with it though.
> 
> Thanks,
> 
> Lewis
> 
> P.S. I've attached the attachments for my original email so others have
> them if desired.
> 
>>> -----Original Message-----
>>> From: J. Lewis Muir [mailto:[email protected]]
>>> Sent: Friday, May 02, 2008 1:10 PM
>>> To: Ralph Lange
>>> Cc: Jeff Hill
>>> Subject: camonitor prints CA errors to stdout rather than stderr
>>>
>>> Hi, Ralph.
>>>
>>> Thanks for writing such a useful tool in camonitor.  I'm using camonitor
>>> to do some simple logging of some EPICS PV values to a file by
>>> redirecting camonitor's stdout to a file.  Unfortunately, CA error
>>> messages are getting printed on stdout also.  I think this is a bug; CA
>>> error messages should be printed on stderr instead.
>>>
>>> I've written some software to parse these camonitor logs, but with CA
>>> error messages printed to stdout, they can corrupt the camonitor output
>>> being logged since they could appear at an arbitrary location.  If they
>>> were atomically written on their own lines I could trivially make my
>>> software ignore them, but when they can appear interleaved in an
>>> arbitrary way with the normal camonitor output, it makes it impractical
>>> to parse.  The attached corrupted.log gives an example of this.
>>>
>>> I've attached a patch, use-stderr.patch, for the EPICS 3.14.9 base file
>>>
>>>   src/catools/camonitor.c
>>>
>>> that replaces the CA printf handler with one that prints to stderr.
>>> Does this seem like a reasonable fix to you?
>>>
>>> According to the CA reference manual at
>>>
>>>   src/ca/CAref.html
>>>
>>> this change to camonitor.c should not be necessary.  In the description
>>> for the ca_replace_printf_handler function, it says the default handler
>>> uses fprintf to send messages to stderr.  This would be great, but it is
>>> not true; the messages are being printed on stdout.  I'd be quite happy
>>> if this were changed in CA somewhere making my change to camonitor.c
>>> unnecessary.
>>>
>>> Using the unmodified camonitor, I ran the following from a Bourne shell
>>>
>>>   camonitor 13ADSC1:det1:ADSCState | tee state.log
>>>
>>> The PV 13ADSC1:det1:ADSCState is provided by a soft IOC running on my
>>> computer.  I then typed "exit" at the soft IOC's console, it exited, and
>>> I started it again.  The resulting state.log file is attached.  It
>>> contains the stdout of the camonitor program and unfortunately also
>>> contains the CA exception message that was written to stdout.
>>>
>>> After modifying camonitor in the way my use-stderr.patch does, I
>>> performed the same experiment again by running
>>>
>>>   camonitor 13ADSC1:det1:ADSCState | tee state2.log
>>>
>>> The resulting state2.log file is attached.  This time it had the correct
>>> behavior; no CA exception message was written to stdout.
>>>
>>> I of course see the CA error message printed on the console where I ran
>>> camonitor both times.
>>>
>>> Thanks,
>>>
>>> Lewis
>>>
>>> --
>>> J. Lewis Muir
>>> Software Engineer
>>> IMCA-CAT/CARS

>From the responses I've gotten, the feeling seems to be that instead of
modifying camonitor or CA, the problem is really that the EPICS IOC
Error Logging facility is writing to the standard output stream but
should be writing to the standard error stream.  Attached are two
patches against EPICS base 3.14.9 to make the Error Logging facility
write to standard error instead of standard output:

  errlog-use-stderr.patch
    Patch against src/libCom/error/errlog.c

  errSymLib-use-stderr.patch
    Patch against src/libCom/error/errSymLib.c

The patch against errlog.c is straightforward.  The patch against
errSymLib.c is a little less so.  It had some places where the message
being printed was clearly an error message; for these I switched them to
print to stderr.  However, in the errSymDump and errSymTestPrint
functions, I left them printing to stdout since I'm not sure what the
intended behavior is.

Would any of the committers be willing to accept these changes?

Thanks,

Lewis

-- 
J. Lewis Muir
Software Engineer
IMCA-CAT/CARS

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System