Handle error events in HCS notifications.

The shim parses the JSON result document and handles the error events
(via `processHcsResult`) returned directly by HCS calls
(e.g.,`vmcompute.HcsCreateComputeSystem`), but ignores the JSON (data)
payload for notifications (which are either received from a
`processAsyncHcsResult` in the appropriate system or process call in
`"internal.hcs"`, or via `waitForNotification` in `waitBackground`).

This leads to ambiguous failure errors (e.g., `"The data is invalid."`)
that require ETW traces to track down the appropriate HCS logs, even
though the error events already provide enough information to identify
the issue.

Add `processNotification()` to:
 1. parse the `notificationData` JSON payload provided by HCS to the
    `notificationWatcher` callback into the an `hcsResult` struct; and
 2. validate that the JSON data matches the notification HResult.

Create a new error type (`resultError`) to mirror the original [HCS
ResultError][result-error] and consolidate the events alongside the
original error.

Also, since `ErrorEvent`s are always converted to strings in the
context of concatenating several of them together, add an
`(*ErrorEvent).writeTo(*string.Builder)` function to provide more
efficient error string generation for `(HCS|System|Process)Error`s.
Additionally, consolidate the joining and formatting of error events
for those error types.

[result-error]: https://learn.microsoft.com/en-us/virtualization/api/hcs/schemareference#ResultError

Signed-off-by: Hamza El-Saawy <hamzaelsaawy@microsoft.com>

Author: helsaawy

internal/hcs/callback.go

