Merge pull request #34846 from Microsoft/jjh/debuggcs

LCOW: Add UVM debugability by grabbing logs before tear-down

libcontainerd/client_windows.go

@@ -530,6 +530,9 @@ func (clnt *client) AddProcess(ctx context.Context, containerID, processFriendly
 	if err != nil {
 		return -1, err
 	}
+
+	defer container.debugGCS()
+
 	// Note we always tell HCS to
 	// create stdout as it's required regardless of '-i' or '-t' options, so that
 	// docker can always grab the output through logs. We also tell HCS to always

libcontainerd/container_windows.go

@@ -50,6 +50,7 @@ func (ctr *container) start(attachStdio StdioCallback) error {
 	logrus.Debugln("libcontainerd: starting container ", ctr.containerID)
 	if err = ctr.hcsContainer.Start(); err != nil {
 		logrus.Errorf("libcontainerd: failed to start container: %s", err)
+		ctr.debugGCS() // Before terminating!
 		if err := ctr.terminate(); err != nil {
 			logrus.Errorf("libcontainerd: failed to cleanup after a failed Start. %s", err)
 		} else {
@@ -58,6 +59,8 @@ func (ctr *container) start(attachStdio StdioCallback) error {
 		return err
 	}
 
+	defer ctr.debugGCS()
+
 	// Note we always tell HCS to
 	// create stdout as it's required regardless of '-i' or '-t' options, so that
 	// docker can always grab the output through logs. We also tell HCS to always

libcontainerd/utils_windows.go

@@ -1,6 +1,10 @@
 package libcontainerd
 
-import "strings"
+import (
+	"strings"
+
+	opengcs "github.com/Microsoft/opengcs/client"
+)
 
 // setupEnvironmentVariables converts a string array of environment variables
 // into a map as required by the HCS. Source array is in format [v1=k1] [v2=k2] etc.
@@ -19,3 +23,16 @@ func setupEnvironmentVariables(a []string) map[string]string {
 func (s *LCOWOption) Apply(interface{}) error {
 	return nil
 }
+
+// debugGCS is a dirty hack for debugging for Linux Utility VMs. It simply
+// runs a bunch of commands inside the UVM, but seriously aides in advanced debugging.
+func (c *container) debugGCS() {
+	if c == nil || c.isWindows || c.hcsContainer == nil {
+		return
+	}
+	cfg := opengcs.Config{
+		Uvm:               c.hcsContainer,
+		UvmTimeoutSeconds: 600,
+	}
+	cfg.DebugGCS()
+}

vendor.conf

@@ -8,7 +8,7 @@ github.com/docker/libtrust 9cbd2a1374f46905c68a4eb3694a130610adc62a
 github.com/go-check/check 4ed411733c5785b40214c70bce814c3a3a689609 https://github.com/cpuguy83/check.git
 github.com/gorilla/context v1.1
 github.com/gorilla/mux v1.1
-github.com/Microsoft/opengcs v0.3.3
+github.com/Microsoft/opengcs v0.3.4
 github.com/kr/pty 5cf931ef8f
 github.com/mattn/go-shellwords v1.0.3
 github.com/sirupsen/logrus v1.0.3

vendor/github.com/Microsoft/opengcs/client/createext4vhdx.go

@@ -57,6 +57,8 @@ func (config *Config) CreateExt4Vhdx(destFile string, sizeGB uint32, cacheFile s
 		return fmt.Errorf("failed to create VHDx %s: %s", destFile, err)
 	}
 
+	defer config.DebugGCS()
+
 	// Attach it to the utility VM, but don't mount it (as there's no filesystem on it)
 	if err := config.HotAddVhd(destFile, "", false, false); err != nil {
 		return fmt.Errorf("opengcs: CreateExt4Vhdx: failed to hot-add %s to utility VM: %s", cacheFile, err)

vendor/github.com/Microsoft/opengcs/client/hotaddvhd.go

@@ -20,6 +20,8 @@ func (config *Config) HotAddVhd(hostPath string, containerPath string, readOnly
 		return fmt.Errorf("cannot hot-add VHD as no utility VM is in configuration")
 	}
 
+	defer config.DebugGCS()
+
 	modification := &hcsshim.ResourceModificationRequestResponse{
 		Resource: "MappedVirtualDisk",
 		Data: hcsshim.MappedVirtualDisk{

vendor/github.com/Microsoft/opengcs/client/hotremovevhd.go

@@ -18,6 +18,8 @@ func (config *Config) HotRemoveVhd(hostPath string) error {
 		return fmt.Errorf("cannot hot-add VHD as no utility VM is in configuration")
 	}
 
+	defer config.DebugGCS()
+
 	modification := &hcsshim.ResourceModificationRequestResponse{
 		Resource: "MappedVirtualDisk",
 		Data: hcsshim.MappedVirtualDisk{

vendor/github.com/Microsoft/opengcs/client/process.go

@@ -3,8 +3,12 @@
 package client
 
 import (
+	"bytes"
 	"fmt"
 	"io"
+	"os"
+	"strings"
+	"time"
 
 	"github.com/Microsoft/hcsshim"
 	"github.com/sirupsen/logrus"
@@ -110,3 +114,44 @@ func (config *Config) RunProcess(commandLine string, stdin io.Reader, stdout io.
 	logrus.Debugf("opengcs: runProcess success: %s", commandLine)
 	return process.Process, nil
 }
+
+func debugCommand(s string) string {
+	return fmt.Sprintf(`echo -e 'DEBUG COMMAND: %s\\n--------------\\n';%s;echo -e '\\n\\n';`, s, s)
+}
+
+// DebugGCS extracts logs from the GCS. It's a useful hack for debugging,
+// but not necessarily optimal, but all that is available to us in RS3.
+func (config *Config) DebugGCS() {
+	if logrus.GetLevel() < logrus.DebugLevel || len(os.Getenv("OPENGCS_DEBUG_ENABLE")) == 0 {
+		return
+	}
+
+	var out bytes.Buffer
+	cmd := os.Getenv("OPENGCS_DEBUG_COMMAND")
+	if cmd == "" {
+		cmd = `sh -c "`
+		cmd += debugCommand("ls -l /tmp")
+		cmd += debugCommand("cat /tmp/gcs.log")
+		cmd += debugCommand("ls -l /tmp/gcs")
+		cmd += debugCommand("ls -l /tmp/gcs/*")
+		cmd += debugCommand("cat /tmp/gcs/*/config.json")
+		cmd += debugCommand("ls -lR /var/run/gcsrunc")
+		cmd += debugCommand("cat /var/run/gcsrunc/log.log")
+		cmd += debugCommand("ps -ef")
+		cmd += `"`
+	}
+	proc, err := config.RunProcess(cmd, nil, &out, nil)
+	defer func() {
+		if proc != nil {
+			proc.Kill()
+			proc.Close()
+		}
+	}()
+	if err != nil {
+		logrus.Debugln("benign failure getting gcs logs: ", err)
+	}
+	if proc != nil {
+		proc.WaitTimeout(time.Duration(int(time.Second) * 30))
+	}
+	logrus.Debugf("GCS Debugging:\n%s\n\nEnd GCS Debugging\n", strings.TrimSpace(out.String()))
+}

vendor/github.com/Microsoft/opengcs/client/tartovhd.go

@@ -17,6 +17,8 @@ func (config *Config) TarToVhd(targetVHDFile string, reader io.Reader) (int64, e
 		return 0, fmt.Errorf("cannot Tar2Vhd as no utility VM is in configuration")
 	}
 
+	defer config.DebugGCS()
+
 	process, err := config.createUtilsProcess("tar2vhd")
 	if err != nil {
 		return 0, fmt.Errorf("failed to start tar2vhd for %s: %s", targetVHDFile, err)

vendor/github.com/Microsoft/opengcs/client/vhdtotar.go

@@ -20,6 +20,8 @@ func (config *Config) VhdToTar(vhdFile string, uvmMountPath string, isSandbox bo
 		return nil, fmt.Errorf("cannot VhdToTar as no utility VM is in configuration")
 	}
 
+	defer config.DebugGCS()
+
 	vhdHandle, err := os.Open(vhdFile)
 	if err != nil {
 		return nil, fmt.Errorf("opengcs: VhdToTar: failed to open %s: %s", vhdFile, err)