maxmustermann/pulumi
1
0
Fork 0
Code Issues Pull requests Projects Releases Wiki Activity

Improve output formatting

Browse source 
This change improves our output formatting by generally adding
fewer prefixes.  As shown in pulumi/pulumi#359, we were being
excessively verbose in many places, including prefixing every
console.out with "langhost[nodejs].stdout: ", displaying full
stack traces for simple errors like missing configuration, etc.

Overall, this change includes the following:

* Don't prefix stdout and stderr output from the program, other
  than the standard "info:" prefix.  I experimented with various
  schemes here, but they all felt gratuitous.  Simply emitting
  the output seems fine, especially as it's closer to what would
  happen if you just ran the program under node.

* Do NOT make writes to stderr fail the plan/deploy.  Previously
  we assumed that any console.errors, for instance, meant that
  the overall program should fail.  This simply isn't how stderr
  is treated generally and meant you couldn't use certain
  logging techniques and libraries, among other things.

* Do make sure that stderr writes in the program end up going to
  stderr in the Pulumi CLI output, however, so that redirection
  works as it should.  This required a new Infoerr log level.

* Make a small fix to the planning logic so we don't attempt to
  print the summary if an error occurs.

* Finally, add a new error type, RunError, that when thrown and
  uncaught does not result in a full stack trace being printed.
  Anyone can use this, however, we currently use it for config
  errors so that we can terminate with a pretty error message,
  rather than the monstrosity shown in pulumi/pulumi#359.
This commit is contained in:
joeduffy 2017-09-23 05:20:11 -07:00
parent d275dec674
commit 141a112950
11 changed files with 112 additions and 46 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

38
pkg/diag/sink.go
View file

