Changing logging to use logrus.WithFields

[jterry75]

Signed-off-by: Justin Terry (VM) juterry@microsoft.com

[jterry75]

Not ready for this to merge still have a lot of work to do in the other packages but before I go crazy I want some early feedback on the approach and if you think this will be helpful to do it in this way.

[jterry75]

@kevpar - FYI

[jstarks]

The example in https://godoc.org/github.com/sirupsen/logrus shows using WithFields for multi-field logging, not individual WithField calls. Which makes sense, because WithFields appears to be more efficient.

[jstarks]

Also, WithError just adds a field called "error" (or alternatively, logrus.ErrorKey), so we don't need to use it separately if there are other fields.

[jterry75]

@jstarks - I don't mind if we write logrus.ErrorKey into fields ourselves if we are already creating the logrus.Fields map previous to calling the log message.

In practice I feel like I want to write code like this (obviously more polished):

func DoWork(ctx context.Context, ...) error {
    ctx := log.Start(ctx, "DoWork")
    defer log.End(ctx, "DoWork")

    // Do something
    if err := ChildOperation(ctx); err != nil {
        return err
    }

    // ctx is restored to the original DoWork context
    SameContext(ctx)
}

func SubOperation(ctx context.Context) error {
    // Start a subcontext that tracks its parent but does not affect it.
    ctx := log.Start(ctx, "SubOperation")
    defer log.End(ctx, "SubOperation")

    id = "test" // RealWork that creates id
    ctx.WithFields("id", id)

    log.Debug(ctx, "Success")
    return nil
}

func SameContext(ctx context.Context) {
    ctx.WithFields("flows-up", true)
    log.Debug(ctx, "SameContext - Success")
}

And then see output like this:

{ "msg": "DoWork: Start Operation" }
{ "msg": "SubOperation: Start Operation", "parent": "DoWork" }
{ "msg": "SubOperation: Success", "id": "test", "parent": "DoWork" }
{ "msg": "SubOperation: End Operation", "id": "test", "parent": "DoWork" }
{ "msg": "DoWork: SameContext - Success", "flows-up": true }
{ "msg": "DoWork: End Operation", "flows-up": true }

[jterry75]

@jstarks @jhowardmsft - PTAL. I removed any additional syscallWatcher that I added. I will wait until #388 to fix these up if we decide to take that. I also changed process and system to use a statically created logctx field rather than alloc the map for each syscall begin/end which simplifies the maps nicely. I think this is good to go for at least these functions. Still need to convert internal/uvm and internal/hcsoci to this style for the best coverage.

[jterry75]

Merging this for now. Will add two additional changes for internal/uvm and internal/hcsoci logging changes.