Re: camonitor prints CA errors to stdout rather than stderr

["J. Lewis Muir" <jlmuir@anl.gov>]

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:jlmuir@anl.gov]
>> 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

--- camonitor.c.orig	2007-01-25 16:21:05.000000000 -0500
+++ camonitor.c	2008-05-02 14:19:21.000000000 -0400
@@ -16,6 +16,7 @@
  *
  */
 
+#include <stdarg.h>
 #include <stdio.h>
 #include <epicsStdlib.h>
 #include <string.h>
@@ -173,6 +174,22 @@
 
 /*+**************************************************************************
  *
+ * Function:	stderr_printf_handler
+ *
+ * Description:	CA printf_handler
+ *
+ * Arg(s) In:	args  -  vprintf args (see vprintf(3))
+ *
+ **************************************************************************-*/
+
+static int stderr_printf_handler (const char *pFormat, va_list args)
+{
+    return vfprintf(stderr, pFormat, args);
+}
+
+
+/*+**************************************************************************
+ *
  * Function:	main
  *
  * Description:	camonitor main()
@@ -312,6 +329,14 @@
                 "to start channel access '%s'.\n", ca_message(result), pvs[n].name);
         return 1;
     }
+                                /* Make CA error messages go to stderr */
+    result = ca_replace_printf_handler(stderr_printf_handler);
+    if (result != ECA_NORMAL) {
+        fprintf(stderr, "CA error %s occurred while trying to initialize "
+                "error printing handler '%s'.\n", ca_message(result),
+                pvs[n].name);
+        return 1;
+    }
                                 /* Allocate PV structure array */
 
     pvs = calloc (nPvs, sizeof(pv));

17bm:AShutterBi                2008-02-29 16:03:34.117216 1 LINK MAJOR
17bm:BShutterBi                2008-02-29 16:03:34.117216 0 
17bm:Unidig1Bi2                2008-02-29 16:03:33.850549 0 
CA.Client.Exception...............................................
    Warning: "Virtual circuit unresponsive"
17bm:AShutterBi                    Context: "2008-02-29 16:08:00.342206 *** disconnected
17bm:BShutterBi                2008-02-29 16:08:00.342243 *** disconnected
17bm:Unidig1Bi2                2008-02-29 16:08:00.342269 *** disconnected
frog.imca.aps.anl.gov:5064"
    Source File: ../tcpiiu.cpp line 921
    Current Time: Fri Feb 29 2008 16:08:00.342167000
..................................................................

13ADSC1:det1:ADSCState         2008-05-02 12:12:57.354558 IDLE 
13ADSC1:det1:ADSCState         2008-05-02 12:14:39.865878 *** disconnected
CA.Client.Exception...............................................
    Warning: "Virtual circuit disconnect"
    Context: "localhost:5064"
    Source File: ../cac.cpp line 1126
    Current Time: Fri May 02 2008 12:14:39.865810000
..................................................................
13ADSC1:det1:ADSCState         2008-05-02 12:14:49.971078 IDLE 

13ADSC1:det1:ADSCState         2008-05-02 12:14:49.971078 IDLE 
13ADSC1:det1:ADSCState         2008-05-02 12:56:47.193059 *** disconnected
13ADSC1:det1:ADSCState         2008-05-02 12:56:59.199033 IDLE