Best logging practice

[Awaken]

Hi all,

I am looking for a way to put debug information in the code everywhere during development and control what specific

debug information (e.g. debug information comes from a specific source file) is outputted during debug easily.

In c, you can accomplish this with macros. But in go, it seems not quite straight forward.

I used to use log4go, but the "filter" it provides is actually an output target.

Any suggestions would be helpful.

[Peter Bourgon]

I don't know if it's best practice, but I'm pretty happy with the
simplicity and usability of something like this...

-----
var debug *bool = flag.Bool("debug", false, "enable debug logging")

func Debugf(format string, args ...interface{}) {
if *debug {
log.Printf("DEBUG "+format, args)
}
}

func Errorf(format string, args ...interface{}) {
log.Printf("ERROR "+format, args)
}

// etc.
-----

[Kyle Lemons]

I'm not aware of any existing way to do it, but you could relatively simply do this by creating a wrapper function that checks a regex passed in from the command-line and runs it against the runtime.Caller of the log function.

[Tom Carstens]

I do something like this: http://play.golang.org/p/fg6Dd9v6up

Where the standard log is used like your Debugf and criticalLog is used like your Errorf.

On Wednesday, May 16, 2012 3:34:58 PM UTC-5, Peter Bourgon wrote:

I don't know if it's best practice, but I'm pretty happy with the
simplicity and usability of something like this...

-----
var debug *bool = flag.Bool("debug", false, "enable debug logging")

func Debugf(format string, args ...interface{}) {
    if *debug {
        log.Printf("DEBUG "+format, args)
    }
}

func Errorf(format string, args ...interface{}) {
    log.Printf("ERROR "+format, args)
}

// etc.
-----

[kortschak]

This came up a while ago when I was interested in doing a similar thing - Dave Symonds gave a very nice solution that I now use: https://groups.google.com/d/msg/golang-nuts/gU7oQGoCkmg/BNIl-TqB-4wJ (also note Robs comment that follows in that thread).

http://play.golang.org/p/QFheQeChIn - Rob's version with a corection.

[Jim Robinson]

> http://play.golang.org/p/QFheQeChIn - Rob's version with a corection.

Though he did caution, in a follow up note:

>> Note that in all these cases, the arguments will be evaluated even if debug is false. This is different in effect and cost from the #define idiom of C.

>> 
>> The compiler is unlikely to be clever any time soon in this sort of thing.

>

> Actually, the language requires that the arguments be evaluated, so s/unlikely/certain never/ and s/any time soon//.

[Joubin Houshyar]

On May 16, 8:44 pm, kortschak <dan.kortsc...@adelaide.edu.au> wrote:
> This came up a while ago when I was interested in doing a similar thing -
> Dave Symonds gave a very nice solution that I now use:https://groups.google.com/d/msg/golang-nuts/gU7oQGoCkmg/BNIl-TqB-4wJ(also
> note Robs comment that follows in that thread).
>

> http://play.golang.org/p/QFheQeChIn- Rob's version with a corection.

try this: http://play.golang.org/p/8o0WywyaDT

[kortschak]

Yes, it is not the same as macro-based debug statements, but those are not possible without altering the source with e.g. sed. If the expressions being reported do not have side-effects there is no issue except for the time spent on the evalutation of the expressions.

[kortschak]

If you want to use levels, why not just use an int with a set of const definitions like None, Log, Debug, ... It seems more complex than it needs to be with no real difference.

[Joubin Houshyar]

On May 17, 8:15 am, kortschak <dan.kortsc...@adelaide.edu.au> wrote:
> If you want to use levels, why not just use an int with a set of const
> definitions like None, Log, Debug, ... It seems more complex than it needs
> to be with no real difference.

The hope is that mr. compiler (in some future variant if not today)
will not bother with nop methods. (Based on comment in cited thread
by r re "compiler".) You would assign your logger to debug or no
debug version and be done with it.

> Levels

You mean something like this? https://gist.github.com/2718939

>
>
>
>
>
>
>
> On Thursday, 17 May 2012 21:19:39 UTC+9:30, Joubin Houshyar wrote:
>
> > On May 16, 8:44 pm, kortschak <dan.kortsc...@adelaide.edu.au> wrote:
> > > This came up a while ago when I was interested in doing a similar thing
> > -
> > > Dave Symonds gave a very nice solution that I now use:

