Improve logging for nsinit

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

libcontainer/network/veth.go

@@ -4,14 +4,12 @@ import (
 	"fmt"
 	"github.com/dotcloud/docker/pkg/libcontainer"
 	"github.com/dotcloud/docker/pkg/libcontainer/utils"
-	"log"
 )
 
 type Veth struct {
 }
 
 func (v *Veth) Create(n *libcontainer.Network, nspid int) (libcontainer.Context, error) {
-	log.Printf("creating veth network")
 	var (
 		bridge string
 		prefix string
@@ -31,7 +29,6 @@ func (v *Veth) Create(n *libcontainer.Network, nspid int) (libcontainer.Context,
 		"vethHost":  name1,
 		"vethChild": name2,
 	}
-	log.Printf("veth pair created %s <> %s", name1, name2)
 	if err := SetInterfaceMaster(name1, bridge); err != nil {
 		return context, err
 	}
@@ -41,7 +38,6 @@ func (v *Veth) Create(n *libcontainer.Network, nspid int) (libcontainer.Context,
 	if err := InterfaceUp(name1); err != nil {
 		return context, err
 	}
-	log.Printf("setting %s inside %d namespace", name2, nspid)
 	if err := SetInterfaceInNamespacePid(name2, nspid); err != nil {
 		return context, err
 	}

libcontainer/nsinit/exec.go

@@ -6,7 +6,6 @@ import (
 	"github.com/dotcloud/docker/pkg/libcontainer"
 	"github.com/dotcloud/docker/pkg/libcontainer/network"
 	"github.com/dotcloud/docker/pkg/system"
-	"log"
 	"os"
 	"os/exec"
 	"syscall"
@@ -14,9 +13,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,
+func (ns *linuxNs) Exec(container *libcontainer.Container, term Terminal, args []string) (int, error) {
-	factory CommandFactory, state StateWriter, term Terminal,
-	logFile string, args []string) (int, error) {
 	var (
 		master  *os.File
 		console string
@@ -31,7 +28,7 @@ func Exec(container *libcontainer.Container,
 	}
 
 	if container.Tty {
-		log.Printf("setting up master and console")
+		ns.logger.Printf("setting up master and console")
 		master, console, err = CreateMasterAndConsole()
 		if err != nil {
 			return -1, err
@@ -39,54 +36,56 @@ func Exec(container *libcontainer.Container,
 		term.SetMaster(master)
 	}
 
-	command := factory.Create(container, console, logFile, syncPipe.child.Fd(), args)
+	command := ns.commandFactory.Create(container, console, ns.logFile, syncPipe.child.Fd(), args)
 	if err := term.Attach(command); err != nil {
 		return -1, err
 	}
 	defer term.Close()
 
-	log.Printf("staring init")
+	ns.logger.Printf("staring init")
 	if err := command.Start(); err != nil {
 		return -1, err
 	}
-	log.Printf("writing state file")
+	ns.logger.Printf("writing state file")
-	if err := state.WritePid(command.Process.Pid); err != nil {
+	if err := ns.stateWriter.WritePid(command.Process.Pid); err != nil {
 		command.Process.Kill()
 		return -1, err
 	}
 	defer func() {
-		log.Printf("removing state file")
+		ns.logger.Printf("removing state file")
-		state.DeletePid()
+		ns.stateWriter.DeletePid()
 	}()
 
 	// Do this before syncing with child so that no children
 	// can escape the cgroup
-	if err := SetupCgroups(container, command.Process.Pid); err != nil {
+	if err := ns.SetupCgroups(container, command.Process.Pid); err != nil {
 		command.Process.Kill()
 		return -1, err
 	}
-	if err := InitializeNetworking(container, command.Process.Pid, syncPipe); err != nil {
+	if err := ns.InitializeNetworking(container, command.Process.Pid, syncPipe); err != nil {
 		command.Process.Kill()
 		return -1, err
 	}
 
 	// Sync with child
-	log.Printf("closing sync pipes")
+	ns.logger.Printf("closing sync pipes")
 	syncPipe.Close()
 
-	log.Printf("waiting on process")
+	ns.logger.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
+	exitCode := command.ProcessState.Sys().(syscall.WaitStatus).ExitStatus()
+	ns.logger.Printf("process ended with exit code %d", exitCode)
+	return exitCode, nil
 }
 
-func SetupCgroups(container *libcontainer.Container, nspid int) error {
+func (ns *linuxNs) SetupCgroups(container *libcontainer.Container, nspid int) error {
 	if container.Cgroups != nil {
-		log.Printf("setting up cgroups")
+		ns.logger.Printf("setting up cgroups")
 		if err := container.Cgroups.Apply(nspid); err != nil {
 			return err
 		}
@@ -94,9 +93,9 @@ func SetupCgroups(container *libcontainer.Container, nspid int) error {
 	return nil
 }
 
-func InitializeNetworking(container *libcontainer.Container, nspid int, pipe *SyncPipe) error {
+func (ns *linuxNs) InitializeNetworking(container *libcontainer.Container, nspid int, pipe *SyncPipe) error {
 	if container.Network != nil {
-		log.Printf("creating host network configuration type %s", container.Network.Type)
+		ns.logger.Printf("creating host network configuration type %s", container.Network.Type)
 		strategy, err := network.GetStrategy(container.Network.Type)
 		if err != nil {
 			return err
@@ -105,7 +104,7 @@ func InitializeNetworking(container *libcontainer.Container, nspid int, pipe *Sy
 		if err != nil {
 			return err
 		}
-		log.Printf("sending %v as network context", networkContext)
+		ns.logger.Printf("sending %v as network context", networkContext)
 		if err := pipe.SendToChild(networkContext); err != nil {
 			return err
 		}

libcontainer/nsinit/execin.go

@@ -12,7 +12,7 @@ import (
 )
 
 // ExecIn uses an existing pid and joins the pid's namespaces with the new command.
-func ExecIn(container *libcontainer.Container, nspid int, args []string) (int, error) {
+func (ns *linuxNs) ExecIn(container *libcontainer.Container, nspid int, args []string) (int, error) {
 	for _, ns := range container.Namespaces {
 		if err := system.Unshare(namespaceMap[ns]); err != nil {
 			return -1, err

libcontainer/nsinit/init.go

@@ -17,7 +17,7 @@ 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, uncleanRootfs, console string, syncPipe *SyncPipe, args []string) error {
+func (ns *linuxNs) Init(container *libcontainer.Container, uncleanRootfs, console string, syncPipe *SyncPipe, args []string) error {
 	rootfs, err := resolveRootfs(uncleanRootfs)
 	if err != nil {
 		return err

libcontainer/nsinit/nsinit.go

@@ -0,0 +1,29 @@
+package nsinit
+
+import (
+	"github.com/dotcloud/docker/pkg/libcontainer"
+	"log"
+)
+
+type NsInit interface {
+	Exec(container *libcontainer.Container, term Terminal, args []string) (int, error)
+	ExecIn(container *libcontainer.Container, nspid int, args []string) (int, error)
+	Init(container *libcontainer.Container, uncleanRootfs, console string, syncPipe *SyncPipe, args []string) error
+}
+
+type linuxNs struct {
+	root           string
+	logFile        string
+	logger         *log.Logger
+	commandFactory CommandFactory
+	stateWriter    StateWriter
+}
+
+func NewNsInit(logger *log.Logger, logFile string, command CommandFactory, state StateWriter) NsInit {
+	return &linuxNs{
+		logger:         logger,
+		commandFactory: command,
+		stateWriter:    state,
+		logFile:        logFile,
+	}
+}

libcontainer/nsinit/nsinit/main.go

@@ -42,13 +42,13 @@ func main() {
 	if err != nil {
 		log.Fatal(err)
 	}
-	if err := setupLogging(); err != nil {
+	ns, err := newNsInit()
+	if err != nil {
 		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 {
@@ -57,20 +57,16 @@ func main() {
 			}
 		}
 		if nspid > 0 {
-			exitCode, err = nsinit.ExecIn(container, nspid, flag.Args()[1:])
+			exitCode, err = ns.ExecIn(container, nspid, flag.Args()[1:])
 		} else {
 			term := nsinit.NewTerminal(os.Stdin, os.Stdout, os.Stderr, container.Tty)
-			exitCode, err = nsinit.Exec(container,
+			exitCode, err = ns.Exec(container, term, flag.Args()[1:])
-				&nsinit.DefaultCommandFactory{}, &nsinit.DefaultStateWriter{},
-				term,
-				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)
@@ -82,7 +78,7 @@ func main() {
 		if err != nil {
 			log.Fatal(err)
 		}
-		if err := nsinit.Init(container, cwd, console, syncPipe, flag.Args()[1:]); err != nil {
+		if err := ns.Init(container, cwd, console, syncPipe, flag.Args()[1:]); err != nil {
 			log.Fatal(err)
 		}
 	default:
@@ -116,19 +112,27 @@ func readPid() (int, error) {
 	return pid, nil
 }
 
-func setupLogging() (err error) {
+func newNsInit() (nsinit.NsInit, error) {
+	logger, err := setupLogging()
+	if err != nil {
+		return nil, err
+	}
+	return nsinit.NewNsInit(logger, logFile, &nsinit.DefaultCommandFactory{}, &nsinit.DefaultStateWriter{}), nil
+}
+
+func setupLogging() (logger *log.Logger, 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 writer, err = os.OpenFile(logFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0755); err != nil {
-		if err != nil {
+			return
-			return err
 		}
 	}
-	log.SetOutput(writer)
+	logger = log.New(writer, "", log.LstdFlags)
-	return nil
+	return
 }