Add good logging support to both sides

Docker-DCO-1.1-Signed-off-by: Michael Crosby <michael@crosbymichael.com> (github: crosbymichael)

libcontainer/nsinit/exec.go

@@ -11,6 +11,7 @@ import (
 	"github.com/dotcloud/docker/pkg/term"
 	"io"
 	"io/ioutil"
+	"log"
 	"os"
 	"os/exec"
 	"syscall"
@@ -18,7 +19,7 @@ import (
 
 // Exec performes setup outside of a namespace so that a container can be
 // executed.  Exec is a high level function for working with container namespaces.
-func Exec(container *libcontainer.Container, args []string) (int, error) {
+func Exec(container *libcontainer.Container, logFile string, args []string) (int, error) {
 	var (
 		master  *os.File
 		console string
@@ -29,6 +30,7 @@ func Exec(container *libcontainer.Container, args []string) (int, error) {
 	)
 
 	if container.Tty {
+		log.Printf("setting up master and console")
 		master, console, err = createMasterAndConsole()
 		if err != nil {
 			return -1, err
@@ -43,8 +45,9 @@ func Exec(container *libcontainer.Container, args []string) (int, error) {
 	}
 	system.UsetCloseOnExec(r.Fd())
 
-	command := createCommand(container, console, r.Fd(), args)
+	command := createCommand(container, console, logFile, r.Fd(), args)
 	if !container.Tty {
+		log.Printf("opening pipes on command")
 		if inPipe, err = command.StdinPipe(); err != nil {
 			return -1, err
 		}
@@ -56,9 +59,11 @@ func Exec(container *libcontainer.Container, args []string) (int, error) {
 		}
 	}
 
+	log.Printf("staring init")
 	if err := command.Start(); err != nil {
 		return -1, err
 	}
+	log.Printf("writting state file")
 	if err := writePidFile(command); err != nil {
 		command.Process.Kill()
 		return -1, err
@@ -68,6 +73,7 @@ func Exec(container *libcontainer.Container, args []string) (int, error) {
 	// Do this before syncing with child so that no children
 	// can escape the cgroup
 	if container.Cgroups != nil {
+		log.Printf("setting up cgroups")
 		if err := container.Cgroups.Apply(command.Process.Pid); err != nil {
 			command.Process.Kill()
 			return -1, err
@@ -75,18 +81,22 @@ func Exec(container *libcontainer.Container, args []string) (int, error) {
 	}
 
 	if container.Network != nil {
-		vethPair, err := initializeContainerVeth(container.Network.Bridge, command.Process.Pid)
+		log.Printf("creating veth pair")
+		vethPair, err := initializeContainerVeth(container.Network.Bridge, container.Network.Mtu, command.Process.Pid)
 		if err != nil {
 			return -1, err
 		}
+		log.Printf("sending %s as veth pair name", vethPair)
 		sendVethName(w, vethPair)
 	}
 
 	// Sync with child
+	log.Printf("closing sync pipes")
 	w.Close()
 	r.Close()
 
 	if container.Tty {
+		log.Printf("starting copy for tty")
 		go io.Copy(os.Stdout, master)
 		go io.Copy(master, os.Stdin)
 
@@ -97,6 +107,7 @@ func Exec(container *libcontainer.Container, args []string) (int, error) {
 		}
 		defer term.RestoreTerminal(os.Stdin.Fd(), state)
 	} else {
+		log.Printf("starting copy for std pipes")
 		go func() {
 			defer inPipe.Close()
 			io.Copy(inPipe, os.Stdin)
@@ -105,11 +116,13 @@ func Exec(container *libcontainer.Container, args []string) (int, error) {
 		go io.Copy(os.Stderr, errPipe)
 	}
 
+	log.Printf("waiting on process")
 	if err := command.Wait(); err != nil {
 		if _, ok := err.(*exec.ExitError); !ok {
 			return -1, err
 		}
 	}
+	log.Printf("process ended")
 	return command.ProcessState.Sys().(syscall.WaitStatus).ExitStatus(), nil
 }
 
@@ -126,17 +139,22 @@ func sendVethName(pipe io.Writer, name string) {
 // Then will with set the other side of the veth pair into the container's namespaced
 // using the pid and returns the veth's interface name to provide to the container to
 // finish setting up the interface inside the namespace
-func initializeContainerVeth(bridge string, nspid int) (string, error) {
+func initializeContainerVeth(bridge string, mtu, nspid int) (string, error) {
 	name1, name2, err := createVethPair()
 	if err != nil {
 		return "", err
 	}
+	log.Printf("veth pair created %s <> %s", name1, name2)
 	if err := network.SetInterfaceMaster(name1, bridge); err != nil {
 		return "", err
 	}
+	if err := network.SetMtu(name1, mtu); err != nil {
+		return "", err
+	}
 	if err := network.InterfaceUp(name1); err != nil {
 		return "", err
 	}
+	log.Printf("setting %s inside %d namespace", name2, nspid)
 	if err := network.SetInterfaceInNamespacePid(name2, nspid); err != nil {
 		return "", err
 	}
@@ -200,8 +218,13 @@ func deletePidFile() error {
 // createCommand will return an exec.Cmd with the Cloneflags set to the proper namespaces
 // defined on the container's configuration and use the current binary as the init with the
 // args provided
-func createCommand(container *libcontainer.Container, console string, pipe uintptr, args []string) *exec.Cmd {
+func createCommand(container *libcontainer.Container, console, logFile string, pipe uintptr, args []string) *exec.Cmd {
-	command := exec.Command("nsinit", append([]string{"-console", console, "-pipe", fmt.Sprint(pipe), "init"}, args...)...)
+	command := exec.Command("nsinit", append([]string{
+		"-console", console,
+		"-pipe", fmt.Sprint(pipe),
+		"-log", logFile,
+		"init"}, args...)...)
+
 	command.SysProcAttr = &syscall.SysProcAttr{
 		Cloneflags: uintptr(getNamespaceFlags(container.Namespaces)),
 	}

libcontainer/nsinit/init.go

@@ -10,6 +10,7 @@ import (
 	"github.com/dotcloud/docker/pkg/system"
 	"io"
 	"io/ioutil"
+	"log"
 	"os"
 	"path/filepath"
 	"syscall"
@@ -17,19 +18,23 @@ import (
 
 // Init is the init process that first runs inside a new namespace to setup mounts, users, networking,
 // and other options required for the new container.
-func Init(container *libcontainer.Container, console string, pipe io.ReadCloser, args []string) error {
+func Init(container *libcontainer.Container, uncleanRootfs, console string, pipe io.ReadCloser, args []string) error {
-	rootfs, err := resolveRootfs()
+	rootfs, err := resolveRootfs(uncleanRootfs)
 	if err != nil {
 		return err
 	}
+	log.Printf("initializing namespace at %s", rootfs)
 
 	// We always read this as it is a way to sync with the parent as well
 	tempVethName, err := getVethName(pipe)
 	if err != nil {
 		return err
 	}
-
+	if tempVethName != "" {
+		log.Printf("received veth name %s", tempVethName)
+	}
 	if console != "" {
+		log.Printf("setting up console for %s", console)
 		// close pipes so that we can replace it with the pty
 		os.Stdin.Close()
 		os.Stdout.Close()
@@ -42,7 +47,6 @@ func Init(container *libcontainer.Container, console string, pipe io.ReadCloser,
 			return fmt.Errorf("dup2 slave %s", err)
 		}
 	}
-
 	if _, err := system.Setsid(); err != nil {
 		return fmt.Errorf("setsid %s", err)
 	}
@@ -63,9 +67,11 @@ func Init(container *libcontainer.Container, console string, pipe io.ReadCloser,
 	if err := system.Sethostname(container.Hostname); err != nil {
 		return fmt.Errorf("sethostname %s", err)
 	}
+	log.Printf("dropping capabilities")
 	if err := capabilities.DropCapabilities(container); err != nil {
 		return fmt.Errorf("drop capabilities %s", err)
 	}
+	log.Printf("setting user in namespace")
 	if err := setupUser(container); err != nil {
 		return fmt.Errorf("setup user %s", err)
 	}
@@ -74,6 +80,7 @@ func Init(container *libcontainer.Container, console string, pipe io.ReadCloser,
 			return fmt.Errorf("chdir to %s %s", container.WorkingDir, err)
 		}
 	}
+	log.Printf("execing %s goodbye", args[0])
 	if err := system.Exec(args[0], args[0:], container.Env); err != nil {
 		return fmt.Errorf("exec %s", err)
 	}
@@ -82,12 +89,8 @@ func Init(container *libcontainer.Container, console string, pipe io.ReadCloser,
 
 // resolveRootfs ensures that the current working directory is
 // not a symlink and returns the absolute path to the rootfs
-func resolveRootfs() (string, error) {
+func resolveRootfs(uncleanRootfs string) (string, error) {
-	cwd, err := os.Getwd()
+	rootfs, err := filepath.Abs(uncleanRootfs)
-	if err != nil {
-		return "", err
-	}
-	rootfs, err := filepath.Abs(cwd)
 	if err != nil {
 		return "", err
 	}

libcontainer/nsinit/nsinit/main.go

@@ -6,6 +6,7 @@ import (
 	"flag"
 	"github.com/dotcloud/docker/pkg/libcontainer"
 	"github.com/dotcloud/docker/pkg/libcontainer/nsinit"
+	"io"
 	"io/ioutil"
 	"log"
 	"os"
@@ -15,6 +16,7 @@ import (
 var (
 	console string
 	pipeFd  int
+	logFile string
 )
 
 var (
@@ -24,22 +26,27 @@ var (
 
 func init() {
 	flag.StringVar(&console, "console", "", "console (pty slave) path")
+	flag.StringVar(&logFile, "log", "none", "log options (none, stderr, or a file path)")
 	flag.IntVar(&pipeFd, "pipe", 0, "sync pipe fd")
 
 	flag.Parse()
 }
 
 func main() {
+	if flag.NArg() < 1 {
+		log.Fatal(ErrWrongArguments)
+	}
 	container, err := loadContainer()
 	if err != nil {
 		log.Fatal(err)
 	}
-	if flag.NArg() < 1 {
+	if err := setupLogging(); err != nil {
-		log.Fatal(ErrWrongArguments)
+		log.Fatal(err)
 	}
-
 	switch flag.Arg(0) {
 	case "exec": // this is executed outside of the namespace in the cwd
+		log.SetPrefix("[nsinit exec] ")
+
 		var exitCode int
 		nspid, err := readPid()
 		if err != nil {
@@ -50,17 +57,22 @@ func main() {
 		if nspid > 0 {
 			exitCode, err = nsinit.ExecIn(container, nspid, flag.Args()[1:])
 		} else {
-			exitCode, err = nsinit.Exec(container, flag.Args()[1:])
+			exitCode, err = nsinit.Exec(container, logFile, flag.Args()[1:])
 		}
 		if err != nil {
 			log.Fatal(err)
 		}
 		os.Exit(exitCode)
 	case "init": // this is executed inside of the namespace to setup the container
+		log.SetPrefix("[nsinit init] ")
+		cwd, err := os.Getwd()
+		if err != nil {
+			log.Fatal(err)
+		}
 		if flag.NArg() < 2 {
 			log.Fatal(ErrWrongArguments)
 		}
-		if err := nsinit.Init(container, console, os.NewFile(uintptr(pipeFd), "pipe"), flag.Args()[1:]); err != nil {
+		if err := nsinit.Init(container, cwd, console, os.NewFile(uintptr(pipeFd), "pipe"), flag.Args()[1:]); err != nil {
 			log.Fatal(err)
 		}
 	default:
@@ -93,3 +105,20 @@ func readPid() (int, error) {
 	}
 	return pid, nil
 }
+
+func setupLogging() (err error) {
+	var writer io.Writer
+	switch logFile {
+	case "stderr":
+		writer = os.Stderr
+	case "none", "":
+		writer = ioutil.Discard
+	default:
+		writer, err = os.OpenFile(logFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0755)
+		if err != nil {
+			return err
+		}
+	}
+	log.SetOutput(writer)
+	return nil
+}