@@ -4,6 +4,7 @@ package hcs
 
 import (
 	"context"
+	"encoding/json"
 	"fmt"
 	"sync"
 	"sync/atomic"
@@ -18,6 +19,8 @@ import (
 )
 
 var (
+	// TODO: don't delete notification contexts on close, so callback can handle delayed notifications
+
 	// used to lock [callbackMap].
 	callbackMapLock = sync.RWMutex{}
 	callbackMap     = map[callbackNumber]*notificationWatcherContext{}
@@ -167,14 +170,14 @@ func notificationWatcher(
 	notificationStatus uintptr,
 	notificationData *uint16,
 ) uintptr {
-	entry := log.G(context.Background()).WithFields(logrus.Fields{
+	ctx, entry := log.SetEntry(context.Background(), logrus.Fields{
 		logfields.CallbackNumber: callbackNum,
 		"notification-type":      notificationType.String(),
 	})
 
-	var result error
-	if int32(notificationStatus) < 0 {
-		result = interop.Win32FromHresult(notificationStatus)
+	result := processNotification(ctx, notificationStatus, notificationData)
+	if result != nil {
+		entry.Data[logrus.ErrorKey] = result
 	}
 
 	callbackMapLock.RLock()
@@ -198,3 +201,44 @@ func notificationWatcher(
 
 	return 0
 }
+
+// processNotification parses and validates HCS notifications and returns the result as an error.
+func processNotification(ctx context.Context, notificationStatus uintptr, notificationData *uint16) (err error) {
+	// TODO: merge/unify with [processHcsResult]
+	status := int32(notificationStatus)
+	if status < 0 {
+		err = interop.Win32FromHresult(notificationStatus)
+	}
+
+	if notificationData == nil {
+		return err
+	}
+
+	// don't call CoTaskMemFree since HCS_NOTIFICATION_CALLBACK's notificationData is PCWSTR.
+	resultJSON := interop.ConvertString(notificationData)
+	result := &hcsResult{}
+	if jsonErr := json.Unmarshal([]byte(resultJSON), result); jsonErr != nil {
+		log.G(ctx).WithFields(logrus.Fields{
+			logfields.JSON:  resultJSON,
+			logrus.ErrorKey: jsonErr,
+		}).Warn("could not unmarshal HCS result")
+		return err
+	}
+	log.G(ctx).WithField("result", result).Trace("parsed notification data")
+
+	// the HResult and data payload should have the same error value
+	if result.Error < 0 && status < 0 && status != result.Error {
+		log.G(ctx).WithFields(logrus.Fields{
+			"status": status,
+			"data":   result.Error,
+		}).Warn("mismatched notification status and data HResult values")
+	}
+
+	if len(result.ErrorEvents) > 0 {
+		return &resultError{
+			Err:    err,
+			Events: result.ErrorEvents,
+		}
+	}
+	return err
+}

internal/hcs/errors.go

@@ -8,9 +8,13 @@ import (
 	"errors"
 	"fmt"
 	"net"
+	"strings"
 	"syscall"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/Microsoft/hcsshim/internal/log"
+	"github.com/Microsoft/hcsshim/internal/logfields"
 )
 
 var (
@@ -102,43 +106,95 @@ type ErrorEvent struct {
 	//Data       []EventData `json:"Data,omitempty"`  // Omit this as HCS doesn't encode this well. It's more confusing to include. It is however logged in debug mode (see processHcsResult function)
 }
 
-type hcsResult struct {
-	Error        int32
-	ErrorMessage string
-	ErrorEvents  []ErrorEvent `json:"ErrorEvents,omitempty"`
+func (ev *ErrorEvent) String() string {
+	sb := new(strings.Builder)
+	ev.writeTo(sb)
+	return sb.String()
 }
 
-func (ev *ErrorEvent) String() string {
-	evs := "[Event Detail: " + ev.Message
+func (ev *ErrorEvent) writeTo(b *strings.Builder) {
+	// rough wag at needed length
+	b.Grow(64 + len(ev.Message) + len(ev.StackTrace) + len(ev.Provider) + len(ev.Source))
+
+	// [strings.Builder] Write* functions always return nil errors
+	_, _ = b.WriteString("[Event Detail: " + ev.Message)
 	if ev.StackTrace != "" {
-		evs += " Stack Trace: " + ev.StackTrace
+		_, _ = b.WriteString(" Stack Trace: " + ev.StackTrace)
 	}
 	if ev.Provider != "" {
-		evs += " Provider: " + ev.Provider
+		_, _ = b.WriteString(" Provider: " + ev.Provider)
 	}
 	if ev.EventID != 0 {
-		evs = fmt.Sprintf("%s EventID: %d", evs, ev.EventID)
+		fmt.Fprintf(b, " EventID: %d", ev.EventID)
 	}
 	if ev.Flags != 0 {
-		evs = fmt.Sprintf("%s flags: %d", evs, ev.Flags)
+		fmt.Fprintf(b, " flags: %d", ev.Flags)
 	}
 	if ev.Source != "" {
-		evs += " Source: " + ev.Source
+		_, _ = b.WriteString(" Source: " + ev.Source)
 	}
-	evs += "]"
-	return evs
+	_ = b.WriteByte(']')
+}
+
+type hcsResult struct {
+	Error        int32
+	ErrorMessage string       // ErrorMessage should be the same as `windows.Errno(Err).Error()`.
+	ErrorEvents  []ErrorEvent `json:"ErrorEvents,omitempty"`
+	// TODO: AttributionRecords
 }
 
 func processHcsResult(ctx context.Context, resultJSON string) []ErrorEvent {
-	if resultJSON != "" {
-		result := &hcsResult{}
-		if err := json.Unmarshal([]byte(resultJSON), result); err != nil {
-			log.G(ctx).WithError(err).Warning("Could not unmarshal HCS result")
-			return nil
-		}
-		return result.ErrorEvents
+	if resultJSON == "" {
+		return nil
 	}
-	return nil
+
+	result := &hcsResult{}
+	if err := json.Unmarshal([]byte(resultJSON), result); err != nil {
+		log.G(ctx).WithFields(logrus.Fields{
+			logfields.JSON:  resultJSON,
+			logrus.ErrorKey: err,
+		}).Warn("Could not unmarshal HCS result")
+		return nil
+	}
+	return result.ErrorEvents
+}
+
+// TODO: move [resultError] and [ErrorEvent] to schema2 and handle parsing results/data directly in vmcompute
+// See: https://learn.microsoft.com/en-us/virtualization/api/hcs/schemareference#ResultError
+
+// resultError describes an HCS operation result and allows retaining the ErrorEvents
+// when an [error] is expected but an [HcsError] is not appropriate (i.e., the operation is not known).
+//
+// It is used in [notificationWatcher] to send the [ErrorEvent]s in a callback's notification data
+// to the corresponding [waitForNotification] via a [notificationChannel].
+type resultError struct {
+	Err    error
+	Events []ErrorEvent
+}
+
+func (e *resultError) Error() string {
+	return appendErrorEvents(e.Err.Error(), e.Events)
+}
+
+func (e *resultError) Is(target error) bool {
+	return errors.Is(e.Err, target)
+}
+
+func (e *resultError) Unwrap() error {
+	return e.Err
+}
+
+// getEvents checks to see if err is a [resultError], and if so, returns the unwrapped error
+// and [ErrorEvent]s.
+//
+// Currently, only [notificationWatcher] creates [resultError]s, and they are subsequently
+// handled in [waitForNotification].
+func getEvents(err error) ([]ErrorEvent, error) {
+	var rErr *resultError
+	if errors.As(err, &rErr) {
+		return rErr.Events, rErr.Err
+	}
+	return nil, err
 }
 
 type HcsError struct {
@@ -149,12 +205,22 @@ type HcsError struct {
 
 var _ net.Error = &HcsError{}
 
-func (e *HcsError) Error() string {
-	s := e.Op + ": " + e.Err.Error()
-	for _, ev := range e.Events {
-		s += "\n" + ev.String()
+func makeHCSError(op string, err error, events []ErrorEvent) error {
+	// Don't double wrap errors
+	var e *HcsError
+	if errors.As(err, &e) {
+		return err
+	}
+
+	return &HcsError{
+		Op:     op,
+		Err:    err,
+		Events: events,
 	}
-	return s
+}
+
+func (e *HcsError) Error() string {
+	return appendErrorEvents(e.Op+": "+e.Err.Error(), e.Events)
 }
 
 func (e *HcsError) Is(target error) bool {
@@ -194,11 +260,7 @@ type SystemError struct {
 var _ net.Error = &SystemError{}
 
 func (e *SystemError) Error() string {
-	s := e.Op + " " + e.ID + ": " + e.Err.Error()
-	for _, ev := range e.Events {
-		s += "\n" + ev.String()
-	}
-	return s
+	return appendErrorEvents(fmt.Sprintf("%s %s: %s", e.Op, e.ID, e.Err.Error()), e.Events)
 }
 
 func makeSystemError(system *System, op string, err error, events []ErrorEvent) error {
@@ -228,11 +290,7 @@ type ProcessError struct {
 var _ net.Error = &ProcessError{}
 
 func (e *ProcessError) Error() string {
-	s := fmt.Sprintf("%s %s:%d: %s", e.Op, e.SystemID, e.Pid, e.Err.Error())
-	for _, ev := range e.Events {
-		s += "\n" + ev.String()
-	}
-	return s
+	return appendErrorEvents(fmt.Sprintf("%s %s:%d: %s", e.Op, e.SystemID, e.Pid, e.Err.Error()), e.Events)
 }
 
 func makeProcessError(process *Process, op string, err error, events []ErrorEvent) error {
@@ -241,6 +299,7 @@ func makeProcessError(process *Process, op string, err error, events []ErrorEven
 	if errors.As(err, &e) {
 		return err
 	}
+
 	return &ProcessError{
 		Pid:      process.Pid(),
 		SystemID: process.SystemID(),
@@ -252,6 +311,22 @@ func makeProcessError(process *Process, op string, err error, events []ErrorEven
 	}
 }
 
+// common formatting for error strings followed by event data,
+func appendErrorEvents(s string, events []ErrorEvent) string {
+	if len(events) == 0 {
+		return s
+	}
+
+	sb := new(strings.Builder)
+	_, _ = sb.WriteString(s)
+	for _, ev := range events {
+		// don't join with newlines since those are ... awkward within error strings
+		_, _ = sb.WriteString(": ")
+		ev.writeTo(sb)
+	}
+	return sb.String()
+}
+
 // IsNotExist checks if an error is caused by the Container or Process not existing.
 // Note: Currently, ErrElementNotFound can mean that a Process has either
 // already exited, or does not exist. Both IsAlreadyStopped and IsNotExist

internal/hcs/process.go

@@ -232,16 +232,15 @@ func (process *Process) waitBackground() {
 		trace.Int64Attribute(logfields.ProcessID, int64(process.processID)))
 
 	var (
-		err            error
 		exitCode       = -1
 		propertiesJSON string
 		resultJSON     string
 	)
 
-	err = waitForNotification(ctx, process.callbackNumber, hcsNotificationProcessExited, nil)
+	events, err := waitForNotification(ctx, process.callbackNumber, hcsNotificationProcessExited, nil)
 	if err != nil {
-		err = makeProcessError(process, operation, err, nil)
-		log.G(ctx).WithError(err).Error("failed wait")
+		err = makeProcessError(process, operation, err, events)
+		log.G(ctx).WithError(err).Error("failed wait on process exit")
 	} else {
 		process.handleLock.RLock()
 		defer process.handleLock.RUnlock()

internal/hcs/service.go

@@ -21,7 +21,7 @@ func GetServiceProperties(ctx context.Context, q hcsschema.PropertyQuery) (*hcss
 	propertiesJSON, resultJSON, err := vmcompute.HcsGetServiceProperties(ctx, string(queryb))
 	events := processHcsResult(ctx, resultJSON)
 	if err != nil {
-		return nil, &HcsError{Op: operation, Err: err, Events: events}
+		return nil, makeHCSError(operation, err, events)
 	}
 
 	if propertiesJSON == "" {
@@ -45,7 +45,7 @@ func ModifyServiceSettings(ctx context.Context, settings hcsschema.ModificationR
 	resultJSON, err := vmcompute.HcsModifyServiceSettings(ctx, string(settingsJSON))
 	events := processHcsResult(ctx, resultJSON)
 	if err != nil {
-		return &HcsError{Op: operation, Err: err, Events: events}
+		return makeHCSError(operation, err, events)
 	}
 	return nil
 }

internal/hcs/system.go

@@ -180,7 +180,7 @@ func GetComputeSystems(ctx context.Context, q schema1.ComputeSystemQuery) ([]sch
 	computeSystemsJSON, resultJSON, err := vmcompute.HcsEnumerateComputeSystems(ctx, string(queryb))
 	events := processHcsResult(ctx, resultJSON)
 	if err != nil {
-		return nil, &HcsError{Op: operation, Err: err, Events: events}
+		return nil, makeHCSError(operation, err, events)
 	}
 
 	if computeSystemsJSON == "" {
@@ -284,15 +284,16 @@ func (computeSystem *System) waitBackground() {
 	defer span.End()
 	span.AddAttributes(trace.StringAttribute(logfields.SystemID, computeSystem.id))
 
-	err := waitForNotification(ctx, computeSystem.callbackNumber, hcsNotificationSystemExited, nil)
+	events, err := waitForNotification(ctx, computeSystem.callbackNumber, hcsNotificationSystemExited, nil)
 	if err == nil {
 		log.G(ctx).Debug("system exited")
 	} else if errors.Is(err, ErrVmcomputeUnexpectedExit) {
 		log.G(ctx).Debug("unexpected system exit")
 		computeSystem.exitError = makeSystemError(computeSystem, operation, err, nil)
 		err = nil
 	} else {
-		err = makeSystemError(computeSystem, operation, err, nil)
+		log.G(ctx).WithError(err).Error("failed wait on system exit")
+		err = makeSystemError(computeSystem, operation, err, events)
 	}
 	computeSystem.closedWaitOnce.Do(func() {
 		computeSystem.waitError = err