[PATCH] debug: Add minimalist D_* macros

[Christof Schmitt]

On Tue, Dec 06, 2016 at 08:08:27AM +1100, Martin Schwenke wrote:
> On Mon, 5 Dec 2016 10:32:22 -0700, Christof Schmitt <cs at samba.org>
> wrote:
> 
> > On Mon, Dec 05, 2016 at 12:06:08PM +1100, Amitay Isaacs wrote:
> > > On Thu, Dec 1, 2016 at 3:57 PM, Martin Schwenke <martin at meltin.net> wrote:
> > >   
> > > > These don't include the function name or any other header.
> > > >
> > > > Please review and maybe push...
> > > >
> > > > peace & happiness,
> > > > martin
> > > >  
> > > 
> > > Since no one has NACKed it, pushed to autobuild. :-)  
> > 
> > I am probably late to this, but could you explain the intended use a bit?
> > 
> > My thoughts: In the past the preference was to always include the
> > function name in each message, that was the reason for adding it to the
> > DBG_* macros. Is the preference now (for ctdb?) to not have the function
> > names in each message?
> 
> Summary: for many state change messages, as opposed to low-level
> debugging messages, the location information adds clutter rather than
> adding useful information.

Thank you for the detailed input.

> At the moment the default debug level in CTDB is NOTICE.  We print a
> bunch of state-change messages that tell us what CTDB is doing.  For
> those we really don't need to know where it is in the code.
> 
> I think it comes down to there being 2 types of things you want to
> debug:
> 
> 1. Bugs in the program (smbd, CTDB) itself.
> 
> 2. System issues (cluster filesystem, communication, overload, ...).
> 
> So, I think what the location information is useful for diagnosing (1),
> it ends up cluttering the logs when you're trying to do (2).
> 
> In CTDB we end up doing a lot of (2) (and expect people running CTDB to
> be able to do some of that too).  Sometimes we need (1) as well.  I
> can imagine that CTDB will end up using both types of macros, provided
> we can fix problems (see below).

The same also applies for Samba code outside of ctdb, so a common
strategy would be good.

> The other thing is that we do different kinds of logging for some
> subprocesses.  We're only now getting to the stage where we can
> initialise logging in a long-lived subprocess and avoid all of the
> debug going through the main ctdbd process.  That is, we're going to
> have multiple processes logging directly to file/syslog.
> 
> However, in some short-lived processes we don't want to add the
> overhead of setting up a connection to a socket.  It is better for
> those to log to stderr and have the parent process capture the output.
> Until now we've avoided DEBUG() in some of those.  However, with
> minimalist macros like D_ERR() and D_NOTICE() available, it makes more
> sense to use debugging macros instead of rolling our own solution to get
> messages to stderr.
> 
> Almost finally, we're writing a lot of new code right now and wanted to
> use non-baroque macros (i.e. not DEBUG(DEBUG_ERR, ("foo %s\n", bar()));)
> in the new code.  So, we wanted something basic right now so we could
> get on with writing the important code and get back out of the logging
> business.  Being in the logging business isn't productive...  unless
> you're in the logging business...  :-)

Agreed. Only that the little logging business that we have should be
contained to lib/util/debug.* as much as possible.

> > My preference would be to have one set of entry points into the debug
> > code, and use those consistently through Samba. If we want to support
> > both styles (with and without function name prefix), then this could
> > become a config option for debug.c or it could be hardcoded for each
> > backend.
> 
> Yeah, true.
> 
> However, another problem is that the DBG_PREFIX() uses 3 writes to log
> (header, function, text), increasing the chance of file-logged
> messages being split.  That's no reason to add another entry point but
> it is going to be hard to fix the DBG_*() macros without simply
> dropping DBG_PREFIX().

I agree that it could be implemented better. My view was to let the code
slowly migrate to the simpler DBG_ interface. Maybe at some point we
could then change the remaining callers of DEBUG and then improve
lib/util/debug.* to reduce the number of calls.

> As I've just (finally) replied to Andreas:
> 
>   > 	debug prefix timestamp
>   > 	timestamp logs
>   > 
>   > 
>   > They are related and are totally broken.  
> 
>   Well, I don't think they're totally broken.  If you read the
>   documentation very carefully then "debug prefix timestamp" does what
>   it says!
> 
>   However, there should really be 3 options:
> 
>     debug location        = Add the file location
>     debug function        = Add the function name
>     debug header prefix   = Don't add a newline after header
> 
> I'm not sure our users want that level of complexity, though.
> 
> I think we need to distinguish between what our users need to see when
> something goes wrong and what we, as developers, need for debugging...

The question is where do we want to distinguish between those. Hardcoded
in the code in the use of D_* and DBG_*, a config option or maybe in the
DEVELOPER build?

I am not necessarily disagreeing with your approach, i am mainly trying
to understand it so that the same approach can be used in all new code.

My understanding from above is that D_* macros should be used for
messages that can be seen by users and DBG_* macros should be used for
messages that are only of interest to developers. If that is correct,
what about adding a comment to lib/util/debug.h and README.Coding to
document this?

Christof