Redo logging so its a little more capable

Signed-off-by: Sven Dowideit <SvenDowideit@home.org.au>

cmd/systemdocker/system-docker.go

@@ -9,7 +9,8 @@ import (
 )
 
 func Main() {
-	log.InitLogger()
+	log.SetLevel(log.DebugLevel)
+
 	if os.Geteuid() != 0 {
 		log.Fatalf("%s: Need to be root", os.Args[0])
 	}
@@ -18,5 +19,5 @@ func Main() {
 		os.Setenv("DOCKER_HOST", config.SystemDockerHost)
 	}
 
-	docker.Main()
+	docker.RancherOSMain()
 }

config/disk.go

@@ -55,7 +55,15 @@ func loadRawConfig(dirPrefix string, full bool) map[interface{}]interface{} {
 }
 
 func LoadConfig() *CloudConfig {
-	return LoadConfigWithPrefix("")
+	cfg := LoadConfigWithPrefix("")
+
+	if cfg.Rancher.Debug {
+		log.SetDefaultLevel(log.DebugLevel)
+	} else {
+		log.SetDefaultLevel(log.InfoLevel)
+	}
+
+	return cfg
 }
 
 func LoadConfigWithPrefix(dirPrefix string) *CloudConfig {

init/init.go

@@ -94,8 +94,6 @@ func sysInit(c *config.CloudConfig) (*config.CloudConfig, error) {
 
 func MainInit() {
 	log.InitDeferedLogger()
-	log.Infof("MainInit() start")
-	defer log.Infof("MainInit() finish")
 
 	if err := RunInit(); err != nil {
 		log.Fatal(err)
@@ -231,14 +229,22 @@ func RunInit() error {
 	configFiles := make(map[string][]byte)
 
 	initFuncs := []config.CfgFuncData{
-		config.CfgFuncData{"preparefs", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
+		config.CfgFuncData{"preparefs", func(c *config.CloudConfig) (*config.CloudConfig, error) {
-			return cfg, dfs.PrepareFs(&mountConfig)
+			return c, dfs.PrepareFs(&mountConfig)
 		}},
-		config.CfgFuncData{"save init cmdline", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
+		config.CfgFuncData{"save init cmdline", func(c *config.CloudConfig) (*config.CloudConfig, error) {
 			// will this be passed to cloud-init-save?
 			cmdLineArgs := strings.Join(os.Args, " ")
 			config.SaveInitCmdline(cmdLineArgs)
 
+			cfg := config.LoadConfig()
+			log.Debugf("Cmdline debug = %s", cfg.Rancher.Debug)
+			if cfg.Rancher.Debug {
+				log.SetLevel(log.DebugLevel)
+			} else {
+				log.SetLevel(log.InfoLevel)
+			}
+
 			return cfg, nil
 		}},
 		config.CfgFuncData{"mount OEM", mountOem},
@@ -258,9 +264,10 @@ func RunInit() error {
 		}},
 		config.CfgFuncData{"load modules", loadModules},
 		config.CfgFuncData{"b2d env", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
-			if util.ResolveDevice("LABEL=B2D_STATE") != "" {
+			if dev := util.ResolveDevice("LABEL=B2D_STATE"); dev != "" {
 				boot2DockerEnvironment = true
 				cfg.Rancher.State.Dev = "LABEL=B2D_STATE"
+				log.Infof("boot2DockerEnvironment %s: %s", cfg.Rancher.State.Dev, dev)
 				return cfg, nil
 			}
 
@@ -277,6 +284,8 @@ func RunInit() error {
 						boot2DockerEnvironment = true
 						cfg.Rancher.State.Dev = "LABEL=B2D_STATE"
 						cfg.Rancher.State.Autoformat = []string{device}
+						log.Infof("boot2DockerEnvironment %s: Autoformat %s", cfg.Rancher.State.Dev, cfg.Rancher.State.Autoformat[0])
+
 						break
 					}
 				}
@@ -319,10 +328,7 @@ func RunInit() error {
 				log.Error(err)
 			}
 
-			// return any newly detected network config.
+			return config.LoadConfig(), nil
-			cfg = config.LoadConfig()
-
-			return cfg, nil
 		}},
 		config.CfgFuncData{"read cfg files", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
 			filesToCopy := []string{
@@ -355,6 +361,7 @@ func RunInit() error {
 		}},
 		config.CfgFuncData{"mount OEM2", mountOem},
 		config.CfgFuncData{"write cfg files", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
+			log.FsReady()
 			for name, content := range configFiles {
 				if err := os.MkdirAll(filepath.Dir(name), os.ModeDir|0700); err != nil {
 					log.Error(err)
@@ -372,11 +379,6 @@ func RunInit() error {
 
 			return cfg, nil
 		}},
-		config.CfgFuncData{"hypervisor tools", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
-			// Maybe we could set `rancher.hypervisor_service`, and defer this further?
-			enableHypervisorService(hypervisor)
-			return config.LoadConfig(), nil
-		}},
 		config.CfgFuncData{"b2d Env", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
 			if boot2DockerEnvironment {
 				if err := config.Set("rancher.state.dev", cfg.Rancher.State.Dev); err != nil {
@@ -389,6 +391,11 @@ func RunInit() error {
 
 			return config.LoadConfig(), nil
 		}},
+		config.CfgFuncData{"hypervisor tools", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
+			// Maybe we could set `rancher.hypervisor_service`, and defer this further?
+			enableHypervisorService(cfg, hypervisor)
+			return config.LoadConfig(), nil
+		}},
 		config.CfgFuncData{"preparefs2", func(cfg *config.CloudConfig) (*config.CloudConfig, error) {
 			return cfg, dfs.PrepareFs(&mountConfig)
 		}},
@@ -409,15 +416,15 @@ func RunInit() error {
 
 	launchConfig, args := getLaunchConfig(cfg, &cfg.Rancher.SystemDocker)
 	launchConfig.Fork = !cfg.Rancher.SystemDocker.Exec
+	//launchConfig.NoLog = true
 
 	log.Info("Launching System Docker")
 	_, err = dfs.LaunchDocker(launchConfig, config.SystemDockerBin, args...)
 	if err != nil {
+		log.Errorf("Error Launching System Docker: %s", err)
 		return err
 	}
-
+	// Code never gets here - rancher.system_docker.exec=true
-	log.Infof("RunInit() finished")
-	log.SyslogReady(true)
 
 	return pidOne()
 }
@@ -431,7 +438,7 @@ func checkHypervisor(cfg *config.CloudConfig) string {
 	return cpuid.CPU.HypervisorName
 }
 
-func enableHypervisorService(hypervisorName string) {
+func enableHypervisorService(cfg *config.CloudConfig, hypervisorName string) {
 	if hypervisorName == "" {
 		return
 	}
@@ -441,7 +448,6 @@ func enableHypervisorService(hypervisorName string) {
 	}
 	serviceName := hypervisorName + "-vm-tools"
 	// check quickly to see if there is a yml file available
-	cfg := config.LoadConfig()
 	if service.ValidService(serviceName, cfg) {
 		log.Infof("Setting rancher.services_include. %s=true", serviceName)
 		if err := config.Set("rancher.services_include."+serviceName, "true"); err != nil {

log/log.go

@@ -3,15 +3,16 @@ package log
 import (
 	"io"
 	"os"
+	"path/filepath"
 
-	"fmt"
+	"io/ioutil"
 
 	"github.com/Sirupsen/logrus"
 )
 
-// Default to using the logrus standard logger until log.InitLogger(logLevel) is called
-var appLog = logrus.StandardLogger()
 var userHook *ShowuserlogHook
+var defaultLogLevel logrus.Level
+var debugThisLogger = false
 
 type Fields logrus.Fields
 type Level logrus.Level
@@ -37,13 +38,15 @@ const (
 )
 
 func SetOutput(out io.Writer) {
-	appLog.Out = out
+	logrus.SetOutput(out)
+}
+func SetDefaultLevel(level Level) {
+	defaultLogLevel = logrus.Level(level)
 }
 func SetLevel(level Level) {
 	if userHook != nil {
 		userHook.Level = logrus.Level(level)
 	} else {
-		appLog.Level = logrus.Level(level)
 		logrus.SetLevel(logrus.Level(level))
 	}
 }
@@ -52,123 +55,160 @@ func GetLevel() Level {
 	if userHook != nil {
 		return Level(userHook.Level)
 	}
-	return Level(appLog.Level)
+	return Level(logrus.GetLevel())
 }
 
 func Debugf(format string, args ...interface{}) {
-	appLog.Debugf(format, args...)
+	logrus.Debugf(format, args...)
 }
 func Infof(format string, args ...interface{}) {
-	appLog.Infof(format, args...)
+	logrus.Infof(format, args...)
 }
 func Printf(format string, args ...interface{}) {
-	appLog.Printf(format, args...)
+	logrus.Printf(format, args...)
 }
 func Warnf(format string, args ...interface{}) {
-	appLog.Warnf(format, args...)
+	logrus.Warnf(format, args...)
 }
 func Warningf(format string, args ...interface{}) {
-	appLog.Warningf(format, args...)
+	logrus.Warningf(format, args...)
 }
 func Errorf(format string, args ...interface{}) {
-	appLog.Errorf(format, args...)
+	logrus.Errorf(format, args...)
 }
 func Fatalf(format string, args ...interface{}) {
-	appLog.Fatalf(format, args...)
+	logrus.Fatalf(format, args...)
 }
 func Panicf(format string, args ...interface{}) {
-	appLog.Panicf(format, args...)
+	logrus.Panicf(format, args...)
 }
 
 func Debug(args ...interface{}) {
-	appLog.Debug(args...)
+	logrus.Debug(args...)
 }
 func Info(args ...interface{}) {
-	appLog.Info(args...)
+	logrus.Info(args...)
 }
 func Print(args ...interface{}) {
-	appLog.Print(args...)
+	logrus.Print(args...)
 }
 func Warn(args ...interface{}) {
-	appLog.Warn(args...)
+	logrus.Warn(args...)
 }
 func Warning(args ...interface{}) {
-	appLog.Warning(args...)
+	logrus.Warning(args...)
 }
 func Error(args ...interface{}) {
-	appLog.Error(args...)
+	logrus.Error(args...)
 }
 func Fatal(args ...interface{}) {
-	appLog.Fatal(args...)
+	logrus.Fatal(args...)
 }
 func Panic(args ...interface{}) {
-	appLog.Panic(args...)
+	logrus.Panic(args...)
 }
 
 func WithField(key string, value interface{}) *logrus.Entry {
-	return appLog.WithField(key, value)
+	return logrus.WithField(key, value)
 }
 func WithFields(fields Fields) *logrus.Entry {
-	return appLog.WithFields(logrus.Fields(fields))
+	return logrus.WithFields(logrus.Fields(fields))
 }
 
 // InitLogger sets up Logging to log to /dev/kmsg and to Syslog
 func InitLogger() {
-	InitDeferedLogger()
+	if logTheseApps() {
-	SyslogReady(false)
+		innerInit(false)
-}
+		FsReady()
-
-// InitDeferedLogger sets up logging to /dev/kmsg and to an internal buffer
-// which is then written to Syslog when signaled by SyslogReady()
-func InitDeferedLogger() {
-	if userHook != nil {
-		return // we've already initialised it
-	}
-	thisLog := logrus.New()
-
-	// Filter what the user sees (info level, unless they set --debug)
-	stdLogger := logrus.StandardLogger()
-	showuserHook, err := NewShowuserlogHook(stdLogger.Level)
-	if err != nil {
-		logrus.Errorf("hook failure %s", err)
-		return
-	}
-
-	filename := "/dev/kmsg"
-	f, err := os.OpenFile(filename, os.O_WRONLY, 0644)
-	if err != nil {
-		logrus.Debugf("error opening %s: %s", filename, err)
-	} else {
-		// We're all set up, now we can make it global
-		appLog = thisLog
-		userHook = showuserHook
-
-		thisLog.Hooks.Add(showuserHook)
-		logrus.StandardLogger().Hooks.Add(showuserHook)
-
-		thisLog.Out = f
-		logrus.SetOutput(f)
-		thisLog.Level = logrus.DebugLevel
-	}
 
 		pwd, err := os.Getwd()
 		if err != nil {
-		thisLog.Error(err)
+			logrus.Error(err)
+		}
+		logrus.Debugf("START: %v in %s", os.Args, pwd)
+	}
 }
 
-	thisLog.Debugf("START: %v in %s", os.Args, pwd)
+func logTheseApps() bool {
+	// TODO: mmm, not very functional.
+	if filepath.Base(os.Args[0]) == "ros" ||
+		filepath.Base(os.Args[0]) == "host_ros" ||
+		filepath.Base(os.Args[0]) == "system-docker" {
+		return false
+	}
+	return true
 }
 
-// SyslogReady tells the storeing User hook to start writing to syslog
+// InitDeferedLogger stores the log messages until FsReady() is called
-func SyslogReady(logHook bool) error {
+// TODO: actually store them :)
+// TODO: need to work out how to pass entries from a binary run before we switchfs back to init and have it store and write it later
+func InitDeferedLogger() {
+	if logTheseApps() {
+		innerInit(true)
+		logrus.SetOutput(ioutil.Discard)
+
+		pwd, err := os.Getwd()
+		if err != nil {
+			logrus.Error(err)
+		}
+		logrus.Debugf("START: %v in %s", os.Args, pwd)
+	}
+}
+
+func innerInit(deferedHook bool) {
 	if userHook != nil {
-		if logHook {
+		return // we've already initialised it
-			Infof("------------info Starting defered Syslog Hook (%s)", os.Args[0])
+	}
-			fmt.Fprintf(appLog.Out, "------------ Starting defered Syslog Hook (%s) ----------------\n", os.Args[0])
+
+	// All logs go through the Hooks, and they choose what to do with them.
+	logrus.StandardLogger().Level = logrus.DebugLevel
+
+	if logTheseApps() {
+		AddUserHook(deferedHook)
+	}
+}
+
+func FsReady() {
+	filename := "/var/log/boot/" + filepath.Base(os.Args[0]) + ".log"
+	if err := os.MkdirAll(filepath.Dir(filename), os.ModeDir|0755); debugThisLogger && err != nil {
+		logrus.Errorf("FsReady mkdir(%s): %s", filename, err)
+	}
+	f, err := os.OpenFile(filename, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
+	if err != nil {
+		if debugThisLogger {
+			logrus.Errorf("FsReady opening %s: %s", filename, err)
+		}
 	} else {
-			fmt.Fprintf(appLog.Out, "------------ Starting Syslog Hook (%s) ----------------\n", os.Args[0])
+		if debugThisLogger {
+			logrus.Infof("Setting log output for %s to: %s", os.Args[0], filename)
 		}
-		return userHook.LogSystemReady()
+		logrus.SetOutput(f)
 	}
+}
+
+// AddUserHook is used to filter what log messages are written to the screen
+func AddUserHook(deferedHook bool) error {
+	if userHook != nil {
+		return nil
+	}
+
+	printLogLevel := logrus.InfoLevel
+
+	uh, err := NewShowuserlogHook(printLogLevel, filepath.Base(os.Args[0]))
+	if err != nil {
+		logrus.Errorf("error creating userHook(%s): %s", os.Args[0], err)
+		return err
+	}
+	userHook = uh
+	logrus.StandardLogger().Hooks.Add(uh)
+
+	if debugThisLogger {
+		if deferedHook {
+			logrus.Debugf("------------info Starting defered User Hook (%s)", os.Args[0])
+		} else {
+			logrus.Debugf("------------info Starting User Hook (%s)", os.Args[0])
+		}
+	}
+
 	return nil
 }

log/showuserlog.go

@@ -15,22 +15,23 @@ type ShowuserlogHook struct {
 	Level         logrus.Level
 	syslogHook    *logrus_syslog.SyslogHook
 	storedEntries []*logrus.Entry
+	appName       string
 }
 
 // NewShowuserlogHook creates a new hook for use
-func NewShowuserlogHook(l logrus.Level) (*ShowuserlogHook, error) {
+func NewShowuserlogHook(l logrus.Level, app string) (*ShowuserlogHook, error) {
-	return &ShowuserlogHook{l, nil, []*logrus.Entry{}}, nil
+	return &ShowuserlogHook{l, nil, []*logrus.Entry{}, app}, nil
 }
 
 // Fire is called by logrus when the Hook is active
 func (hook *ShowuserlogHook) Fire(entry *logrus.Entry) error {
-	line, err := entry.String()
-	if err != nil {
-		fmt.Fprintf(os.Stderr, "Unable to read entry, %v", err)
-		return err
-	}
 	if entry.Level <= hook.Level {
-		fmt.Printf("SVEN %s", line)
+		//if f, err := os.OpenFile("/dev/kmsg", os.O_WRONLY, 0644); err != nil {
+		//	fmt.Fprintf(f, "%s:%s: %s\n", hook.appName, entry.Level, entry.Message)
+		//	f.Close()
+		//} else {
+		fmt.Printf("[            ] %s:%s: %s\n", hook.appName, entry.Level, entry.Message)
+		//}
 	}
 
 	if hook.syslogHook == nil {
@@ -38,7 +39,7 @@ func (hook *ShowuserlogHook) Fire(entry *logrus.Entry) error {
 	} else {
 		err := hook.syslogHook.Fire(entry)
 		if err != nil {
-			fmt.Fprintf(os.Stderr, "LOGERR: Unable to write %s, %v", line, err)
+			fmt.Fprintf(os.Stderr, "LOGERR: Unable to syslog.Fire %v, %v", entry, err)
 			return err
 		}
 	}
@@ -59,7 +60,7 @@ func (hook *ShowuserlogHook) Levels() []logrus.Level {
 }
 
 // Set up Syslog Hook, and replay any stored entries.
-func (hook *ShowuserlogHook) LogSystemReady() error {
+func (hook *ShowuserlogHook) NotUsedYetLogSystemReady() error {
 	if hook.syslogHook == nil {
 		h, err := logrus_syslog.NewSyslogHook("", "", syslog.LOG_INFO, "")
 		if err != nil {

scripts/global.cfg

@@ -1,3 +1,2 @@
-#APPEND rancher.console=ttyS1 rancher.debug=true rancher.autologin=tty1 rancher.autologin=ttyS0 rancher.autologin=ttyS1 console=tty0 console=ttyS0 console=ttyS1 printk.devkmsg=on ${APPEND}
+APPEND rancher.autologin=tty1 rancher.autologin=ttyS0 rancher.autologin=ttyS1 console=tty1 console=ttyS0 printk.devkmsg=on ${APPEND}
-APPEND  rancher.console=ttyS1 rancher.debug=true rancher.autologin=tty1 rancher.autologin=ttyS0 rancher.autologin=ttyS1 console=tty0 console=ttyS0 printk.devkmsg=on ${APPEND}
 

vendor/github.com/docker/docker/docker/docker.go

@@ -7,10 +7,9 @@ import (
 	"github.com/Sirupsen/logrus"
 	"github.com/docker/docker/api/client"
 	"github.com/docker/docker/cli"
-	"github.com/docker/docker/dockerversion"
 	flag "github.com/docker/docker/pkg/mflag"
 	"github.com/docker/docker/pkg/term"
-	"github.com/docker/docker/utils"
+	"github.com/rancher/os/config"
 )
 
 func Main() {
@@ -68,10 +67,60 @@ func Main() {
 	}
 }
 
+// RancherOSMain lets us set the logger, instead of hardcoding it to Stderr
+func RancherOSMain() {
+	// Set terminal emulation based on platform as required.
+	stdin, stdout, stderr := term.StdStreams()
+
+	flag.Merge(flag.CommandLine, clientFlags.FlagSet, commonFlags.FlagSet)
+
+	flag.Usage = func() {
+		fmt.Fprint(stdout, "Usage: system-docker [OPTIONS] COMMAND [arg...]\n"+daemonUsage+"       docker [ --help | -v | --version ]\n\n")
+		fmt.Fprint(stdout, "A self-sufficient runtime for containers.\n\nOptions:\n")
+
+		flag.CommandLine.SetOutput(stdout)
+		flag.PrintDefaults()
+
+		help := "\nCommands:\n"
+
+		for _, cmd := range dockerCommands {
+			help += fmt.Sprintf("    %-10.10s%s\n", cmd.Name, cmd.Description)
+		}
+
+		help += "\nRun 'system-docker COMMAND --help' for more information on a command."
+		fmt.Fprintf(stdout, "%s\n", help)
+	}
+
+	flag.Parse()
+
+	if *flVersion {
+		showVersion()
+		return
+	}
+
+	if *flHelp {
+		// if global flag --help is present, regardless of what other options and commands there are,
+		// just print the usage.
+		flag.Usage()
+		return
+	}
+
+	clientCli := client.NewDockerCli(stdin, stdout, stderr, clientFlags)
+
+	c := cli.New(clientCli, daemonCli)
+	if err := c.Run(flag.Args()...); err != nil {
+		if sterr, ok := err.(cli.StatusError); ok {
+			if sterr.Status != "" {
+				fmt.Fprintln(stderr, sterr.Status)
+				os.Exit(1)
+			}
+			os.Exit(sterr.StatusCode)
+		}
+		fmt.Fprintln(stderr, err)
+		os.Exit(1)
+	}
+}
+
 func showVersion() {
-	if utils.ExperimentalBuild() {
+	fmt.Printf("RancherOS System-Docker version %s\n", config.Version)
-		fmt.Printf("Docker version %s, build %s, experimental\n", dockerversion.Version, dockerversion.GitCommit)
-	} else {
-		fmt.Printf("Docker version %s, build %s\n", dockerversion.Version, dockerversion.GitCommit)
-	}
 }