@ -24,8 +24,10 @@ type Sink interface {
Count() int
// Infos fetches the number of debug messages issued.
Debugs() int
// Infos fetches the number of informational messages issued.
// Infos fetches the number of stdout informational messages issued.
Infos() int
// Infos fetches the number of stderr informational messages issued.
Infoerrs() int
// Errors fetches the number of errors issued.
Errors() int
// Warnings fetches the number of warnings issued.
@ -37,8 +39,10 @@ type Sink interface {
Logf(sev Severity, diag *Diag, args ...interface{})
// Debugf issues a debugging message.
Debugf(diag *Diag, args ...interface{})
// Infof issues an informational message.
// Infof issues an informational message (to stdout).
Infof(diag *Diag, args ...interface{})
// Infoerrf issues an informational message (to stderr).
Infoerrf(diag *Diag, args ...interface{})
// Errorf issues a new error diagnostic.
Errorf(diag *Diag, args ...interface{})
// Warningf issues a new warning diagnostic.
@ -56,6 +60,7 @@ type Severity string
const (
Debug Severity = "debug"
Info Severity = "info"
Infoerr Severity = "info#err"
Warning Severity = "warning"
Error Severity = "error"
)
@ -71,25 +76,25 @@ type FormatOptions struct {
// DefaultSink returns a default sink that simply logs output to stderr/stdout.
func DefaultSink(opts FormatOptions) Sink {
debug := ioutil.Discard
// Default info to stdout if there's no override in the options.
stdout := io.Writer(os.Stdout)
stderr := io.Writer(os.Stderr)
if opts.Stdout != nil {
stdout = opts.Stdout
}
// Default info(err), error, warning to stderr if there's no override in the options.
stderr := io.Writer(os.Stderr)
if opts.Stderr != nil {
stderr = opts.Stderr
}
// Discard debug output by default unless requested.
debug := ioutil.Discard
if opts.Debug {
debug = stdout
}
return newDefaultSink(opts, map[Severity]io.Writer{
Debug: debug,
Info: stdout,
Infoerr: stderr,
Error: stderr,
Warning: stderr,
})
@ -98,6 +103,7 @@ func DefaultSink(opts FormatOptions) Sink {
func newDefaultSink(opts FormatOptions, writers map[Severity]io.Writer) *defaultSink {
contract.Assert(writers[Debug] != nil)
contract.Assert(writers[Info] != nil)
contract.Assert(writers[Infoerr] != nil)
contract.Assert(writers[Error] != nil)
contract.Assert(writers[Warning] != nil)
return &defaultSink{
@ -107,7 +113,7 @@ func newDefaultSink(opts FormatOptions, writers map[Severity]io.Writer) *default
}
}
const DefaultSinkIDPrefix = "LUMI"
const DefaultSinkIDPrefix = "PU"
// defaultSink is the default sink which logs output to stderr/stdout.
type defaultSink struct {
@ -121,6 +127,7 @@ type defaultSink struct {
func (d *defaultSink) Count() int { return d.Debugs() + d.Infos() + d.Errors() + d.Warnings() }
func (d *defaultSink) Debugs() int { return d.getCount(Debug) }
func (d *defaultSink) Infos() int { return d.getCount(Info) }
func (d *defaultSink) Infoerrs() int { return d.getCount(Infoerr) }
func (d *defaultSink) Errors() int { return d.getCount(Error) }
func (d *defaultSink) Warnings() int { return d.getCount(Warning) }
func (d *defaultSink) Success() bool { return d.Errors() == 0 }
@ -131,6 +138,8 @@ func (d *defaultSink) Logf(sev Severity, diag *Diag, args ...interface{}) {
d.Debugf(diag, args...)
case Info:
d.Infof(diag, args...)
case Infoerr:
d.Infoerrf(diag, args...)
case Warning:
d.Warningf(diag, args...)
case Error:
@ -160,6 +169,15 @@ func (d *defaultSink) Infof(diag *Diag, args ...interface{}) {
d.incrementCount(Info)
}
func (d *defaultSink) Infoerrf(diag *Diag, args ...interface{}) {
msg := d.Stringify(Info /* not Infoerr, just "info: "*/, diag, args...)
if glog.V(5) {
glog.V(5).Infof("defaultSink::Infoerr(%v)", msg[:len(msg)-1])
}
fmt.Fprintf(d.writers[Infoerr], msg)
d.incrementCount(Infoerr)
}
func (d *defaultSink) Errorf(diag *Diag, args ...interface{}) {
msg := d.Stringify(Error, diag, args...)
if glog.V(5) {
@ -209,7 +227,7 @@ func (d *defaultSink) Stringify(sev Severity, diag *Diag, args ...interface{}) s
switch sev {
case Debug:
buffer.WriteString(colors.SpecDebug)
case Info:
case Info, Infoerr:
buffer.WriteString(colors.SpecInfo)
case Error:
buffer.WriteString(colors.SpecError)

5
pkg/diag/sink_test.go
View file

@ -15,6 +15,7 @@ func discardSink() Sink {
return newDefaultSink(FormatOptions{}, map[Severity]io.Writer{
Debug: ioutil.Discard,
Info: ioutil.Discard,
Infoerr: ioutil.Discard,
Error: ioutil.Discard,
Warning: ioutil.Discard,
})
@ -30,10 +31,12 @@ func TestCounts(t *testing.T) {
for i := 0; i < numEach; i++ {
assert.Equal(t, sink.Debugs(), 0, "expected debugs pre to stay at zero")
assert.Equal(t, sink.Infos(), 0, "expected infos pre to stay at zero")
assert.Equal(t, sink.Infoerrs(), 0, "expected infoerrs pre to stay at zero")
assert.Equal(t, sink.Errors(), 0, "expected errors pre to stay at zero")
assert.Equal(t, sink.Warnings(), i, "expected warnings pre to be at iteration count")
sink.Warningf(&Diag{Message: "A test of the emergency warning system: %v."}, i)
assert.Equal(t, sink.Infos(), 0, "expected infos post to stay at zero")
assert.Equal(t, sink.Infoerrs(), 0, "expected infoerrs post to stay at zero")
assert.Equal(t, sink.Errors(), 0, "expected errors post to stay at zero")
assert.Equal(t, sink.Warnings(), i+1, "expected warnings post to be at iteration count+1")
}
@ -41,11 +44,13 @@ func TestCounts(t *testing.T) {
for i := 0; i < numEach; i++ {
assert.Equal(t, sink.Debugs(), 0, "expected debugs pre to stay at zero")
assert.Equal(t, sink.Infos(), 0, "expected infos pre to stay at zero")
assert.Equal(t, sink.Infoerrs(), 0, "expected infoerrs pre to stay at zero")
assert.Equal(t, sink.Errors(), i, "expected errors pre to be at iteration count")
assert.Equal(t, sink.Warnings(), numEach, "expected warnings pre to stay at numEach")
sink.Errorf(&Diag{Message: "A test of the emergency error system: %v."}, i)
assert.Equal(t, sink.Debugs(), 0, "expected deugs post to stay at zero")
assert.Equal(t, sink.Infos(), 0, "expected infos post to stay at zero")
assert.Equal(t, sink.Infoerrs(), 0, "expected infoerrs post to stay at zero")
assert.Equal(t, sink.Errors(), i+1, "expected errors post to be at iteration count+1")
assert.Equal(t, sink.Warnings(), numEach, "expected warnings post to stay at numEach")
}

16
pkg/engine/plan.go
View file

@ -63,11 +63,6 @@ func (eng *Engine) Plan(opts PlanOptions) error {
return err
}
}
if !eng.Diag().Success() {
// If any error occurred while walking the plan, be sure to let the developer know. Otherwise,
// although error messages may have spewed to the output, the final lines of the plan may look fine.
return errors.New("One or more errors occurred during the creation of this plan")
}
return nil
}
@ -170,6 +165,11 @@ func (eng *Engine) printPlan(result *planResult) error {
for step != nil {
var err error
// If any errors were emitted, stop planning.
if !eng.Diag().Success() {
break
}
// Perform the pre-step.
if err = step.Pre(); err != nil {
return errors.Errorf("An error occurred preparing the plan: %v", err)
@ -196,6 +196,12 @@ func (eng *Engine) printPlan(result *planResult) error {
}
}
if !eng.Diag().Success() {
// If any error occurred while walking the plan, be sure to let the developer know. Otherwise,
// although error messages may have spewed to the output, the final lines of the plan may look fine.
return errors.New("One or more errors occurred during the creation of this plan")
}
// Print a summary of operation counts.
printChangeSummary(&summary, counts, true)
fmt.Fprint(eng.Stdout, colors.Colorize(&summary))

2
pkg/resource/plugin/analyzer_plugin.go
View file

@ -28,7 +28,7 @@ type analyzer struct {
func NewAnalyzer(host Host, ctx *Context, name tokens.QName) (Analyzer, error) {
// Go ahead and attempt to load the plugin from the PATH.
srvexe := AnalyzerPluginPrefix + strings.Replace(string(name), tokens.QNameDelimiter, "_", -1)
plug, err := newPlugin(ctx, srvexe, fmt.Sprintf("analyzer[%v]", name), []string{host.ServerAddr()})
plug, err := newPlugin(ctx, srvexe, fmt.Sprintf("%v (analyzer)", name), []string{host.ServerAddr()})
if err != nil {
return nil, err
} else if plug == nil {

4
pkg/resource/plugin/langruntime_plugin.go
View file

@ -3,7 +3,6 @@
package plugin
import (
"fmt"
"strings"
"github.com/golang/glog"
@ -27,8 +26,7 @@ type langhost struct {
func NewLanguageRuntime(host Host, ctx *Context, runtime string, monitorAddr string) (LanguageRuntime, error) {
// Go ahead and attempt to load the plugin from the PATH.
srvexe := LanguagePluginPrefix + strings.Replace(runtime, tokens.QNameDelimiter, "_", -1)
plug, err := newPlugin(ctx, srvexe,
fmt.Sprintf("langhost[%v]", runtime), []string{monitorAddr, host.ServerAddr()})
plug, err := newPlugin(ctx, srvexe, "nodejs", []string{monitorAddr, host.ServerAddr()})
if err != nil {
return nil, err
} else if plug == nil {

24
pkg/resource/plugin/plugin.go
View file

@ -4,7 +4,6 @@ package plugin
import (
"bufio"
"fmt"
"io"
"os"
"os/exec"
@ -60,29 +59,24 @@ func newPlugin(ctx *Context, bin string, prefix string, args []string) (*plugin,
contract.Assert(plug != nil)
// For now, we will spawn goroutines that will spew STDOUT/STDERR to the relevant diag streams.
// TODO[pulumi/pulumi#143]: eventually we want real progress reporting, etc., out of band
// via RPC. This will be particularly important when we parallelize the application of the resource graph.
tracers := map[io.Reader]struct {
lbl string
cb func(string)
}{
plug.Stderr: {"stderr", func(line string) { ctx.Diag.Errorf(diag.Message("%s"), line) }},
plug.Stdout: {"stdout", func(line string) { ctx.Diag.Infof(diag.Message("%s"), line) }},
}
runtrace := func(t io.Reader) {
ts := tracers[t]
runtrace := func(t io.Reader, stderr bool) {
reader := bufio.NewReader(t)
for {
line, readerr := reader.ReadString('\n')
if readerr != nil {
break
}
ts.cb(fmt.Sprintf("%v.%v: %v", prefix, ts.lbl, line[:len(line)-1]))
msg := line[:len(line)-1]
if stderr {
ctx.Diag.Infoerrf(diag.Message("%s"), msg)
} else {
ctx.Diag.Infof(diag.Message("%s"), msg)
}
}
}
// Set up a tracer on stderr before going any further, since important errors might get communicated this way.
go runtrace(plug.Stderr)
go runtrace(plug.Stderr, true)
// Now that we have a process, we expect it to write a single line to STDOUT: the port it's listening on. We only
// read a byte at a time so that STDOUT contains everything after the first newline.
@ -113,7 +107,7 @@ func newPlugin(ctx *Context, bin string, prefix string, args []string) (*plugin,
}
// After reading the port number, set up a tracer on stdout just so other output doesn't disappear.
go runtrace(plug.Stdout)
go runtrace(plug.Stdout, false)
// Now that we have the port, go ahead and create a gRPC client connection to it.
conn, err := grpc.Dial(":"+port, grpc.WithInsecure())

2
pkg/resource/plugin/provider_plugin.go
View file

@ -30,7 +30,7 @@ type provider struct {
func NewProvider(host Host, ctx *Context, pkg tokens.Package) (Provider, error) {
// Go ahead and attempt to load the plugin from the PATH.
srvexe := ProviderPluginPrefix + strings.Replace(string(pkg), tokens.QNameDelimiter, "_", -1)
plug, err := newPlugin(ctx, srvexe, fmt.Sprintf("resource[%v]", pkg), []string{host.ServerAddr()})
plug, err := newPlugin(ctx, srvexe, fmt.Sprintf("%v (resource)", pkg), []string{host.ServerAddr()})
if err != nil {
return nil, err
} else if plug == nil {

14
sdk/nodejs/cmd/run/index.ts
View file

@ -4,6 +4,7 @@
import * as minimist from "minimist";
import * as path from "path";
import { RunError } from "../../errors";
import * as runtime from "../../runtime";
let grpc = require("grpc");
@ -131,9 +132,16 @@ export function main(args: string[]): void {
require(program);
}
catch (err) {
runtime.Log.debug(`Running program '${program}' failed with an unhandled exception:`);
runtime.Log.debug(err);
throw err;
if (err instanceof RunError) {
// For errors that are subtypes of RunError, we will print the message without hitting the unhandled error
// logic, which will dump all sorts of verbose spew like the origin source and stack trace.
runtime.Log.error(err.message);
}
else {
runtime.Log.debug(`Running program '${program}' failed with an unhandled exception:`);
runtime.Log.debug(err);
throw err;
}
}
finally {
runtime.disconnect();

40
sdk/nodejs/config.ts
View file

@ -1,5 +1,6 @@
// Copyright 2016-2017, Pulumi Corporation. All rights reserved.
import { RunError } from "./errors";
import * as runtime from "./runtime";
/**
@ -10,7 +11,9 @@ import * as runtime from "./runtime";
* fully qualified names, such as `pulumi:foo:a`, ..., and `pulumi:bar:a`, respectively.
*/
export class Config {
// name is the configuration bag's logical name and uniquely identifies it.
/**
* name is the configuration bag's logical name and uniquely identifies it.
*/
public readonly name: string;
constructor(name: string) {
@ -41,7 +44,7 @@ export class Config {
} else if (v === "false") {
return false;
}
throw new Error(`Configuration '${key}' value '${v}' is not a valid boolean`);
throw new ConfigTypeError(this.fullKey(key), v, "boolean");
}
/**
@ -57,7 +60,7 @@ export class Config {
}
let f: number = parseFloat(v);
if (isNaN(f)) {
throw new Error(`Configuration '${key}' value '${v}' is not a valid number`);
throw new ConfigTypeError(this.fullKey(key), v, "number");
}
return f;
}
@ -77,7 +80,7 @@ export class Config {
return <T>JSON.parse(v);
}
catch (err) {
throw new Error(`Configuration key '${key}' is not a valid JSON object: ${err}`);
throw new ConfigTypeError(this.fullKey(key), v, "JSON object");
}
}
@ -89,7 +92,7 @@ export class Config {
public require(key: string): string {
let v: string | undefined = this.get(key);
if (v === undefined) {
throw new Error(`Missing required configuration variable '${this.fullKey(key)}'`);
throw new ConfigMissingError(this.fullKey(key));
}
return v;
}
@ -103,7 +106,7 @@ export class Config {
public requireBoolean(key: string): boolean {
let v: boolean | undefined = this.getBoolean(key);
if (v === undefined) {
throw new Error(`Missing required configuration variable '${this.fullKey(key)}'`);
throw new ConfigMissingError(this.fullKey(key));
}
return v;
}
@ -117,7 +120,7 @@ export class Config {
public requireNumber(key: string): number {
let v: number | undefined = this.getNumber(key);
if (v === undefined) {
throw new Error(`Missing required configuration variable '${this.fullKey(key)}'`);
throw new ConfigMissingError(this.fullKey(key));
}
return v;
}
@ -131,7 +134,7 @@ export class Config {
public requireObject<T>(key: string): T {
let v: T | undefined = this.getObject<T>(key);
if (v === undefined) {
throw new Error(`Missing required configuration variable '${this.fullKey(key)}'`);
throw new ConfigMissingError(this.fullKey(key));
}
return v;
}
@ -146,3 +149,24 @@ export class Config {
}
}
/**
* ConfigTypeError is used when a configuration value is of the wrong type.
*/
class ConfigTypeError extends RunError {
constructor(key: string, v: any, expectedType: string) {
super(`Configuration '${key}' value '${v}' is not a valid ${expectedType}`);
}
}
/**
* ConfigMissingError is used when a configuration value is completely missing.
*/
class ConfigMissingError extends RunError {
constructor(key: string) {
super(
`Missing required configuration variable '${key}'\n` +
`\tplease set a value using the command \`pulumi config ${key} <value>\``
);
}
}

12
sdk/nodejs/errors.ts Normal file
View file

@ -0,0 +1,12 @@
// Copyright 2016-2017, Pulumi Corporation. All rights reserved.
/**
* RunError can be used for terminating a program abruptly, but resulting in a clean exit rather than the usual
* verbose unhandled error logic which emits the source program text and complete stack trace.
*/
export class RunError extends Error {
constructor(message: string) {
super(message);
}
}

1
sdk/nodejs/tsconfig.json
View file

@ -18,6 +18,7 @@
"files": [
"index.ts",
"config.ts",
"errors.ts",
"resource.ts",
"asset/index.ts",