[test] Log to ETW for benchmarks; retry layer removal

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 == "" {