Merge pull request #4645 from crosbymichael/add-logger

Add logger to libcontainer

execdriver/native/driver.go

@@ -9,7 +9,9 @@ import (
 	"github.com/dotcloud/docker/pkg/libcontainer/apparmor"
 	"github.com/dotcloud/docker/pkg/libcontainer/nsinit"
 	"github.com/dotcloud/docker/pkg/system"
+	"io"
 	"io/ioutil"
+	"log"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -27,7 +29,7 @@ func init() {
 	execdriver.RegisterInitFunc(DriverName, func(args *execdriver.InitArgs) error {
 		var (
 			container *libcontainer.Container
-			ns        = nsinit.NewNsInit(&nsinit.DefaultCommandFactory{}, &nsinit.DefaultStateWriter{args.Root})
+			ns        = nsinit.NewNsInit(&nsinit.DefaultCommandFactory{}, &nsinit.DefaultStateWriter{args.Root}, createLogger(""))
 		)
 		f, err := os.Open(filepath.Join(args.Root, "container.json"))
 		if err != nil {
@@ -85,7 +87,7 @@ func (d *driver) Run(c *execdriver.Command, pipes *execdriver.Pipes, startCallba
 			c:        c,
 			dsw:      &nsinit.DefaultStateWriter{filepath.Join(d.root, c.ID)},
 		}
-		ns   = nsinit.NewNsInit(factory, stateWriter)
+		ns   = nsinit.NewNsInit(factory, stateWriter, createLogger(os.Getenv("DEBUG")))
 		args = append([]string{c.Entrypoint}, c.Arguments...)
 	)
 	if err := d.createContainerRoot(c.ID); err != nil {
@@ -251,3 +253,14 @@ func (d *dockerStateWriter) WritePid(pid int) error {
 func (d *dockerStateWriter) DeletePid() error {
 	return d.dsw.DeletePid()
 }
+
+func createLogger(debug string) *log.Logger {
+	var w io.Writer
+	// if we are in debug mode set the logger to stderr
+	if debug != "" {
+		w = os.Stderr
+	} else {
+		w = ioutil.Discard
+	}
+	return log.New(w, "[libcontainer] ", log.LstdFlags)
+}

pkg/libcontainer/nsinit/exec.go

@@ -26,8 +26,10 @@ func (ns *linuxNs) Exec(container *libcontainer.Container, term Terminal, args [
 	if err != nil {
 		return -1, err
 	}
+	ns.logger.Printf("created sync pipe parent fd %d child fd %d\n", syncPipe.parent.Fd(), syncPipe.child.Fd())
 
 	if container.Tty {
+		ns.logger.Println("creating master and console")
 		master, console, err = system.CreateMasterAndConsole()
 		if err != nil {
 			return -1, err
@@ -36,31 +38,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 +80,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 {

pkg/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

pkg/libcontainer/nsinit/init.go

@@ -24,14 +24,17 @@ func (ns *linuxNs) Init(container *libcontainer.Container, uncleanRootfs, consol
 	}
 
 	// We always read this as it is a way to sync with the parent as well
+	ns.logger.Printf("reading from sync pipe fd %d\n", syncPipe.child.Fd())
 	context, err := syncPipe.ReadFromParent()
 	if err != nil {
 		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)
@@ -53,6 +56,7 @@ func (ns *linuxNs) Init(container *libcontainer.Container, uncleanRootfs, consol
 	if err := system.ParentDeathSignal(uintptr(syscall.SIGTERM)); 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)
 	}
@@ -66,9 +70,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 {
-		return err
+	if profile := container.Context["apparmor_profile"]; profile != "" {
+		ns.logger.Printf("setting apparmor profile %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)
 }
 

pkg/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,
 	}
 }

pkg/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
-	pipeFd        int
+	root, console, logs string
+	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) {
-	return nsinit.NewNsInit(&nsinit.DefaultCommandFactory{root}, &nsinit.DefaultStateWriter{root}), nil
+func newNsInit(l *log.Logger) (nsinit.NsInit, error) {
+	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
 }