Add initial logging to libcontainer

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

libcontainer/nsinit/command.go

@@ -1,6 +1,7 @@
 package nsinit
 
 import (
+	"fmt"
 	"github.com/dotcloud/docker/pkg/libcontainer"
 	"github.com/dotcloud/docker/pkg/system"
 	"os"
@@ -25,7 +26,7 @@ func (c *DefaultCommandFactory) Create(container *libcontainer.Container, consol
 	// get our binary name from arg0 so we can always reexec ourself
 	command := exec.Command(os.Args[0], append([]string{
 		"-console", console,
-		"-pipe", "3",
+		"-pipe", fmt.Sprint(pipe.Fd()),
 		"-root", c.Root,
 		"init"}, args...)...)
 

libcontainer/nsinit/exec.go

@@ -28,6 +28,7 @@ func (ns *linuxNs) Exec(container *libcontainer.Container, term Terminal, args [
 	}
 
 	if container.Tty {
+		ns.logger.Println("creating master and console")
 		master, console, err = system.CreateMasterAndConsole()
 		if err != nil {
 			return -1, err
@@ -36,31 +37,40 @@ func (ns *linuxNs) Exec(container *libcontainer.Container, term Terminal, args [
 	}
 
 	command := ns.commandFactory.Create(container, console, syncPipe.child, args)
+	ns.logger.Println("attach terminal to command")
 	if err := term.Attach(command); err != nil {
 		return -1, err
 	}
 	defer term.Close()
 
+	ns.logger.Println("starting command")
 	if err := command.Start(); err != nil {
 		return -1, err
 	}
+	ns.logger.Printf("writting pid %d to file\n", command.Process.Pid)
 	if err := ns.stateWriter.WritePid(command.Process.Pid); err != nil {
 		command.Process.Kill()
 		return -1, err
 	}
-	defer ns.stateWriter.DeletePid()
+	defer func() {
+		ns.logger.Println("removing pid file")
+		ns.stateWriter.DeletePid()
+	}()
 
 	// Do this before syncing with child so that no children
 	// can escape the cgroup
+	ns.logger.Println("setting cgroups")
 	if err := ns.SetupCgroups(container, command.Process.Pid); err != nil {
 		command.Process.Kill()
 		return -1, err
 	}
+	ns.logger.Println("setting up network")
 	if err := ns.InitializeNetworking(container, command.Process.Pid, syncPipe); err != nil {
 		command.Process.Kill()
 		return -1, err
 	}
 
+	ns.logger.Println("closing sync pipe with child")
 	// Sync with child
 	syncPipe.Close()
 
@@ -69,7 +79,9 @@ func (ns *linuxNs) Exec(container *libcontainer.Container, term Terminal, args [
 			return -1, err
 		}
 	}
-	return command.ProcessState.Sys().(syscall.WaitStatus).ExitStatus(), nil
+	status := command.ProcessState.Sys().(syscall.WaitStatus).ExitStatus()
+	ns.logger.Printf("process exited with status %d\n", status)
+	return status, err
 }
 
 func (ns *linuxNs) SetupCgroups(container *libcontainer.Container, nspid int) error {

libcontainer/nsinit/execin.go

@@ -14,6 +14,7 @@ import (
 
 // ExecIn uses an existing pid and joins the pid's namespaces with the new command.
 func (ns *linuxNs) ExecIn(container *libcontainer.Container, nspid int, args []string) (int, error) {
+	ns.logger.Println("unshare namespaces")
 	for _, ns := range container.Namespaces {
 		if err := system.Unshare(ns.Value); err != nil {
 			return -1, err
@@ -33,6 +34,7 @@ func (ns *linuxNs) ExecIn(container *libcontainer.Container, nspid int, args []s
 	// foreach namespace fd, use setns to join an existing container's namespaces
 	for _, fd := range fds {
 		if fd > 0 {
+			ns.logger.Printf("setns on %d\n", fd)
 			if err := system.Setns(fd, 0); err != nil {
 				closeFds()
 				return -1, fmt.Errorf("setns %s", err)
@@ -44,6 +46,7 @@ func (ns *linuxNs) ExecIn(container *libcontainer.Container, nspid int, args []s
 	// if the container has a new pid and mount namespace we need to
 	// remount proc and sys to pick up the changes
 	if container.Namespaces.Contains("NEWNS") && container.Namespaces.Contains("NEWPID") {
+		ns.logger.Println("forking to remount /proc and /sys")
 		pid, err := system.Fork()
 		if err != nil {
 			return -1, err

libcontainer/nsinit/init.go

@@ -29,9 +29,11 @@ func (ns *linuxNs) Init(container *libcontainer.Container, uncleanRootfs, consol
 		syncPipe.Close()
 		return err
 	}
+	ns.logger.Println("received context from parent")
 	syncPipe.Close()
 
 	if console != "" {
+		ns.logger.Printf("setting up %s as console\n", console)
 		slave, err := system.OpenTerminal(console, syscall.O_RDWR)
 		if err != nil {
 			return fmt.Errorf("open terminal %s", err)
@@ -51,6 +53,7 @@ func (ns *linuxNs) Init(container *libcontainer.Container, uncleanRootfs, consol
 	if err := system.ParentDeathSignal(); err != nil {
 		return fmt.Errorf("parent death signal %s", err)
 	}
+	ns.logger.Println("setup mount namespace")
 	if err := setupNewMountNamespace(rootfs, container.Mounts, console, container.ReadonlyFs, container.NoPivotRoot); err != nil {
 		return fmt.Errorf("setup mount namespace %s", err)
 	}
@@ -64,9 +67,13 @@ func (ns *linuxNs) Init(container *libcontainer.Container, uncleanRootfs, consol
 		return fmt.Errorf("finalize namespace %s", err)
 	}
 
-	if err := apparmor.ApplyProfile(os.Getpid(), container.Context["apparmor_profile"]); err != nil {
+	if profile := container.Context["apparmor_profile"]; profile != "" {
-		return err
+		ns.logger.Printf("setting apparmor prifile %s\n", profile)
+		if err := apparmor.ApplyProfile(os.Getpid(), profile); err != nil {
+			return err
+		}
 	}
+	ns.logger.Printf("execing %s\n", args[0])
 	return system.Execv(args[0], args[0:], container.Env)
 }
 

libcontainer/nsinit/nsinit.go

@@ -2,6 +2,7 @@ package nsinit
 
 import (
 	"github.com/dotcloud/docker/pkg/libcontainer"
+	"log"
 )
 
 // NsInit is an interface with the public facing methods to provide high level
@@ -16,11 +17,13 @@ type linuxNs struct {
 	root           string
 	commandFactory CommandFactory
 	stateWriter    StateWriter
+	logger         *log.Logger
 }
 
-func NewNsInit(command CommandFactory, state StateWriter) NsInit {
+func NewNsInit(command CommandFactory, state StateWriter, logger *log.Logger) NsInit {
 	return &linuxNs{
 		commandFactory: command,
 		stateWriter:    state,
+		logger:         logger,
 	}
 }

libcontainer/nsinit/nsinit/main.go

@@ -5,6 +5,7 @@ import (
 	"flag"
 	"github.com/dotcloud/docker/pkg/libcontainer"
 	"github.com/dotcloud/docker/pkg/libcontainer/nsinit"
+	"io"
 	"io/ioutil"
 	"log"
 	"os"
@@ -13,14 +14,15 @@ import (
 )
 
 var (
-	root, console string
+	root, console, logs string
-	pipeFd        int
+	pipeFd              int
 )
 
 func registerFlags() {
 	flag.StringVar(&console, "console", "", "console (pty slave) path")
 	flag.IntVar(&pipeFd, "pipe", 0, "sync pipe fd")
 	flag.StringVar(&root, "root", ".", "root for storing configuration data")
+	flag.StringVar(&logs, "log", "none", "set stderr or a filepath to enable logging")
 
 	flag.Parse()
 }
@@ -35,7 +37,12 @@ func main() {
 	if err != nil {
 		log.Fatalf("Unable to load container: %s", err)
 	}
-	ns, err := newNsInit()
+	l, err := getLogger("[exec] ")
+	if err != nil {
+		log.Fatal(err)
+	}
+
+	ns, err := newNsInit(l)
 	if err != nil {
 		log.Fatalf("Unable to initialize nsinit: %s", err)
 	}
@@ -46,7 +53,7 @@ func main() {
 		nspid, err := readPid()
 		if err != nil {
 			if !os.IsNotExist(err) {
-				log.Fatalf("Unable to read pid: %s", err)
+				l.Fatalf("Unable to read pid: %s", err)
 			}
 		}
 		if nspid > 0 {
@@ -56,26 +63,26 @@ func main() {
 			exitCode, err = ns.Exec(container, term, flag.Args()[1:])
 		}
 		if err != nil {
-			log.Fatalf("Failed to exec: %s", err)
+			l.Fatalf("Failed to exec: %s", err)
 		}
 		os.Exit(exitCode)
 	case "init": // this is executed inside of the namespace to setup the container
 		cwd, err := os.Getwd()
 		if err != nil {
-			log.Fatal(err)
+			l.Fatal(err)
 		}
 		if flag.NArg() < 2 {
-			log.Fatalf("wrong number of argments %d", flag.NArg())
+			l.Fatalf("wrong number of argments %d", flag.NArg())
 		}
 		syncPipe, err := nsinit.NewSyncPipeFromFd(0, uintptr(pipeFd))
 		if err != nil {
-			log.Fatalf("Unable to create sync pipe: %s", err)
+			l.Fatalf("Unable to create sync pipe: %s", err)
 		}
 		if err := ns.Init(container, cwd, console, syncPipe, flag.Args()[1:]); err != nil {
-			log.Fatalf("Unable to initialize for container: %s", err)
+			l.Fatalf("Unable to initialize for container: %s", err)
 		}
 	default:
-		log.Fatalf("command not supported for nsinit %s", flag.Arg(0))
+		l.Fatalf("command not supported for nsinit %s", flag.Arg(0))
 	}
 }
 
@@ -105,6 +112,23 @@ func readPid() (int, error) {
 	return pid, nil
 }
 
-func newNsInit() (nsinit.NsInit, error) {
+func newNsInit(l *log.Logger) (nsinit.NsInit, error) {
-	return nsinit.NewNsInit(&nsinit.DefaultCommandFactory{root}, &nsinit.DefaultStateWriter{root}), nil
+	return nsinit.NewNsInit(&nsinit.DefaultCommandFactory{root}, &nsinit.DefaultStateWriter{root}, l), nil
+}
+
+func getLogger(prefix string) (*log.Logger, error) {
+	var w io.Writer
+	switch logs {
+	case "", "none":
+		w = ioutil.Discard
+	case "stderr":
+		w = os.Stderr
+	default: // we have a filepath
+		f, err := os.OpenFile(logs, os.O_CREATE|os.O_RDWR|os.O_APPEND, 0755)
+		if err != nil {
+			return nil, err
+		}
+		w = f
+	}
+	return log.New(w, prefix, log.LstdFlags), nil
 }