search

vmware / vic

vSphere Integrated Containers Engine is a container runtime for vSphere.
http://vmware.github.io/vic
Other
639 stars 173 forks source link

Logging framework #3051

Open hmahmood opened 7 years ago

hmahmood commented 7 years ago

As a developer, I would like to use a logging API/library to trace operations across library boundaries, with consistent and clearly formatted log output.

hickeng update: @casualjim has suggested we look at https://github.com/opentracing/opentracing-go

hmahmood commented 7 years ago

Some inconsistency problems to fix:

We lack consistency in our log output. For example, in vic-machine with --debug 1 we get something like:

DEBU[2016-11-07T17:01:40-06:00] Setting scratch image size to 8000000 KB in VCHConfig
time=2016-11-07T17:01:40.302454405-06:00 level=debug msg=[ END ] [github.com/vmware/vic/lib/install/validate.(*Validator).basics:267] [21.444µs]
time=2016-11-07T17:01:40.302469694-06:00 level=debug msg=[BEGIN] [github.com/vmware/vic/lib/install/validate.(*Validator).target:311]
time=2016-11-07T17:01:40.302479382-06:00 level=debug msg=[BEGIN] [github.com/vmware/vic/lib/install/validate.(*Validator).managedbyVC:337]
time=2016-11-07T17:01:40.316679876-06:00 level=debug msg=[ END ] [github.com/vmware/vic/lib/install/validate.(*Validator).managedbyVC:337] [14.186425ms]
time=2016-11-07T17:01:40.316915104-06:00 level=debug msg=[ END ] [github.com/vmware/vic/lib/install/validate.(*Validator).target:311] [14.441012ms]
time=2016-11-07T17:01:40.317132795-06:00 level=debug msg=[BEGIN] [github.com/vmware/vic/lib/install/validate.(*Validator).compute:36]
time=2016-11-07T17:01:40.317351909-06:00 level=debug msg=[BEGIN] [github.com/vmware/vic/lib/install/validate.(*Validator).ResourcePoolHelper:78]
DEBU[2016-11-07T17:01:40-06:00] Using default resource pool for compute resource: "/ha-datacenter/host/localhost.localdomain/Resources"

In addition we are using the default formatter object from logrus, which just outputs the key value pairs, in addition to escaping " and \n:

time="2016-11-07T23:01:58Z" level=debug msg="Encoding object: exec.Cmd{Path:\"/sbin/port-layer-server\", Args:[]string{\"/sbin/port-layer-server\", \"--host=localhost\", \"--port=2377\"}, Env:[]string{\"VC_URL=https://root:password@172.16.127.133/sdk\", \"DC_PATH=ha-datacenter\", \"CS_PATH=/ha-datacenter/host/localhost.localdomain\", \"POOL_PATH=/ha-datacenter/host/localhost.localdomain/Resources\", \"DS_PATH=datastore1\", \"HOME=/root\"}, Dir:\"\", Stdin:(*dio.multiReader)(0xc42030e080), Stdout:(*dio.multiWriter)(0xc420307170), Stderr:(*dio.multiWriter)(0xc420307230), ExtraFiles:[]*os.File{}, SysProcAttr:(*syscall.SysProcAttr)(nil), Process:(*os.Process)(0xc420315dd0), ProcessState:(*os.ProcessState)(nil), ctx:context.Context(nil), lookPathErr:error(nil), finished:false, childFiles:[]*os.File{(*os.File)(0xc4203120e0), (*os.File)(0xc420312108), (*os.File)(0xc420312118)}, closeAfterStart:[]io.Closer{(*os.File)(0xc4203120e0), (*os.File)(0xc420312108), (*os.File)(0xc420312118)}, closeAfterWait:[]io.Closer{(*os.File)(0xc4203120e8), (*os.File)(0xc420312100), (*os.File)(0xc420312110)}, goroutine:[]func() error{(func() error)(0x52a710), (func() error)(0x52a810), (func() error)(0x52a810)}, errch:(chan error)(0xc4202ab200), waitDone:(chan struct {})(nil)}" 
time="2016-11-07T23:01:58Z" level=debug msg="Tags: \"\""

This makes debugging even more challenging than it already is.

We need a formatter that will cleanly, and consistently format the logs across our packages and binaries. Here is an example from vmware.log:

2016-11-07T23:01:48.012Z| vmx| I125: Log for VMware ESX pid=73639 version=6.5.0 build=build-4564106 option=Release
2016-11-07T23:01:48.012Z| vmx| I125: The process is 64-bit.
2016-11-07T23:01:48.012Z| vmx| I125: Host codepage=UTF-8 encoding=UTF-8
2016-11-07T23:01:48.012Z| vmx| I125: Host is VMkernel 6.5.0
2016-11-07T23:01:48.004Z| vmx| I125: VTHREAD initialize main thread 0 "vmx" tid 73639
2016-11-07T23:01:48.004Z| vmx| I125: Msg_SetLocaleEx: HostLocale=UTF-8 UserLocale=NULL
2016-11-07T23:01:48.005Z| vmx| I125: DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.
2016-11-07T23:01:48.005Z| vmx| I125: ConfigDB: Failed to load /usr/lib/vmware/config
fdawg4l commented 7 years ago

@hmahmood vmware.log comes from vsphere. We (VIC) don't author that.

Also, I would like to see component level logging. I should be able to twiddle the verbosity of a given component and ONLY get that component's spew in the log.

hmahmood commented 7 years ago

@fdawg4l I just put vmware.log as an example of a clean looking log.

I'll add a story for the component level logging bit.

fdawg4l commented 7 years ago

One of the issues I've had with vmware.log is there isn't enough time granularity. For instance, in the snippet you posted above, it looks like the first 4 lines happened in parallel. Our date/time header, on the other hand, has the right level of granularity but is waaaaay too verbose. I don't care about the time zone, for instance.