From 42b1c42d1acac3a4de8b12023310402466a30c5b Mon Sep 17 00:00:00 2001 From: Maksim An Date: Sat, 7 Aug 2021 15:22:32 -0700 Subject: [PATCH 1/2] Add more debug messages when stdio finishes and scsi mount fails Additionally cleanup dead code during scsi mount, bump scsi mount timeout to 5 seconds. Signed-off-by: Maksim An --- internal/guest/runtime/hcsv2/uvm.go | 2 +- internal/guest/runtime/runc/runc.go | 4 ++++ internal/guest/storage/scsi/scsi.go | 27 +++++++++++++++++++-------- 3 files changed, 24 insertions(+), 9 deletions(-) diff --git a/internal/guest/runtime/hcsv2/uvm.go b/internal/guest/runtime/hcsv2/uvm.go index 64d47cb764..49229db24b 100644 --- a/internal/guest/runtime/hcsv2/uvm.go +++ b/internal/guest/runtime/hcsv2/uvm.go @@ -408,7 +408,7 @@ func newInvalidRequestTypeError(rt prot.ModifyRequestType) error { func modifyMappedVirtualDisk(ctx context.Context, rt prot.ModifyRequestType, mvd *prot.MappedVirtualDiskV2) (err error) { switch rt { case prot.MreqtAdd: - mountCtx, cancel := context.WithTimeout(ctx, time.Second*4) + mountCtx, cancel := context.WithTimeout(ctx, time.Second*5) defer cancel() if mvd.MountPath != "" { return scsi.Mount(mountCtx, mvd.Controller, mvd.Lun, mvd.MountPath, mvd.ReadOnly, false, mvd.Options) diff --git a/internal/guest/runtime/runc/runc.go b/internal/guest/runtime/runc/runc.go index d3c9086913..e6d929f5d1 100644 --- a/internal/guest/runtime/runc/runc.go +++ b/internal/guest/runtime/runc/runc.go @@ -498,6 +498,9 @@ func (p *process) Wait() (int, error) { if p.pipeRelay != nil { p.pipeRelay.Wait() } + + l.WithField("pid", p.pid).Debug("relay wait completed") + return exitCode, err } @@ -524,6 +527,7 @@ func (c *container) Wait() (int, error) { } } exitCode, err := c.init.Wait() + logrus.WithField("cid", c.id).Debug("runc.container::init process wait completed") if err != nil { return -1, err } diff --git a/internal/guest/storage/scsi/scsi.go b/internal/guest/storage/scsi/scsi.go index 5ea3f56211..dbb8837955 100644 --- a/internal/guest/storage/scsi/scsi.go +++ b/internal/guest/storage/scsi/scsi.go @@ -8,6 +8,7 @@ import ( "io/ioutil" "os" "path/filepath" + "strings" "time" "github.com/Microsoft/hcsshim/internal/guest/storage" @@ -29,6 +30,10 @@ var ( controllerLunToName = ControllerLunToName ) +const ( + scsiDevicesPath = "/sys/bus/scsi/devices" +) + // Mount creates a mount from the SCSI device on `controller` index `lun` to // `target` // @@ -38,7 +43,7 @@ var ( // If `encrypted` is set to true, the SCSI device will be encrypted using // dm-crypt. func Mount(ctx context.Context, controller, lun uint8, target string, readonly bool, encrypted bool, options []string) (err error) { - ctx, span := trace.StartSpan(ctx, "scsi::Mount") + spnCtx, span := trace.StartSpan(ctx, "scsi::Mount") defer span.End() defer func() { oc.SetSpanStatus(span, err) }() @@ -54,7 +59,7 @@ func Mount(ctx context.Context, controller, lun uint8, target string, readonly b osRemoveAll(target) } }() - source, err := controllerLunToName(ctx, controller, lun) + source, err := controllerLunToName(spnCtx, controller, lun) if err != nil { return err } @@ -68,7 +73,7 @@ func Mount(ctx context.Context, controller, lun uint8, target string, readonly b } if encrypted { - encryptedSource, err := crypt.EncryptDevice(ctx, source) + encryptedSource, err := crypt.EncryptDevice(spnCtx, source) if err != nil { return errors.Wrapf(err, "failed to mount encrypted device: "+source) } @@ -149,7 +154,7 @@ func ControllerLunToName(ctx context.Context, controller, lun uint8) (_ string, // Devices matching the given SCSI code should each have a subdirectory // under /sys/bus/scsi/devices//block. - blockPath := filepath.Join("/sys/bus/scsi/devices", scsiID, "block") + blockPath := filepath.Join(scsiDevicesPath, scsiID, "block") var deviceNames []os.FileInfo for { deviceNames, err = ioutil.ReadDir(blockPath) @@ -159,6 +164,15 @@ func ControllerLunToName(ctx context.Context, controller, lun uint8) (_ string, if len(deviceNames) == 0 { select { case <-ctx.Done(): + if dirContents, iErr := ioutil.ReadDir(scsiDevicesPath); iErr != nil { + log.G(ctx).WithError(iErr).Debug("failed to list scsi devices") + } else { + var scsiDevices []string + for _, elem := range dirContents { + scsiDevices = append(scsiDevices, elem.Name()) + } + log.G(ctx).WithField("scsiDevices", strings.Join(scsiDevices, "\n")).Debug("scsi devices at context timeout") + } return "", ctx.Err() default: time.Sleep(time.Millisecond * 10) @@ -168,9 +182,6 @@ func ControllerLunToName(ctx context.Context, controller, lun uint8) (_ string, break } - if len(deviceNames) == 0 { - return "", errors.Errorf("no matching device names found for SCSI ID \"%s\"", scsiID) - } if len(deviceNames) > 1 { return "", errors.Errorf("more than one block device could match SCSI ID \"%s\"", scsiID) } @@ -194,7 +205,7 @@ func UnplugDevice(ctx context.Context, controller, lun uint8) (err error) { trace.Int64Attribute("lun", int64(lun))) scsiID := fmt.Sprintf("0:0:%d:%d", controller, lun) - f, err := os.OpenFile(filepath.Join("/sys/bus/scsi/devices", scsiID, "delete"), os.O_WRONLY, 0644) + f, err := os.OpenFile(filepath.Join(scsiDevicesPath, scsiID, "delete"), os.O_WRONLY, 0644) if err != nil { if os.IsNotExist(err) { return nil From c25defddc29f773b63d6f9ce1fa51fd43ce9d6bf Mon Sep 17 00:00:00 2001 From: Maksim An Date: Sat, 21 Aug 2021 11:50:19 -0700 Subject: [PATCH 2/2] remove logging scsi devices on context timeout Signed-off-by: Maksim An --- internal/guest/storage/scsi/scsi.go | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/internal/guest/storage/scsi/scsi.go b/internal/guest/storage/scsi/scsi.go index dbb8837955..6cdada713d 100644 --- a/internal/guest/storage/scsi/scsi.go +++ b/internal/guest/storage/scsi/scsi.go @@ -8,7 +8,6 @@ import ( "io/ioutil" "os" "path/filepath" - "strings" "time" "github.com/Microsoft/hcsshim/internal/guest/storage" @@ -164,15 +163,6 @@ func ControllerLunToName(ctx context.Context, controller, lun uint8) (_ string, if len(deviceNames) == 0 { select { case <-ctx.Done(): - if dirContents, iErr := ioutil.ReadDir(scsiDevicesPath); iErr != nil { - log.G(ctx).WithError(iErr).Debug("failed to list scsi devices") - } else { - var scsiDevices []string - for _, elem := range dirContents { - scsiDevices = append(scsiDevices, elem.Name()) - } - log.G(ctx).WithField("scsiDevices", strings.Join(scsiDevices, "\n")).Debug("scsi devices at context timeout") - } return "", ctx.Err() default: time.Sleep(time.Millisecond * 10)