diff --git a/cmd/containerd-shim-runhcs-v1/nopformatter.go b/cmd/containerd-shim-runhcs-v1/nopformatter.go deleted file mode 100644 index 5e0e38c110..0000000000 --- a/cmd/containerd-shim-runhcs-v1/nopformatter.go +++ /dev/null @@ -1,10 +0,0 @@ -package main - -import ( - "github.com/sirupsen/logrus" -) - -type nopFormatter struct{} - -// Format does nothing and returns a nil slice. -func (nopFormatter) Format(*logrus.Entry) ([]byte, error) { return nil, nil } diff --git a/cmd/containerd-shim-runhcs-v1/serve.go b/cmd/containerd-shim-runhcs-v1/serve.go index c131f7db77..290f986c42 100644 --- a/cmd/containerd-shim-runhcs-v1/serve.go +++ b/cmd/containerd-shim-runhcs-v1/serve.go @@ -154,7 +154,7 @@ var serveCommand = cli.Command{ case runhcsopts.Options_FILE: panic("file log output mode is not supported") case runhcsopts.Options_ETW: - logrus.SetFormatter(nopFormatter{}) + logrus.SetFormatter(hcslog.NopFormatter{}) logrus.SetOutput(io.Discard) } diff --git a/internal/log/nopformatter.go b/internal/log/nopformatter.go new file mode 100644 index 0000000000..909ba68b28 --- /dev/null +++ b/internal/log/nopformatter.go @@ -0,0 +1,12 @@ +package log + +import ( + "github.com/sirupsen/logrus" +) + +type NopFormatter struct{} + +var _ logrus.Formatter = NopFormatter{} + +// Format does nothing and returns a nil slice. +func (NopFormatter) Format(*logrus.Entry) ([]byte, error) { return nil, nil } diff --git a/scripts/Run-Tests.ps1 b/scripts/Run-Tests.ps1 index 2faafa172b..6796460b58 100644 --- a/scripts/Run-Tests.ps1 +++ b/scripts/Run-Tests.ps1 @@ -40,12 +40,16 @@ param ( [switch] $TestVerbose, + [string] + $LogLevel, + [string] $Run, [string[]] $Features ) + $ErrorActionPreference = 'Stop' Import-Module ( Join-Path $PSScriptRoot Testing.psm1 ) -Force @@ -65,6 +69,7 @@ $testcmd, $out = New-TestCommand ` -Note $Note ` -Shuffle:$Shuffle ` -TestVerbose:$TestVerbose ` + -LogLevel $LogLevel ` -Count $Count ` -BenchTime $BenchTime ` -Timeout $Timeout ` @@ -75,5 +80,9 @@ $testcmd, $out = New-TestCommand ` Invoke-TestCommand ` -TestCmd $testcmd ` -OutputFile $out ` - -OutputCmd (& { if ( $Action -eq 'Bench' ) { $BenchstatPath } }) ` + -OutputCmd (& { + if ( $Action -eq 'Bench' -and -not [string]::IsNullOrWhiteSpace($BenchstatPath) ) { + "$BenchstatPath -table=`"`"" + } + }) ` -Verbose:$Verbose diff --git a/scripts/Testing.psm1 b/scripts/Testing.psm1 index 8526f8f96c..1b64d880c0 100644 --- a/scripts/Testing.psm1 +++ b/scripts/Testing.psm1 @@ -31,9 +31,15 @@ function New-TestCommand { [switch] $Shuffle, + # whether to enable verbose testing logs, ie the `-test.v` flag [switch] $TestVerbose, + # the log level of the shim code itself (ie, logrus, via the `-log-level` flag) + [string] + [ValidateSet('', 'panic', 'fatal', 'error', 'warn', 'warning', 'info', 'debug', 'trace')] + $LogLevel, + [int] $Count, @@ -83,6 +89,10 @@ function New-TestCommand { } } + if ( -not [string]::IsNullOrWhiteSpace($LogLevel) ) { + $testcmd += "'-log-level=$($LogLevel.ToLower())' " + } + foreach ( $Feature in $Features ) { $Feature = $Feature -replace ' ', '' if ( $Feature ) { @@ -96,7 +106,7 @@ function New-TestCommand { } $out = Join-Path $OutDirectory "$f-$(Get-Date -Date $date -Format FileDateTime).txt" - return $testcmd, $out + return $testcmd.Trim(), $out } function Invoke-TestCommand { @@ -125,7 +135,11 @@ function Invoke-TestCommand { if ( $OutputCmd -and $OutputFile -ne 'nul' ) { $oc = "$OutputCmd $OutputFile" - Write-Verbose "Running command: $oc" - Invoke-Expression $oc + if ( Test-Path -PathType Leaf $OutputFile ) { + Write-Verbose "Running output command: $oc" + Invoke-Expression $oc + } else { + Write-Warning "Cannot run output command with non-existant output file: $oc" + } } } diff --git a/test/containerd-shim-runhcs-v1/start_test.go b/test/containerd-shim-runhcs-v1/start_test.go index be03cf0a2c..78a8fff0e0 100644 --- a/test/containerd-shim-runhcs-v1/start_test.go +++ b/test/containerd-shim-runhcs-v1/start_test.go @@ -13,7 +13,6 @@ import ( "path/filepath" "strings" "testing" - "time" "github.com/Microsoft/go-winio" task "github.com/containerd/containerd/api/runtime/task/v2" @@ -22,6 +21,8 @@ import ( "github.com/opencontainers/runtime-tools/generate" "github.com/Microsoft/hcsshim/pkg/annotations" + + "github.com/Microsoft/hcsshim/test/internal/util" "github.com/Microsoft/hcsshim/test/pkg/require" ) @@ -56,18 +57,7 @@ func createStartCommandWithID(t *testing.T, id string) (*exec.Cmd, *bytes.Buffer func cleanupTestBundle(t *testing.T, dir string) { t.Helper() - var err error - for i := 0; i < 2; i++ { - // sporadic access-denies errors if trying to delete bundle (namely panic.log) before OS realizes - // shim exited and releases dile handle - if err = os.RemoveAll(dir); err == nil { - // does not os.RemoveAll does not if path doesn't exist - return - } - time.Sleep(time.Millisecond) - } - - if err != nil { + if err := util.RemoveAll(dir); err != nil { t.Errorf("failed removing test bundle with: %v", err) } } diff --git a/test/functional/main_test.go b/test/functional/main_test.go index 15b73a9a29..4f523f53a8 100644 --- a/test/functional/main_test.go +++ b/test/functional/main_test.go @@ -10,7 +10,7 @@ package functional import ( "context" "flag" - "log" + "io" "os" "os/exec" "strconv" @@ -18,12 +18,15 @@ import ( "testing" "time" + "github.com/Microsoft/go-winio/pkg/etw" + "github.com/Microsoft/go-winio/pkg/etwlogrus" "github.com/containerd/containerd/namespaces" "github.com/sirupsen/logrus" "go.opencensus.io/trace" "github.com/Microsoft/hcsshim/internal/cow" "github.com/Microsoft/hcsshim/internal/hcsoci" + "github.com/Microsoft/hcsshim/internal/log" "github.com/Microsoft/hcsshim/internal/oc" "github.com/Microsoft/hcsshim/internal/resources" "github.com/Microsoft/hcsshim/internal/uvm" @@ -110,7 +113,7 @@ var ( func init() { if !winapi.IsElevated() { - log.Fatal("tests must be run in an elevated context") + panic("tests must be run in an elevated context") } // This allows for debugging a utility VM. @@ -148,10 +151,34 @@ func TestMain(m *testing.M) { // print additional configuration options when running benchmarks, so we can better track performance. if util.RunningBenchmarks() { util.PrintAdditionalBenchmarkConfig() + + // also, print to ETW instead of stdout to mirror actual deployments, and prevent logs from + // interfering with benchmarking output + + provider, err := etw.NewProviderWithOptions("Microsoft.Virtualization.RunHCS") + if err != nil { + logrus.Error(err) + } else { + if hook, err := etwlogrus.NewHookFromProvider(provider); err == nil { + logrus.AddHook(hook) + } else { + logrus.WithError(err).Error("could not create ETW logrus hook") + } + } + + // regardless of ETW provider status, still discard logs + logrus.SetFormatter(log.NopFormatter{}) + logrus.SetOutput(io.Discard) } e := m.Run() + if util.RunningBenchmarks() { + // un-discard logs during cleanup + logrus.SetFormatter(&logrus.TextFormatter{FullTimestamp: true}) + logrus.SetOutput(os.Stdout) + } + // close any uVMs that escaped cmdStr := ` foreach ($vm in Get-ComputeProcess -Owner '` + hcsOwner + `') { Write-Output "uVM $($vm.Id) was left running" ; Stop-ComputeProcess -Force -Id $vm.Id } ` @@ -166,8 +193,14 @@ func TestMain(m *testing.M) { // delete downloaded layers; cant use defer, since os.exit does not run them for _, l := range images { - // just ignore errors: they are logged, and no other cleanup possible - _ = l.Close(context.Background()) + // just log errors: no other cleanup possible + if err := l.Close(context.Background()); err != nil { + logrus.WithFields(logrus.Fields{ + logrus.ErrorKey: err, + "image": l.Image, + "platform": l.Platform, + }).Warning("layer cleanup failed") + } } os.Exit(e) diff --git a/test/functional/uvm_mem_backingtype_test.go b/test/functional/uvm_mem_backingtype_test.go index 5839d099e4..fece0b30ff 100644 --- a/test/functional/uvm_mem_backingtype_test.go +++ b/test/functional/uvm_mem_backingtype_test.go @@ -6,26 +6,24 @@ package functional import ( "context" - "io" "testing" "github.com/Microsoft/hcsshim/internal/uvm" "github.com/Microsoft/hcsshim/osversion" "github.com/Microsoft/hcsshim/test/pkg/require" - "github.com/sirupsen/logrus" - tuvm "github.com/Microsoft/hcsshim/test/pkg/uvm" + testuvm "github.com/Microsoft/hcsshim/test/pkg/uvm" ) func runMemStartLCOWTest(t *testing.T, opts *uvm.OptionsLCOW) { t.Helper() - u := tuvm.CreateAndStartLCOWFromOpts(context.Background(), t, opts) + u := testuvm.CreateAndStartLCOWFromOpts(context.Background(), t, opts) u.Close() } func runMemStartWCOWTest(t *testing.T, opts *uvm.OptionsWCOW) { t.Helper() - u, _, _ := tuvm.CreateWCOWUVMFromOptsWithImage(context.Background(), t, opts, "microsoft/nanoserver") + u, _, _ := testuvm.CreateWCOWUVMFromOptsWithImage(context.Background(), t, opts, "microsoft/nanoserver") u.Close() } @@ -104,7 +102,6 @@ func BenchmarkMemBackingTypeVirtualLCOW(b *testing.B) { require.Build(b, osversion.RS5) requireFeatures(b, featureLCOW) - logrus.SetOutput(io.Discard) runBenchMemStartLcowTest(b, true, false) } @@ -114,7 +111,6 @@ func BenchmarkMemBackingTypeVirtualDeferredLCOW(b *testing.B) { require.Build(b, osversion.RS5) requireFeatures(b, featureLCOW) - logrus.SetOutput(io.Discard) runBenchMemStartLcowTest(b, true, true) } @@ -124,7 +120,6 @@ func BenchmarkMemBackingTypePhyscialLCOW(b *testing.B) { require.Build(b, osversion.RS5) requireFeatures(b, featureLCOW) - logrus.SetOutput(io.Discard) runBenchMemStartLcowTest(b, false, false) } diff --git a/test/internal/layers/lazy.go b/test/internal/layers/lazy.go index 33d3e7a3ff..a922e4bf53 100644 --- a/test/internal/layers/lazy.go +++ b/test/internal/layers/lazy.go @@ -20,7 +20,6 @@ import ( "github.com/Microsoft/hcsshim/ext4/tar2ext4" "github.com/Microsoft/hcsshim/internal/log" - "github.com/Microsoft/hcsshim/internal/wclayer" "github.com/Microsoft/hcsshim/pkg/ociwclayer" "github.com/Microsoft/hcsshim/test/internal/util" @@ -52,12 +51,9 @@ func (x *LazyImageLayers) Close(ctx context.Context) error { return nil } - if _, err := os.Stat(x.dir); err != nil && !os.IsNotExist(err) { - return fmt.Errorf("path %q is not valid: %w", x.dir, err) - } // DestroyLayer will remove the entire directory and all its contents, regardless of if // its a Windows container layer or not. - if err := wclayer.DestroyLayer(ctx, x.dir); err != nil { + if err := util.DestroyLayer(ctx, x.dir); err != nil { return fmt.Errorf("could not destroy layer directory %q: %w", x.dir, err) } return nil diff --git a/test/internal/layers/scratch.go b/test/internal/layers/scratch.go index 5e7489988f..82b7a0ae81 100644 --- a/test/internal/layers/scratch.go +++ b/test/internal/layers/scratch.go @@ -4,12 +4,13 @@ package layers import ( "context" - "os" "path/filepath" "testing" "github.com/Microsoft/hcsshim/internal/lcow" "github.com/Microsoft/hcsshim/internal/uvm" + + "github.com/Microsoft/hcsshim/test/internal/util" ) const ( @@ -23,7 +24,7 @@ func CacheFile(_ context.Context, tb testing.TB, dir string) string { if dir == "" { dir = tb.TempDir() tb.Cleanup(func() { - os.RemoveAll(dir) + _ = util.RemoveAll(dir) }) } cache := filepath.Join(dir, CacheFileName) @@ -31,14 +32,14 @@ func CacheFile(_ context.Context, tb testing.TB, dir string) string { } // ScratchSpace creates an LCOW scratch space VHD at `dir\name`, and returns the dir and name. -// If name, dir, or chache are empty, ScratchSpace uses a default name or creates a temporary -// directory, respectively. +// If name, (dir, or cache) are empty, ScratchSpace uses [ScratchSpace] (creates a temporary +// directory), respectively. func ScratchSpace(ctx context.Context, tb testing.TB, vm *uvm.UtilityVM, name, dir, cache string) (string, string) { tb.Helper() if dir == "" { dir = tb.TempDir() tb.Cleanup(func() { - os.RemoveAll(dir) + _ = util.RemoveAll(dir) }) } if cache == "" { diff --git a/test/internal/util/util.go b/test/internal/util/util.go index 35caaa9a43..d2634f2d5e 100644 --- a/test/internal/util/util.go +++ b/test/internal/util/util.go @@ -40,12 +40,9 @@ func RunningBenchmarks() (b bool) { // go doesn't run benchmarks unless -test.bench flag is passed, so thats our cue. // ref: https://pkg.go.dev/testing#hdr-Benchmarks - - // `go test` (and `go test -c`) runs in a binary with a suite of `-test.*` flags defined. - // use that as our cue that we are in a testing binary. // - // even if benchmarks are run via `go test -bench='.' `, go will still compile a testing binary - // and pass the flags as `-test.*` + // (even if benchmarks are run via `go test -bench='.' `, go will still compile a testing binary + // and pass the flags as `-test.*`) f := flag.Lookup("test.bench") return f != nil && f.Value.String() != "" } @@ -56,9 +53,8 @@ func RunningBenchmarks() (b bool) { // - go version // - version information from [github.com/Microsoft/hcsshim/internal/version] (if set) // -// Benchmark configuration format: -// https://go.googlesource.com/proposal/+/master/design/14313-benchmark-format.md#configuration-lines -// +// Benchmark configuration format: https://golang.org/design/14313-benchmark-format#configuration-lines + // For default configuration printed, see: [testing.(*B).Run()] in src/testing/benchmark.go func PrintAdditionalBenchmarkConfig() { // test binaries are not built with module information, so [debug.ReadBuildInfo] will only give @@ -124,3 +120,33 @@ func RandNameSuffix(xs ...any) (s string) { s += "-" + hex.EncodeToString(b) return s } + +const ( + RemoveAttempts = 3 + RemoveWait = time.Millisecond +) + +// RemoveAll tries [RemoveAttempts] times to remove the path via [os.RemoveAll], waiting +// [RemoveWait] between attempts. +func RemoveAll(p string) (err error) { + // os.RemoveAll does not error if path doesn't exist + return repeat(func() error { return os.RemoveAll(p) }, RemoveAttempts, RemoveWait) +} + +func repeat(f func() error, n int, d time.Duration) (err error) { + if n < 1 { + n = 1 + } + + err = f() + for i := 1; i < n; i++ { + if err == nil { + break + } + + time.Sleep(d) + err = f() + } + + return err +} diff --git a/test/internal/util/util_windows.go b/test/internal/util/util_windows.go new file mode 100644 index 0000000000..36be3cc6ee --- /dev/null +++ b/test/internal/util/util_windows.go @@ -0,0 +1,19 @@ +//go:build windows + +package util + +import ( + "context" + "os" + + "github.com/Microsoft/hcsshim/internal/wclayer" +) + +// DestroyLayer is similar to [RemoveAll], but uses [wclayer.DestroyLayer] instead of [os.RemoveAll]. +func DestroyLayer(ctx context.Context, p string) (err error) { + // check if the path exists + if _, err := os.Stat(p); os.IsNotExist(err) { + return nil + } + return repeat(func() error { return wclayer.DestroyLayer(ctx, p) }, RemoveAttempts, RemoveWait) +} diff --git a/test/pkg/uvm/lcow.go b/test/pkg/uvm/lcow.go index d883e6f4a2..cf2dca8c5c 100644 --- a/test/pkg/uvm/lcow.go +++ b/test/pkg/uvm/lcow.go @@ -69,8 +69,8 @@ func CreateAndStartLCOWFromOpts(ctx context.Context, tb testing.TB, opts *uvm.Op } vm, cleanup := CreateLCOW(ctx, tb, opts) - Start(ctx, tb, vm) tb.Cleanup(func() { cleanup(ctx) }) + Start(ctx, tb, vm) return vm } diff --git a/test/pkg/uvm/wcow.go b/test/pkg/uvm/wcow.go index 427710a300..a158d573d0 100644 --- a/test/pkg/uvm/wcow.go +++ b/test/pkg/uvm/wcow.go @@ -12,6 +12,8 @@ import ( "github.com/Microsoft/hcsshim/test/pkg/images" ) +// TODO: add cleanup return to CreateWCOWUVM*(), and have it remove layer and scratch dirs + // CreateWCOWUVM creates a WCOW utility VM with all default options. Returns the // UtilityVM object; folder used as its scratch. func CreateWCOWUVM(ctx context.Context, tb testing.TB, id, image string) (*uvm.UtilityVM, []string, string) {