how do you log function call return values in golang

Question

I want to know the return values at time of exit from a golang function. The golang defer mechanism is helpful, but it evaluates arguments at the time the defer statement is registered rather than when it is executed. I can work with this using an anonymous function which accesses the return values:

func try() (int i) {
  defer func() {fmt.Printf("%d", i)}()
  i = 10
  return i+1
}

func main() {
  try()
}

This would work ok, i think, but I would like to handle this in a generic manner, perhaps something like:

func try(in string) (out int) {
  enter("%s", in);exit("%d", out)
}

or, even better, use reflection to output the arguments/return values at time of entry/exit. I'm assuming runtime performance isn't critical :).

Is there a good way to do this? Shaba Abhiram's handy Tracey lib does go a long way towards this but stops short of printing the return values.

the equivalent question for c#: [link](http://stackoverflow.com/questions/7393778/log-function-calls-parameter-values-return-values-in-c-sharp). They are using a runtime. Perhaps there is a way to use the Go runtime to generate trace output without requiring the programmer to do any instrumentation. — David Aiken, Apr 26 '15 at 02:02
even when it is generic you still plan to use it for something. Debugging per chance? — RickyA, Apr 26 '15 at 11:17
my immediate need is just for offline debugging/sanity checking. — David Aiken, Apr 26 '15 at 14:11
perhaps of interest to some: [optimal logging](http://googletesting.blogspot.com/2013/06/optimal-logging.html) — David Aiken, Apr 27 '15 at 18:43

score 3 · Answer 1 · answered Apr 26 '15 at 04:28

3

You are correct in assesing that the arguments to a deferred function are evaluated at the point the defer is queued, not when it is executed.

Your method of making an anonymous function that refers to named returns is valid. Another approach is to pass in the address of the return values:

func try() (i int) {
    defer printReturns(time.Now(), &i)
    time.Sleep(10 * time.Millisecond)
    i = 10
    return i + 1
}

func printReturns(start time.Time, rets ...interface{}) {
    fmt.Println(time.Now().Sub(start))
    for _,ret := range rets{
        fmt.Println(ret)
    }
}

The problem with this approach is that your logging function now has a pointer instead of the real type and must unwrap the pointers to do anything with them. But if you are using reflect, that is not horribly difficult.

answered Apr 26 '15 at 04:28

captncraig

22,118
17
108
151

Thanks captn. I am beginning to think that there should be a way to do this via function entry/exit hooks at the debug level. I don't think the go runtime exposes the required hooks, but could be wrong. I suspect you can retrieve the trace info in GDB without digging heavily into golang specifics. Golang has c underpinnings and there is a lot of existing, relatively fast, unobtrusive tooling there. – David Aiken Apr 26 '15 at 06:30
@DavidAiken I think a lot of tools do that kind of thing by generating code that inserts debug code. – captncraig Apr 27 '15 at 01:08
i think the disadvantage is that often the customer has a non-debug build and a debug build is too slow for heisenbugs. Ideally you would be able to get them to create logs with their current build to help you to troubleshoot and even reproduce the problem in your environment. I think the Go runtime has the data. Perhaps an option could enable trace logging at different levels of detail without incurring a heavy cost during normal operation. Such an option would avoid the need for custom instrumentation code in the app and the log could be processed using standard tools. – David Aiken Apr 27 '15 at 20:32
@DavidAiken I have used this approach more for runtime instrumentation than for debugging. Things like metrics / logging / etc. If you want debugging, use a debugger. Printfs get me most of what I need. – captncraig Apr 27 '15 at 21:00
thanks captn.. I'm on Yosemite, which has gone exclusively to LLVM now, but i may revisit it later. Different strokes for different folks.. there are a few c macros out there for capturing nested function entry/exit traces. A fast facility in the runtime which made use of the reflection data might also be helpful when supporting production code in the field, but that's just an opinion. – David Aiken Apr 27 '15 at 23:24

score 2 · Answer 2 · answered Apr 26 '15 at 02:50

2

The closest thing you will get to do it without adding a lot of printf's is using godebug, which pretty much adds the printfs for you.

answered Apr 26 '15 at 02:50

OneOfOne

95,033
20
184
185

Thanks One. It's a nice addition to the toolset. There are also [options at the DWARF level](http://stackoverflow.com/questions/311840/tool-to-trace-local-function-calls-in-linux#311912). It seems one of the GCC 4.8+ releases with built-in Go support might be usable. There is also a [recent clang port](https://github.com/sbinet/go-clang). – David Aiken Apr 26 '15 at 03:42
1

Be aware that although this is promising stuff it is currently also very immature. I was able to get some interesting insights with this, but the installation also killed the dependencies in my gopath. Do not use (yet) in a production gopath. – RickyA Apr 26 '15 at 15:06
Yes.. my experience as well. As you know, OSX has recently dropped GCC in favour of LLVM and homebrew has problems doing a clean install of GCC 4.9 on Yosemite. For now i've just slightly modded the Tracey lib to print output values.. i don't have a lot of calls to monitor. I think the go runtime has sufficient metadata to do automatic tracing, but i don't think the necessary interface is exposed. If a standard interface was available it might also be useful in event sourcing. – David Aiken Apr 26 '15 at 16:56

how do you log function call return values in golang

2 Answers2