From 0ccc5ad735c4e60dec36f5501df9675f53a283e6 Mon Sep 17 00:00:00 2001 From: Sven Dowideit Date: Wed, 12 Jul 2017 23:58:38 +1000 Subject: [PATCH] Redo logging so its a little more capable Signed-off-by: Sven Dowideit --- cmd/systemdocker/system-docker.go | 5 +- config/disk.go | 10 +- init/init.go | 46 +++-- log/log.go | 178 +++++++++++------- log/showuserlog.go | 21 ++- scripts/global.cfg | 3 +- .../github.com/docker/docker/docker/docker.go | 63 ++++++- 7 files changed, 215 insertions(+), 111 deletions(-) diff --git a/cmd/systemdocker/system-docker.go b/cmd/systemdocker/system-docker.go index b9e9907a..5ef6a6e8 100644 --- a/cmd/systemdocker/system-docker.go +++ b/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() } diff --git a/config/disk.go b/config/disk.go index c1458267..31df5a7f 100755 --- a/config/disk.go +++ b/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 { diff --git a/init/init.go b/init/init.go index 682a3d6a..3b3444b3 100755 --- a/init/init.go +++ b/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) { - return cfg, dfs.PrepareFs(&mountConfig) + config.CfgFuncData{"preparefs", func(c *config.CloudConfig) (*config.CloudConfig, error) { + 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. - cfg = config.LoadConfig() - - return cfg, nil + return config.LoadConfig(), 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 } - - log.Infof("RunInit() finished") - log.SyslogReady(true) + // Code never gets here - rancher.system_docker.exec=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 { diff --git a/log/log.go b/log/log.go index a233d03c..dacea7d0 100755 --- a/log/log.go +++ b/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() - SyslogReady(false) + if logTheseApps() { + innerInit(false) + FsReady() + + pwd, err := os.Getwd() + if err != nil { + logrus.Error(err) + } + logrus.Debugf("START: %v in %s", os.Args, pwd) + } } -// InitDeferedLogger sets up logging to /dev/kmsg and to an internal buffer -// which is then written to Syslog when signaled by SyslogReady() +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 +} + +// InitDeferedLogger stores the log messages until FsReady() is called +// 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 { 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 + // All logs go through the Hooks, and they choose what to do with them. + logrus.StandardLogger().Level = logrus.DebugLevel + + if logTheseApps() { + AddUserHook(deferedHook) } - - 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) - } - - thisLog.Debugf("START: %v in %s", os.Args, pwd) } -// SyslogReady tells the storeing User hook to start writing to syslog -func SyslogReady(logHook bool) error { - if userHook != nil { - if logHook { - Infof("------------info Starting defered Syslog Hook (%s)", os.Args[0]) - fmt.Fprintf(appLog.Out, "------------ Starting defered Syslog Hook (%s) ----------------\n", os.Args[0]) - } else { - fmt.Fprintf(appLog.Out, "------------ Starting Syslog Hook (%s) ----------------\n", os.Args[0]) - } - return userHook.LogSystemReady() +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 { + if debugThisLogger { + logrus.Infof("Setting log output for %s to: %s", os.Args[0], filename) + } + 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 } diff --git a/log/showuserlog.go b/log/showuserlog.go index a2a09e1c..bb486e81 100644 --- a/log/showuserlog.go +++ b/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) { - return &ShowuserlogHook{l, nil, []*logrus.Entry{}}, nil +func NewShowuserlogHook(l logrus.Level, app string) (*ShowuserlogHook, error) { + 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 { diff --git a/scripts/global.cfg b/scripts/global.cfg index 8caf499c..a842995e 100755 --- a/scripts/global.cfg +++ b/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.console=ttyS1 rancher.debug=true rancher.autologin=tty1 rancher.autologin=ttyS0 rancher.autologin=ttyS1 console=tty0 console=ttyS0 printk.devkmsg=on ${APPEND} +APPEND rancher.autologin=tty1 rancher.autologin=ttyS0 rancher.autologin=ttyS1 console=tty1 console=ttyS0 printk.devkmsg=on ${APPEND} diff --git a/vendor/github.com/docker/docker/docker/docker.go b/vendor/github.com/docker/docker/docker/docker.go index cbb1e4cf..c66eeca1 100644 --- a/vendor/github.com/docker/docker/docker/docker.go +++ b/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() { } } -func showVersion() { - if utils.ExperimentalBuild() { - 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) +// 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() { + fmt.Printf("RancherOS System-Docker version %s\n", config.Version) +}