diff --git a/cmd/gcs-sidecar/main.go b/cmd/gcs-sidecar/main.go index cb1535ec25..a86ea20ecd 100644 --- a/cmd/gcs-sidecar/main.go +++ b/cmd/gcs-sidecar/main.go @@ -14,9 +14,13 @@ import ( "unsafe" "github.com/Microsoft/go-winio" + "github.com/Microsoft/go-winio/pkg/etw" + "github.com/Microsoft/go-winio/pkg/etwlogrus" + "github.com/Microsoft/go-winio/pkg/guid" "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 +195,44 @@ func main() { } os.Stderr = logFileHandle + var loggingOptions []func(*securitypolicy.SecurityOptions) + runtimeLogging := sidecar.NewRuntimeLoggingController() + provider, err := etw.NewProvider(logsources.SidecarProviderName, func( + _ guid.GUID, + state etw.ProviderState, + _ etw.Level, + _, _ uint64, + _ uintptr, + ) { + switch state { + case etw.ProviderStateEnable: + runtimeLogging.SetCollectionEnabled(true) + case etw.ProviderStateDisable: + runtimeLogging.SetCollectionEnabled(false) + default: + return + } + }) + 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 { + runtimeHook := sidecar.NewRuntimeLoggingHook(hook) + defer func() { + runtimeHook.Close() + if err := provider.Close(); err != nil { + logrus.WithError(err).Error("failed to close sidecar ETW provider") + } + }() + runtimeLogging.Attach(runtimeHook) + logrus.AddHook(runtimeHook) + loggingOptions = append(loggingOptions, securitypolicy.WithRuntimeLoggingChanged(runtimeHook.SetAllowed)) + } + chsrv := make(chan error) go func() { defer close(chsrv) @@ -278,7 +320,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. diff --git a/docs/sidecar-gcs-logging.md b/docs/sidecar-gcs-logging.md new file mode 100644 index 0000000000..c9a5546453 --- /dev/null +++ b/docs/sidecar-gcs-logging.md @@ -0,0 +1,75 @@ +# 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 buffers a bounded number of pre-policy startup events. It forwards +them only after the guest validates and installs a policy allowing +`allow_runtime_logging` and an ETW collection session is enabled. If policy +denies runtime logging, buffered events are discarded. 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. Startup buffering is capped at 128 events and 256 KiB; individual +events larger than 16 KiB are dropped. Once streaming starts, events produced +while collection is disabled are not buffered for later replay. + +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. diff --git a/internal/gcs-sidecar/bridge.go b/internal/gcs-sidecar/bridge.go index dd22b15322..0183bd7398 100644 --- a/internal/gcs-sidecar/bridge.go +++ b/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{}), diff --git a/internal/gcs-sidecar/host.go b/internal/gcs-sidecar/host.go index 2160d6091d..46b9e84edc 100644 --- a/internal/gcs-sidecar/host.go +++ b/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), diff --git a/internal/gcs-sidecar/logging.go b/internal/gcs-sidecar/logging.go new file mode 100644 index 0000000000..5e80f3332d --- /dev/null +++ b/internal/gcs-sidecar/logging.go @@ -0,0 +1,408 @@ +//go:build windows + +package bridge + +import ( + "fmt" + "reflect" + "sync" + "time" + + "github.com/sirupsen/logrus" +) + +const ( + maxBufferedStartupEvents = 128 + maxBufferedStartupBytes = 256 * 1024 + maxStartupEventBytes = 16 * 1024 + maxStartupFields = 32 + maxStartupArrayElements = 256 +) + +// RuntimeLoggingHook holds pre-policy startup events until both the policy and +// an ETW collection session permit forwarding. +type RuntimeLoggingHook struct { + next logrus.Hook + + mu sync.Mutex + allowed bool + policyResolved bool + collectionEnabled bool + streaming bool + started bool + closed bool + pending []*logrus.Entry + pendingBytes int + + wake chan struct{} + stop chan struct{} + done chan struct{} + closeOnce sync.Once +} + +// RuntimeLoggingController coordinates ETW collector notifications with hook +// publication so an enable notification cannot be overwritten by stale state. +type RuntimeLoggingController struct { + mu sync.Mutex + hook *RuntimeLoggingHook + enabled bool +} + +func NewRuntimeLoggingController() *RuntimeLoggingController { + return &RuntimeLoggingController{} +} + +func (c *RuntimeLoggingController) Attach(hook *RuntimeLoggingHook) { + c.mu.Lock() + c.hook = hook + hook.SetCollectionEnabled(c.enabled) + c.mu.Unlock() +} + +func (c *RuntimeLoggingController) SetCollectionEnabled(enabled bool) { + c.mu.Lock() + c.enabled = enabled + if c.hook != nil { + c.hook.SetCollectionEnabled(enabled) + } + c.mu.Unlock() +} + +func NewRuntimeLoggingHook(next logrus.Hook) *RuntimeLoggingHook { + h := &RuntimeLoggingHook{ + next: next, + wake: make(chan struct{}, 1), + stop: make(chan struct{}), + done: make(chan struct{}), + } + go h.forward() + return h +} + +// SetAllowed publishes the runtime-logging decision from the validated guest +// policy. A denial permanently discards pending startup events. +func (h *RuntimeLoggingHook) SetAllowed(allowed bool) { + h.mu.Lock() + if h.closed { + h.mu.Unlock() + return + } + h.policyResolved = true + h.allowed = allowed + if !allowed { + h.pending = nil + h.pendingBytes = 0 + } + h.streaming = false + if h.readyLocked() { + if len(h.pending) == 0 { + h.streaming = true + h.started = true + } else { + h.streaming = false + } + } + h.mu.Unlock() + h.signal() +} + +// SetCollectionEnabled is called when ETW reports collector enable/disable. +func (h *RuntimeLoggingHook) SetCollectionEnabled(enabled bool) { + h.mu.Lock() + if h.closed { + h.mu.Unlock() + return + } + h.collectionEnabled = enabled + if h.readyLocked() { + if len(h.pending) == 0 { + h.streaming = true + h.started = true + } else { + h.streaming = false + } + } else { + h.streaming = false + } + h.mu.Unlock() + h.signal() +} + +func (h *RuntimeLoggingHook) readyLocked() bool { + return !h.closed && h.policyResolved && h.allowed && h.collectionEnabled +} + +func (h *RuntimeLoggingHook) Levels() []logrus.Level { + return h.next.Levels() +} + +func (h *RuntimeLoggingHook) Fire(entry *logrus.Entry) error { + h.mu.Lock() + defer h.mu.Unlock() + + if h.closed || (h.policyResolved && !h.allowed) || (h.started && !h.collectionEnabled) { + return nil + } + if h.readyLocked() && h.streaming { + return h.next.Fire(entry) + } + + buffered, size, ok := copyStartupEntry(entry) + if !ok || len(h.pending) >= maxBufferedStartupEvents || + size > maxBufferedStartupBytes-h.pendingBytes { + return nil + } + h.pending = append(h.pending, buffered) + h.pendingBytes += size + h.signal() + return nil +} + +func (h *RuntimeLoggingHook) signal() { + select { + case h.wake <- struct{}{}: + default: + } +} + +func (h *RuntimeLoggingHook) forward() { + defer close(h.done) + for { + select { + case <-h.stop: + return + case <-h.wake: + h.mu.Lock() + if !h.readyLocked() { + h.mu.Unlock() + continue + } + entries := h.pending + h.pending = nil + h.pendingBytes = 0 + h.started = true + for _, entry := range entries { + if !h.readyLocked() { + break + } + _ = h.next.Fire(entry) + } + if h.readyLocked() { + h.streaming = true + h.started = true + } + h.mu.Unlock() + } + } +} + +// Close discards queued events and waits for any in-flight ETW write before the +// provider is unregistered. +func (h *RuntimeLoggingHook) Close() { + h.closeOnce.Do(func() { + h.mu.Lock() + h.closed = true + h.pending = nil + h.pendingBytes = 0 + h.mu.Unlock() + close(h.stop) + <-h.done + }) +} + +func copyStartupEntry(entry *logrus.Entry) (*logrus.Entry, int, bool) { + if len(entry.Message) > maxStartupEventBytes { + return nil, 0, false + } + data := make(logrus.Fields, len(entry.Data)) + size := len(entry.Message) + for key, value := range entry.Data { + if len(data) == maxStartupFields || size+len(key)+32 > maxStartupEventBytes { + return nil, 0, false + } + remaining := maxStartupEventBytes - size - len(key) - 32 + copied, valueSize, ok := copyStartupField(value, remaining) + if !ok || size+len(key)+valueSize+32 > maxStartupEventBytes { + return nil, 0, false + } + data[key] = copied + size += len(key) + valueSize + 32 + } + if size > maxStartupEventBytes { + return nil, 0, false + } + + copied := &logrus.Entry{ + Logger: entry.Logger, + Data: data, + Time: entry.Time, + Level: entry.Level, + Message: entry.Message, + } + return copied, size, true +} + +func copyStartupField(value interface{}, maxBytes int) (interface{}, int, bool) { + switch v := value.(type) { + case string: + return v, len(v), len(v) <= maxBytes + case []byte: + if len(v) > maxBytes { + return nil, 0, false + } + return append([]byte(nil), v...), len(v), true + case bool: + return v, 1, true + case int: + return v, 8, true + case int8: + return v, 1, true + case int16: + return v, 2, true + case int32: + return v, 4, true + case int64: + return v, 8, true + case uint: + return v, 8, true + case uint8: + return v, 1, true + case uint16: + return v, 2, true + case uint32: + return v, 4, true + case uint64: + return v, 8, true + case uintptr: + return v, 8, true + case float32: + return v, 4, true + case float64: + return v, 8, true + case time.Time: + return v, 16, true + case time.Duration: + return v, 8, true + case error: + message := v.Error() + return message, len(message), len(message) <= maxBytes + case []string: + if len(v) > maxStartupArrayElements { + return nil, 0, false + } + size := len(v) * 16 + if size > maxBytes { + return nil, 0, false + } + for _, item := range v { + if len(item) > maxBytes-size { + return nil, 0, false + } + size += len(item) + } + copied := append([]string(nil), v...) + return copied, size, true + case map[string]interface{}, map[interface{}]interface{}, []interface{}: + return copyStartupValue(v, maxBytes, 0) + default: + serialized := fmt.Sprintf("(Unsupported: %T) %v", value, value) + return serialized, len(serialized), len(serialized) <= maxBytes + } +} + +func copyStartupValue(value interface{}, maxBytes, depth int) (interface{}, int, bool) { + if depth >= 8 { + return nil, 0, false + } + switch v := value.(type) { + case nil: + return nil, 1, true + case string: + return v, len(v), len(v) <= maxBytes + case []byte: + if len(v) > maxBytes { + return nil, 0, false + } + return append([]byte(nil), v...), len(v), true + case bool: + return v, 1, true + case int: + return v, 8, true + case int8: + return v, 1, true + case int16: + return v, 2, true + case int32: + return v, 4, true + case int64: + return v, 8, true + case uint: + return v, 8, true + case uint8: + return v, 1, true + case uint16: + return v, 2, true + case uint32: + return v, 4, true + case uint64: + return v, 8, true + case float32: + return v, 4, true + case float64: + return v, 8, true + case map[string]interface{}: + if len(v) > maxStartupArrayElements { + return nil, 0, false + } + cloned := make(map[string]interface{}, len(v)) + size := len(v) * 32 + for key, item := range v { + if len(key) > maxBytes-size { + return nil, 0, false + } + copied, itemSize, ok := copyStartupValue(item, maxBytes-size-len(key), depth+1) + if !ok || size+len(key)+itemSize > maxBytes { + return nil, 0, false + } + cloned[key] = copied + size += len(key) + itemSize + } + return cloned, size, size <= maxBytes + case map[interface{}]interface{}: + if len(v) > maxStartupArrayElements { + return nil, 0, false + } + cloned := make(map[interface{}]interface{}, len(v)) + size := len(v) * 32 + for key, item := range v { + copiedKey, keySize, ok := copyStartupValue(key, maxBytes-size, depth+1) + if !ok || copiedKey == nil || !reflect.TypeOf(copiedKey).Comparable() { + return nil, 0, false + } + copiedValue, valueSize, ok := copyStartupValue(item, maxBytes-size-keySize, depth+1) + if !ok || size+keySize+valueSize > maxBytes { + return nil, 0, false + } + cloned[copiedKey] = copiedValue + size += keySize + valueSize + } + return cloned, size, size <= maxBytes + case []interface{}: + if len(v) > maxStartupArrayElements || len(v)*16 > maxBytes { + return nil, 0, false + } + cloned := make([]interface{}, len(v)) + size := len(v) * 16 + for i, item := range v { + copied, itemSize, ok := copyStartupValue(item, maxBytes-size, depth+1) + if !ok || size+itemSize > maxBytes { + return nil, 0, false + } + cloned[i] = copied + size += itemSize + } + return cloned, size, size <= maxBytes + default: + return nil, 0, false + } +} diff --git a/internal/gcs-sidecar/logging_policy_test.go b/internal/gcs-sidecar/logging_policy_test.go new file mode 100644 index 0000000000..967bcf4e85 --- /dev/null +++ b/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") + } + } +} diff --git a/internal/gcs-sidecar/logging_test.go b/internal/gcs-sidecar/logging_test.go new file mode 100644 index 0000000000..51ae6b7504 --- /dev/null +++ b/internal/gcs-sidecar/logging_test.go @@ -0,0 +1,276 @@ +//go:build windows + +package bridge + +import ( + "io" + "reflect" + "strings" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/sirupsen/logrus" +) + +type runtimeLogCapture struct { + count atomic.Int64 + entries chan *logrus.Entry +} + +func (h *runtimeLogCapture) Levels() []logrus.Level { return logrus.AllLevels } +func (h *runtimeLogCapture) Fire(entry *logrus.Entry) error { + h.count.Add(1) + h.entries <- entry + return nil +} + +func newTestRuntimeLoggingHook(next logrus.Hook) *RuntimeLoggingHook { + hook := NewRuntimeLoggingHook(next) + return hook +} + +func receiveLogEntry(t *testing.T, entries <-chan *logrus.Entry) *logrus.Entry { + t.Helper() + select { + case entry := <-entries: + return entry + case <-time.After(time.Second): + t.Fatal("timed out waiting for ETW hook") + return nil + } +} + +func TestRuntimeLoggingHookFlushesAfterPolicyAndCollector(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 8)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + logger := logrus.New() + logger.SetOutput(io.Discard) + logger.AddHook(hook) + + logger.WithField("containerID", "startup").Info("sidecar initialized") + if capture.count.Load() != 0 { + t.Fatal("startup event emitted before policy validation") + } + + hook.SetAllowed(true) + logger.Info("policy installed") + if capture.count.Load() != 0 { + t.Fatal("event emitted before an ETW collector was enabled") + } + + hook.SetCollectionEnabled(true) + logger.WithField("containerID", "ready").Info("forwarding active") + claims := map[interface{}]interface{}{"svn": uint64(7)} + logger.WithField("cwtClaims", claims).Info("structured live field") + + first := receiveLogEntry(t, capture.entries) + second := receiveLogEntry(t, capture.entries) + third := receiveLogEntry(t, capture.entries) + fourth := receiveLogEntry(t, capture.entries) + if got := []string{first.Message, second.Message, third.Message, fourth.Message}; !reflect.DeepEqual(got, []string{ + "sidecar initialized", "policy installed", "forwarding active", "structured live field", + }) { + t.Fatalf("forwarded messages = %v", got) + } + if first.Data["containerID"] != "startup" || third.Data["containerID"] != "ready" { + t.Fatal("structured startup or live fields were not preserved") + } + if got, ok := fourth.Data["cwtClaims"].(map[interface{}]interface{}); !ok || got["svn"] != uint64(7) { + t.Fatalf("live structured field was not passed through: %#v", fourth.Data["cwtClaims"]) + } + + hook.SetCollectionEnabled(false) + logger.Info("collector stopped") + if capture.count.Load() != 4 { + t.Fatal("event emitted while ETW collection was disabled") + } + hook.mu.Lock() + defer hook.mu.Unlock() + if len(hook.pending) != 0 { + t.Fatal("live event was buffered after collection stopped") + } +} + +func TestRuntimeLoggingHookCollectorCanPrecedePolicy(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 2)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + entry := logrus.NewEntry(logrus.New()) + entry.Message = "captured before policy" + claims := map[interface{}]interface{}{"svn": uint64(7)} + entry.Data["cwtClaims"] = claims + if err := hook.Fire(entry); err != nil { + t.Fatal(err) + } + claims["svn"] = uint64(8) + hook.SetCollectionEnabled(true) + if capture.count.Load() != 0 { + t.Fatal("event emitted before policy validation") + } + hook.SetAllowed(true) + got := receiveLogEntry(t, capture.entries) + if got.Message != entry.Message { + t.Fatalf("forwarded %q, want %q", got.Message, entry.Message) + } + if value, ok := got.Data["cwtClaims"].(map[interface{}]interface{}); !ok || value["svn"] != uint64(7) { + t.Fatalf("startup structured field was not safely copied: %#v", got.Data["cwtClaims"]) + } +} + +func TestRuntimeLoggingControllerDoesNotLoseEnableNotification(t *testing.T) { + for _, collectorFirst := range []bool{false, true} { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 1)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + controller := NewRuntimeLoggingController() + if collectorFirst { + controller.SetCollectionEnabled(true) + } + controller.Attach(hook) + + entry := logrus.NewEntry(logrus.New()) + entry.Message = "startup event" + if err := hook.Fire(entry); err != nil { + t.Fatal(err) + } + hook.SetAllowed(true) + if !collectorFirst { + controller.SetCollectionEnabled(true) + } + + if got := receiveLogEntry(t, capture.entries); got.Message != entry.Message { + t.Fatalf("collectorFirst=%v: got %q, want %q", collectorFirst, got.Message, entry.Message) + } + } +} + +func TestRuntimeLoggingHookPolicyDenialDropsStartupEvents(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 4)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + logger := logrus.New() + logger.SetOutput(io.Discard) + logger.AddHook(hook) + + logger.Info("must be discarded") + hook.SetCollectionEnabled(true) + hook.SetAllowed(false) + logger.Info("also denied") + if capture.count.Load() != 0 { + t.Fatal("policy-denied startup events were emitted") + } + hook.mu.Lock() + defer hook.mu.Unlock() + if len(hook.pending) != 0 { + t.Fatal("policy denial retained startup events") + } +} + +func TestRuntimeLoggingHookDropsOversizedStartupEntry(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 1)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + entry := logrus.NewEntry(logrus.New()) + entry.Message = "oversized" + entry.Data = logrus.Fields{"payload": make([]byte, maxStartupEventBytes+1)} + if err := hook.Fire(entry); err != nil { + t.Fatal(err) + } + hook.SetAllowed(true) + hook.SetCollectionEnabled(true) + if capture.count.Load() != 0 { + t.Fatal("oversized startup entry was buffered") + } + hook.mu.Lock() + defer hook.mu.Unlock() + if len(hook.pending) != 0 { + t.Fatal("oversized startup entry was retained") + } +} + +func TestRuntimeLoggingHookDropsOversizedStartupFieldArray(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 1)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + entry := logrus.NewEntry(logrus.New()) + entry.Data = logrus.Fields{"values": make([]string, maxStartupArrayElements+1)} + if err := hook.Fire(entry); err != nil { + t.Fatal(err) + } + hook.SetAllowed(true) + hook.SetCollectionEnabled(true) + if capture.count.Load() != 0 { + t.Fatal("startup event with an oversized field array was buffered") + } + hook.mu.Lock() + defer hook.mu.Unlock() + if len(hook.pending) != 0 { + t.Fatal("startup event with oversized field array was retained") + } +} + +func TestRuntimeLoggingHookBoundsStartupBufferBytes(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 20)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + logger := logrus.New() + logger.SetOutput(io.Discard) + logger.AddHook(hook) + message := strings.Repeat("x", maxStartupEventBytes-32) + for range 20 { + logger.Info(message) + } + hook.SetAllowed(true) + hook.SetCollectionEnabled(true) + for range maxBufferedStartupBytes / maxStartupEventBytes { + receiveLogEntry(t, capture.entries) + } + if got := capture.count.Load(); got != maxBufferedStartupBytes/maxStartupEventBytes { + t.Fatalf("forwarded %d events, want byte-budget limit %d", got, maxBufferedStartupBytes/maxStartupEventBytes) + } +} + +func TestRuntimeLoggingHookBoundsStartupBuffer(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, maxBufferedStartupEvents+1)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + logger := logrus.New() + logger.SetOutput(io.Discard) + logger.AddHook(hook) + + for i := 0; i < maxBufferedStartupEvents+1; i++ { + logger.WithField("index", i).Info("startup") + } + hook.SetAllowed(true) + hook.SetCollectionEnabled(true) + for range maxBufferedStartupEvents { + receiveLogEntry(t, capture.entries) + } + if capture.count.Load() != maxBufferedStartupEvents { + t.Fatalf("forwarded %d events, want bounded count %d", capture.count.Load(), maxBufferedStartupEvents) + } +} + +func TestRuntimeLoggingHookConcurrentStateChanges(t *testing.T) { + capture := &runtimeLogCapture{entries: make(chan *logrus.Entry, 10000)} + hook := newTestRuntimeLoggingHook(capture) + t.Cleanup(hook.Close) + 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) + hook.SetCollectionEnabled(i%3 == 0) + _ = hook.Fire(entry) + } + }() + } + wg.Wait() + hook.Close() +} diff --git a/internal/vm/vmutils/etw/default-sources.go b/internal/vm/vmutils/etw/default-sources.go index ee8f79466f..88edafb879 100644 --- a/internal/vm/vmutils/etw/default-sources.go +++ b/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", diff --git a/internal/vm/vmutils/etw/etw_map.go b/internal/vm/vmutils/etw/etw_map.go index 13513e81d6..75ff614529 100644 --- a/internal/vm/vmutils/etw/etw_map.go +++ b/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", diff --git a/internal/vm/vmutils/etw/provider_map.go b/internal/vm/vmutils/etw/provider_map.go index 9a37022c2a..2f4e3237a7 100644 --- a/internal/vm/vmutils/etw/provider_map.go +++ b/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 diff --git a/internal/vm/vmutils/etw/sidecar_test.go b/internal/vm/vmutils/etw/sidecar_test.go new file mode 100644 index 0000000000..b68ff767ce --- /dev/null +++ b/internal/vm/vmutils/etw/sidecar_test.go @@ -0,0 +1,70 @@ +package etw + +import ( + "strings" + "testing" +) + +func TestSidecarDefaultLogSource(t *testing.T) { + // Updating sources mutates the shared defaults; restore them after the test. + original := cloneLogSourcesInfo(defaultLogSourcesInfo) + t.Cleanup(func() { defaultLogSourcesInfo = original }) + for _, tc := range []struct { + name string + level string + }{ + {SidecarProviderName, "Information"}, + {SidecarProviderName, "Verbose"}, + {strings.ToLower(SidecarProviderName), "Verbose"}, + {strings.ToUpper(SidecarProviderName), "Verbose"}, + } { + var user LogSourcesInfo + if tc.level == "Verbose" { + user.LogConfig.Sources = []Source{{Type: "ETW", Providers: []EtwProvider{ + {ProviderName: tc.name, Level: tc.level}, + }}} + } + + encoded, err := UpdateLogSourcesFromInfo(user, true, true) + if err != nil { + t.Fatal(err) + } + sources, err := DecodeAndUnmarshalLogSources(encoded) + if err != nil { + t.Fatal(err) + } + count := 0 + for _, source := range sources.LogConfig.Sources { + for _, provider := range source.Providers { + if !strings.EqualFold(provider.ProviderName, SidecarProviderName) { + continue + } + count++ + if provider.Level != tc.level || provider.ProviderGUID != GetProviderGUIDFromName(SidecarProviderName) { + t.Fatalf("unexpected sidecar configuration: %+v", provider) + } + } + } + if count != 1 { + t.Fatalf("sidecar provider count = %d, want 1", count) + } + // Keep the next configuration independent. + defaultLogSourcesInfo = cloneLogSourcesInfo(original) + } +} + +func TestMergeProvidersCaseInsensitive(t *testing.T) { + const id = "5400e7dc-0f0f-553d-19b5-3672635b5f7b" + for _, withName := range []bool{false, true} { + defaultProvider := EtwProvider{ProviderGUID: id, Level: "Information"} + userProvider := EtwProvider{ProviderGUID: strings.ToUpper(id), Level: "Verbose"} + if withName { + defaultProvider.ProviderName = SidecarProviderName + userProvider.ProviderName = strings.ToLower(SidecarProviderName) + } + merged := mergeProviders([]EtwProvider{defaultProvider}, []EtwProvider{userProvider}) + if len(merged) != 1 || merged[0] != userProvider { + t.Fatalf("case-insensitive override failed: %+v", merged) + } + } +} diff --git a/internal/vm/vmutils/etw/sidecar_windows_test.go b/internal/vm/vmutils/etw/sidecar_windows_test.go new file mode 100644 index 0000000000..85b5233a57 --- /dev/null +++ b/internal/vm/vmutils/etw/sidecar_windows_test.go @@ -0,0 +1,24 @@ +//go:build windows + +package etw + +import ( + "testing" + + winioetw "github.com/Microsoft/go-winio/pkg/etw" +) + +func TestSidecarProviderIdentity(t *testing.T) { + provider, err := winioetw.NewProvider(SidecarProviderName, nil) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := provider.Close(); err != nil { + t.Error(err) + } + }) + if got, want := provider.ID.String(), GetProviderGUIDFromName(SidecarProviderName); got != want { + t.Fatalf("registered provider GUID = %s, trusted GUID = %s", got, want) + } +} diff --git a/pkg/securitypolicy/runtime_logging_test.go b/pkg/securitypolicy/runtime_logging_test.go new file mode 100644 index 0000000000..6be2704a06 --- /dev/null +++ b/pkg/securitypolicy/runtime_logging_test.go @@ -0,0 +1,58 @@ +package securitypolicy + +import ( + "bytes" + "context" + "io" + "testing" + + "github.com/sirupsen/logrus" +) + +func TestConfigureRuntimeLogging(t *testing.T) { + original := logrus.StandardLogger().Out + t.Cleanup(func() { logrus.SetOutput(original) }) + for _, tc := range []struct { + name string + enforcer SecurityPolicyEnforcer + allowed bool + }{ + {"allow", &OpenDoorSecurityPolicyEnforcer{}, true}, + {"deny", &ClosedDoorSecurityPolicyEnforcer{}, false}, + } { + t.Run(tc.name, func(t *testing.T) { + var output bytes.Buffer + called := false + s := NewSecurityOptions(tc.enforcer, true, "", "", &output, + WithRuntimeLoggingChanged(func(allowed bool) { + called = true + if allowed != tc.allowed { + t.Fatalf("allowed = %v, want %v", allowed, tc.allowed) + } + want := io.Writer(io.Discard) + if allowed { + want = &output + } + if logrus.StandardLogger().Out != want { + t.Fatal("callback and output writer decisions differ") + } + })) + s.configureRuntimeLogging(context.Background()) + if !called { + t.Fatal("callback not invoked") + } + }) + } +} + +func TestRuntimeLoggingCallbackNotCalledOnRejectedPolicy(t *testing.T) { + for _, alreadySet := range []bool{false, true} { + s := NewSecurityOptions(&ClosedDoorSecurityPolicyEnforcer{}, alreadySet, "", "", io.Discard, + WithRuntimeLoggingChanged(func(bool) { + t.Error("rejected policy changed logging authorization") + })) + if err := s.SetConfidentialOptions(context.Background(), "", "invalid-base64!", "", ""); err == nil { + t.Fatal("expected invalid or duplicate policy rejection") + } + } +} diff --git a/pkg/securitypolicy/securitypolicy_options.go b/pkg/securitypolicy/securitypolicy_options.go index c0d87a0fee..6fbf5a4642 100644 --- a/pkg/securitypolicy/securitypolicy_options.go +++ b/pkg/securitypolicy/securitypolicy_options.go @@ -42,7 +42,8 @@ type SecurityOptions struct { tcbReferenceInfo []byte platformReferenceInfo []byte - logWriter io.Writer + logWriter io.Writer + runtimeLoggingChanged func(bool) } // Global counter for fragment injection requests, used to create unique @@ -70,14 +71,26 @@ func (s *SecurityOptions) EnsureFragmentDiagnosticsDir() error { return writeFileIfNotExists(filepath.Join(dir, "README"), fragmentsInfoREADME, 0644) } -func NewSecurityOptions(enforcer SecurityPolicyEnforcer, enforcerSet bool, uvmReferenceInfo string, uvmHashEnvelopeReferenceInfo string, logWriter io.Writer) *SecurityOptions { - return &SecurityOptions{ +// WithRuntimeLoggingChanged observes the validated policy's runtime logging +// decision. The callback must not block or reenter SecurityOptions. +func WithRuntimeLoggingChanged(callback func(bool)) func(*SecurityOptions) { + return func(s *SecurityOptions) { + s.runtimeLoggingChanged = callback + } +} + +func NewSecurityOptions(enforcer SecurityPolicyEnforcer, enforcerSet bool, uvmReferenceInfo string, uvmHashEnvelopeReferenceInfo string, logWriter io.Writer, options ...func(*SecurityOptions)) *SecurityOptions { + s := &SecurityOptions{ PolicyEnforcer: enforcer, PolicyEnforcerSet: enforcerSet, UvmReferenceInfo: uvmReferenceInfo, UvmHashEnvelopeReferenceInfo: uvmHashEnvelopeReferenceInfo, logWriter: logWriter, } + for _, option := range options { + option(s) + } + return s } // SetConfidentialOptions takes guestresource.ConfidentialOptions @@ -128,26 +141,27 @@ func (s *SecurityOptions) SetConfidentialOptions(ctx context.Context, enforcerTy return fmt.Errorf("error creating security policy enforcer: %w", err) } - // This is one of two points at which we might change our logging. - // At this time, we now have a policy and can determine what the policy - // author put as policy around runtime logging. - // The other point is on startup where we take a flag to set the default - // policy enforcer to use before a policy arrives. After that flag is set, - // we use the enforcer in question to set up logging as well. - if err = p.EnforceRuntimeLoggingPolicy(ctx); err == nil { - logrus.SetOutput(s.logWriter) - } else { - logrus.SetOutput(io.Discard) - } - s.PolicyEnforcer = p s.PolicyEnforcerSet = true s.UvmReferenceInfo = encodedUVMReference s.UvmHashEnvelopeReferenceInfo = encodedUVMHashEnvelopeReference + s.configureRuntimeLogging(ctx) return nil } +func (s *SecurityOptions) configureRuntimeLogging(ctx context.Context) { + allowed := s.PolicyEnforcer.EnforceRuntimeLoggingPolicy(ctx) == nil + if allowed { + logrus.SetOutput(s.logWriter) + } else { + logrus.SetOutput(io.Discard) + } + if s.runtimeLoggingChanged != nil { + s.runtimeLoggingChanged(allowed) + } +} + // Media types carried by the fragment-injection delivery mechanism. The host // may deliver blobs of different types through the same path; the guest decides // how to treat each one based on its media type.