Add policy-gated ETW logging for sidecar GCS

cmd/gcs-sidecar/main.go

@@ -14,9 +14,12 @@ import (
 	"unsafe"
 
 	"github.com/Microsoft/go-winio"
+	"github.com/Microsoft/go-winio/pkg/etw"
+	"github.com/Microsoft/go-winio/pkg/etwlogrus"
 	"github.com/Microsoft/hcsshim/internal/gcs/prot"
 	shimlog "github.com/Microsoft/hcsshim/internal/log"
 	"github.com/Microsoft/hcsshim/internal/ot"
+	logsources "github.com/Microsoft/hcsshim/internal/vm/vmutils/etw"
 	"github.com/Microsoft/hcsshim/pkg/amdsevsnp"
 	"github.com/Microsoft/hcsshim/pkg/securitypolicy"
 	"github.com/sirupsen/logrus"
@@ -191,6 +194,22 @@ func main() {
 	}
 	os.Stderr = logFileHandle
 
+	var loggingOptions []func(*securitypolicy.SecurityOptions)
+	// Keep the provider registered until process exit, as in the host shim.
+	provider, err := etw.NewProvider(logsources.SidecarProviderName, nil)
+	if err != nil {
+		logrus.WithError(err).Error("failed to register sidecar ETW provider")
+	} else if hook, err := etwlogrus.NewHookFromProvider(provider); err != nil {
+		logrus.WithError(err).Error("failed to initialize sidecar ETW hook")
+		if err := provider.Close(); err != nil {
+			logrus.WithError(err).Error("failed to close sidecar ETW provider")
+		}
+	} else {
+		gatedHook := sidecar.NewRuntimeLoggingHook(hook)
+		logrus.AddHook(gatedHook)
+		loggingOptions = append(loggingOptions, securitypolicy.WithRuntimeLoggingChanged(gatedHook.SetAllowed))
+	}
+
 	chsrv := make(chan error)
 	go func() {
 		defer close(chsrv)
@@ -278,7 +297,7 @@ func main() {
 	initialEnforcer := &securitypolicy.ClosedDoorSecurityPolicyEnforcer{}
 
 	// 3. Create bridge and initializa
-	brdg := sidecar.NewBridge(shimCon, gcsCon, initialEnforcer, logFileHandle)
+	brdg := sidecar.NewBridge(shimCon, gcsCon, initialEnforcer, logFileHandle, loggingOptions...)
 	brdg.AssignHandlers()
 
 	// 3. Listen and serve for hcsshim requests.

docs/sidecar-gcs-logging.md

@@ -0,0 +1,71 @@
+# Sidecar GCS ETW logging
+
+Sidecar GCS emits runtime diagnostics through the
+`Microsoft.Virtualization.GCSSidecar` ETW provider
+(`5400e7dc-0f0f-553d-19b5-3672635b5f7b`), using the same Logrus ETW hook as
+the host shim. Log Forward Service collects these events and forwards them
+through the existing Windows logging socket, not the GCS control bridge.
+
+## Policy
+
+The ETW hook starts disabled. After the guest validates and installs the
+confidential policy, `allow_runtime_logging` controls both ordinary runtime
+output and ETW emission. The existing Log Forward Service provider policy
+separately controls collection. There is no additional forwarding permission.
+
+Example policy excerpt (not a complete policy):
+
+```rego
+allow_runtime_logging := true
+allowed_log_providers := [
+    "Microsoft.Virtualization.GCSSidecar",
+]
+allow_log_provider_dropping := false
+log_provider := data.framework.log_provider
+```
+
+Existing versioned policy compatibility defaults still apply. Older policies
+can allow collection without an explicit provider list.
+
+## Collection
+
+The provider is included in the default sources at Information level. Enable
+forwarding with `io.microsoft.virtualmachine.forwardlogs.enable = true`.
+C-WCOW forwarding remains disabled by default. Every requested default provider
+must satisfy provider policy: a disallowed provider is dropped if dropping is
+enabled, or the request fails otherwise. Under the existing confidential startup
+behavior, that failure aborts UVM startup, even if runtime logging is disabled.
+
+To collect only sidecar logs at Verbose level, set
+`io.microsoft.virtualmachine.forwardlogs.defaultsources.enable = false` and
+set `io.microsoft.virtualmachine.forwardlogs.sources` to the base64 encoding of:
+
+```json
+{
+  "LogConfig": {
+    "sources": [{
+      "type": "ETW",
+      "providers": [{
+        "providerName": "Microsoft.Virtualization.GCSSidecar",
+        "level": "Verbose"
+      }]
+    }]
+  }
+}
+```
+
+Provider names are matched case-insensitively when overriding default levels.
+The sidecar Logrus level also filters events; debug and trace map to ETW
+Verbose. Existing guest-local file output is retained when runtime logging is
+allowed. No events suppressed before policy installation are replayed.
+
+Delivery is best effort. ETW events emitted before collection starts may be
+lost; direct stderr writes and Go panic dumps are not forwarded by the hook.
+Provider initialization failures are reported locally without terminating the
+sidecar. Stopping Log Forward Service stops forwarding, not authorized local
+ETW emission.
+
+On non-confidential WCOW guests, an absent sidecar provider does not require
+installing the sidecar. Guests without log-forwarding capability retain the
+existing unsupported-feature behavior; supported collectors can subscribe to
+the provider GUID even when no process has registered it.

internal/gcs-sidecar/bridge.go

@@ -87,8 +87,8 @@ type request struct {
 	message []byte
 }
 
-func NewBridge(shimConn io.ReadWriteCloser, inboxGCSConn io.ReadWriteCloser, initialEnforcer securitypolicy.SecurityPolicyEnforcer, logWriter io.Writer) *Bridge {
-	hostState := NewHost(initialEnforcer, logWriter)
+func NewBridge(shimConn io.ReadWriteCloser, inboxGCSConn io.ReadWriteCloser, initialEnforcer securitypolicy.SecurityPolicyEnforcer, logWriter io.Writer, options ...func(*securitypolicy.SecurityOptions)) *Bridge {
+	hostState := NewHost(initialEnforcer, logWriter, options...)
 	return &Bridge{
 		pending:        make(map[sequenceID]chan *prot.ContainerExecuteProcessResponse),
 		monitoredIDs:   make(map[sequenceID]struct{}),

internal/gcs-sidecar/host.go

@@ -104,13 +104,14 @@ type containerProcess struct {
 	pid uint32
 }
 
-func NewHost(initialEnforcer securitypolicy.SecurityPolicyEnforcer, logWriter io.Writer) *Host {
+func NewHost(initialEnforcer securitypolicy.SecurityPolicyEnforcer, logWriter io.Writer, options ...func(*securitypolicy.SecurityOptions)) *Host {
 	securityPolicyOptions := securitypolicy.NewSecurityOptions(
 		initialEnforcer,
 		false,
 		"",
 		"",
 		logWriter,
+		options...,
 	)
 	return &Host{
 		containers:               make(map[string]*Container),

internal/gcs-sidecar/logging.go

@@ -0,0 +1,35 @@
+//go:build windows
+
+package bridge
+
+import (
+	"sync/atomic"
+
+	"github.com/sirupsen/logrus"
+)
+
+// RuntimeLoggingHook gates a logging sink independently of Logrus's output
+// writer, which does not control hooks. Its initial state denies emission.
+type RuntimeLoggingHook struct {
+	next    logrus.Hook
+	allowed atomic.Bool
+}
+
+func NewRuntimeLoggingHook(next logrus.Hook) *RuntimeLoggingHook {
+	return &RuntimeLoggingHook{next: next}
+}
+
+func (h *RuntimeLoggingHook) SetAllowed(allowed bool) {
+	h.allowed.Store(allowed)
+}
+
+func (h *RuntimeLoggingHook) Levels() []logrus.Level {
+	return h.next.Levels()
+}
+
+func (h *RuntimeLoggingHook) Fire(entry *logrus.Entry) error {
+	if !h.allowed.Load() {
+		return nil
+	}
+	return h.next.Fire(entry)
+}

internal/gcs-sidecar/logging_policy_test.go

@@ -0,0 +1,57 @@
+//go:build windows
+
+package bridge
+
+import (
+	"encoding/json"
+	"testing"
+
+	"github.com/Microsoft/hcsshim/internal/gcs/prot"
+	"github.com/Microsoft/hcsshim/internal/protocol/guestrequest"
+	"github.com/Microsoft/hcsshim/internal/vm/vmutils/etw"
+	"github.com/Microsoft/hcsshim/pkg/securitypolicy"
+)
+
+func TestSidecarLogProviderPolicy(t *testing.T) {
+	for _, allow := range []bool{false, true} {
+		var enforcer securitypolicy.SecurityPolicyEnforcer = &securitypolicy.ClosedDoorSecurityPolicyEnforcer{}
+		if allow {
+			enforcer = &securitypolicy.OpenDoorSecurityPolicyEnforcer{}
+		}
+		b := newTestBridge(enforcer)
+		req := newModifyServiceSettingsRequest(buildLogForwardServiceRequest(t, etw.SidecarProviderName))
+		err := b.modifyServiceSettings(req)
+		if !allow {
+			if err == nil {
+				t.Fatal("denied sidecar subscription succeeded")
+			}
+			select {
+			case <-b.sendToGCSCh:
+				t.Fatal("denied subscription forwarded")
+			default:
+			}
+			continue
+		}
+		if err != nil {
+			t.Fatal(err)
+		}
+		select {
+		case forwarded := <-b.sendToGCSCh:
+			settings := &guestrequest.LogForwardServiceRPCRequest{}
+			message := prot.ServiceModificationRequest{Settings: settings}
+			if err := json.Unmarshal(forwarded.message, &message); err != nil {
+				t.Fatal(err)
+			}
+			sources, err := etw.DecodeAndUnmarshalLogSources(settings.Settings)
+			if err != nil {
+				t.Fatal(err)
+			}
+			providers := sources.LogConfig.Sources[0].Providers
+			if len(providers) != 1 || providers[0].ProviderGUID != etw.GetProviderGUIDFromName(etw.SidecarProviderName) {
+				t.Fatalf("unexpected forwarded providers: %+v", providers)
+			}
+		default:
+			t.Fatal("approved subscription not forwarded")
+		}
+	}
+}

internal/gcs-sidecar/logging_test.go

@@ -0,0 +1,91 @@
+//go:build windows
+
+package bridge
+
+import (
+	"errors"
+	"io"
+	"reflect"
+	"sync"
+	"sync/atomic"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+)
+
+type runtimeLogCapture struct {
+	count atomic.Int64
+	entry atomic.Pointer[logrus.Entry]
+	err   error
+}
+
+func (h *runtimeLogCapture) Levels() []logrus.Level { return logrus.AllLevels }
+func (h *runtimeLogCapture) Fire(entry *logrus.Entry) error {
+	h.count.Add(1)
+	h.entry.Store(entry)
+	return h.err
+}
+
+func TestRuntimeLoggingHook(t *testing.T) {
+	capture := &runtimeLogCapture{}
+	hook := NewRuntimeLoggingHook(capture)
+	logger := logrus.New()
+	logger.SetOutput(io.Discard)
+	logger.AddHook(hook)
+	logger.Info("before policy")
+	if capture.count.Load() != 0 {
+		t.Fatal("hook emitted before authorization")
+	}
+	if !reflect.DeepEqual(hook.Levels(), capture.Levels()) {
+		t.Fatal("hook changed supported levels")
+	}
+	hook.SetAllowed(true)
+	logger.WithField("containerID", "test").Info("allowed")
+	if capture.count.Load() != 1 {
+		t.Fatal("allowed hook was suppressed by discarded output")
+	}
+	if got := capture.entry.Load(); got.Message != "allowed" || got.Data["containerID"] != "test" {
+		t.Fatalf("event fields not preserved: %+v", got)
+	}
+	hook.SetAllowed(false)
+	logger.Info("denied")
+	if capture.count.Load() != 1 {
+		t.Fatal("denied hook emitted")
+	}
+
+	entry := logrus.NewEntry(logger).WithField("containerID", "test")
+	capture.err = errors.New("sink failed")
+	hook.SetAllowed(true)
+	if err := hook.Fire(entry); !errors.Is(err, capture.err) {
+		t.Fatalf("sink error not preserved: %v", err)
+	}
+	if capture.entry.Load() != entry {
+		t.Fatal("hook replaced the log entry")
+	}
+}
+
+func TestRuntimeLoggingHookConcurrent(t *testing.T) {
+	capture := &runtimeLogCapture{}
+	hook := NewRuntimeLoggingHook(capture)
+	entry := logrus.NewEntry(logrus.New())
+	var wg sync.WaitGroup
+	for range 8 {
+		wg.Add(1)
+		go func() {
+			defer wg.Done()
+			for i := range 1000 {
+				hook.SetAllowed(i%2 == 0)
+				if err := hook.Fire(entry); err != nil {
+					t.Error(err)
+				}
+			}
+		}()
+	}
+	wg.Wait()
+	hook.SetAllowed(false)
+	before := capture.count.Load()
+	_ = hook.Fire(entry)
+	if capture.count.Load() != before {
+		t.Fatal("hook emitted after denial")
+	}
+}

internal/vm/vmutils/etw/default-sources.go

@@ -7,6 +7,10 @@ var defaultLogSourcesInfo = LogSourcesInfo{
 			{
 				Type: "ETW",
 				Providers: []EtwProvider{
+					{
+						ProviderName: SidecarProviderName,
+						Level:        "Information",
+					},
 					{
 						ProviderName: "microsoft.windows.hyperv.compute",
 						Level:        "Information",

internal/vm/vmutils/etw/etw_map.go

@@ -1,7 +1,10 @@
 package etw
 
+const SidecarProviderName = "Microsoft.Virtualization.GCSSidecar"
+
 // LOWERCASE ONLY keys for easier lookups and case-insensitive matching.
 var etwNameToGUIDMap = map[string]string{
+	"microsoft.virtualization.gcssidecar":                                        "5400e7dc-0f0f-553d-19b5-3672635b5f7b",
 	"microsoft.windows.containers.setup":                                         "22267b1c-b979-5c81-9e24-0db386a62dd1",
 	"microsoft.windows.containers.storage":                                       "2551390d-5927-5c84-6f0a-027a7e78d38d",
 	"microsoft.windows.containers.library":                                       "67eb0417-9297-42ae-a1d9-98bfeb359059",

internal/vm/vmutils/etw/provider_map.go

@@ -44,15 +44,16 @@ func GetProviderGUIDFromName(providerName string) string {
 }
 
 // providerKey returns a unique key for an EtwProvider, used for deduplication during merge.
-// If both Name and GUID are present, key is "Name|GUID". If only GUID, key is GUID. Otherwise, key is Name.
+// Names and GUIDs are case-insensitive. If both are present, key is
+// "Name|GUID". If only GUID, key is GUID. Otherwise, key is Name.
 func providerKey(provider EtwProvider) string {
 	if provider.ProviderGUID != "" {
 		if provider.ProviderName != "" {
-			return provider.ProviderName + "|" + provider.ProviderGUID
+			return strings.ToLower(provider.ProviderName + "|" + provider.ProviderGUID)
 		}
-		return provider.ProviderGUID
+		return strings.ToLower(provider.ProviderGUID)
 	}
-	return provider.ProviderName
+	return strings.ToLower(provider.ProviderName)
 }
 
 // mergeProviders merges two slices of EtwProvider, with userProviders taking precedence over defaultProviders