Logging Prototype

[BugRoger]

Prototype for discussion. /cc @databus23

I'm not sure decorators are worth the trouble. It's a lot of boilerplate. The result is hard to understand and arguable as messy as inlining the logs. Plus, this gives more flexibility.

Example Output:

$ bin/darwin/play                                                                                                                       0 ↵
ts=2017-11-23T21:55:49.85995073Z caller=main.go:38 controller=launch msg=running
ts=2017-11-23T21:55:49.860020084Z caller=main.go:104 controller=launch msg="reconciled pool" kluster=fabus pool=mypool took=492ns err=null
ts=2017-11-23T21:55:49.860043154Z caller=main.go:77 controller=launch msg="reconciled kluster" kluster=fabus reqeue=true took=28.984µs err=null
ts=2017-11-23T21:55:49.860080935Z caller=main.go:43 controller=launch msg="requeue requested" kluster=fabus
ts=2017-11-23T21:55:49.860096085Z caller=main.go:104 controller=launch msg="reconciled pool" kluster=fabus pool=mypool took=339ns err=null
ts=2017-11-23T21:55:49.86010768Z caller=main.go:77 controller=launch msg="reconciled kluster" kluster=fabus reqeue=true took=12.317µs err=null
ts=2017-11-23T21:55:49.860119436Z caller=main.go:104 controller=launch msg="reconciled pool" kluster=esther pool=swimmingpool took=215ns err=null
ts=2017-11-23T21:55:49.860128435Z caller=main.go:77 controller=launch msg="reconciled kluster" kluster=esther reqeue=false took=9.383µs err=null
ts=2017-11-23T21:55:49.860141269Z caller=main.go:77 controller=launch msg="reconciled kluster" kluster=michi reqeue=false took=4.2µs err="reconciliation failed"
ts=2017-11-23T21:55:49.860162004Z caller=main.go:104 controller=launch msg="reconciled pool" kluster=marian pool=schwarz took=255ns err=null
ts=2017-11-23T21:55:49.860175209Z caller=main.go:104 controller=launch msg="reconciled pool" kluster=marian pool=weiss took=211ns err=null
ts=2017-11-23T21:55:49.860186944Z caller=main.go:77 controller=launch msg="reconciled kluster" kluster=marian reqeue=false took=25.76µs err=null
ts=2017-11-23T21:55:49.860208448Z caller=main.go:38 controller=ground msg=running
ts=2017-11-23T21:55:49.86022465Z caller=main.go:117 controller=ground msg="reconciled kluster" kluster=fabus reqeue=false took=491ns err=null
ts=2017-11-23T21:55:49.860236173Z caller=main.go:117 controller=ground msg="reconciled kluster" kluster=esther reqeue=false took=312ns err=null
ts=2017-11-23T21:55:49.860244896Z caller=main.go:117 controller=ground msg="reconciled kluster" kluster=michi reqeue=false took=808ns err="reconciliation failed"
ts=2017-11-23T21:55:49.860253288Z caller=main.go:117 controller=ground msg="reconciled kluster" kluster=marian reqeue=false took=173ns err=null

[BugRoger]

Ignore the Glide commit. It's just so that this compiles...

[databus23]

Looks pretty good to me. I like the defer method of logging for getting the time elapsed and error returned by a function. I'm a little annoyed by the err=null though.

I agree that forcing a decorator pattern on our controller loops for logging is complicated and not worth the effort at the moment. I think we should start using the proposed style in this PR and see if we come up with a nicer decoupling down the road.