From 6290b58393c3047b6c0198751656088b207f88f1 Mon Sep 17 00:00:00 2001 From: "Justin Terry (VM)" Date: Wed, 21 Nov 2018 14:06:41 -0800 Subject: [PATCH] Changing logging to use logrus.WithFields Signed-off-by: Justin Terry (VM) --- cmd/runhcs/container.go | 32 ++- cmd/runhcs/vm.go | 9 +- internal/copywithtimeout/copywithtimeout.go | 22 +- internal/hcs/errors.go | 9 +- internal/hcs/log.go | 15 + internal/hcs/process.go | 154 ++++++---- internal/hcs/system.go | 304 +++++++++++++------- internal/hcs/watcher.go | 9 +- internal/logfields/fields.go | 37 +++ 9 files changed, 402 insertions(+), 189 deletions(-) create mode 100644 internal/hcs/log.go create mode 100644 internal/logfields/fields.go diff --git a/cmd/runhcs/container.go b/cmd/runhcs/container.go index 592017c64a..657a80bb82 100644 --- a/cmd/runhcs/container.go +++ b/cmd/runhcs/container.go @@ -15,6 +15,7 @@ import ( "github.com/Microsoft/hcsshim/internal/guid" "github.com/Microsoft/hcsshim/internal/hcs" "github.com/Microsoft/hcsshim/internal/hcsoci" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/regstate" "github.com/Microsoft/hcsshim/internal/runhcs" "github.com/Microsoft/hcsshim/internal/uvm" @@ -235,7 +236,11 @@ func parseAnnotationsBool(a map[string]string, key string) *bool { case "false": return &no default: - logrus.Warningf("annotation: '%s', with value: '%s', could not be parsed into boolean", key, v) + logrus.WithFields(logrus.Fields{ + logfields.OCIAnnotation: key, + logfields.Value: v, + logfields.ExpectedType: logfields.Bool, + }).Warning("annotation could not be parsed") } } return nil @@ -270,7 +275,12 @@ func parseAnnotationsUint32(a map[string]string, key string) *uint32 { v := uint32(countu) return &v } - logrus.Warningf("annotation: '%s', with value: '%s', could not be parsed into uint32: %s", key, v, err) + logrus.WithFields(logrus.Fields{ + logfields.OCIAnnotation: key, + logfields.Value: v, + logfields.ExpectedType: logfields.Uint32, + logrus.ErrorKey: err, + }).Warning("annotation could not be parsed") } return nil } @@ -283,7 +293,12 @@ func parseAnnotationsUint64(a map[string]string, key string) *uint64 { if err == nil { return &countu } - logrus.Warningf("annotation: '%s', with value: '%s', could not be parsed into uint64: %s", key, v, err) + logrus.WithFields(logrus.Fields{ + logfields.OCIAnnotation: key, + logfields.Value: v, + logfields.ExpectedType: logfields.Uint64, + logrus.ErrorKey: err, + }).Warning("annotation could not be parsed") } return nil } @@ -589,7 +604,11 @@ func (c *container) Unmount(all bool) error { err := c.issueVMRequest(op) if err != nil { if _, ok := err.(*noVMError); ok { - logrus.Warnf("did not unmount resources for container %s because VM shim for %s could not be contacted", c.ID, c.HostID) + logrus.WithFields(logrus.Fields{ + logfields.ContainerID: c.ID, + logfields.UVMID: c.HostID, + logrus.ErrorKey: errors.New("failed to unmount container resources"), + }).Warning("VM shim could not be contacted") } else { return err } @@ -617,7 +636,10 @@ func createContainerInHost(c *container, vm *uvm.UtilityVM) (err error) { if vm != nil { vmid = vm.ID() } - logrus.Infof("creating container %s (VM: '%s')", c.ID, vmid) + logrus.WithFields(logrus.Fields{ + logfields.ContainerID: c.ID, + logfields.UVMID: vmid, + }).Info("creating container in UVM") hc, resources, err := hcsoci.CreateContainer(opts) if err != nil { return err diff --git a/cmd/runhcs/vm.go b/cmd/runhcs/vm.go index 35b58bd395..058c2ef540 100644 --- a/cmd/runhcs/vm.go +++ b/cmd/runhcs/vm.go @@ -10,6 +10,7 @@ import ( winio "github.com/Microsoft/go-winio" "github.com/Microsoft/hcsshim/internal/appargs" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/runhcs" "github.com/Microsoft/hcsshim/internal/uvm" "github.com/pkg/errors" @@ -112,7 +113,8 @@ var vmshimCommand = cli.Command{ ioutil.ReadAll(pipe) } } else { - logrus.Error("failed creating container in VM: ", err) + logrus.WithError(err). + Error("failed creating container in VM") fmt.Fprintf(pipe, "%v", err) } pipe.Close() @@ -140,7 +142,10 @@ func processRequest(vm *uvm.UtilityVM, pipe net.Conn) error { if err != nil { return err } - logrus.Debug("received operation ", req.Op, " for ", req.ID) + logrus.WithFields(logrus.Fields{ + logfields.ContainerID: req.ID, + logfields.VMShimOperation: req.Op, + }).Debug("process request") c, err := getContainer(req.ID, false) if err != nil { return err diff --git a/internal/copywithtimeout/copywithtimeout.go b/internal/copywithtimeout/copywithtimeout.go index c5ee9a2633..c73fbd412a 100644 --- a/internal/copywithtimeout/copywithtimeout.go +++ b/internal/copywithtimeout/copywithtimeout.go @@ -31,11 +31,11 @@ func init() { // Copy is a wrapper for io.Copy using a timeout duration func Copy(dst io.Writer, src io.Reader, size int64, context string, timeout time.Duration) (int64, error) { - log := "to EOF" - if size > 0 { - log = fmt.Sprintf("%d bytes", size) - } - logrus.Debugf(fmt.Sprintf("hcsshim::copywithtimeout (%s) %s", context, log)) + logrus.WithFields(logrus.Fields{ + "stdval": context, + "size": size, + "timeout": timeout, + }).Debug("hcsshim::copywithtimeout - Begin") type resultType struct { err error @@ -62,7 +62,7 @@ func Copy(dst io.Writer, src io.Reader, size int64, context string, timeout time if size > 0 { bytes := make([]byte, size) if _, err := buf.Read(bytes); err == nil { - logrus.Debugf(fmt.Sprintf("hcsshim: copyWithTimeout\n%s", hex.Dump(bytes))) + logrus.Debugf("hcsshim::copyWithTimeout - Read bytes\n%s", hex.Dump(bytes)) } } } @@ -85,13 +85,19 @@ func Copy(dst io.Writer, src io.Reader, size int64, context string, timeout time errBrokenPipe = syscall.Errno(109) ) if se == errNoData || se == errBrokenPipe { - logrus.Debugf("hcsshim::copyWithTimeout: hit NoData or BrokenPipe: %d: %s", se, context) + logrus.WithFields(logrus.Fields{ + "stdval": context, + logrus.ErrorKey: se, + }).Debug("hcsshim::copywithtimeout - End") return result.bytes, nil } } return 0, fmt.Errorf("hcsshim::copyWithTimeout: error reading: '%s' after %d bytes (%s)", result.err, result.bytes, context) } } - logrus.Debugf("hcsshim::copyWithTimeout: success - copied %d bytes (%s)", result.bytes, context) + logrus.WithFields(logrus.Fields{ + "stdval": context, + "copied-bytes": result.bytes, + }).Debug("hcsshim::copywithtimeout - Completed Successfully") return result.bytes, nil } diff --git a/internal/hcs/errors.go b/internal/hcs/errors.go index 7471f5cc13..6368b57174 100644 --- a/internal/hcs/errors.go +++ b/internal/hcs/errors.go @@ -7,6 +7,7 @@ import ( "syscall" "github.com/Microsoft/hcsshim/internal/interop" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/sirupsen/logrus" ) @@ -116,10 +117,14 @@ func (ev *ErrorEvent) String() string { func processHcsResult(resultp *uint16) []ErrorEvent { if resultp != nil { resultj := interop.ConvertAndFreeCoTaskMemString(resultp) - logrus.Debugf("Result: %s", resultj) + logrus.WithField(logfields.JSON, resultj). + Debug("HCS Result") result := &hcsResult{} if err := json.Unmarshal([]byte(resultj), result); err != nil { - logrus.Warnf("Could not unmarshal HCS result %s: %s", resultj, err) + logrus.WithFields(logrus.Fields{ + logfields.JSON: resultj, + logrus.ErrorKey: err, + }).Warning("Could not unmarshal HCS result") return nil } return result.ErrorEvents diff --git a/internal/hcs/log.go b/internal/hcs/log.go new file mode 100644 index 0000000000..90d164e35e --- /dev/null +++ b/internal/hcs/log.go @@ -0,0 +1,15 @@ +package hcs + +import "github.com/sirupsen/logrus" + +func logOperationBegin(ctx logrus.Fields, msg string) { + logrus.WithFields(ctx).Debug(msg) +} + +func logOperationEnd(ctx logrus.Fields, msg string, err error) { + if err == nil { + logrus.WithFields(ctx).Debug(msg) + } else { + logrus.WithFields(ctx).WithError(err).Error(msg) + } +} diff --git a/internal/hcs/process.go b/internal/hcs/process.go index d356cdc4d6..42598cf2f5 100644 --- a/internal/hcs/process.go +++ b/internal/hcs/process.go @@ -2,7 +2,6 @@ package hcs import ( "encoding/json" - "fmt" "io" "sync" "syscall" @@ -10,6 +9,7 @@ import ( "github.com/Microsoft/hcsshim/internal/guestrequest" "github.com/Microsoft/hcsshim/internal/interop" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/sirupsen/logrus" ) @@ -21,6 +21,21 @@ type Process struct { system *System cachedPipes *cachedPipes callbackNumber uintptr + + logctx logrus.Fields +} + +func newProcess(process hcsProcess, processID int, computeSystem *System) *Process { + return &Process{ + handle: process, + processID: processID, + system: computeSystem, + logctx: logrus.Fields{ + logfields.HCSOperation: "", + logfields.ContainerID: computeSystem.ID(), + logfields.ProcessID: processID, + }, + } } type cachedPipes struct { @@ -72,13 +87,36 @@ func (process *Process) SystemID() string { return process.system.ID() } +func (process *Process) logOperationBegin(operation string) { + process.logctx[logfields.HCSOperation] = operation + logOperationBegin( + process.logctx, + "hcsshim::Process - Begin Operation") +} + +func (process *Process) logOperationEnd(err error) { + var result string + if err == nil { + result = "Success" + } else { + result = "Error" + } + + logOperationEnd( + process.logctx, + "hcsshim::Process - End Operation - "+result, + err) + process.logctx[logfields.HCSOperation] = "" +} + // Signal signals the process with `options`. -func (process *Process) Signal(options guestrequest.SignalProcessOptions) error { +func (process *Process) Signal(options guestrequest.SignalProcessOptions) (err error) { process.handleLock.RLock() defer process.handleLock.RUnlock() - operation := "Signal" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) + + operation := "hcsshim::Process::Signal" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) if process.handle == 0 { return makeProcessError(process, operation, ErrAlreadyClosed, nil) @@ -93,7 +131,7 @@ func (process *Process) Signal(options guestrequest.SignalProcessOptions) error var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("SignalProcess %s: %d", process.SystemID(), process.Pid()), &completed) + go syscallWatcher(process.logctx, &completed) err = hcsSignalProcess(process.handle, optionsStr, &resultp) completed = true events := processHcsResult(resultp) @@ -101,17 +139,17 @@ func (process *Process) Signal(options guestrequest.SignalProcessOptions) error return makeProcessError(process, operation, err, events) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return nil } // Kill signals the process to terminate but does not wait for it to finish terminating. -func (process *Process) Kill() error { +func (process *Process) Kill() (err error) { process.handleLock.RLock() defer process.handleLock.RUnlock() - operation := "Kill" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) + + operation := "hcsshim::Process::Kill" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) if process.handle == 0 { return makeProcessError(process, operation, ErrAlreadyClosed, nil) @@ -119,56 +157,54 @@ func (process *Process) Kill() error { var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("TerminateProcess %s: %d", process.SystemID(), process.Pid()), &completed) - err := hcsTerminateProcess(process.handle, &resultp) + go syscallWatcher(process.logctx, &completed) + err = hcsTerminateProcess(process.handle, &resultp) completed = true events := processHcsResult(resultp) if err != nil { return makeProcessError(process, operation, err, events) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return nil } // Wait waits for the process to exit. -func (process *Process) Wait() error { - operation := "Wait" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) +func (process *Process) Wait() (err error) { + operation := "hcsshim::Process::Wait" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) - err := waitForNotification(process.callbackNumber, hcsNotificationProcessExited, nil) + err = waitForNotification(process.callbackNumber, hcsNotificationProcessExited, nil) if err != nil { return makeProcessError(process, operation, err, nil) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return nil } // WaitTimeout waits for the process to exit or the duration to elapse. It returns // false if timeout occurs. -func (process *Process) WaitTimeout(timeout time.Duration) error { - operation := "WaitTimeout" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) +func (process *Process) WaitTimeout(timeout time.Duration) (err error) { + operation := "hcssshim::Process::WaitTimeout" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) - err := waitForNotification(process.callbackNumber, hcsNotificationProcessExited, &timeout) + err = waitForNotification(process.callbackNumber, hcsNotificationProcessExited, &timeout) if err != nil { return makeProcessError(process, operation, err, nil) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return nil } // ResizeConsole resizes the console of the process. -func (process *Process) ResizeConsole(width, height uint16) error { +func (process *Process) ResizeConsole(width, height uint16) (err error) { process.handleLock.RLock() defer process.handleLock.RUnlock() - operation := "ResizeConsole" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) + + operation := "hcsshim::Process::ResizeConsole" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) if process.handle == 0 { return makeProcessError(process, operation, ErrAlreadyClosed, nil) @@ -196,16 +232,16 @@ func (process *Process) ResizeConsole(width, height uint16) error { return makeProcessError(process, operation, err, events) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return nil } -func (process *Process) Properties() (*ProcessStatus, error) { +func (process *Process) Properties() (_ *ProcessStatus, err error) { process.handleLock.RLock() defer process.handleLock.RUnlock() - operation := "Properties" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) + + operation := "hcsshim::Process::Properties" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) if process.handle == 0 { return nil, makeProcessError(process, operation, ErrAlreadyClosed, nil) @@ -216,8 +252,8 @@ func (process *Process) Properties() (*ProcessStatus, error) { propertiesp *uint16 ) completed := false - go syscallWatcher(fmt.Sprintf("GetProcessProperties %s: %d", process.SystemID(), process.Pid()), &completed) - err := hcsGetProcessProperties(process.handle, &propertiesp, &resultp) + go syscallWatcher(process.logctx, &completed) + err = hcsGetProcessProperties(process.handle, &propertiesp, &resultp) completed = true events := processHcsResult(resultp) if err != nil { @@ -234,14 +270,16 @@ func (process *Process) Properties() (*ProcessStatus, error) { return nil, makeProcessError(process, operation, err, nil) } - logrus.Debugf(title+" succeeded processid=%d, properties=%s", process.processID, propertiesRaw) return properties, nil } // ExitCode returns the exit code of the process. The process must have // already terminated. -func (process *Process) ExitCode() (int, error) { - operation := "ExitCode" +func (process *Process) ExitCode() (_ int, err error) { + operation := "hcsshim::Process::ExitCode" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) + properties, err := process.Properties() if err != nil { return 0, makeProcessError(process, operation, err, nil) @@ -261,12 +299,13 @@ func (process *Process) ExitCode() (int, error) { // Stdio returns the stdin, stdout, and stderr pipes, respectively. Closing // these pipes does not close the underlying pipes; it should be possible to // call this multiple times to get multiple interfaces. -func (process *Process) Stdio() (io.WriteCloser, io.ReadCloser, io.ReadCloser, error) { +func (process *Process) Stdio() (_ io.WriteCloser, _ io.ReadCloser, _ io.ReadCloser, err error) { process.handleLock.RLock() defer process.handleLock.RUnlock() - operation := "Stdio" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) + + operation := "hcsshim::Process::Stdio" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) if process.handle == 0 { return nil, nil, nil, makeProcessError(process, operation, ErrAlreadyClosed, nil) @@ -279,7 +318,7 @@ func (process *Process) Stdio() (io.WriteCloser, io.ReadCloser, io.ReadCloser, e processInfo hcsProcessInformation resultp *uint16 ) - err := hcsGetProcessInfo(process.handle, &processInfo, &resultp) + err = hcsGetProcessInfo(process.handle, &processInfo, &resultp) events := processHcsResult(resultp) if err != nil { return nil, nil, nil, makeProcessError(process, operation, err, events) @@ -299,18 +338,18 @@ func (process *Process) Stdio() (io.WriteCloser, io.ReadCloser, io.ReadCloser, e return nil, nil, nil, makeProcessError(process, operation, err, nil) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return pipes[0], pipes[1], pipes[2], nil } // CloseStdin closes the write side of the stdin pipe so that the process is // notified on the read side that there is no more data in stdin. -func (process *Process) CloseStdin() error { +func (process *Process) CloseStdin() (err error) { process.handleLock.RLock() defer process.handleLock.RUnlock() - operation := "CloseStdin" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) + + operation := "hcsshim::Process::CloseStdin" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) if process.handle == 0 { return makeProcessError(process, operation, ErrAlreadyClosed, nil) @@ -337,35 +376,34 @@ func (process *Process) CloseStdin() error { return makeProcessError(process, operation, err, events) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return nil } // Close cleans up any state associated with the process but does not kill // or wait on it. -func (process *Process) Close() error { +func (process *Process) Close() (err error) { process.handleLock.Lock() defer process.handleLock.Unlock() - operation := "Close" - title := "hcsshim::Process::" + operation - logrus.Debugf(title+" processid=%d", process.processID) + + operation := "hcsshim::Process::Close" + process.logOperationBegin(operation) + defer process.logOperationEnd(err) // Don't double free this if process.handle == 0 { return nil } - if err := process.unregisterCallback(); err != nil { + if err = process.unregisterCallback(); err != nil { return makeProcessError(process, operation, err, nil) } - if err := hcsCloseProcess(process.handle); err != nil { + if err = hcsCloseProcess(process.handle); err != nil { return makeProcessError(process, operation, err, nil) } process.handle = 0 - logrus.Debugf(title+" succeeded processid=%d", process.processID) return nil } diff --git a/internal/hcs/system.go b/internal/hcs/system.go index 57afd5ec6b..2629380fd1 100644 --- a/internal/hcs/system.go +++ b/internal/hcs/system.go @@ -2,7 +2,6 @@ package hcs import ( "encoding/json" - "fmt" "os" "strconv" "sync" @@ -10,6 +9,7 @@ import ( "time" "github.com/Microsoft/hcsshim/internal/interop" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/schema1" "github.com/Microsoft/hcsshim/internal/timeout" "github.com/sirupsen/logrus" @@ -41,16 +41,49 @@ type System struct { handle hcsSystem id string callbackNumber uintptr -} -// CreateComputeSystem creates a new compute system with the given configuration but does not start it. -func CreateComputeSystem(id string, hcsDocumentInterface interface{}) (*System, error) { - operation := "CreateComputeSystem" - title := "hcsshim::" + operation + logctx logrus.Fields +} - computeSystem := &System{ +func newSystem(id string) *System { + return &System{ id: id, + logctx: logrus.Fields{ + logfields.HCSOperation: "", + logfields.ContainerID: id, + }, } +} + +func (computeSystem *System) logOperationBegin(operation string) { + computeSystem.logctx[logfields.HCSOperation] = operation + logOperationBegin( + computeSystem.logctx, + "hcsshim::ComputeSystem - Begin Operation") +} + +func (computeSystem *System) logOperationEnd(err error) { + var result string + if err == nil { + result = "Success" + } else { + result = "Error" + } + + logOperationEnd( + computeSystem.logctx, + "hcsshim::ComputeSystem - End Operation - "+result, + err) + computeSystem.logctx[logfields.HCSOperation] = "" +} + +// CreateComputeSystem creates a new compute system with the given configuration but does not start it. +func CreateComputeSystem(id string, hcsDocumentInterface interface{}) (_ *System, err error) { + operation := "hcsshim::CreateComputeSystem" + + computeSystem := newSystem(id) + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) hcsDocumentB, err := json.Marshal(hcsDocumentInterface) if err != nil { @@ -58,19 +91,22 @@ func CreateComputeSystem(id string, hcsDocumentInterface interface{}) (*System, } hcsDocument := string(hcsDocumentB) - logrus.Debugf(title+" ID=%s config=%s", id, hcsDocument) + + logrus.WithFields(computeSystem.logctx). + WithField(logfields.JSON, hcsDocument). + Debug("HCS ComputeSystem Document") var ( resultp *uint16 identity syscall.Handle ) completed := false - go syscallWatcher(fmt.Sprintf("CreateCompleteSystem %s: %s", id, hcsDocument), &completed) + go syscallWatcher(computeSystem.logctx, &completed) createError := hcsCreateComputeSystem(id, hcsDocument, identity, &computeSystem.handle, &resultp) completed = true if createError == nil || IsPending(createError) { - if err := computeSystem.registerCallback(); err != nil { + if err = computeSystem.registerCallback(); err != nil { // Terminate the compute system if it still exists. We're okay to // ignore a failure here. computeSystem.Terminate() @@ -88,25 +124,22 @@ func CreateComputeSystem(id string, hcsDocumentInterface interface{}) (*System, return nil, makeSystemError(computeSystem, operation, hcsDocument, err, events) } - logrus.Debugf(title+" succeeded id=%s handle=%d", id, computeSystem.handle) return computeSystem, nil } // OpenComputeSystem opens an existing compute system by ID. -func OpenComputeSystem(id string) (*System, error) { - operation := "OpenComputeSystem" - title := "hcsshim::" + operation - logrus.Debugf(title+" ID=%s", id) +func OpenComputeSystem(id string) (_ *System, err error) { + operation := "hcsshim::OpenComputeSystem" - computeSystem := &System{ - id: id, - } + computeSystem := newSystem(id) + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) var ( handle hcsSystem resultp *uint16 ) - err := hcsOpenComputeSystem(id, &handle, &resultp) + err = hcsOpenComputeSystem(id, &handle, &resultp) events := processHcsResult(resultp) if err != nil { return nil, makeSystemError(computeSystem, operation, "", err, events) @@ -114,18 +147,36 @@ func OpenComputeSystem(id string) (*System, error) { computeSystem.handle = handle - if err := computeSystem.registerCallback(); err != nil { + if err = computeSystem.registerCallback(); err != nil { return nil, makeSystemError(computeSystem, operation, "", err, nil) } - logrus.Debugf(title+" succeeded id=%s handle=%d", id, handle) return computeSystem, nil } // GetComputeSystems gets a list of the compute systems on the system that match the query -func GetComputeSystems(q schema1.ComputeSystemQuery) ([]schema1.ContainerProperties, error) { - operation := "GetComputeSystems" - title := "hcsshim::" + operation +func GetComputeSystems(q schema1.ComputeSystemQuery) (_ []schema1.ContainerProperties, err error) { + operation := "hcsshim::GetComputeSystems" + fields := logrus.Fields{ + logfields.HCSOperation: operation, + } + logOperationBegin( + fields, + "hcsshim::ComputeSystem - Begin Operation") + + defer func() { + var result string + if err == nil { + result = "Success" + } else { + result = "Error" + } + + logOperationEnd( + fields, + "hcsshim::ComputeSystem - End Operation - "+result, + err) + }() queryb, err := json.Marshal(q) if err != nil { @@ -133,14 +184,17 @@ func GetComputeSystems(q schema1.ComputeSystemQuery) ([]schema1.ContainerPropert } query := string(queryb) - logrus.Debugf(title+" query=%s", query) + + logrus.WithFields(fields). + WithField(logfields.JSON, query). + Debug("HCS ComputeSystem Query") var ( resultp *uint16 computeSystemsp *uint16 ) completed := false - go syscallWatcher(fmt.Sprintf("GetComputeSystems %s:", query), &completed) + go syscallWatcher(fields, &completed) err = hcsEnumerateComputeSystems(query, &computeSystemsp, &resultp) completed = true events := processHcsResult(resultp) @@ -153,20 +207,21 @@ func GetComputeSystems(q schema1.ComputeSystemQuery) ([]schema1.ContainerPropert } computeSystemsRaw := interop.ConvertAndFreeCoTaskMemBytes(computeSystemsp) computeSystems := []schema1.ContainerProperties{} - if err := json.Unmarshal(computeSystemsRaw, &computeSystems); err != nil { + if err = json.Unmarshal(computeSystemsRaw, &computeSystems); err != nil { return nil, err } - logrus.Debugf(title + " succeeded") return computeSystems, nil } // Start synchronously starts the computeSystem. -func (computeSystem *System) Start() error { +func (computeSystem *System) Start() (err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::ComputeSystem::Start ID=" + computeSystem.ID() - logrus.Debugf(title) + + operation := "hcsshim::ComputeSystem::Start" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) if computeSystem.handle == 0 { return makeSystemError(computeSystem, "Start", "", ErrAlreadyClosed, nil) @@ -200,15 +255,14 @@ func (computeSystem *System) Start() error { var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("StartComputeSystem %s:", computeSystem.ID()), &completed) - err := hcsStartComputeSystem(computeSystem.handle, "", &resultp) + go syscallWatcher(computeSystem.logctx, &completed) + err = hcsStartComputeSystem(computeSystem.handle, "", &resultp) completed = true events, err := processAsyncHcsResult(err, resultp, computeSystem.callbackNumber, hcsNotificationSystemStartCompleted, &timeout.SystemStart) if err != nil { return makeSystemError(computeSystem, "Start", "", err, events) } - logrus.Debugf(title + " succeeded") return nil } @@ -219,36 +273,40 @@ func (computeSystem *System) ID() string { // Shutdown requests a compute system shutdown, if IsPending() on the error returned is true, // it may not actually be shut down until Wait() succeeds. -func (computeSystem *System) Shutdown() error { +func (computeSystem *System) Shutdown() (err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::ComputeSystem::Shutdown" - logrus.Debugf(title) + + operation := "hcsshim::ComputeSystem::Shutdown" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) + if computeSystem.handle == 0 { return makeSystemError(computeSystem, "Shutdown", "", ErrAlreadyClosed, nil) } var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("ShutdownComputeSystem %s:", computeSystem.ID()), &completed) - err := hcsShutdownComputeSystem(computeSystem.handle, "", &resultp) + go syscallWatcher(computeSystem.logctx, &completed) + err = hcsShutdownComputeSystem(computeSystem.handle, "", &resultp) completed = true events := processHcsResult(resultp) if err != nil { return makeSystemError(computeSystem, "Shutdown", "", err, events) } - logrus.Debugf(title + " succeeded") return nil } // Terminate requests a compute system terminate, if IsPending() on the error returned is true, // it may not actually be shut down until Wait() succeeds. -func (computeSystem *System) Terminate() error { +func (computeSystem *System) Terminate() (err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::ComputeSystem::Terminate ID=" + computeSystem.ID() - logrus.Debugf(title) + + operation := "hcsshim::ComputeSystem::Terminate" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) if computeSystem.handle == 0 { return makeSystemError(computeSystem, "Terminate", "", ErrAlreadyClosed, nil) @@ -256,59 +314,66 @@ func (computeSystem *System) Terminate() error { var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("TerminateComputeSystem %s:", computeSystem.ID()), &completed) - err := hcsTerminateComputeSystem(computeSystem.handle, "", &resultp) + go syscallWatcher(computeSystem.logctx, &completed) + err = hcsTerminateComputeSystem(computeSystem.handle, "", &resultp) completed = true events := processHcsResult(resultp) if err != nil { return makeSystemError(computeSystem, "Terminate", "", err, events) } - logrus.Debugf(title + " succeeded") return nil } // Wait synchronously waits for the compute system to shutdown or terminate. -func (computeSystem *System) Wait() error { - title := "hcsshim::ComputeSystem::Wait ID=" + computeSystem.ID() - logrus.Debugf(title) +func (computeSystem *System) Wait() (err error) { + operation := "hcsshim::ComputeSystem::Wait" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) - err := waitForNotification(computeSystem.callbackNumber, hcsNotificationSystemExited, nil) + err = waitForNotification(computeSystem.callbackNumber, hcsNotificationSystemExited, nil) if err != nil { return makeSystemError(computeSystem, "Wait", "", err, nil) } - logrus.Debugf(title + " succeeded") return nil } // WaitTimeout synchronously waits for the compute system to terminate or the duration to elapse. // If the timeout expires, IsTimeout(err) == true -func (computeSystem *System) WaitTimeout(timeout time.Duration) error { - title := "hcsshim::ComputeSystem::WaitTimeout ID=" + computeSystem.ID() - logrus.Debugf(title) +func (computeSystem *System) WaitTimeout(timeout time.Duration) (err error) { + operation := "hcsshim::ComputeSystem::WaitTimeout" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) - err := waitForNotification(computeSystem.callbackNumber, hcsNotificationSystemExited, &timeout) + err = waitForNotification(computeSystem.callbackNumber, hcsNotificationSystemExited, &timeout) if err != nil { return makeSystemError(computeSystem, "WaitTimeout", "", err, nil) } - logrus.Debugf(title + " succeeded") return nil } -func (computeSystem *System) Properties(types ...schema1.PropertyType) (*schema1.ContainerProperties, error) { +func (computeSystem *System) Properties(types ...schema1.PropertyType) (_ *schema1.ContainerProperties, err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() + operation := "hcsshim::ComputeSystem::Properties" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) + queryj, err := json.Marshal(schema1.PropertyQuery{types}) if err != nil { return nil, makeSystemError(computeSystem, "Properties", "", err, nil) } + logrus.WithFields(computeSystem.logctx). + WithField(logfields.JSON, queryj). + Debug("HCS ComputeSystem Properties Query") + var resultp, propertiesp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("GetComputeSystemProperties %s:", computeSystem.ID()), &completed) + go syscallWatcher(computeSystem.logctx, &completed) err = hcsGetComputeSystemProperties(computeSystem.handle, string(queryj), &propertiesp, &resultp) completed = true events := processHcsResult(resultp) @@ -324,15 +389,18 @@ func (computeSystem *System) Properties(types ...schema1.PropertyType) (*schema1 if err := json.Unmarshal(propertiesRaw, properties); err != nil { return nil, makeSystemError(computeSystem, "Properties", "", err, nil) } + return properties, nil } // Pause pauses the execution of the computeSystem. This feature is not enabled in TP5. -func (computeSystem *System) Pause() error { +func (computeSystem *System) Pause() (err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::ComputeSystem::Pause ID=" + computeSystem.ID() - logrus.Debugf(title) + + operation := "hcsshim::ComputeSystem::Pause" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) if computeSystem.handle == 0 { return makeSystemError(computeSystem, "Pause", "", ErrAlreadyClosed, nil) @@ -340,24 +408,25 @@ func (computeSystem *System) Pause() error { var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("PauseComputeSystem %s:", computeSystem.ID()), &completed) - err := hcsPauseComputeSystem(computeSystem.handle, "", &resultp) + go syscallWatcher(computeSystem.logctx, &completed) + err = hcsPauseComputeSystem(computeSystem.handle, "", &resultp) completed = true events, err := processAsyncHcsResult(err, resultp, computeSystem.callbackNumber, hcsNotificationSystemPauseCompleted, &timeout.SystemPause) if err != nil { return makeSystemError(computeSystem, "Pause", "", err, events) } - logrus.Debugf(title + " succeeded") return nil } // Resume resumes the execution of the computeSystem. This feature is not enabled in TP5. -func (computeSystem *System) Resume() error { +func (computeSystem *System) Resume() (err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::ComputeSystem::Resume ID=" + computeSystem.ID() - logrus.Debugf(title) + + operation := "hcsshim::ComputeSystem::Resume" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) if computeSystem.handle == 0 { return makeSystemError(computeSystem, "Resume", "", ErrAlreadyClosed, nil) @@ -365,23 +434,26 @@ func (computeSystem *System) Resume() error { var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("ResumeComputeSystem %s:", computeSystem.ID()), &completed) - err := hcsResumeComputeSystem(computeSystem.handle, "", &resultp) + go syscallWatcher(computeSystem.logctx, &completed) + err = hcsResumeComputeSystem(computeSystem.handle, "", &resultp) completed = true events, err := processAsyncHcsResult(err, resultp, computeSystem.callbackNumber, hcsNotificationSystemResumeCompleted, &timeout.SystemResume) if err != nil { return makeSystemError(computeSystem, "Resume", "", err, events) } - logrus.Debugf(title + " succeeded") return nil } // CreateProcess launches a new process within the computeSystem. -func (computeSystem *System) CreateProcess(c interface{}) (*Process, error) { +func (computeSystem *System) CreateProcess(c interface{}) (_ *Process, err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::ComputeSystem::CreateProcess ID=" + computeSystem.ID() + + operation := "hcsshim::ComputeSystem::CreateProcess" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) + var ( processInfo hcsProcessInformation processHandle hcsProcess @@ -398,10 +470,13 @@ func (computeSystem *System) CreateProcess(c interface{}) (*Process, error) { } configuration := string(configurationb) - logrus.Debugf(title+" config=%s", configuration) + + logrus.WithFields(computeSystem.logctx). + WithField(logfields.JSON, configuration). + Debug("HCS ComputeSystem Process Document") completed := false - go syscallWatcher(fmt.Sprintf("CreateProcess %s: %s", computeSystem.ID(), configuration), &completed) + go syscallWatcher(computeSystem.logctx, &completed) err = hcsCreateProcess(computeSystem.handle, configuration, &processInfo, &processHandle, &resultp) completed = true events := processHcsResult(resultp) @@ -409,31 +484,37 @@ func (computeSystem *System) CreateProcess(c interface{}) (*Process, error) { return nil, makeSystemError(computeSystem, "CreateProcess", configuration, err, events) } - process := &Process{ - handle: processHandle, - processID: int(processInfo.ProcessId), - system: computeSystem, - cachedPipes: &cachedPipes{ - stdIn: processInfo.StdInput, - stdOut: processInfo.StdOutput, - stdErr: processInfo.StdError, - }, + logrus.WithFields(computeSystem.logctx). + WithField(logfields.ProcessID, processInfo.ProcessId). + Debug("HCS ComputeSystem CreateProcess PID") + + process := newProcess(processHandle, int(processInfo.ProcessId), computeSystem) + process.cachedPipes = &cachedPipes{ + stdIn: processInfo.StdInput, + stdOut: processInfo.StdOutput, + stdErr: processInfo.StdError, } - if err := process.registerCallback(); err != nil { + if err = process.registerCallback(); err != nil { return nil, makeSystemError(computeSystem, "CreateProcess", "", err, nil) } - logrus.Debugf(title+" succeeded processid=%d", process.processID) return process, nil } // OpenProcess gets an interface to an existing process within the computeSystem. -func (computeSystem *System) OpenProcess(pid int) (*Process, error) { +func (computeSystem *System) OpenProcess(pid int) (_ *Process, err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::ComputeSystem::OpenProcess ID=" + computeSystem.ID() - logrus.Debugf(title+" processid=%d", pid) + + // Add PID for the context of this operation + computeSystem.logctx[logfields.ProcessID] = pid + defer delete(computeSystem.logctx, logfields.ProcessID) + + operation := "hcsshim::ComputeSystem::OpenProcess" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) + var ( processHandle hcsProcess resultp *uint16 @@ -444,47 +525,43 @@ func (computeSystem *System) OpenProcess(pid int) (*Process, error) { } completed := false - go syscallWatcher(fmt.Sprintf("OpenProcess %s: %d", computeSystem.ID(), pid), &completed) - err := hcsOpenProcess(computeSystem.handle, uint32(pid), &processHandle, &resultp) + go syscallWatcher(computeSystem.logctx, &completed) + err = hcsOpenProcess(computeSystem.handle, uint32(pid), &processHandle, &resultp) completed = true events := processHcsResult(resultp) if err != nil { return nil, makeSystemError(computeSystem, "OpenProcess", "", err, events) } - process := &Process{ - handle: processHandle, - processID: pid, - system: computeSystem, - } - - if err := process.registerCallback(); err != nil { + process := newProcess(processHandle, pid, computeSystem) + if err = process.registerCallback(); err != nil { return nil, makeSystemError(computeSystem, "OpenProcess", "", err, nil) } - logrus.Debugf(title+" succeeded processid=%s", process.processID) return process, nil } // Close cleans up any state associated with the compute system but does not terminate or wait for it. -func (computeSystem *System) Close() error { +func (computeSystem *System) Close() (err error) { computeSystem.handleLock.Lock() defer computeSystem.handleLock.Unlock() - title := "hcsshim::ComputeSystem::Close ID=" + computeSystem.ID() - logrus.Debugf(title) + + operation := "hcsshim::ComputeSystem::Close" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) // Don't double free this if computeSystem.handle == 0 { return nil } - if err := computeSystem.unregisterCallback(); err != nil { + if err = computeSystem.unregisterCallback(); err != nil { return makeSystemError(computeSystem, "Close", "", err, nil) } completed := false - go syscallWatcher(fmt.Sprintf("CloseComputeSystem %s:", computeSystem.ID()), &completed) - err := hcsCloseComputeSystem(computeSystem.handle) + go syscallWatcher(computeSystem.logctx, &completed) + err = hcsCloseComputeSystem(computeSystem.handle) completed = true if err != nil { return makeSystemError(computeSystem, "Close", "", err, nil) @@ -492,7 +569,6 @@ func (computeSystem *System) Close() error { computeSystem.handle = 0 - logrus.Debugf(title + " succeeded") return nil } @@ -553,11 +629,14 @@ func (computeSystem *System) unregisterCallback() error { return nil } -// Modifies the System by sending a request to HCS -func (computeSystem *System) Modify(config interface{}) error { +// Modify the System by sending a request to HCS +func (computeSystem *System) Modify(config interface{}) (err error) { computeSystem.handleLock.RLock() defer computeSystem.handleLock.RUnlock() - title := "hcsshim::Modify ID=" + computeSystem.id + + operation := "hcsshim::ComputeSystem::Modify" + computeSystem.logOperationBegin(operation) + defer computeSystem.logOperationEnd(err) if computeSystem.handle == 0 { return makeSystemError(computeSystem, "Modify", "", ErrAlreadyClosed, nil) @@ -569,17 +648,20 @@ func (computeSystem *System) Modify(config interface{}) error { } requestString := string(requestJSON) - logrus.Debugf(title + " " + requestString) + + logrus.WithFields(computeSystem.logctx). + WithField(logfields.JSON, requestString). + Debug("HCS ComputeSystem Modify Document") var resultp *uint16 completed := false - go syscallWatcher(fmt.Sprintf("ModifyComputeSystem %s: %s", computeSystem.ID(), requestString), &completed) + go syscallWatcher(computeSystem.logctx, &completed) err = hcsModifyComputeSystem(computeSystem.handle, requestString, &resultp) completed = true events := processHcsResult(resultp) if err != nil { return makeSystemError(computeSystem, "Modify", requestString, err, events) } - logrus.Debugf(title + " succeeded ") + return nil } diff --git a/internal/hcs/watcher.go b/internal/hcs/watcher.go index a015f871c8..e09dd1334f 100644 --- a/internal/hcs/watcher.go +++ b/internal/hcs/watcher.go @@ -3,6 +3,7 @@ package hcs import ( "time" + "github.com/Microsoft/hcsshim/internal/logfields" "github.com/Microsoft/hcsshim/internal/timeout" "github.com/sirupsen/logrus" ) @@ -17,14 +18,16 @@ import ( // Usage is: // // completed := false -// go syscallWatcher("some description", &completed) +// go syscallWatcher(context, &completed) // // completed = true // -func syscallWatcher(description string, syscallCompleted *bool) { +func syscallWatcher(context logrus.Fields, syscallCompleted *bool) { time.Sleep(timeout.SyscallWatcher) if *syscallCompleted { return } - logrus.Warnf("%s: Did not complete within %s. This may indicate a platform issue. If it appears to be making no forward progress, obtain the stacks and see if there is a syscall stuck in the platform API for a significant length of time.", description, timeout.SyscallWatcher) + logrus.WithFields(context). + WithField(logfields.Timeout, timeout.SyscallWatcher). + Warning("Syscall did not complete within operation timeout. This may indicate a platform issue. If it appears to be making no forward progress, obtain the stacks and see if there is a syscall stuck in the platform API for a significant length of time.") } diff --git a/internal/logfields/fields.go b/internal/logfields/fields.go new file mode 100644 index 0000000000..a1527d7060 --- /dev/null +++ b/internal/logfields/fields.go @@ -0,0 +1,37 @@ +package logfields + +const ( + // Identifiers + + ContainerID = "cid" + UVMID = "uvm-id" + ProcessID = "pid" + + // Common Misc + + // Timeout represents an operation timeout. + Timeout = "timeout" + JSON = "json" + + // Keys/values + + Field = "field" + OCIAnnotation = "oci-annotation" + Value = "value" + + // Golang type's + + ExpectedType = "expected-type" + Bool = "bool" + Uint32 = "uint32" + Uint64 = "uint64" + + // HCS + + HCSOperation = "hcs-op" + HCSOperationResult = "hcs-op-result" + + // runhcs + + VMShimOperation = "vmshim-op" +)