Proposal: Unstructured (pretty) log output to stdout/stderr

[marccampbell]

Currently, when running ship init, the debug output is a somewhat difficult to grok. For example, when running ship init on an app (in debug mode), I see:

ts=2019-03-25T16:58:39.517145142Z caller=github.com/replicatedhq/ship/pkg/state/manager.go level=debug method=serializeConfig event=tryLoadState
ts=2019-03-25T16:58:39.517308598Z caller=github.com/replicatedhq/ship/pkg/state/manager.go level=debug event=state.resolve type=versioned
ts=2019-03-25T16:58:39.517349604Z caller=github.com/replicatedhq/ship/pkg/state/manager.go level=debug method=serializeAndWriteState stateFrom=file
ts=2019-03-25T16:58:39.517643845Z caller=github.com/replicatedhq/ship/pkg/lifecycle/daemon/routes_navcycle_config.go level=debug handler=finalizeAppConfig event=configSaved.send.complete
ts=2019-03-25T16:58:39.526662334Z caller=github.com/replicatedhq/ship/pkg/lifecycle/daemon/routes_navcycle_completestep.go level=debug handler=completeStep step=config event=call
ts=2019-03-25T16:58:39.526940332Z caller=github.com/replicatedhq/ship/pkg/state/manager.go level=debug event=state.resolve type=versioned
ts=2019-03-25T16:58:39.526994787Z caller=github.com/replicatedhq/ship/pkg/lifecycle/daemon/routes_navcycle.go level=debug method=getRequiredButIncompleteStepFor event=steps.notEmpty completed=map[message:true]
ts=2019-03-25T16:58:39.527075773Z caller=github.com/replicatedhq/ship/pkg/lifecycle/daemon/routes_navcycle_completestep.go level=debug method=execute event=step.resolve type=config
ts=2019-03-25T16:58:39.537321928Z caller=github.com/replicatedhq/ship/pkg/state/manager.go level=debug event=state.resolve type=versioned
ts=2019-03-25T16:58:39.537520276Z caller=github.com/replicatedhq/ship/pkg/state/manager.go level=debug event=state.resolve type=versioned

When something doesn't work properly, the Ship UI asks you to "look at .ship/debug.log" to diagnose. But this log format is hard to scan and hard to read without a decent understanding of the ship architecture and how it all should work.

The value of structured logging is great, and I don't propose removing it. I'd like to discuss changing the default log output to unstructured, human readable, possibly even color coded to be much more approachable. We should retain the structured log output in a way that can be used when running ship in a headless system such as CI and having a log aggregator pick up and centralize the logs, or when sending logs to for support. Ideally, stdout/err will show "pretty" logs, and structured logs will be stored on disk.

[dexhorthy]

It's still kind of rough super non-optimized, but I hacked together a prototype of how this might parse our structured logs and output them to console/file. This is more to guide discussion of "what do we want" than anything else.

[marccampbell]

Thanks for sharing that screenshot/prototype. I think it would helpful to figure out our goals with making a change like this, and use that to guide a solution.

Given a blank canvas, what would we like the output to look like, and what type of data should be included in it?

My hope with adding unstructured logs is to remove much of the ship internals from the logs that are used by a ship cluster operator to make ship more approachable to a non-developer. Logging function names as a trace through the application is incredibly useful when working on Ship, but makes Ship harder to debug when something isn't working properly for the cluster operator user. I don't want to remove the logs as they are today, but I'm suggesting that we instead work to simplify them. In the screenshot attached, there are info-level steps (i'll ignore the debug level for now) of:

"daemon.startonce.exit"
"shutdown"
"shutdown.prePause"
"shutdown.commence"
"shutdown.complete".

There's an argument to be made that these specific lines shouldn't be info-level, but they are, so I'm using them as the example. If there's another spot of the logging that makes more sense to discuss, let's attach some logs and take this same approach.

I think the relevant information for an operator (not a ship developer) is:

2019-03-27T01:01:40: Shutdown requested.
2019-03-27T01:01:40: Preparing to shutdown
2019-03-27T01:01:43: Ship is terminating. Shutdown took 3 seconds.

I'm suggesting a different approach -- not just a log formatter, but thinking through logging from a cluster operator perspective, and how can we make the logs more clear, in addition to prettier.

[dexhorthy]

I think that makes sense. I'd llike to avoid is having to go through every single info+ level log statement and write a separate 'log-nicely-stdout' command. I wonder if we could build some kind of map 'event -> message'. Not only does that feel like a the right abstraction to me, but it sets us up for i18n nicely.

messages := map[string]interface{}{
   "shutdown":          "Shutdown requested",
   "shutdown.complete": "Ship is terminating. Shutdown took 3 seconds.",
'
   // and even, for event=kustomizeYAML.write path=.ship/tmp/kustomize-prebuild.yaml

   "kustomizeYAML.write": "Writing Kustomize YAML to {{.path}}",
}

and so on

[dexhorthy]

I think you picked up on this -- the key thing architecturally is that if we focus on machine-readable, operable logging, we can build the formatting/templating on top of that easily, but going the other way would be trickier.

[dexhorthy]

Anyhow, prototype is up here. Disclaimer -- loaded with jank.

[dexhorthy]

@marccampbell should we consider removing timestamps in that case?