[test] Log to ETW for benchmarks; retry layer removal (#1947)

Write logs to ETW instead of stdout when running benchmarks to mimic
actual deployments.
Add log level to `Run-Test.ps1` helper script.

Add `RemoveAll` function that wraps and retries `os.RemoveAll` (waiting
in between attempts) since the OS may take a while to remove locks on a
directory after handles are closed.

Bug: defer uVM cleanup after creation (not start) during tests.

Signed-off-by: Hamza El-Saawy <[email protected]>

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)
 		}
 

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 }

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

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"
+        }
     }
 }

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)
 	}
 }

test/functional/main_test.go

@@ -10,20 +10,23 @@ package functional
 import (
 	"context"
 	"flag"
-	"log"
+	"io"
 	"os"
 	"os/exec"
 	"strconv"
 	"strings"
 	"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)

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)
 }

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

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,22 +24,22 @@ 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)
 	return cache
 }
 
 // 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 == "" {