diff --git a/integration/init_app/integration_test.go b/integration/init_app/integration_test.go index e2879ebb8..23ddbb22a 100644 --- a/integration/init_app/integration_test.go +++ b/integration/init_app/integration_test.go @@ -21,6 +21,7 @@ import ( "github.com/replicatedhq/ship/pkg/logger" "github.com/spf13/viper" "gopkg.in/yaml.v2" + "github.com/spf13/afero" ) type TestMetadata struct { @@ -157,7 +158,10 @@ func createRelease( vendorClient := &e2e.GraphQLClient{ GQLServer: endpointURL, Token: vendorToken, - Logger: logger.FromViper(viper.GetViper()), + Logger: logger.New( + viper.GetViper(), + afero.Afero{Fs: afero.NewMemMapFs()}, + ), } releaseContents, err := ioutil.ReadFile(path.Join(testInputPath, ".ship/release.yml")) Expect(err).NotTo(HaveOccurred()) diff --git a/pkg/cli/devtoolreleaser/cmd.go b/pkg/cli/devtoolreleaser/cmd.go index b15334b0f..58a1c91a1 100644 --- a/pkg/cli/devtoolreleaser/cmd.go +++ b/pkg/cli/devtoolreleaser/cmd.go @@ -9,6 +9,7 @@ import ( "github.com/mitchellh/cli" "github.com/pkg/errors" + "github.com/replicatedhq/ship/pkg/fs" "github.com/replicatedhq/ship/pkg/logger" "github.com/spf13/cobra" "github.com/spf13/viper" @@ -26,7 +27,7 @@ func Cmd() *cobra.Command { releaser := &Releaser{ viper: vip, - logger: logger.FromViper(vip), + logger: logger.New(vip, fs.NewBaseFilesystem()), ui: &cli.ColoredUi{ OutputColor: cli.UiColorNone, ErrorColor: cli.UiColorRed, diff --git a/pkg/cli/root.go b/pkg/cli/root.go index a299dbd35..f2180568a 100644 --- a/pkg/cli/root.go +++ b/pkg/cli/root.go @@ -4,6 +4,7 @@ import ( "fmt" "os" + "github.com/hashicorp/go-multierror" "github.com/replicatedhq/ship/pkg/constants" "strings" @@ -36,7 +37,11 @@ func RootCmd() *cobra.Command { return os.MkdirAll(constants.ShipPathInternalTmp, 0755) }, PersistentPostRunE: func(cmd *cobra.Command, args []string) error { - return os.RemoveAll(constants.ShipPathInternalTmp) + var multiErr *multierror.Error + multiErr = multierror.Append(os.RemoveAll(constants.ShipPathInternalTmp)) + // if we got here, it means we finished successfully, so remove the internal debug log file + multiErr = multierror.Append(os.RemoveAll(constants.ShipPathInternalLog)) + return multiErr.ErrorOrNil() }, } cobra.OnInitialize(initConfig) diff --git a/pkg/constants/filepaths.go b/pkg/constants/filepaths.go index 21b855d48..bcaca3bfd 100644 --- a/pkg/constants/filepaths.go +++ b/pkg/constants/filepaths.go @@ -17,7 +17,9 @@ const ( var ( // ShipPathInternalTmp is a temporary folder that will get cleaned up on exit - ShipPathInternalTmp = path.Join(".ship", "tmp") + ShipPathInternalTmp = path.Join(ShipPathInternal, "tmp") + // ShipPathInternalTmp is a temporary folder that will get cleaned up on exit + ShipPathInternalLog = path.Join(ShipPathInternal, "debug.log") // InternalTempHelmHome is the path to a helm home directory InternalTempHelmHome = path.Join(ShipPathInternalTmp, ".helm") // StatePath is the default state file path diff --git a/pkg/images/save_test.go b/pkg/images/save_test.go index 5fe344ffc..2fb221e77 100644 --- a/pkg/images/save_test.go +++ b/pkg/images/save_test.go @@ -12,12 +12,9 @@ import ( mockimages "github.com/replicatedhq/ship/pkg/test-mocks/images" - "github.com/replicatedhq/ship/pkg/logger" - "github.com/spf13/viper" - "github.com/docker/docker/api/types" "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" + logger2 "github.com/replicatedhq/ship/pkg/testing/logger" ) func Test_buildDestinationParams(t *testing.T) { @@ -89,7 +86,7 @@ func TestCLISaver_pushImage(t *testing.T) { { name: "Success", fields: fields{ - Logger: log.With(level.Debug(logger.FromViper(viper.GetViper()))), + Logger: &logger2.TestLogger{T: t}, }, args: args{ ctx: context.Background(), diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index 44fe888a2..b160d1640 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -5,38 +5,68 @@ import ( golog "log" "os" - "sync" + "path" "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/level" "github.com/go-stack/stack" + "github.com/hashicorp/go-multierror" + "github.com/replicatedhq/ship/pkg/constants" + "github.com/spf13/afero" "github.com/spf13/viper" ) -var ( - fullPathCaller = pathCaller(3) - globalLogger log.Logger - logMtx sync.Mutex -) +type compositeLogger struct { + loggers []log.Logger +} + +func (c *compositeLogger) Log(keyvals ...interface{}) error { + var multiErr *multierror.Error + for _, logger := range c.loggers { + multiErr = multierror.Append(multiErr, logger.Log(keyvals...)) + } + return multiErr.ErrorOrNil() +} -// FromViper builds a logger from env using viper -func FromViper(v *viper.Viper) log.Logger { +// New builds a logger from env using viper +func New(v *viper.Viper, fs afero.Afero) log.Logger { - // one at a time plz - logMtx.Lock() - defer logMtx.Unlock() + fullPathCaller := pathCaller(3) + var stdoutLogger log.Logger + stdoutLogger = withFormat(viper.GetString("log-format")) + stdoutLogger = log.With(stdoutLogger, "ts", log.DefaultTimestampUTC) + stdoutLogger = log.With(stdoutLogger, "caller", fullPathCaller) + stdoutLogger = withLevel(stdoutLogger, v.GetString("log-level")) - if globalLogger != nil { - return globalLogger + debugLogFile := path.Join(constants.ShipPathInternalLog) + var debugLogger log.Logger + err := fs.RemoveAll(debugLogFile) + if err != nil { + level.Warn(stdoutLogger).Log("msg", "failed to remove existing debug log file", "path", debugLogFile, "error", err) + golog.SetOutput(log.NewStdlibAdapter(level.Debug(stdoutLogger))) + return stdoutLogger + } + debugLogWriter, err := fs.Create(debugLogFile) + if err != nil { + level.Warn(stdoutLogger).Log("msg", "failed to initialize debug log file", "path", debugLogFile, "error", err) + golog.SetOutput(log.NewStdlibAdapter(level.Debug(stdoutLogger))) + return stdoutLogger } - globalLogger = withFormat(viper.GetString("log-format")) - globalLogger = log.With(globalLogger, "ts", log.DefaultTimestampUTC) - globalLogger = withLevel(globalLogger, v.GetString("log-level")) - globalLogger = log.With(globalLogger, "caller", fullPathCaller) - golog.SetOutput(log.NewStdlibAdapter(level.Debug(globalLogger))) + debugLogger = log.NewJSONLogger(debugLogWriter) + debugLogger = log.With(debugLogger, "ts", log.DefaultTimestampUTC) + debugLogger = log.With(debugLogger, "caller", fullPathCaller) + debugLogger = withLevel(debugLogger, "debug") + + realLogger := &compositeLogger{ + loggers: []log.Logger{ + stdoutLogger, + debugLogger, + }, + } - return globalLogger + golog.SetOutput(log.NewStdlibAdapter(level.Debug(realLogger))) + return realLogger } func withFormat(format string) log.Logger { diff --git a/pkg/ship/dig.go b/pkg/ship/dig.go index e520dee29..22807537c 100644 --- a/pkg/ship/dig.go +++ b/pkg/ship/dig.go @@ -55,7 +55,7 @@ func buildInjector(v *viper.Viper) (*dig.Container, error) { provide(v), clock, - logger.FromViper, + logger.New, ui.FromViper, fs.NewBaseFilesystem, daemon.WebUIFactoryFactory, @@ -198,7 +198,7 @@ func navcycleProviders() []interface{} { func Get(v *viper.Viper) (*Ship, error) { // who injects the injectors? - debug := log.With(level.Debug(logger.FromViper(v)), "component", "injector", "phase", "instance.get") + debug := log.With(level.Debug(logger.New(v, fs.NewBaseFilesystem())), "component", "injector", "phase", "instance.get") debug.Log("event", "injector.build") injector, err := buildInjector(v) diff --git a/pkg/ship/exit.go b/pkg/ship/exit.go new file mode 100644 index 000000000..73e25a855 --- /dev/null +++ b/pkg/ship/exit.go @@ -0,0 +1,58 @@ +package ship + +import ( + "fmt" + "os" + "path" + "time" + + "github.com/go-kit/kit/log/level" + "github.com/replicatedhq/ship/pkg/constants" +) + +// ExitWithError can be called if something goes wrong to print some friendly output +func (s *Ship) ExitWithError(err error) { + s.printAndLogError(err, s.UI.Error) + time.Sleep(100 * time.Millisecond) // hack, need to wait for flush output from above + s.preserveDebugLogsOrRequestReRun() + + // we want to avoid exiting in certain integration testing scenarios + if !s.Viper.GetBool("no-os-exit") { + os.Exit(1) + } +} + +// ExitWithWarn can be called if something goes wrong to print some friendly output +func (s *Ship) ExitWithWarn(err error) { + s.printAndLogError(err, s.UI.Warn) + os.Exit(1) +} + +func (s *Ship) printAndLogError(err error, uiOutput func(string)) { + if s.Viper.GetString("log-level") == "debug" { + uiOutput(fmt.Sprintf("There was an unexpected error! %+v", err)) + } else { + uiOutput(fmt.Sprintf("There was an unexpected error! %v", err)) + } + level.Warn(s.Logger).Log("event", "exit.withErr", "errorWithStack", fmt.Sprintf("%+v", err)) + s.UI.Output("") +} + +func (s *Ship) preserveDebugLogsOrRequestReRun() { + debugLogFile := path.Join(constants.ShipPathInternalLog) + // make sure it exists + if exists, err := s.FS.Exists(debugLogFile); err != nil || !exists { + s.UI.Info( + "There was an error configuring the application. " + + "Please re-run with --log-level=debug and include " + + "the output in any support inquiries.", + ) + } else { + s.UI.Info(fmt.Sprintf( + "There was an error configuring the application. "+ + "A debug log has been written to %q, please include it "+ + "in any support inquiries.", + debugLogFile), + ) + } +} diff --git a/pkg/ship/ship.go b/pkg/ship/ship.go index e14668405..95e3be113 100644 --- a/pkg/ship/ship.go +++ b/pkg/ship/ship.go @@ -4,13 +4,12 @@ import ( "context" "fmt" "os" + "os/signal" + "syscall" "time" "github.com/replicatedhq/ship/pkg/helpers/flags" - "os/signal" - "syscall" - "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/level" "github.com/mitchellh/cli" @@ -92,7 +91,9 @@ func NewShip( } func (s *Ship) Shutdown(cancelFunc context.CancelFunc) { + // remove the temp dir -- if we're exiting with an error, then cobra wont get a chance to clean up s.FS.RemoveAll(constants.ShipPathInternalTmp) + // need to pause beforce canceling the context, because we need // the daemon to stay up for a few seconds so the UI can know its // time to show the "You're all done" page @@ -206,37 +207,3 @@ func (s *Ship) execute(ctx context.Context, release *api.Release, selector *repl return result } } - -// ExitWithError should be called by the parent cobra commands if something goes wrong. -func (s *Ship) ExitWithError(err error) { - if s.Viper.GetString("log-level") == "debug" { - s.UI.Error(fmt.Sprintf("There was an unexpected error! %+v", err)) - } else { - s.UI.Error(fmt.Sprintf("There was an unexpected error! %v", err)) - } - s.UI.Output("") - - time.Sleep(100 * time.Millisecond) - - // TODO this should probably be part of lifecycle - s.UI.Info("There was an error configuring the application. Please re-run with --log-level=debug and include the output in any support inquiries.") - // we want to avoid exiting in certain integration testing scenarios - if !s.Viper.GetBool("no-os-exit") { - os.Exit(1) - } -} - -func (s *Ship) ExitWithWarn(err error) { - if s.Viper.GetString("log-level") == "debug" { - s.UI.Warn(fmt.Sprintf("%+v", err)) - } else { - s.UI.Warn(fmt.Sprintf("%v", err)) - } - s.UI.Output("") - - time.Sleep(100 * time.Millisecond) - - // TODO this should probably be part of lifecycle - s.UI.Info("There was an error configuring the application. Please re-run with --log-level=debug and include the output in any support inquiries.") - os.Exit(1) -}