From 565a5429af3a9b84c9bd2c6edd7b31d23e0eb473 Mon Sep 17 00:00:00 2001 From: Manish Ranjan Mahanta Date: Thu, 22 Oct 2026 15:18:55 +0530 Subject: [PATCH 1/5] Add policy-gated ETW logging for sidecar GCS Signed-off-by: Manish Ranjan Mahanta --- cmd/gcs-sidecar/main.go | 21 ++++- docs/sidecar-gcs-logging.md | 66 ++++++++++++++ internal/gcs-sidecar/bridge.go | 4 +- internal/gcs-sidecar/host.go | 3 +- internal/gcs-sidecar/logging.go | 35 +++++++ internal/gcs-sidecar/logging_policy_test.go | 57 ++++++++++++ internal/gcs-sidecar/logging_test.go | 91 +++++++++++++++++++ internal/vm/vmutils/etw/default-sources.go | 4 + internal/vm/vmutils/etw/etw_map.go | 3 + internal/vm/vmutils/etw/sidecar_test.go | 45 +++++++++ .../vm/vmutils/etw/sidecar_windows_test.go | 24 +++++ pkg/securitypolicy/runtime_logging_test.go | 58 ++++++++++++ pkg/securitypolicy/securitypolicy_options.go | 44 ++++++--- 13 files changed, 436 insertions(+), 19 deletions(-) create mode 100644 docs/sidecar-gcs-logging.md create mode 100644 internal/gcs-sidecar/logging.go create mode 100644 internal/gcs-sidecar/logging_policy_test.go create mode 100644 internal/gcs-sidecar/logging_test.go create mode 100644 internal/vm/vmutils/etw/sidecar_test.go create mode 100644 internal/vm/vmutils/etw/sidecar_windows_test.go create mode 100644 pkg/securitypolicy/runtime_logging_test.go diff --git a/cmd/gcs-sidecar/main.go b/cmd/gcs-sidecar/main.go index cb1535ec25..40004fb735 100644 --- a/cmd/gcs-sidecar/main.go +++ b/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. diff --git a/docs/sidecar-gcs-logging.md b/docs/sidecar-gcs-logging.md new file mode 100644 index 0000000000..1016b8ceb0 --- /dev/null +++ b/docs/sidecar-gcs-logging.md @@ -0,0 +1,66 @@ +# 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" + }] + }] + } +} +``` + +Use the same canonical provider name when overriding its default level. +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. 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..616ff27dde --- /dev/null +++ b/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) +} 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..e76a132238 --- /dev/null +++ b/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") + } +} 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/sidecar_test.go b/internal/vm/vmutils/etw/sidecar_test.go new file mode 100644 index 0000000000..366212311f --- /dev/null +++ b/internal/vm/vmutils/etw/sidecar_test.go @@ -0,0 +1,45 @@ +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 _, level := range []string{"Information", "Verbose"} { + var user LogSourcesInfo + if level == "Verbose" { + user.LogConfig.Sources = []Source{{Type: "ETW", Providers: []EtwProvider{ + {ProviderName: SidecarProviderName, Level: 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 != 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) + } +} 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. From 03b8e516ba74f77db7fab5e08e80e5d3e8be2cfb Mon Sep 17 00:00:00 2001 From: Manish Ranjan Mahanta Date: Thu, 5 Nov 2026 20:50:31 +0530 Subject: [PATCH 2/5] Merge ETW provider overrides case-insensitively Signed-off-by: Manish Ranjan Mahanta --- docs/sidecar-gcs-logging.md | 7 +++++- internal/vm/vmutils/etw/provider_map.go | 9 ++++--- internal/vm/vmutils/etw/sidecar_test.go | 33 ++++++++++++++++++++++--- 3 files changed, 40 insertions(+), 9 deletions(-) diff --git a/docs/sidecar-gcs-logging.md b/docs/sidecar-gcs-logging.md index 1016b8ceb0..a8f128ca4f 100644 --- a/docs/sidecar-gcs-logging.md +++ b/docs/sidecar-gcs-logging.md @@ -54,7 +54,7 @@ set `io.microsoft.virtualmachine.forwardlogs.sources` to the base64 encoding of: } ``` -Use the same canonical provider name when overriding its default level. +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. @@ -64,3 +64,8 @@ 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/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 index 366212311f..b68ff767ce 100644 --- a/internal/vm/vmutils/etw/sidecar_test.go +++ b/internal/vm/vmutils/etw/sidecar_test.go @@ -9,13 +9,22 @@ 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 _, level := range []string{"Information", "Verbose"} { + for _, tc := range []struct { + name string + level string + }{ + {SidecarProviderName, "Information"}, + {SidecarProviderName, "Verbose"}, + {strings.ToLower(SidecarProviderName), "Verbose"}, + {strings.ToUpper(SidecarProviderName), "Verbose"}, + } { var user LogSourcesInfo - if level == "Verbose" { + if tc.level == "Verbose" { user.LogConfig.Sources = []Source{{Type: "ETW", Providers: []EtwProvider{ - {ProviderName: SidecarProviderName, Level: level}, + {ProviderName: tc.name, Level: tc.level}, }}} } + encoded, err := UpdateLogSourcesFromInfo(user, true, true) if err != nil { t.Fatal(err) @@ -31,7 +40,7 @@ func TestSidecarDefaultLogSource(t *testing.T) { continue } count++ - if provider.Level != level || provider.ProviderGUID != GetProviderGUIDFromName(SidecarProviderName) { + if provider.Level != tc.level || provider.ProviderGUID != GetProviderGUIDFromName(SidecarProviderName) { t.Fatalf("unexpected sidecar configuration: %+v", provider) } } @@ -43,3 +52,19 @@ func TestSidecarDefaultLogSource(t *testing.T) { 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) + } + } +} From 9f136931dd0579a6c166f363faed41283ffc8cbb Mon Sep 17 00:00:00 2001 From: Manish Ranjan Mahanta Date: Mon, 9 Nov 2026 10:41:36 +0530 Subject: [PATCH 3/5] Close sidecar ETW provider on normal exit Signed-off-by: Manish Ranjan Mahanta --- cmd/gcs-sidecar/main.go | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/cmd/gcs-sidecar/main.go b/cmd/gcs-sidecar/main.go index 40004fb735..a04907ee70 100644 --- a/cmd/gcs-sidecar/main.go +++ b/cmd/gcs-sidecar/main.go @@ -195,7 +195,6 @@ 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") @@ -206,6 +205,12 @@ func main() { } } else { gatedHook := sidecar.NewRuntimeLoggingHook(hook) + defer func() { + gatedHook.SetAllowed(false) + if err := provider.Close(); err != nil { + logrus.WithError(err).Error("failed to close sidecar ETW provider") + } + }() logrus.AddHook(gatedHook) loggingOptions = append(loggingOptions, securitypolicy.WithRuntimeLoggingChanged(gatedHook.SetAllowed)) } From e6a629113250adf5cf4d832878b746ff34868c3c Mon Sep 17 00:00:00 2001 From: Manish Ranjan Mahanta Date: Tue, 10 Nov 2026 11:03:16 +0530 Subject: [PATCH 4/5] Buffer policy-gated sidecar startup logs Signed-off-by: Manish Ranjan Mahanta --- cmd/gcs-sidecar/main.go | 34 +++- docs/sidecar-gcs-logging.md | 14 +- internal/gcs-sidecar/logging.go | 233 +++++++++++++++++++++++++-- internal/gcs-sidecar/logging_test.go | 219 ++++++++++++++++++++----- 4 files changed, 441 insertions(+), 59 deletions(-) diff --git a/cmd/gcs-sidecar/main.go b/cmd/gcs-sidecar/main.go index a04907ee70..3da2aac653 100644 --- a/cmd/gcs-sidecar/main.go +++ b/cmd/gcs-sidecar/main.go @@ -10,12 +10,14 @@ import ( "fmt" "net" "os" + "sync/atomic" "time" "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" @@ -195,7 +197,27 @@ func main() { os.Stderr = logFileHandle var loggingOptions []func(*securitypolicy.SecurityOptions) - provider, err := etw.NewProvider(logsources.SidecarProviderName, nil) + var runtimeLogHook atomic.Pointer[sidecar.RuntimeLoggingHook] + var collectionEnabled atomic.Bool + provider, err := etw.NewProvider(logsources.SidecarProviderName, func( + _ guid.GUID, + state etw.ProviderState, + _ etw.Level, + _, _ uint64, + _ uintptr, + ) { + switch state { + case etw.ProviderStateEnable: + collectionEnabled.Store(true) + case etw.ProviderStateDisable: + collectionEnabled.Store(false) + default: + return + } + if hook := runtimeLogHook.Load(); hook != nil { + hook.SetCollectionEnabled(collectionEnabled.Load()) + } + }) if err != nil { logrus.WithError(err).Error("failed to register sidecar ETW provider") } else if hook, err := etwlogrus.NewHookFromProvider(provider); err != nil { @@ -204,15 +226,17 @@ func main() { logrus.WithError(err).Error("failed to close sidecar ETW provider") } } else { - gatedHook := sidecar.NewRuntimeLoggingHook(hook) + runtimeHook := sidecar.NewRuntimeLoggingHook(hook) defer func() { - gatedHook.SetAllowed(false) + runtimeHook.Close() if err := provider.Close(); err != nil { logrus.WithError(err).Error("failed to close sidecar ETW provider") } }() - logrus.AddHook(gatedHook) - loggingOptions = append(loggingOptions, securitypolicy.WithRuntimeLoggingChanged(gatedHook.SetAllowed)) + runtimeLogHook.Store(runtimeHook) + runtimeHook.SetCollectionEnabled(collectionEnabled.Load()) + logrus.AddHook(runtimeHook) + loggingOptions = append(loggingOptions, securitypolicy.WithRuntimeLoggingChanged(runtimeHook.SetAllowed)) } chsrv := make(chan error) diff --git a/docs/sidecar-gcs-logging.md b/docs/sidecar-gcs-logging.md index a8f128ca4f..c9a5546453 100644 --- a/docs/sidecar-gcs-logging.md +++ b/docs/sidecar-gcs-logging.md @@ -8,10 +8,12 @@ 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. +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): @@ -57,7 +59,9 @@ set `io.microsoft.virtualmachine.forwardlogs.sources` to the base64 encoding of: 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. +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. diff --git a/internal/gcs-sidecar/logging.go b/internal/gcs-sidecar/logging.go index 616ff27dde..fcbd2c935b 100644 --- a/internal/gcs-sidecar/logging.go +++ b/internal/gcs-sidecar/logging.go @@ -3,24 +3,78 @@ package bridge import ( - "sync/atomic" + "sync" + "time" "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. +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 - allowed atomic.Bool + next logrus.Hook + + mu sync.Mutex + allowed bool + policyResolved bool + collectionEnabled bool + closed bool + pending []*logrus.Entry + pendingBytes int + + wake chan struct{} + stop chan struct{} + done chan struct{} + closeOnce sync.Once } func NewRuntimeLoggingHook(next logrus.Hook) *RuntimeLoggingHook { - return &RuntimeLoggingHook{next: next} + 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.allowed.Store(allowed) + 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.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 + h.mu.Unlock() + h.signal() } func (h *RuntimeLoggingHook) Levels() []logrus.Level { @@ -28,8 +82,169 @@ func (h *RuntimeLoggingHook) Levels() []logrus.Level { } func (h *RuntimeLoggingHook) Fire(entry *logrus.Entry) error { - if !h.allowed.Load() { + h.mu.Lock() + if h.closed || (h.policyResolved && (!h.allowed || !h.collectionEnabled)) { + h.mu.Unlock() + return nil + } + + buffered, size, ok := copyStartupEntry(entry) + if !ok || len(h.pending) >= maxBufferedStartupEvents || + size > maxBufferedStartupBytes-h.pendingBytes { + h.mu.Unlock() return nil } - return h.next.Fire(entry) + h.pending = append(h.pending, buffered) + h.pendingBytes += size + h.mu.Unlock() + 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.closed || !h.policyResolved || !h.allowed || !h.collectionEnabled { + h.mu.Unlock() + continue + } + entries := h.pending + h.pending = nil + h.pendingBytes = 0 + h.mu.Unlock() + + for _, entry := range entries { + h.mu.Lock() + allowed := !h.closed && h.policyResolved && h.allowed && h.collectionEnabled + h.mu.Unlock() + if !allowed { + break + } + _ = h.next.Fire(entry) + } + } + } +} + +// 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 + default: + return nil, 0, false + } } diff --git a/internal/gcs-sidecar/logging_test.go b/internal/gcs-sidecar/logging_test.go index e76a132238..939e786ce2 100644 --- a/internal/gcs-sidecar/logging_test.go +++ b/internal/gcs-sidecar/logging_test.go @@ -3,70 +3,215 @@ package bridge import ( - "errors" "io" "reflect" + "strings" "sync" "sync/atomic" "testing" + "time" "github.com/sirupsen/logrus" ) type runtimeLogCapture struct { - count atomic.Int64 - entry atomic.Pointer[logrus.Entry] - err error + 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.entry.Store(entry) - return h.err + h.entries <- entry + return nil } -func TestRuntimeLoggingHook(t *testing.T) { - capture := &runtimeLogCapture{} - hook := NewRuntimeLoggingHook(capture) +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.Info("before policy") + + logger.WithField("containerID", "startup").Info("sidecar initialized") if capture.count.Load() != 0 { - t.Fatal("hook emitted before authorization") - } - if !reflect.DeepEqual(hook.Levels(), capture.Levels()) { - t.Fatal("hook changed supported levels") + t.Fatal("startup event emitted before policy validation") } + hook.SetAllowed(true) - logger.WithField("containerID", "test").Info("allowed") - if capture.count.Load() != 1 { - t.Fatal("allowed hook was suppressed by discarded output") + 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") + + first := receiveLogEntry(t, capture.entries) + second := receiveLogEntry(t, capture.entries) + if got := []string{first.Message, second.Message}; !reflect.DeepEqual(got, []string{ + "sidecar initialized", "forwarding active", + }) { + t.Fatalf("forwarded messages = %v", got) + } + if first.Data["containerID"] != "startup" || second.Data["containerID"] != "ready" { + t.Fatal("structured startup or live fields were not preserved") + } + + hook.SetCollectionEnabled(false) + logger.Info("collector stopped") + if capture.count.Load() != 2 { + t.Fatal("event emitted while ETW collection was disabled") + } +} + +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" + if err := hook.Fire(entry); err != nil { + t.Fatal(err) + } + hook.SetCollectionEnabled(true) + if capture.count.Load() != 0 { + t.Fatal("event emitted before policy validation") } - if got := capture.entry.Load(); got.Message != "allowed" || got.Data["containerID"] != "test" { - t.Fatalf("event fields not preserved: %+v", got) + hook.SetAllowed(true) + if got := receiveLogEntry(t, capture.entries); got.Message != entry.Message { + t.Fatalf("forwarded %q, want %q", 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("denied") - if capture.count.Load() != 1 { - t.Fatal("denied hook emitted") + 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") } +} - entry := logrus.NewEntry(logger).WithField("containerID", "test") - capture.err = errors.New("sink failed") +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) - if err := hook.Fire(entry); !errors.Is(err, capture.err) { - t.Fatalf("sink error not preserved: %v", err) + hook.SetCollectionEnabled(true) + if capture.count.Load() != 0 { + t.Fatal("oversized startup entry was buffered") } - if capture.entry.Load() != entry { - t.Fatal("hook replaced the log entry") + hook.mu.Lock() + defer hook.mu.Unlock() + if len(hook.pending) != 0 { + t.Fatal("oversized startup entry was retained") } } -func TestRuntimeLoggingHookConcurrent(t *testing.T) { - capture := &runtimeLogCapture{} - hook := NewRuntimeLoggingHook(capture) +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 { @@ -75,17 +220,11 @@ func TestRuntimeLoggingHookConcurrent(t *testing.T) { defer wg.Done() for i := range 1000 { hook.SetAllowed(i%2 == 0) - if err := hook.Fire(entry); err != nil { - t.Error(err) - } + hook.SetCollectionEnabled(i%3 == 0) + _ = hook.Fire(entry) } }() } wg.Wait() - hook.SetAllowed(false) - before := capture.count.Load() - _ = hook.Fire(entry) - if capture.count.Load() != before { - t.Fatal("hook emitted after denial") - } + hook.Close() } From 580166b1d218c767d1cdf94d4b1a07459cda11f4 Mon Sep 17 00:00:00 2001 From: Manish Ranjan Mahanta Date: Tue, 10 Nov 2026 17:45:52 +0530 Subject: [PATCH 5/5] Fix sidecar ETW logging review issues Signed-off-by: Manish Ranjan Mahanta --- cmd/gcs-sidecar/main.go | 14 +-- internal/gcs-sidecar/logging.go | 180 +++++++++++++++++++++++++-- internal/gcs-sidecar/logging_test.go | 56 ++++++++- 3 files changed, 224 insertions(+), 26 deletions(-) diff --git a/cmd/gcs-sidecar/main.go b/cmd/gcs-sidecar/main.go index 3da2aac653..a86ea20ecd 100644 --- a/cmd/gcs-sidecar/main.go +++ b/cmd/gcs-sidecar/main.go @@ -10,7 +10,6 @@ import ( "fmt" "net" "os" - "sync/atomic" "time" "unsafe" @@ -197,8 +196,7 @@ func main() { os.Stderr = logFileHandle var loggingOptions []func(*securitypolicy.SecurityOptions) - var runtimeLogHook atomic.Pointer[sidecar.RuntimeLoggingHook] - var collectionEnabled atomic.Bool + runtimeLogging := sidecar.NewRuntimeLoggingController() provider, err := etw.NewProvider(logsources.SidecarProviderName, func( _ guid.GUID, state etw.ProviderState, @@ -208,15 +206,12 @@ func main() { ) { switch state { case etw.ProviderStateEnable: - collectionEnabled.Store(true) + runtimeLogging.SetCollectionEnabled(true) case etw.ProviderStateDisable: - collectionEnabled.Store(false) + runtimeLogging.SetCollectionEnabled(false) default: return } - if hook := runtimeLogHook.Load(); hook != nil { - hook.SetCollectionEnabled(collectionEnabled.Load()) - } }) if err != nil { logrus.WithError(err).Error("failed to register sidecar ETW provider") @@ -233,8 +228,7 @@ func main() { logrus.WithError(err).Error("failed to close sidecar ETW provider") } }() - runtimeLogHook.Store(runtimeHook) - runtimeHook.SetCollectionEnabled(collectionEnabled.Load()) + runtimeLogging.Attach(runtimeHook) logrus.AddHook(runtimeHook) loggingOptions = append(loggingOptions, securitypolicy.WithRuntimeLoggingChanged(runtimeHook.SetAllowed)) } diff --git a/internal/gcs-sidecar/logging.go b/internal/gcs-sidecar/logging.go index fcbd2c935b..5e80f3332d 100644 --- a/internal/gcs-sidecar/logging.go +++ b/internal/gcs-sidecar/logging.go @@ -3,6 +3,8 @@ package bridge import ( + "fmt" + "reflect" "sync" "time" @@ -26,6 +28,8 @@ type RuntimeLoggingHook struct { allowed bool policyResolved bool collectionEnabled bool + streaming bool + started bool closed bool pending []*logrus.Entry pendingBytes int @@ -36,6 +40,34 @@ type RuntimeLoggingHook 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, @@ -61,6 +93,15 @@ func (h *RuntimeLoggingHook) SetAllowed(allowed bool) { 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() } @@ -73,30 +114,46 @@ func (h *RuntimeLoggingHook) SetCollectionEnabled(enabled bool) { 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() - if h.closed || (h.policyResolved && (!h.allowed || !h.collectionEnabled)) { - h.mu.Unlock() + 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 { - h.mu.Unlock() return nil } h.pending = append(h.pending, buffered) h.pendingBytes += size - h.mu.Unlock() h.signal() return nil } @@ -116,24 +173,25 @@ func (h *RuntimeLoggingHook) forward() { return case <-h.wake: h.mu.Lock() - if h.closed || !h.policyResolved || !h.allowed || !h.collectionEnabled { + if !h.readyLocked() { h.mu.Unlock() continue } entries := h.pending h.pending = nil h.pendingBytes = 0 - h.mu.Unlock() - + h.started = true for _, entry := range entries { - h.mu.Lock() - allowed := !h.closed && h.policyResolved && h.allowed && h.collectionEnabled - h.mu.Unlock() - if !allowed { + if !h.readyLocked() { break } _ = h.next.Fire(entry) } + if h.readyLocked() { + h.streaming = true + h.started = true + } + h.mu.Unlock() } } } @@ -244,6 +302,106 @@ func copyStartupField(value interface{}, maxBytes int) (interface{}, int, bool) } 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_test.go b/internal/gcs-sidecar/logging_test.go index 939e786ce2..51ae6b7504 100644 --- a/internal/gcs-sidecar/logging_test.go +++ b/internal/gcs-sidecar/logging_test.go @@ -63,23 +63,35 @@ func TestRuntimeLoggingHookFlushesAfterPolicyAndCollector(t *testing.T) { 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) - if got := []string{first.Message, second.Message}; !reflect.DeepEqual(got, []string{ - "sidecar initialized", "forwarding active", + 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" || second.Data["containerID"] != "ready" { + 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() != 2 { + 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) { @@ -88,17 +100,51 @@ func TestRuntimeLoggingHookCollectorCanPrecedePolicy(t *testing.T) { 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) - if got := receiveLogEntry(t, capture.entries); got.Message != entry.Message { + 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) {