diff --git a/internal/logging/logging.go b/internal/logging/logging.go index e78758543..970686344 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -24,14 +24,22 @@ const ( envLogProvider = "TF_LOG_PROVIDER" ) -// ValidLevels are the log level names that Terraform recognizes. -var ValidLevels = []string{"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "OFF"} +var ( + // ValidLevels are the log level names that Terraform recognizes. + ValidLevels = []string{"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "OFF"} -// logger is the global hclog logger -var logger hclog.Logger + // logger is the global hclog logger + logger hclog.Logger -// logWriter is a global writer for logs, to be used with the std log package -var logWriter io.Writer + // logWriter is a global writer for logs, to be used with the std log package + logWriter io.Writer + + // initialize our cache of panic output from providers + panics = &panicRecorder{ + panics: make(map[string][]string), + maxLines: 100, + } +) func init() { logger = newHCLogger("") @@ -98,13 +106,17 @@ func NewLogger(name string) hclog.Logger { if name == "" { panic("logger name required") } - return logger.Named(name) + return &logPanicWrapper{ + Logger: logger.Named(name), + } } // NewProviderLogger returns a logger for the provider plugin, possibly with a // different log level from the global logger. func NewProviderLogger(prefix string) hclog.Logger { - l := logger.Named(prefix + "provider") + l := &logPanicWrapper{ + Logger: logger.Named(prefix + "provider"), + } level := providerLogLevel() logger.Debug("created provider logger", "level", level) diff --git a/internal/logging/panic.go b/internal/logging/panic.go index cc639b38f..960d4f685 100644 --- a/internal/logging/panic.go +++ b/internal/logging/panic.go @@ -5,7 +5,10 @@ import ( "io" "io/ioutil" "os" + "strings" + "sync" + "github.com/hashicorp/go-hclog" "github.com/mitchellh/panicwrap" ) @@ -69,3 +72,111 @@ func PanicHandler(tmpLogPath string) panicwrap.HandlerFunc { fmt.Printf(panicOutput, f.Name()) } } + +const pluginPanicOutput = ` +Stack trace from the %[1]s plugin: + +%s + +Error: The %[1]s plugin crashed! + +This is always indicative of a bug within the plugin. It would be immensely +helpful if you could report the crash with the plugin's maintainers so that it +can be fixed. The output above should help diagnose the issue. +` + +// PluginPanics returns a series of provider panics that were collected during +// execution, and formatted for output. +func PluginPanics() []string { + return panics.allPanics() +} + +// panicRecorder provides a registry to check for plugin panics that may have +// happened when a plugin suddenly terminates. +type panicRecorder struct { + sync.Mutex + + // panics maps the plugin name to the panic output lines received from + // the logger. + panics map[string][]string + + // maxLines is the max number of lines we'll record after seeing a + // panic header. Since this is going to be printed in the UI output, we + // don't want to destroy the scrollback. In most cases, the first few lines + // of the stack trace is all that are required. + maxLines int +} + +// registerPlugin returns an accumulator function which will accept lines of +// a panic stack trace to collect into an error when requested. +func (p *panicRecorder) registerPlugin(name string) func(string) { + p.Lock() + defer p.Unlock() + + // In most cases we shouldn't be starting a plugin if it already + // panicked, but clear out previous entries just in case. + delete(p.panics, name) + + count := 0 + + // this callback is used by the logger to store panic output + return func(line string) { + p.Lock() + defer p.Unlock() + + // stop recording if there are too many lines. + if count > p.maxLines { + return + } + count++ + + p.panics[name] = append(p.panics[name], line) + } +} + +func (p *panicRecorder) allPanics() []string { + p.Lock() + defer p.Unlock() + + var res []string + for name, lines := range p.panics { + if len(lines) == 0 { + continue + } + + res = append(res, fmt.Sprintf(pluginPanicOutput, name, strings.Join(lines, "\n"))) + } + return res +} + +// logPanicWrapper wraps an hclog.Logger and intercepts and records any output +// that appears to be a panic. +type logPanicWrapper struct { + hclog.Logger + panicRecorder func(string) + inPanic bool +} + +// go-plugin will create a new named logger for each plugin binary. +func (l *logPanicWrapper) Named(name string) hclog.Logger { + return &logPanicWrapper{ + Logger: l.Logger.Named(name), + panicRecorder: panics.registerPlugin(name), + } +} + +// we only need to implement Debug, since that is the default output level used +// by go-plugin when encountering unstructured output on stderr. +func (l *logPanicWrapper) Debug(msg string, args ...interface{}) { + // We don't have access to the binary itself, so guess based on the stderr + // output if this is the start of the traceback. An occasional false + // positive shouldn't be a big deal, since this is only retrieved after an + // error of some sort. + l.inPanic = l.inPanic || strings.HasPrefix(msg, "panic: ") || strings.HasPrefix(msg, "fatal error: ") + + if l.inPanic && l.panicRecorder != nil { + l.panicRecorder(msg) + } + + l.Logger.Debug(msg, args...) +} diff --git a/internal/logging/panic_test.go b/internal/logging/panic_test.go new file mode 100644 index 000000000..e83a0ba5a --- /dev/null +++ b/internal/logging/panic_test.go @@ -0,0 +1,51 @@ +package logging + +import ( + "fmt" + "strings" + "testing" +) + +func TestPanicRecorder(t *testing.T) { + rec := panics.registerPlugin("test") + + output := []string{ + "panic: test", + " stack info", + } + + for _, line := range output { + rec(line) + } + + expected := fmt.Sprintf(pluginPanicOutput, "test", strings.Join(output, "\n")) + + res := PluginPanics() + if len(res) == 0 { + t.Fatal("no output") + } + + if res[0] != expected { + t.Fatalf("expected: %q\ngot: %q", expected, res[0]) + } +} + +func TestPanicLimit(t *testing.T) { + rec := panics.registerPlugin("test") + + rec("panic: test") + + for i := 0; i < 200; i++ { + rec(fmt.Sprintf("LINE: %d", i)) + } + + res := PluginPanics() + // take the extra content into account + max := strings.Count(pluginPanicOutput, "\n") + panics.maxLines + for _, out := range res { + found := strings.Count(out, "\n") + if found > max { + t.Fatalf("expected no more than %d lines, got: %d", max, found) + } + } +} diff --git a/main.go b/main.go index 0a40ae0f1..183698408 100644 --- a/main.go +++ b/main.go @@ -288,6 +288,16 @@ func wrappedMain() int { return 1 } + // if we are exiting with a non-zero code, check if it was caused by any + // plugins crashing + if exitCode != 0 { + for _, panicLog := range logging.PluginPanics() { + // we don't write this to Error, or else panicwrap will think this + // process panicked + Ui.Info(panicLog) + } + } + return exitCode } diff --git a/plugin/grpc_error.go b/plugin/grpc_error.go new file mode 100644 index 000000000..4875b576c --- /dev/null +++ b/plugin/grpc_error.go @@ -0,0 +1,74 @@ +package plugin + +import ( + "fmt" + "path" + "runtime" + + "github.com/hashicorp/terraform/tfdiags" + "google.golang.org/grpc/codes" + "google.golang.org/grpc/status" +) + +// grpcErr extracts some known error types and formats them into better +// representations for core. This must only be called from plugin methods. +// Since we don't use RPC status errors for the plugin protocol, these do not +// contain any useful details, and we can return some text that at least +// indicates the plugin call and possible error condition. +func grpcErr(err error) (diags tfdiags.Diagnostics) { + if err == nil { + return + } + + // extract the method name from the caller. + pc, _, _, ok := runtime.Caller(1) + if !ok { + logger.Error("unknown grpc call", "error", err) + return diags.Append(err) + } + + f := runtime.FuncForPC(pc) + + // Function names will contain the full import path. Take the last + // segment, which will let users know which method was being called. + _, requestName := path.Split(f.Name()) + + // Here we can at least correlate the error in the logs to a particular binary. + logger.Error(requestName, "error", err) + + // TODO: while this expands the error codes into somewhat better messages, + // this still does not easily link the error to an actual user-recognizable + // plugin. The grpc plugin does not know its configured name, and the + // errors are in a list of diagnostics, making it hard for the caller to + // annotate the returned errors. + switch status.Code(err) { + case codes.Unavailable: + // This case is when the plugin has stopped running for some reason, + // and is usually the result of a crash. + diags = diags.Append(tfdiags.Sourceless( + tfdiags.Error, + "Plugin did not respond", + fmt.Sprintf("The plugin encountered an error, and failed to respond to the %s call. "+ + "The plugin logs may contain more details.", requestName), + )) + case codes.Canceled: + diags = diags.Append(tfdiags.Sourceless( + tfdiags.Error, + "Request cancelled", + fmt.Sprintf("The %s request was cancelled.", requestName), + )) + case codes.Unimplemented: + diags = diags.Append(tfdiags.Sourceless( + tfdiags.Error, + "Unsupported plugin method", + fmt.Sprintf("The %s method is not supported by this plugin.", requestName), + )) + default: + diags = diags.Append(tfdiags.Sourceless( + tfdiags.Error, + "Plugin error", + fmt.Sprintf("The plugin returned an unexpected error from %s: %v", requestName, err), + )) + } + return +} diff --git a/plugin/grpc_provider.go b/plugin/grpc_provider.go index 495347bfd..d2a287e61 100644 --- a/plugin/grpc_provider.go +++ b/plugin/grpc_provider.go @@ -3,12 +3,12 @@ package plugin import ( "context" "errors" - "log" "sync" "github.com/zclconf/go-cty/cty" plugin "github.com/hashicorp/go-plugin" + "github.com/hashicorp/terraform/internal/logging" proto "github.com/hashicorp/terraform/internal/tfplugin5" "github.com/hashicorp/terraform/plugin/convert" "github.com/hashicorp/terraform/providers" @@ -17,6 +17,8 @@ import ( "google.golang.org/grpc" ) +var logger = logging.HCLogger() + // GRPCProviderPlugin implements plugin.GRPCPlugin for the go-plugin package. type GRPCProviderPlugin struct { plugin.Plugin @@ -114,7 +116,7 @@ func (p *GRPCProvider) getProviderMetaSchema() providers.Schema { } func (p *GRPCProvider) GetSchema() (resp providers.GetSchemaResponse) { - log.Printf("[TRACE] GRPCProvider: GetSchema") + logger.Trace("GRPCProvider: GetSchema") p.mu.Lock() defer p.mu.Unlock() @@ -133,7 +135,7 @@ func (p *GRPCProvider) GetSchema() (resp providers.GetSchemaResponse) { const maxRecvSize = 64 << 20 protoResp, err := p.client.GetSchema(p.ctx, new(proto.GetProviderSchema_Request), grpc.MaxRecvMsgSizeCallOption{MaxRecvMsgSize: maxRecvSize}) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } @@ -146,7 +148,7 @@ func (p *GRPCProvider) GetSchema() (resp providers.GetSchemaResponse) { resp.Provider = convert.ProtoToProviderSchema(protoResp.Provider) if protoResp.ProviderMeta == nil { - log.Printf("[TRACE] No provider meta schema returned") + logger.Debug("No provider meta schema returned") } else { resp.ProviderMeta = convert.ProtoToProviderSchema(protoResp.ProviderMeta) } @@ -165,7 +167,7 @@ func (p *GRPCProvider) GetSchema() (resp providers.GetSchemaResponse) { } func (p *GRPCProvider) PrepareProviderConfig(r providers.PrepareProviderConfigRequest) (resp providers.PrepareProviderConfigResponse) { - log.Printf("[TRACE] GRPCProvider: PrepareProviderConfig") + logger.Trace("GRPCProvider: PrepareProviderConfig") schema := p.getSchema() ty := schema.Provider.Block.ImpliedType() @@ -182,7 +184,7 @@ func (p *GRPCProvider) PrepareProviderConfig(r providers.PrepareProviderConfigRe protoResp, err := p.client.PrepareProviderConfig(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } @@ -198,7 +200,7 @@ func (p *GRPCProvider) PrepareProviderConfig(r providers.PrepareProviderConfigRe } func (p *GRPCProvider) ValidateResourceTypeConfig(r providers.ValidateResourceTypeConfigRequest) (resp providers.ValidateResourceTypeConfigResponse) { - log.Printf("[TRACE] GRPCProvider: ValidateResourceTypeConfig") + logger.Trace("GRPCProvider: ValidateResourceTypeConfig") resourceSchema := p.getResourceSchema(r.TypeName) mp, err := msgpack.Marshal(r.Config, resourceSchema.Block.ImpliedType()) @@ -214,7 +216,7 @@ func (p *GRPCProvider) ValidateResourceTypeConfig(r providers.ValidateResourceTy protoResp, err := p.client.ValidateResourceTypeConfig(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } @@ -223,7 +225,7 @@ func (p *GRPCProvider) ValidateResourceTypeConfig(r providers.ValidateResourceTy } func (p *GRPCProvider) ValidateDataSourceConfig(r providers.ValidateDataSourceConfigRequest) (resp providers.ValidateDataSourceConfigResponse) { - log.Printf("[TRACE] GRPCProvider: ValidateDataSourceConfig") + logger.Trace("GRPCProvider: ValidateDataSourceConfig") dataSchema := p.getDatasourceSchema(r.TypeName) @@ -240,7 +242,7 @@ func (p *GRPCProvider) ValidateDataSourceConfig(r providers.ValidateDataSourceCo protoResp, err := p.client.ValidateDataSourceConfig(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -248,7 +250,7 @@ func (p *GRPCProvider) ValidateDataSourceConfig(r providers.ValidateDataSourceCo } func (p *GRPCProvider) UpgradeResourceState(r providers.UpgradeResourceStateRequest) (resp providers.UpgradeResourceStateResponse) { - log.Printf("[TRACE] GRPCProvider: UpgradeResourceState") + logger.Trace("GRPCProvider: UpgradeResourceState") resSchema := p.getResourceSchema(r.TypeName) @@ -263,7 +265,7 @@ func (p *GRPCProvider) UpgradeResourceState(r providers.UpgradeResourceStateRequ protoResp, err := p.client.UpgradeResourceState(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -285,7 +287,7 @@ func (p *GRPCProvider) UpgradeResourceState(r providers.UpgradeResourceStateRequ } func (p *GRPCProvider) Configure(r providers.ConfigureRequest) (resp providers.ConfigureResponse) { - log.Printf("[TRACE] GRPCProvider: Configure") + logger.Trace("GRPCProvider: Configure") schema := p.getSchema() @@ -307,7 +309,7 @@ func (p *GRPCProvider) Configure(r providers.ConfigureRequest) (resp providers.C protoResp, err := p.client.Configure(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -315,7 +317,7 @@ func (p *GRPCProvider) Configure(r providers.ConfigureRequest) (resp providers.C } func (p *GRPCProvider) Stop() error { - log.Printf("[TRACE] GRPCProvider: Stop") + logger.Trace("GRPCProvider: Stop") resp, err := p.client.Stop(p.ctx, new(proto.Stop_Request)) if err != nil { @@ -329,7 +331,7 @@ func (p *GRPCProvider) Stop() error { } func (p *GRPCProvider) ReadResource(r providers.ReadResourceRequest) (resp providers.ReadResourceResponse) { - log.Printf("[TRACE] GRPCProvider: ReadResource") + logger.Trace("GRPCProvider: ReadResource") resSchema := p.getResourceSchema(r.TypeName) metaSchema := p.getProviderMetaSchema() @@ -357,7 +359,7 @@ func (p *GRPCProvider) ReadResource(r providers.ReadResourceRequest) (resp provi protoResp, err := p.client.ReadResource(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -374,7 +376,7 @@ func (p *GRPCProvider) ReadResource(r providers.ReadResourceRequest) (resp provi } func (p *GRPCProvider) PlanResourceChange(r providers.PlanResourceChangeRequest) (resp providers.PlanResourceChangeResponse) { - log.Printf("[TRACE] GRPCProvider: PlanResourceChange") + logger.Trace("GRPCProvider: PlanResourceChange") resSchema := p.getResourceSchema(r.TypeName) metaSchema := p.getProviderMetaSchema() @@ -416,7 +418,7 @@ func (p *GRPCProvider) PlanResourceChange(r providers.PlanResourceChangeRequest) protoResp, err := p.client.PlanResourceChange(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -440,7 +442,7 @@ func (p *GRPCProvider) PlanResourceChange(r providers.PlanResourceChangeRequest) } func (p *GRPCProvider) ApplyResourceChange(r providers.ApplyResourceChangeRequest) (resp providers.ApplyResourceChangeResponse) { - log.Printf("[TRACE] GRPCProvider: ApplyResourceChange") + logger.Trace("GRPCProvider: ApplyResourceChange") resSchema := p.getResourceSchema(r.TypeName) metaSchema := p.getProviderMetaSchema() @@ -480,7 +482,7 @@ func (p *GRPCProvider) ApplyResourceChange(r providers.ApplyResourceChangeReques protoResp, err := p.client.ApplyResourceChange(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -500,7 +502,7 @@ func (p *GRPCProvider) ApplyResourceChange(r providers.ApplyResourceChangeReques } func (p *GRPCProvider) ImportResourceState(r providers.ImportResourceStateRequest) (resp providers.ImportResourceStateResponse) { - log.Printf("[TRACE] GRPCProvider: ImportResourceState") + logger.Trace("GRPCProvider: ImportResourceState") protoReq := &proto.ImportResourceState_Request{ TypeName: r.TypeName, @@ -509,7 +511,7 @@ func (p *GRPCProvider) ImportResourceState(r providers.ImportResourceStateReques protoResp, err := p.client.ImportResourceState(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -534,7 +536,7 @@ func (p *GRPCProvider) ImportResourceState(r providers.ImportResourceStateReques } func (p *GRPCProvider) ReadDataSource(r providers.ReadDataSourceRequest) (resp providers.ReadDataSourceResponse) { - log.Printf("[TRACE] GRPCProvider: ReadDataSource") + logger.Trace("GRPCProvider: ReadDataSource") dataSchema := p.getDatasourceSchema(r.TypeName) metaSchema := p.getProviderMetaSchema() @@ -563,7 +565,7 @@ func (p *GRPCProvider) ReadDataSource(r providers.ReadDataSourceRequest) (resp p protoResp, err := p.client.ReadDataSource(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -580,7 +582,7 @@ func (p *GRPCProvider) ReadDataSource(r providers.ReadDataSourceRequest) (resp p // closing the grpc connection is final, and terraform will call it at the end of every phase. func (p *GRPCProvider) Close() error { - log.Printf("[TRACE] GRPCProvider: Close") + logger.Trace("GRPCProvider: Close") // Make sure to stop the server if we're not running within go-plugin. if p.TestServer != nil { @@ -592,7 +594,7 @@ func (p *GRPCProvider) Close() error { // where the factory is built and is the only point with access to the // plugin.Client. if p.PluginClient == nil { - log.Println("[DEBUG] provider has no plugin.Client") + logger.Debug("provider has no plugin.Client") return nil } diff --git a/plugin/grpc_provisioner.go b/plugin/grpc_provisioner.go index 136c88d68..c57daa9af 100644 --- a/plugin/grpc_provisioner.go +++ b/plugin/grpc_provisioner.go @@ -4,7 +4,6 @@ import ( "context" "errors" "io" - "log" "sync" plugin "github.com/hashicorp/go-plugin" @@ -61,7 +60,7 @@ func (p *GRPCProvisioner) GetSchema() (resp provisioners.GetSchemaResponse) { protoResp, err := p.client.GetSchema(p.ctx, new(proto.GetProvisionerSchema_Request)) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -96,7 +95,7 @@ func (p *GRPCProvisioner) ValidateProvisionerConfig(r provisioners.ValidateProvi } protoResp, err := p.client.ValidateProvisionerConfig(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } resp.Diagnostics = resp.Diagnostics.Append(convert.ProtoToDiagnostics(protoResp.Diagnostics)) @@ -130,7 +129,7 @@ func (p *GRPCProvisioner) ProvisionResource(r provisioners.ProvisionResourceRequ outputClient, err := p.client.ProvisionResource(p.ctx, protoReq) if err != nil { - resp.Diagnostics = resp.Diagnostics.Append(err) + resp.Diagnostics = resp.Diagnostics.Append(grpcErr(err)) return resp } @@ -169,7 +168,7 @@ func (p *GRPCProvisioner) Stop() error { func (p *GRPCProvisioner) Close() error { // check this since it's not automatically inserted during plugin creation if p.PluginClient == nil { - log.Println("[DEBUG] provider has no plugin.Client") + logger.Debug("provisioner has no plugin.Client") return nil }