> >https://groups.google.com/d/msg/golang-nuts/gU7oQGoCkmg/BNIl-TqB-4wJ(...

> > > note Robs comment that follows in that thread).
>

> > >http://play.golang.org/p/QFheQeChIn-Rob's version with a corection.

[Jim Whitehead II]

On Thu, May 17, 2012 at 2:29 PM, Joubin Houshyar <jhou...@gmail.com> wrote:
>
>
> On May 17, 8:15 am, kortschak <dan.kortsc...@adelaide.edu.au> wrote:
>> If you want to use levels, why not just use an int with a set of const
>> definitions like None, Log, Debug, ... It seems more complex than it needs
>> to be with no real difference.
>
> The hope is that mr. compiler (in some future variant if not today)
> will not bother with nop methods.  (Based on comment in cited thread
> by r re "compiler".)   You would assign your logger to debug or no
> debug version and be done with it.

That would be surprising behaviour in a language with side effects. It
would prevent us from being able to read the following code and have
any idea what is going on:

foo(bar())

Regardless of how foo is defined I would expect that bar() is
evaluated when viewing this code from a birds-eye view. I'd resist any
sort of change like this simply because it's voodoo.

There's no reason you can't have a pre-processor as part of your build
process that does these sorts of things for.

- Jim

[Jim Whitehead II]

On Thu, May 17, 2012 at 4:32 PM, chris dollin <ehog....@googlemail.com> wrote:

> On 17 May 2012 16:22, Jim Whitehead II <jnwh...@gmail.com> wrote:
>> On Thu, May 17, 2012 at 2:29 PM, Joubin Houshyar <jhou...@gmail.com> wrote:
>>>
>>>
>>> On May 17, 8:15 am, kortschak <dan.kortsc...@adelaide.edu.au> wrote:
>>>> If you want to use levels, why not just use an int with a set of const
>>>> definitions like None, Log, Debug, ... It seems more complex than it needs
>>>> to be with no real difference.
>>>
>>> The hope is that mr. compiler (in some future variant if not today)
>>> will not bother with nop methods.  (Based on comment in cited thread
>>> by r re "compiler".)   You would assign your logger to debug or no
>>> debug version and be done with it.
>>
>> That would be surprising behaviour in a language with side effects. It
>> would prevent us from being able to read the following code and have
>> any idea what is going on:
>>
>> foo(bar())
>>
>> Regardless of how foo is defined I would expect that bar() is
>> evaluated when viewing this code from a birds-eye view. I'd resist any
>> sort of change like this simply because it's voodoo.
>

> If bar has no side-effects (which is what I think the OP meant
> by "nop method") then if foo discards bar's value the compiler
> could discard the evaluation of foo without damaging anyone's
> notion of what's going on.
>
> It's not a matter of the .language. having no side-effects, but
> of the .specific instance. not having them.

I'm bringing the list back into this, since I suspect you just forgot
to include it in your reply.

I don't actually think we mean different things, but let's look at a
more concrete example. Let's say you define a function called
'debugf', and call it like

debugf("just did something: %d", bar())

What I read being proposed was that if debugf is assigned a noop
(func(){} being the only acceptable definition of a noop in this
case), then bar would never be evaluated and everything would be
happy.

That's precisely what I disagree with, because I don't understand how
that would make sense in the context of the full language.

Certainly you can determine statically at compile-time if debugf is
set to a noop function and that it is never assigned any other value.
Even if that were the case, you don't currently have the information
needed in the compiler to determine whether or not bar has side
effects and can be safely dropped. Also, what happens if the value of
debugf can change during the running of a program?

I'm just confused how this could ever make sense in the language specification.

- Jim

[Joubin Houshyar]

On Thu, May 17, 2012 at 11:22 AM, Jim Whitehead II <jnwh...@gmail.com> wrote:

On Thu, May 17, 2012 at 2:29 PM, Joubin Houshyar <jhou...@gmail.com> wrote:
>
>
> On May 17, 8:15 am, kortschak <dan.kortsc...@adelaide.edu.au> wrote:
>> If you want to use levels, why not just use an int with a set of const
>> definitions like None, Log, Debug, ... It seems more complex than it needs
>> to be with no real difference.
>
> The hope is that mr. compiler (in some future variant if not today)
> will not bother with nop methods.  (Based on comment in cited thread
> by r re "compiler".)   You would assign your logger to debug or no
> debug version and be done with it.

