Debugging

Author: E4242

pkg/sentry/fs/dirent.go

@@ -29,6 +29,7 @@ import (
 	"gvisor.dev/gvisor/pkg/sentry/socket/unix/transport"
 	"gvisor.dev/gvisor/pkg/sentry/uniqueid"
 	"gvisor.dev/gvisor/pkg/syserror"
+	"gvisor.dev/gvisor/pkg/log"
 )
 
 type globalDirentMap struct {
@@ -461,6 +462,8 @@ func (d *Dirent) walk(ctx context.Context, root *Dirent, name string, walkMayUnl
 		return nil, syscall.ENOTDIR
 	}
 
+	log.Infof("TRACE-dirent_walk-(root=" + d.name + ", target=" + name + ")")
+
 	if name == "" || name == "." {
 		d.IncRef()
 		return d, nil
@@ -592,6 +595,7 @@ func (d *Dirent) walk(ctx context.Context, root *Dirent, name string, walkMayUnl
 		// only reference we'll ever get. d owns the reference.
 		return nil, syscall.ENOENT
 	}
+	log.Infof("Returning positive dirent")
 
 	// Return the positive Dirent.
 	return c, nil

pkg/sentry/fs/imgfs/file.go

@@ -18,6 +18,7 @@ import (
 	"io"
 	"gvisor.dev/gvisor/pkg/sentry/context"
 	"gvisor.dev/gvisor/pkg/sentry/fs"
+	"gvisor.dev/gvisor/pkg/log"
 	"gvisor.dev/gvisor/pkg/sentry/fs/fsutil"
 	"gvisor.dev/gvisor/pkg/sentry/memmap"
 	"gvisor.dev/gvisor/pkg/sentry/usermem"
@@ -48,6 +49,8 @@ type regularFileOperations struct {
 
 // Read implements fs.FileOperations.Read.
 func (r *regularFileOperations) Read(ctx context.Context, file *fs.File, dst usermem.IOSequence, offset int64) (int64, error) {
+	name, _ := file.Dirent.FullName(nil)
+	log.Infof("imgfs - Reading a file now %v", name)
 	return r.iops.read(ctx, file, dst, offset)
 }
 
@@ -63,5 +66,6 @@ func (r *regularFileOperations) ConfigureMMap(ctx context.Context, file *fs.File
 
 // ReadFrom implements fs.FileOperations.ReadFrom.
 func (r *regularFileOperations) ReadFrom(context.Context, *fs.File, io.Reader, int64) (int64, error) {
+	log.Infof("imgfs - ReadFrom not implemented")
 	return 0, syserror.ENOSYS
 }

pkg/sentry/fs/inode_overlay.go

@@ -50,6 +50,8 @@ func overlayWriteOut(ctx context.Context, o *overlayEntry) error {
 // If name exists, it returns true if the Dirent is in the upper, false if the
 // Dirent is in the lower.
 func overlayLookup(ctx context.Context, parent *overlayEntry, inode *Inode, name string) (*Dirent, bool, error) {
+	log.Infof("imgfs - looking up in overlay: %v", name)
+	
 	// Hot path. Avoid defers.
 	parent.copyMu.RLock()
 
@@ -68,6 +70,7 @@ func overlayLookup(ctx context.Context, parent *overlayEntry, inode *Inode, name
 
 	// Does the parent directory exist in the upper file system?
 	if parent.upper != nil {
+		log.Infof("The upper fs is: %v", parent.upper.MountSource.FilesystemType)
 		// First check if a file object exists in the upper file system.
 		// A file could have been created over a whiteout, so we need to
 		// check if something exists in the upper file system first.
@@ -123,6 +126,7 @@ func overlayLookup(ctx context.Context, parent *overlayEntry, inode *Inode, name
 	// the lower filesystem (e.g. device number, inode number) that were
 	// visible before a copy up.
 	if parent.lower != nil {
+		log.Infof("The lower fs is: %v", parent.lower.MountSource.FilesystemType)
 		// Check the lower file system.
 		child, err := parent.lower.Lookup(ctx, name)
 		// Same song and dance as above.

pkg/sentry/fs/mounts.go

@@ -474,6 +474,8 @@ func (mns *MountNamespace) FindLink(ctx context.Context, root, wd *Dirent, path
 	if len(path) == 0 {
 		panic("MountNamespace.FindLink: path is empty")
 	}
+	
+	log.Infof("Finding link in mountspace for path: %v", path)
 
 	// Split the path.
 	first, remainder := SplitFirst(path)
@@ -532,6 +534,7 @@ func (mns *MountNamespace) FindLink(ctx context.Context, root, wd *Dirent, path
 		current.DecRef()
 
 		if remainder != "" {
+			log.Infof("About to resolve last stage")
 			// Ensure it's resolved, unless it's the last level.
 			//
 			// See resolve for reference semantics; on err next
@@ -591,6 +594,7 @@ func (mns *MountNamespace) resolve(ctx context.Context, root, node *Dirent, rema
 		return target, nil
 
 	case syscall.ENOLINK:
+		log.Infof("Not sym")
 		// Not a symlink.
 		return node, nil
 
@@ -608,6 +612,8 @@ func (mns *MountNamespace) resolve(ctx context.Context, root, node *Dirent, rema
 			return nil, err
 		}
 
+		log.Infof("targetPath: " + targetPath)
+
 		// Find the node; we resolve relative to the current symlink's parent.
 		*remainingTraversals--
 		d, err := mns.FindInode(ctx, root, node.parent, targetPath, remainingTraversals)

pkg/sentry/fs/ramfs/BUILD

@@ -23,6 +23,7 @@ go_library(
         "//pkg/sentry/usermem",
         "//pkg/syserror",
         "//pkg/waiter",
+        "//pkg/log",
     ],
 )
 

pkg/sentry/fs/ramfs/symlink.go

@@ -20,6 +20,7 @@ import (
 	"gvisor.dev/gvisor/pkg/sentry/fs"
 	"gvisor.dev/gvisor/pkg/sentry/fs/fsutil"
 	"gvisor.dev/gvisor/pkg/waiter"
+	"gvisor.dev/gvisor/pkg/log"
 )
 
 // Symlink represents a symlink.
@@ -79,6 +80,7 @@ func (s *Symlink) Readlink(ctx context.Context, _ *fs.Inode) (string, error) {
 // Getlink returns ErrResolveViaReadlink, falling back to walking to the result
 // of Readlink().
 func (*Symlink) Getlink(context.Context, *fs.Inode) (*fs.Dirent, error) {
+	log.Infof("Getting link in ramfs")
 	return nil, fs.ErrResolveViaReadlink
 }
 

pkg/sentry/syscalls/linux/sys_file.go

@@ -30,6 +30,7 @@ import (
 	"gvisor.dev/gvisor/pkg/sentry/limits"
 	"gvisor.dev/gvisor/pkg/sentry/usermem"
 	"gvisor.dev/gvisor/pkg/syserror"
+	"gvisor.dev/gvisor/pkg/log"
 )
 
 // fileOpAt performs an operation on the second last component in the path.
@@ -67,6 +68,7 @@ func fileOpOn(t *kernel.Task, dirFD int32, path string, resolve bool, fn func(ro
 		f   *fs.File   // The file corresponding to dirFD (if required.)
 		err error
 	)
+	log.Infof("imgfs - fileOpOn %v", path)
 
 	// Extract the working directory (maybe).
 	if len(path) > 0 && path[0] == '/' {

runsc/boot/fs.go

@@ -160,6 +160,7 @@ func compileMounts(spec *specs.Spec) []specs.Mount {
 
 // p9MountOptions creates a slice of options for a p9 mount.
 func p9MountOptions(fd int, fa FileAccessType) []string {
+	log.Infof("Creating 9p mount options")
 	opts := []string{
 		"trans=fd",
 		"rfdno=" + strconv.Itoa(fd),
@@ -270,37 +271,39 @@ func addSubmountOverlay(ctx context.Context, inode *fs.Inode, submounts []string
 
 // mountExpFS should be executed after root create ramfs stub
 func mountExpFS(ctx context.Context, layerFDs []int, submounts []string) (*fs.Inode, error) {
-       var currentNode *fs.Inode
-
-       if submounts != nil {
-               msrc := fs.NewPseudoMountSource(ctx)
-               mountTree, err := ramfs.MakeDirectoryTree(ctx, msrc, submounts)
-               if err != nil {
-                       return nil, fmt.Errorf("creating mount tree: %v", err)
-               }
-               currentNode = mountTree
-       }
-
-       flags := fs.MountSourceFlags{ReadOnly: true}
-       imgFS := mustFindFilesystem("imgfs")
-
-       for index, lfd := range layerFDs {
-               imgfsNode, err := imgFS.Mount(ctx, "imgfs-layer-" + strconv.Itoa(index), flags, "packageFD=" + strconv.Itoa(lfd), nil)
-               if err != nil {
-                       return nil, fmt.Errorf("mounting imgfs layer %v, layerFD %v, err: %v", index, lfd, err)
-               }
-    if currentNode != nil {
-           if currentNode, err = fs.NewOverlayRoot(ctx, imgfsNode, currentNode, flags); err != nil {
-                   return nil, fmt.Errorf("creating imgfs overlay: %v", err)
-      }
-               } else {
-      currentNode = imgfsNode
-    }
-       }
-  if currentNode == nil {
-    return nil, fmt.Errorf("container fs: currentNode is nil")
-  }
-       return currentNode, nil
+	var currentNode *fs.Inode
+	log.Infof("imgfs - mounting imgfs in mountExpFS")
+
+	if submounts != nil {
+			msrc := fs.NewPseudoMountSource(ctx)
+			mountTree, err := ramfs.MakeDirectoryTree(ctx, msrc, submounts)
+			if err != nil {
+					return nil, fmt.Errorf("creating mount tree: %v", err)
+			}
+			currentNode = mountTree
+	}
+
+	flags := fs.MountSourceFlags{ReadOnly: true}
+	imgFS := mustFindFilesystem("imgfs")
+
+	for index, lfd := range layerFDs {
+			imgfsNode, err := imgFS.Mount(ctx, "imgfs-layer-" + strconv.Itoa(index), flags, "packageFD=" + strconv.Itoa(lfd), nil)
+			if err != nil {
+				return nil, fmt.Errorf("mounting imgfs layer %v, layerFD %v, err: %v", index, lfd, err)
+			}
+		if currentNode != nil {
+		if currentNode, err = fs.NewOverlayRoot(ctx, imgfsNode, currentNode, flags); err != nil {
+				return nil, fmt.Errorf("creating imgfs overlay: %v", err)
+			}
+		} else {
+			currentNode = imgfsNode
+		}
+	}
+		
+	if currentNode == nil {
+		return nil, fmt.Errorf("container fs: currentNode is nil")
+	}
+	return currentNode, nil
 }
 
 // subtargets takes a set of Mounts and returns only the targets that are
@@ -637,7 +640,7 @@ func (c *containerMounter) setupFS(conf *Config, procArgs *kernel.CreateProcessA
 
 	// Set namespace here so that it can be found in rootCtx.
 	rootProcArgs.MountNamespace = mns
-
+	log.Infof("imgfs - About to mount submounts in setupFS")
 	if err := c.mountSubmounts(rootCtx, conf, mns); err != nil {
 		return nil, err
 	}
@@ -649,6 +652,7 @@ func (c *containerMounter) createMountNamespace(ctx context.Context, conf *Confi
 	if err != nil {
 		return nil, fmt.Errorf("creating filesystem for container: %v", err)
 	}
+	log.Infof("imgfs - About to create a new Mount namespace")
 	mns, err := fs.NewMountNamespace(ctx, rootInode)
 	if err != nil {
 		return nil, fmt.Errorf("creating new mount namespace for container: %v", err)
@@ -663,6 +667,7 @@ func (c *containerMounter) mountSubmounts(ctx context.Context, conf *Config, mns
 	for _, m := range c.mounts {
 		log.Debugf("Mounting %q to %q, type: %s, options: %s", m.Source, m.Destination, m.Type, m.Options)
 		if hint := c.hints.findMount(m); hint != nil && hint.isSupported() {
+			log.Infof("imgfs - mounting with hint in mountSubmounts")
 			if err := c.mountSharedSubmount(ctx, mns, root, m, hint); err != nil {
 				return fmt.Errorf("mount shared mount %q to %q: %v", hint.name, m.Destination, err)
 			}
@@ -697,6 +702,7 @@ func (c *containerMounter) checkDispenser() error {
 // mountSharedMaster mounts the master of a volume that is shared among
 // containers in a pod. It returns the root mount's inode.
 func (c *containerMounter) mountSharedMaster(ctx context.Context, conf *Config, hint *mountHint) (*fs.Inode, error) {
+	log.Infof("Mounting shared master")
 	// Map mount type to filesystem name, and parse out the options that we are
 	// capable of dealing with.
 	fsName, opts, useOverlay, err := c.getMountNameAndOptions(conf, hint.mount)
@@ -806,6 +812,7 @@ func (c *containerMounter) getMountNameAndOptions(conf *Config, m specs.Mount) (
 		}
 
 	case bind:
+		log.Infof("imgfs - about to create p9 options")
 		fd := c.fds.remove()
 		fsName = "9p"
 		// Non-root bind mounts are always shared.
@@ -814,6 +821,7 @@ func (c *containerMounter) getMountNameAndOptions(conf *Config, m specs.Mount) (
 		useOverlay = conf.Overlay && !mountFlags(m.Options).ReadOnly
 
 	case imgfs:
+		log.Infof("imgfs - got here in switch")
 		fsName = m.Type
 		opts = []string{"packageFD=" + strconv.Itoa(conf.PackageFD)}
 		useOverlay = true // ImgFS will always use overlay
@@ -833,6 +841,7 @@ func (c *containerMounter) getMountNameAndOptions(conf *Config, m specs.Mount) (
 func (c *containerMounter) mountSubmount(ctx context.Context, conf *Config, mns *fs.MountNamespace, root *fs.Dirent, m specs.Mount) (*fs.Inode, *fs.Dirent, error) {
 	// Map mount type to filesystem name, and parse out the options that we are
 	// capable of dealing with.
+	log.Infof("mounting submount")
 	fsName, opts, useOverlay, err := c.getMountNameAndOptions(conf, m)
 	if err != nil {
 		return nil, nil, err
@@ -917,6 +926,7 @@ func (c *containerMounter) mountSharedSubmount(ctx context.Context, mns *fs.Moun
 // addRestoreMount adds a mount to the MountSources map used for restoring a
 // checkpointed container.
 func (c *containerMounter) addRestoreMount(conf *Config, renv *fs.RestoreEnvironment, m specs.Mount) error {
+	log.Infof("Adding restore mount")
 	fsName, opts, useOverlay, err := c.getMountNameAndOptions(conf, m)
 	if err != nil {
 		return err
@@ -946,6 +956,7 @@ func (c *containerMounter) createRestoreEnvironment(conf *Config) (*fs.RestoreEn
 		MountSources: make(map[string][]fs.MountArgs),
 	}
 
+	log.Infof("imgfs - Creating/restoring enviornement")
 	// Add root mount.
 	fd := c.fds.remove()
 	opts := p9MountOptions(fd, conf.FileAccess)

runsc/sandbox/sandbox.go

@@ -333,6 +333,7 @@ func (s *Sandbox) connError(err error) error {
 // createSandboxProcess starts the sandbox as a subprocess by running the "boot"
 // command, passing in the bundle dir.
 func (s *Sandbox) createSandboxProcess(conf *boot.Config, args *Args, startSyncFile *os.File) error {
+	log.Infof("imgfs - createSandboxProcess")
 	// nextFD is used to get unused FDs that we can pass to the sandbox.  It
 	// starts at 3 because 0, 1, and 2 are taken by stdin/out/err.
 	nextFD := 3
@@ -443,6 +444,7 @@ func (s *Sandbox) createSandboxProcess(conf *boot.Config, args *Args, startSyncF
 	}
 
 	//Experiemntal Feature: use multiple layers of imgfs to replace gofer.
+	log.Infof("imgfs - reading dir to get img files")
     files, err := ioutil.ReadDir(args.Spec.Root.Path)
     var layers []string
     for _, file := range files {
@@ -455,11 +457,12 @@ func (s *Sandbox) createSandboxProcess(conf *boot.Config, args *Args, startSyncF
     for _, layer := range layers {
         layerFile, err := os.OpenFile(path.Join(args.Spec.Root.Path, layer), os.O_RDONLY, 0644)
         if err != nil {
-                return fmt.Errorf("opening layer file: %v", err)
-           }
+            return fmt.Errorf("opening layer file: %v", err)
+        }
         defer layerFile.Close()
-           cmd.ExtraFiles = append(cmd.ExtraFiles, layerFile)
-           cmd.Args = append(cmd.Args, "--layer-fds="+strconv.Itoa(nextFD))
+        cmd.ExtraFiles = append(cmd.ExtraFiles, layerFile)
+		cmd.Args = append(cmd.Args, "--layer-fds="+strconv.Itoa(nextFD))
+		log.Infof("imgfs - added FD to --layer-fds: %v", nextFD)
         nextFD++
     }