Ship should generate a debug log file on every run

What I Did
------------

Cause ship to generate a debug log file on every run, and preserve it in case of failures. (Resolves #400)

```
$ ship init not-a-chart
Reading not-a-chart ...
Determining application type ...
There was an unexpected error! resolve release: determine type of not-a-chart: fetch chart with helm: : Non-absolute URLs should be in form of repo_name/path_to_chart, got: not-a-chart

There was an error configuring the application. A debug log has been written to ".ship/debug.log", please include it in any support inquiries.
```

```
$ cat .ship/debug.log | tail -n 3 | jq .
{
  "caller": "github.com/replicatedhq/ship/vendor/github.com/go-kit/kit/log/level/level.go",
  "event": "shutdown.commence",
  "level": "info",
  "ts": "2018-08-20T19:47:09.238656358Z",
  "waitTime": "1s"
}
{
  "caller": "github.com/replicatedhq/ship/vendor/github.com/go-kit/kit/log/level/level.go",
  "event": "shutdown.complete",
  "level": "info",
  "ts": "2018-08-20T19:47:10.312992803Z"
}
{
  "caller": "github.com/replicatedhq/ship/vendor/github.com/go-kit/kit/log/level/level.go",
  "errorWithStack": "Non-absolute URLs should be in form of repo_name/path_to_chart, got: not-a-chart\nfetch chart with helm: \ngithub.com/replicatedhq/ship/pkg/specs/apptype.(*inspector).DetermineApplicationType\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/specs/apptype/determine_type.go:106\ngithub.com/replicatedhq/ship/pkg/specs.(*Resolver).ResolveRelease\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/specs/interface.go:33\ngithub.com/replicatedhq/ship/pkg/ship.(*Ship).Init\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/ship/kustomize.go:169\ngithub.com/replicatedhq/ship/pkg/ship.(*Ship).InitAndMaybeExit\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/ship/kustomize.go:24\ngithub.com/replicatedhq/ship/pkg/cli.Init.func1\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/cli/init.go:32\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:698\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).ExecuteC\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:783\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).Execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:736\ngithub.com/replicatedhq/ship/pkg/cli.Execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/cli/root.go:82\nmain.main\n\t/Users/dex/go/src/github.com/replicatedhq/ship/cmd/ship/main.go:6\nruntime.main\n\t/Users/dex/homebrew/Cellar/go/1.10.3/libexec/src/runtime/proc.go:198\nruntime.goexit\n\t/Users/dex/homebrew/Cellar/go/1.10.3/libexec/src/runtime/asm_amd64.s:2361\ndetermine type of not-a-chart\ngithub.com/replicatedhq/ship/pkg/specs.(*Resolver).ResolveRelease\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/specs/interface.go:35\ngithub.com/replicatedhq/ship/pkg/ship.(*Ship).Init\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/ship/kustomize.go:169\ngithub.com/replicatedhq/ship/pkg/ship.(*Ship).InitAndMaybeExit\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/ship/kustomize.go:24\ngithub.com/replicatedhq/ship/pkg/cli.Init.func1\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/cli/init.go:32\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:698\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).ExecuteC\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:783\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).Execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:736\ngithub.com/replicatedhq/ship/pkg/cli.Execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/cli/root.go:82\nmain.main\n\t/Users/dex/go/src/github.com/replicatedhq/ship/cmd/ship/main.go:6\nruntime.main\n\t/Users/dex/homebrew/Cellar/go/1.10.3/libexec/src/runtime/proc.go:198\nruntime.goexit\n\t/Users/dex/homebrew/Cellar/go/1.10.3/libexec/src/runtime/asm_amd64.s:2361\nresolve release\ngithub.com/replicatedhq/ship/pkg/ship.(*Ship).Init\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/ship/kustomize.go:171\ngithub.com/replicatedhq/ship/pkg/ship.(*Ship).InitAndMaybeExit\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/ship/kustomize.go:24\ngithub.com/replicatedhq/ship/pkg/cli.Init.func1\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/cli/init.go:32\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:698\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).ExecuteC\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:783\ngithub.com/replicatedhq/ship/vendor/github.com/spf13/cobra.(*Command).Execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/vendor/github.com/spf13/cobra/command.go:736\ngithub.com/replicatedhq/ship/pkg/cli.Execute\n\t/Users/dex/go/src/github.com/replicatedhq/ship/pkg/cli/root.go:82\nmain.main\n\t/Users/dex/go/src/github.com/replicatedhq/ship/cmd/ship/main.go:6\nruntime.main\n\t/Users/dex/homebrew/Cellar/go/1.10.3/libexec/src/runtime/proc.go:198\nruntime.goexit\n\t/Users/dex/homebrew/Cellar/go/1.10.3/libexec/src/runtime/asm_amd64.s:2361",
  "event": "exit.withErr",
  "level": "warn",
  "ts": "2018-08-20T19:47:10.313454242Z"
}
```

How I Did it
------------

- add new type `compositeLogger` that implements `log.Logger` by forwarding down to any number of delegate loggers
- `logger.New()` tries to create a file at `.ship/debug.log`, and add a `debugLogger` that writes to that file at debug level, regardless of the configured `log-level`
- `logger.New()` returns a compositeLogger that combines the stdout and debug loggers. Fails silently if it can't open the file.
- `pkg/ship/exit.go` will now message about the location of the log file if we were able to create it, rather than requesting a re-run with `--log-level=debug`
- Cobra deletes `.ship/debug.log` on successful exit

Not directly related:

- move `ExitWithXXX` methods and their helpers into `pkg/ship/exit.go`

How to verify it
------------

Run `ship init not-a-chart`, see new messaging and inspect debug log. It looks nice when piped to `jq`:

```
cat .ship/debug.log | jq .
```

Description for the Changelog
------------

Ship will provide a debug log file on failures to aid in troubleshooting any issues.

![](https://upload.wikimedia.org/wikipedia/commons/thumb/7/75/New_Carissa_Shipwreck_%2823428021605%29.jpg/1920px-New_Carissa_Shipwreck_%2823428021605%29.jpg)

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())

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,

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)

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

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(),

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 {

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)

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),
+		)
+	}
+}

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)
-}