That would be surprising behaviour in a language with side effects.

I appreciate your point, Jim.  But Go is also a static language.  

Can you help me understand why (beyond the requirements of academic rigor :-) the invariant fact that a function call e.g. foo() is a no-side-effect--no-thing--function and thus has been optimized away by the compiler of the static facts is "voodoo"?

It
would prevent us from being able to read the following code and have
any idea what is going on:

foo(bar())

Regardless of how foo is defined I would expect that bar() is
evaluated when viewing this code from a birds-eye view. I'd resist any
sort of change like this simply because it's voodoo.

There's no reason you can't have a pre-processor as part of your build
process that does these sorts of things for.

True.

 

- Jim

[Jim Whitehead II]

On Thu, May 17, 2012 at 5:30 PM, Joubin Houshyar <jhou...@gmail.com> wrote:
>
>
> On Thu, May 17, 2012 at 11:22 AM, Jim Whitehead II <jnwh...@gmail.com>
> wrote:
>>
>> On Thu, May 17, 2012 at 2:29 PM, Joubin Houshyar <jhou...@gmail.com>
>> wrote:
>> >
>> >
>> > On May 17, 8:15 am, kortschak <dan.kortsc...@adelaide.edu.au> wrote:
>> >> If you want to use levels, why not just use an int with a set of const
>> >> definitions like None, Log, Debug, ... It seems more complex than it
>> >> needs
>> >> to be with no real difference.
>> >
>> > The hope is that mr. compiler (in some future variant if not today)
>> > will not bother with nop methods.  (Based on comment in cited thread
>> > by r re "compiler".)   You would assign your logger to debug or no
>> > debug version and be done with it.
>>
>> That would be surprising behaviour in a language with side effects.
>
>
> I appreciate your point, Jim.  But Go is also a static language.
> Can you help me understand why (beyond the requirements of academic rigor
> :-) the invariant fact that a function call e.g. foo() is a
> no-side-effect--no-thing--function and thus has been optimized away by the
> compiler of the static facts is "voodoo"?

If we're talking a function that has no body and takes no arguments, I
don't think it is. However, in the context of actually debugging
programs, the functions we're talking about take arguments and those
arguments may themselves be the evaluation of functions with
side-effects.

If we're talking func(){}() being optimized away, I have no issue with
that, but that wasn't my understanding.

[Darren Grant]

Closure evaluation is explicit. Why is it necessary to bring compiler
optimization into the discussion?

I may be missing something here. :)

Cheers,
Darren

[kortschak]

Jim has already answered this well - the issue is that the arguments to call must be evaluated, the receiver is not going to make any difference to that. Given that in Rob's alteration the receiver is a const there is just as much compile-time information as in your example as far as I can see; i.e. if your example is optimised away then why is not a function call to an if false { ...} block?

On Thursday, 17 May 2012 22:59:58 UTC+9:30, Joubin Houshyar wrote:

The hope is that mr. compiler (in some future variant if not today)
will not bother with nop methods.  (Based on comment in cited thread
by r re "compiler".)   You would assign your logger to debug or no
debug version and be done with it.

> Levels

You mean something like this? https://gist.github.com/2718939

Less like that and more like a non-binary version of Dave Symonds' example.

[Dmitry Bond]

You could look how we do that in Seelog package and use it if you
like. Here is the document on this topic:

https://github.com/cihub/seelog/wiki/Constraints-and-exceptions

Our config sections for that looks like:

<seelog minlevel="info">
<exceptions>
<exception funcpattern="main.testFunc" minlevel="warn"/>
<exception funcpattern="main.testFunc2"
minlevel="error"/>
<exception funcpattern="*test*" filepattern="tests.go"
levels="off"/>
<exception funcpattern="*perfCritical"
minlevel="critical"/>
</exceptions>
...


We use Caller to get the caller info (if binary symbols are not
stripped). Also, we perform some optimizations, so that Caller is
called only once for each file/func/level and then cached + our config-
wide analysis allows us to find out which log levels should never be
used (for example, no debug or trace for production) and for these log
levels Caller is not called even once.